I''m curious about all the "slow xxxx" messages on our OSSs. It is true that the OSSs are getting hammered and the "spindles" (actually RAID 5 LUNs) are saturated (96% to 100% busy in iostat). However, await and svctm numbers are *very* reasonable (in my experience). The await times range from 50 to 250 ms and the svctm numbers are usually only a few ms. The cpus are mostly idle or servicing interrupts from the FC HCAs and IB HCAs and the MDT threads are mostly sleeping or in disk wait. The answer seems obvious enough but lustre is reporting delays of (that''s what I assume the "slow whatevers" are about) on the order of a minute which is 2 to 3 orders of magnitude beyond anything I''m seeing in I/O stat. What is Lustre really trying to tell us? It seems like there may be some race condition that is forcing some of these operations to wait until one or more timers expire before they can proceed. Device delays alone don''t seem to account for it. Thanks, Charlie Taylor UF HPC Center Jun 24 21:36:01 tebow1 kernel: Lustre: 2003:0:(lustre_fsfilt.h: 306:fsfilt_setattr()) crn-OST0001: slow setattr 45s Jun 25 00:20:03 tebow1 kernel: Lustre: 876:0:(lustre_fsfilt.h: 306:fsfilt_setattr()) crn-OST0008: slow setattr 46s Jun 25 00:30:00 tebow1 kernel: Lustre: 349:0:(lustre_fsfilt.h: 306:fsfilt_setattr()) crn-OST000a: slow setattr 57s Jun 25 02:51:03 tebow1 kernel: Lustre: 31903:0:(filter_io_26.c: 698:filter_commitrw_write()) crn-OST0005: slow i_mutex 30s Jun 25 02:51:03 tebow1 kernel: Lustre: 31903:0:(filter_io_26.c: 711:filter_commitrw_write()) crn-OST0005: slow brw_start 30s Jun 25 02:51:03 tebow1 kernel: Lustre: 6559:0:(lustre_fsfilt.h: 296:fsfilt_commit_wait()) crn-OST0005: slow journal start 30s Jun 25 02:51:03 tebow1 kernel: Lustre: 2691:0:(filter_io_26.c: 776:filter_commitrw_write()) crn-OST0005: slow commitrw commit 30s Jun 25 02:51:03 tebow1 kernel: Lustre: 7681:0:(filter_io_26.c: 763:filter_commitrw_write()) crn-OST0005: slow direct_io 30s Jun 25 02:52:43 tebow1 kernel: Lustre: 6541:0:(lustre_fsfilt.h: 205:fsfilt_start_log()) crn-OST0005: slow journal start 81s Jun 25 02:52:43 tebow1 kernel: Lustre: 32269:0:(lustre_fsfilt.h: 240:fsfilt_brw_start_log()) crn-OST0005: slow journal start 68s Jun 25 02:52:43 tebow1 kernel: Lustre: 32269:0:(filter_io_26.c: 711:filter_commitrw_write()) crn-OST0005: slow brw_start 68s Jun 25 02:52:43 tebow1 kernel: Lustre: 6619:0:(lustre_fsfilt.h: 240:fsfilt_brw_start_log()) crn-OST0005: slow journal start 68s Jun 25 02:52:43 tebow1 kernel: Lustre: 6580:0:(filter_io_26.c: 698:filter_commitrw_write()) crn-OST0005: slow i_mutex 88s Jun 25 02:52:43 tebow1 kernel: Lustre: 5651:0:(filter_io_26.c: 763:filter_commitrw_write()) crn-OST0005: slow direct_io 83s Jun 25 02:52:43 tebow1 kernel: Lustre: 869:0:(filter_io_26.c: 776:filter_commitrw_write()) crn-OST0005: slow commitrw commit 88s Jun 25 02:52:43 tebow1 kernel: Lustre: 30543:0:(lustre_fsfilt.h: 296:fsfilt_commit_wait()) crn-OST0005: slow journal start 88s Jun 25 02:52:43 tebow1 kernel: Lustre: 5654:0:(lustre_fsfilt.h: 205:fsfilt_start_log()) crn-OST0005: slow journal start 68s Jun 25 03:17:31 tebow1 kernel: Lustre: 7681:0:(filter_io_26.c: 698:filter_commitrw_write()) crn-OST000b: slow i_mutex 52s Jun 25 03:17:31 tebow1 kernel: Lustre: 6598:0:(lustre_fsfilt.h: 240:fsfilt_brw_start_log()) crn-OST000b: slow journal start 31s Jun 25 03:17:31 tebow1 kernel: Lustre: 6598:0:(filter_io_26.c: 711:filter_commitrw_write()) crn-OST000b: slow brw_start 31s Jun 25 03:17:31 tebow1 kernel: Lustre: 6598:0:(filter_io_26.c: 763:filter_commitrw_write()) crn-OST000b: slow direct_io 31s Jun 25 03:17:31 tebow1 kernel: Lustre: 2004:0:(filter_io_26.c: 698:filter_commitrw_write()) crn-OST000b: slow i_mutex 52s Jun 25 03:17:31 tebow1 kernel: Lustre: 2004:0:(filter_io_26.c: 711:filter_commitrw_write()) crn-OST000b: slow brw_start 52s Jun 25 03:17:31 tebow1 kernel: Lustre: 1633:0:(filter_io_26.c: 776:filter_commitrw_write()) crn-OST000b: slow commitrw commit 52s Jun 25 03:19:11 tebow1 kernel: [<ffffffff800615a6>] __mutex_lock_slowpath+0x55/0x90 Jun 25 03:19:12 tebow1 kernel: [<ffffffff800615a6>] __mutex_lock_slowpath+0x55/0x90 Jun 25 03:19:12 tebow1 kernel: [<ffffffff800615a6>] __mutex_lock_slowpath+0x55/0x90 Jun 25 03:19:12 tebow1 kernel: [<ffffffff800615a6>] __mutex_lock_slowpath+0x55/0x90 Jun 25 03:19:22 tebow1 kernel: [<ffffffff800615a6>] __mutex_lock_slowpath+0x55/0x90 Jun 25 03:20:19 tebow1 kernel: Lustre: 7897:0:(lustre_fsfilt.h: 240:fsfilt_brw_start_log()) crn-OST000b: slow journal start 129s Jun 25 03:20:19 tebow1 kernel: Lustre: 4272:0:(filter_io_26.c: 698:filter_commitrw_write()) crn-OST000b: slow i_mutex 168s Jun 25 03:20:19 tebow1 kernel: Lustre: 17835:0:(filter_io_26.c: 711:filter_commitrw_write()) crn-OST000b: slow brw_start 154s Jun 25 03:20:19 tebow1 kernel: Lustre: 869:0:(lustre_fsfilt.h: 205:fsfilt_start_log()) crn-OST000b: slow journal start 133s Jun 25 03:20:20 tebow1 kernel: Lustre: 7897:0:(filter_io_26.c: 763:filter_commitrw_write()) crn-OST000b: slow direct_io 129s Jun 25 03:20:20 tebow1 kernel: Lustre: 14215:0:(lustre_fsfilt.h: 296:fsfilt_commit_wait()) crn-OST000b: slow journal start 157s Jun 25 03:20:20 tebow1 kernel: Lustre: 6617:0:(filter_io_26.c: 776:filter_commitrw_write()) crn-OST000b: slow commitrw commit 168s Jun 25 05:51:53 tebow1 kernel: Lustre: 6625:0:(filter_io_26.c: 698:filter_commitrw_write()) crn-OST0009: slow i_mutex 54s Jun 25 05:51:53 tebow1 kernel: Lustre: 6625:0:(filter_io_26.c: 711:filter_commitrw_write()) crn-OST0009: slow brw_start 54s Jun 25 05:51:53 tebow1 kernel: Lustre: 31170:0:(filter_io_26.c: 763:filter_commitrw_write()) crn-OST0009: slow direct_io 54s Jun 25 05:51:53 tebow1 kernel: Lustre: 31176:0:(filter_io_26.c: 776:filter_commitrw_write()) crn-OST0009: slow commitrw commit 54s Jun 25 05:51:53 tebow1 kernel: Lustre: 11514:0:(lustre_fsfilt.h: 296:fsfilt_commit_wait()) crn-OST0009: slow journal start 54s Jun 25 05:52:38 tebow1 kernel: Lustre: 6600:0:(lustre_fsfilt.h: 240:fsfilt_brw_start_log()) crn-OST0009: slow journal start 32s Jun 25 05:52:38 tebow1 kernel: Lustre: 6600:0:(filter_io_26.c: 711:filter_commitrw_write()) crn-OST0009: slow brw_start 32s Jun 25 05:52:38 tebow1 kernel: Lustre: 4262:0:(filter_io_26.c: 698:filter_commitrw_write()) crn-OST0009: slow i_mutex 43s Jun 25 05:52:38 tebow1 kernel: Lustre: 6581:0:(filter_io_26.c: 763:filter_commitrw_write()) crn-OST0009: slow direct_io 43s Jun 25 05:52:38 tebow1 kernel: Lustre: 6581:0:(filter_io_26.c: 776:filter_commitrw_write()) crn-OST0009: slow commitrw commit 43s Jun 25 05:52:38 tebow1 kernel: Lustre: 18886:0:(lustre_fsfilt.h: 296:fsfilt_commit_wait()) crn-OST0009: slow journal start 43s Jun 25 14:43:31 tebow1 kernel: Lustre: 18335:0:(lustre_fsfilt.h: 306:fsfilt_setattr()) crn-OST000c: slow setattr 34s Jun 25 14:43:40 tebow1 kernel: Lustre: 1959:0:(lustre_fsfilt.h: 306:fsfilt_setattr()) crn-OST000b: slow setattr 46s Jun 26 04:00:31 tebow1 kernel: Lustre: 6525:0:(lustre_fsfilt.h: 240:fsfilt_brw_start_log()) crn-OST0003: slow journal start 36s Jun 26 04:00:31 tebow1 kernel: Lustre: 29138:0:(filter_io_26.c: 698:filter_commitrw_write()) crn-OST0003: slow i_mutex 40s Jun 26 04:00:31 tebow1 kernel: Lustre: 29138:0:(filter_io_26.c: 711:filter_commitrw_write()) crn-OST0003: slow brw_start 40s Jun 26 04:00:31 tebow1 kernel: Lustre: 6525:0:(filter_io_26.c: 763:filter_commitrw_write()) crn-OST0003: slow direct_io 36s Jun 26 04:00:31 tebow1 kernel: Lustre: 24264:0:(filter_io_26.c: 776:filter_commitrw_write()) crn-OST0003: slow commitrw commit 40s Jun 26 04:01:35 tebow1 kernel: Lustre: 885:0:(filter_io_26.c: 698:filter_commitrw_write()) crn-OST0003: slow i_mutex 41s Jun 26 04:01:35 tebow1 kernel: Lustre: 31901:0:(lustre_fsfilt.h: 240:fsfilt_brw_start_log()) crn-OST0003: slow journal start 30s Jun 26 04:01:35 tebow1 kernel: Lustre: 31901:0:(filter_io_26.c: 711:filter_commitrw_write()) crn-OST0003: slow brw_start 30s Jun 26 04:01:35 tebow1 kernel: Lustre: 24269:0:(lustre_fsfilt.h: 296:fsfilt_commit_wait()) crn-OST0003: slow journal start 40s Jun 26 04:01:35 tebow1 kernel: Lustre: 24269:0:(filter_io_26.c: 776:filter_commitrw_write()) crn-OST0003: slow commitrw commit 40s Jun 26 04:01:35 tebow1 kernel: Lustre: 31901:0:(filter_io_26.c: 763:filter_commitrw_write()) crn-OST0003: slow direct_io 30s Jun 26 04:02:06 tebow1 kernel: Lustre: 884:0:(filter_io_26.c: 763:filter_commitrw_write()) crn-OST0003: slow direct_io 31s Jun 26 04:02:06 tebow1 kernel: Lustre: 32337:0:(filter_io_26.c: 776:filter_commitrw_write()) crn-OST0003: slow commitrw commit 31s Jun 26 04:04:22 tebow1 kernel: Lustre: 6617:0:(filter_io_26.c: 763:filter_commitrw_write()) crn-OST0003: slow direct_io 30s Jun 26 04:04:22 tebow1 kernel: Lustre: 6617:0:(filter_io_26.c: 776:filter_commitrw_write()) crn-OST0003: slow commitrw commit 30s Jun 26 04:06:04 tebow1 kernel: [<ffffffff800615ae>] __mutex_lock_slowpath+0x5d/0x90 Jun 26 04:06:04 tebow1 kernel: [<ffffffff800615a6>] __mutex_lock_slowpath+0x55/0x90 Jun 26 04:06:04 tebow1 kernel: [<ffffffff800615a6>] __mutex_lock_slowpath+0x55/0x90 Jun 26 04:06:04 tebow1 kernel: [<ffffffff800615a6>] __mutex_lock_slowpath+0x55/0x90 Jun 26 04:06:04 tebow1 kernel: [<ffffffff800615a6>] __mutex_lock_slowpath+0x55/0x90 Jun 26 04:06:04 tebow1 kernel: [<ffffffff800615a6>] __mutex_lock_slowpath+0x55/0x90 Jun 26 04:06:04 tebow1 kernel: [<ffffffff800615a6>] __mutex_lock_slowpath+0x55/0x90 Jun 26 04:06:05 tebow1 kernel: [<ffffffff800615a6>] __mutex_lock_slowpath+0x55/0x90 Jun 26 04:06:05 tebow1 kernel: [<ffffffff800615a6>] __mutex_lock_slowpath+0x55/0x90 Jun 26 04:06:44 tebow1 kernel: Lustre: 31167:0:(filter_io_26.c: 698:filter_commitrw_write()) crn-OST0003: slow i_mutex 140s Jun 26 04:06:44 tebow1 kernel: Lustre: 7680:0:(lustre_fsfilt.h: 240:fsfilt_brw_start_log()) crn-OST0003: slow journal start 119s Jun 26 04:06:44 tebow1 kernel: Lustre: 7680:0:(filter_io_26.c: 711:filter_commitrw_write()) crn-OST0003: slow brw_start 119s Jun 26 04:06:44 tebow1 kernel: Lustre: 13743:0:(lustre_fsfilt.h: 205:fsfilt_start_log()) crn-OST0003: slow journal start 61s Jun 26 04:06:44 tebow1 kernel: Lustre: 7680:0:(filter_io_26.c: 763:filter_commitrw_write()) crn-OST0003: slow direct_io 119s Jun 26 04:06:44 tebow1 kernel: Lustre: 14979:0:(filter_io_26.c: 776:filter_commitrw_write()) crn-OST0003: slow commitrw commit 140s Jun 26 04:08:24 tebow1 kernel: [<ffffffff800615a6>] __mutex_lock_slowpath+0x55/0x90 Jun 26 04:08:24 tebow1 kernel: [<ffffffff800615a6>] __mutex_lock_slowpath+0x55/0x90 Jun 26 04:08:24 tebow1 kernel: [<ffffffff800615a6>] __mutex_lock_slowpath+0x55/0x90 Jun 26 04:08:24 tebow1 kernel: [<ffffffff800615a6>] __mutex_lock_slowpath+0x55/0x90 Jun 26 04:08:24 tebow1 kernel: [<ffffffff800615a6>] __mutex_lock_slowpath+0x55/0x90 Jun 26 04:08:24 tebow1 kernel: [<ffffffff800615a6>] __mutex_lock_slowpath+0x55/0x90 Jun 26 04:08:24 tebow1 kernel: [<ffffffff800615a6>] __mutex_lock_slowpath+0x55/0x90 Jun 26 04:11:37 tebow1 kernel: Lustre: 18876:0:(filter_io_26.c: 698:filter_commitrw_write()) crn-OST0003: slow i_mutex 293s Jun 26 04:11:37 tebow1 kernel: Lustre: 7005:0:(lustre_fsfilt.h: 240:fsfilt_brw_start_log()) crn-OST0003: slow journal start 260s Jun 26 04:11:37 tebow1 kernel: Lustre: 7005:0:(filter_io_26.c: 711:filter_commitrw_write()) crn-OST0003: slow brw_start 260s Jun 26 04:11:37 tebow1 kernel: Lustre: 29130:0:(filter_io_26.c: 763:filter_commitrw_write()) crn-OST0003: slow direct_io 263s Jun 26 04:11:37 tebow1 kernel: Lustre: 6511:0:(filter_io_26.c: 776:filter_commitrw_write()) crn-OST0003: slow commitrw commit 293s Jun 26 04:14:20 tebow1 kernel: Lustre: 2704:0:(filter_io_26.c: 698:filter_commitrw_write()) crn-OST0003: slow i_mutex 44s Jun 26 04:14:20 tebow1 kernel: Lustre: 2704:0:(filter_io_26.c: 711:filter_commitrw_write()) crn-OST0003: slow brw_start 44s Jun 26 04:14:20 tebow1 kernel: Lustre: 31905:0:(filter_io_26.c: 763:filter_commitrw_write()) crn-OST0003: slow direct_io 44s Jun 26 04:14:20 tebow1 kernel: Lustre: 31905:0:(filter_io_26.c: 776:filter_commitrw_write()) crn-OST0003: slow commitrw commit 44s Jun 26 11:07:40 tebow1 kernel: Lustre: 6610:0:(filter_io_26.c: 763:filter_commitrw_write()) crn-OST0003: slow direct_io 47s Jun 26 11:07:40 tebow1 kernel: Lustre: 6610:0:(filter_io_26.c: 776:filter_commitrw_write()) crn-OST0003: slow commitrw commit 47s Jun 26 11:07:44 tebow1 kernel: Lustre: 6506:0:(filter_io_26.c: 698:filter_commitrw_write()) crn-OST0003: slow i_mutex 31s Jun 26 11:07:45 tebow1 kernel: Lustre: 885:0:(filter_io_26.c: 763:filter_commitrw_write()) crn-OST0003: slow direct_io 31s Jun 26 11:07:45 tebow1 kernel: Lustre: 885:0:(filter_io_26.c: 776:filter_commitrw_write()) crn-OST0003: slow commitrw commit 31s Jun 26 11:07:45 tebow1 kernel: Lustre: 6506:0:(filter_io_26.c: 711:filter_commitrw_write()) crn-OST0003: slow brw_start 31s Jun 26 12:42:23 tebow1 kernel: Lustre: 14215:0:(lustre_fsfilt.h: 306:fsfilt_setattr()) crn-OST0007: slow setattr 56s
On Fri, Jun 27, 2008 at 06:08:12AM -0400, Charles Taylor wrote:> I''m curious about all the "slow xxxx" messages on our OSSs. It is > true that the OSSs are getting hammered and the "spindles" (actually > RAID 5 LUNs) are saturated (96% to 100% busy in iostat). However, > await and svctm numbers are *very* reasonable (in my experience). > The await times range from 50 to 250 ms and the svctm numbers are > usually only a few ms. > > The cpus are mostly idle or servicing interrupts from the FC HCAs and > IB HCAs and the MDT threads are mostly sleeping or in disk wait. The > answer seems obvious enough but lustre is reporting delays of (that''s > what I assume the "slow whatevers" are about) on the order of a > minute which is 2 to 3 orders of magnitude beyond anything I''m seeing > in I/O stat. > > What is Lustre really trying to tell us? It seems like there may be > some race condition that is forcing some of these operations to wait > until one or more timers expire before they can proceed. Device > delays alone don''t seem to account for it. > 296:fsfilt_commit_wait()) crn-OST0009: slow journal start 43shelo! We have the same problem with one of our meta servers (meta1). But we switched to its pair (meta2) and now everything seems to be all right. By the way when we created the cluster, there was only meta2, meta1 was attached to it later with drbd. Anything else is the same about them. Just for your information, I know, it''s not a big help. Bye, tamas
On Fri, 2008-06-27 at 06:08 -0400, Charles Taylor wrote:> I''m curious about all the "slow xxxx" messages on our OSSs.Barring any erroneous conditions (i.e. storage server problems, etc.), this usually means you are oversubscribing your storage servers. Try reducing the number of OST threads on your OSSes. b. -------------- next part -------------- A non-text attachment was scrubbed... Name: not available Type: application/pgp-signature Size: 189 bytes Desc: This is a digitally signed message part Url : http://lists.lustre.org/pipermail/lustre-discuss/attachments/20080627/9936be4d/attachment.bin