I've been chasing a fault since "upgrading" from Fedora 15 to Fedora 16.
When under heavy IO load my root volume will hang and block any
additional writes. Reading appears to be ok but I can't tell if I'm
reading the actual md device or cache memory. This problem occurs most
often when doing a weekly check of all md devices in the early AM hours
and particularly when the check fires before my backup job completes.
The checks do appear to complete normally, and without error.
There are no error or warning messages in any log or in the console.
There is no indication of any problem except that any IO of the root
volume will hang and ctrl-c does not get me back to a prompt.
Interestingly, to me, when in this state, 'iostat -dx 1' shows the root
LVM volume at 100% utilization yet neither the mv physical volume nor
any of the constituent devices show any activity and all read 0%
utilization. IO wait reads 50% (6 core machine) so it appears that
something is waiting for an event that will never occur.
The md device showed a value of 26 for stripe_cache_active during the
most recent occurrence and that number did not change over time.
Further, mdadm -D /dev/md0 showed the following:
dev/md0:
Version : 1.2
Creation Time : Tue Dec 21 16:28:52 2010
Raid Level : raid5
Array Size : 2180641792 (2079.62 GiB 2232.98 GB)
Used Dev Size : 311520256 (297.09 GiB 319.00 GB)
Raid Devices : 8
Total Devices : 8
Persistence : Superblock is persistent
Update Time : Sun Jan 8 03:31:42 2012
State : active
Active Devices : 8
Working Devices : 8
Failed Devices : 0
Spare Devices : 0
Layout : left-symmetric
Chunk Size : 64K
Name : ****.****.com:1 (local to host ****.****.com)
UUID : 4e95a658:13a5a387:dd62bdbe:ea655271
Events : 736102
Number Major Minor RaidDevice State
0 8 2 0 active sync /dev/sda2
1 8 18 1 active sync /dev/sdb2
9 8 34 2 active sync /dev/sdc2
3 8 50 3 active sync /dev/sdd2
4 8 66 4 active sync /dev/sde2
5 8 82 5 active sync /dev/sdf2
6 8 98 6 active sync /dev/sdg2
8 8 114 7 active sync /dev/sdh2
I noted that state is active and not idle. The output of 'mdadm -D
/dev/md0' did not change between executions.
It appears that either something is deadlocked somewhere or some other
event was missed and something is waiting forever for it to happen. I
was able to read from /dev/md0 and all the constituent devices via dd
and 'smartctl -a' did not indicate any problems. I was able to read from
/proc/mdstat and no problems were indicated.
I have no idea how to debug this further. What else should I look at
when I encounter this problem? What kind of logging can I enable which
might show additional, and hopefully useful, information when the
problem occurs?
I'm running Fedora 16 with the latest packages updated via yum. The
mdadm is v3.2.2 - 17th June 2011 and the kernel is 3.1.6-1.fc16.x86_64.
I have 6 devices connected to the AMD SB850 ACHI SATA controller and 2
devices to the built-in JMicron JMB362/363 controller to make /dev/md0.
I also have 6 devices connected to 3 sil3132 SATA controllers to make
/dev/md1. I have never encountered this problem with md1 but its I/O is
no where near as great.
Suggestions?
--Larkin
On Sun, 08 Jan 2012 16:03:10 -0600 Larkin Lowrey [off-list ref]
wrote:
Suggestions?
# echo t > /proc/sysrq-trigger
and capture that messages that go to 'dmesg'. Post them.
Hopefully your message ring buffer is big enough to collect the entire
output. If it isn't you might need to boot with
log_buf_len=1M
or similar.
That should show what process is blocking on what.
NeilBrown
I did another sysrq dump and have attached the output.
Again, 'iostat -dx 1' showed 100% utilization on the LVM which uses
/dev/md0 as a pv and /sys/block/md0/md/stripe_cache_active was 29 and
that value did not change. There were no error messages in
/var/log/messages or 'dmesg'.
My suspicions lie with md0 since the stripe_cache_active value remains
at a fixed non-zero value even though all disks are (or appear to be)
idle. Should I be looking elsewhere? This hardware did not exhibit this
problem before "upgrading" from Fedora 15 to Fedora 16.
Thank you,
--Larkin
On 1/8/2012 6:26 PM, NeilBrown wrote:
On Sun, 08 Jan 2012 16:03:10 -0600 Larkin Lowrey
[off-list ref]
wrote:
quoted
Suggestions?
# echo t > /proc/sysrq-trigger
and capture that messages that go to 'dmesg'. Post them.
Hopefully your message ring buffer is big enough to collect the entire
output. If it isn't you might need to boot with
log_buf_len=1M
or similar.
That should show what process is blocking on what.
NeilBrown
I either have more info or a totally different scenario. I initiated a
raid5->raid6 reshape on a different machine. At the same time I (perhaps
stupidly) ran resize2fs to shrink the ext4 fs on the array being
reshaped. The reshape is going slowly (as I would expect) but the resize
is nearly dead. It is only able to write a single 4k block to the array
about every 5-6 seconds.
If that's expected then sorry for the noise and please ignore the rest.
Otherwise...
When I tried reducing sync_speed_min to 1000 the resize2fs write
interval increased to once per 8-10s. When I lowered sync_speed_max to
1000 I saw no more writes until I set the min/max back to 500000 at
which point iostat reported a w_await time roughly equal to the time the
array had the lower max.
The '# echo t > /proc/sysrq-trigger ' output seems to indicate that
resize2fs is stuck doing an fsync. The full dump is attached.
Here's an iostat showing 100% utilization of the LVM volume and the 4k
block writes.
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s
avgrq-sz avgqu-sz await r_await w_await svctm %util
md2 0.00 0.00 0.00 0.00 0.00 0.00
0.00 0.00 0.00 0.00 0.00 0.00 0.00
dm-2 0.00 0.00 0.00 0.00 0.00 0.00
0.00 1.00 0.00 0.00 0.00 0.00 100.00
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s
avgrq-sz avgqu-sz await r_await w_await svctm %util
md2 0.00 0.00 0.00 1.00 0.00 4.00
8.00 0.00 0.00 0.00 0.00 0.00 0.00
dm-2 0.00 0.00 0.00 1.00 0.00 4.00
8.00 1.00 6200.00 0.00 6200.00 1000.00 100.00
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s
avgrq-sz avgqu-sz await r_await w_await svctm %util
md2 0.00 0.00 0.00 0.00 0.00 0.00
0.00 0.00 0.00 0.00 0.00 0.00 0.00
dm-2 0.00 0.00 0.00 0.00 0.00 0.00
0.00 1.00 0.00 0.00 0.00 0.00 100.00
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s
avgrq-sz avgqu-sz await r_await w_await svctm %util
md2 0.00 0.00 0.00 0.00 0.00 0.00
0.00 0.00 0.00 0.00 0.00 0.00 0.00
dm-2 0.00 0.00 0.00 0.00 0.00 0.00
0.00 1.00 0.00 0.00 0.00 0.00 100.00
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s
avgrq-sz avgqu-sz await r_await w_await svctm %util
md2 0.00 0.00 0.00 0.00 0.00 0.00
0.00 0.00 0.00 0.00 0.00 0.00 0.00
dm-2 0.00 0.00 0.00 0.00 0.00 0.00
0.00 1.00 0.00 0.00 0.00 0.00 100.00
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s
avgrq-sz avgqu-sz await r_await w_await svctm %util
md2 0.00 0.00 0.00 0.00 0.00 0.00
0.00 0.00 0.00 0.00 0.00 0.00 0.00
dm-2 0.00 0.00 0.00 0.00 0.00 0.00
0.00 1.00 0.00 0.00 0.00 0.00 100.00
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s
avgrq-sz avgqu-sz await r_await w_await svctm %util
md2 0.00 0.00 0.00 1.00 0.00 4.00
8.00 0.00 0.00 0.00 0.00 0.00 0.00
dm-2 0.00 0.00 0.00 1.00 0.00 4.00
8.00 1.00 5450.00 0.00 5450.00 1000.00 100.00
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s
avgrq-sz avgqu-sz await r_await w_await svctm %util
md2 0.00 0.00 0.00 0.00 0.00 0.00
0.00 0.00 0.00 0.00 0.00 0.00 0.00
dm-2 0.00 0.00 0.00 0.00 0.00 0.00
0.00 1.00 0.00 0.00 0.00 0.00 100.00
/proc/mdstat
Personalities : [raid1] [raid6] [raid5] [raid4] [raid0]
md10 : active raid5 md11[3] sdo1[1] sdn1[0]
1250259200 blocks super 1.2 level 5, 128k chunk, algorithm 2 [3/3]
[UUU]
md11 : active raid0 sdm1[1] sdad1[0]
625138176 blocks super 1.2 128k chunks
md5 : active raid5 sdq1[6] sdp1[4] sdf1[3] sde1[2] sdd1[1] sdc1[0]
1220981760 blocks super 1.2 level 5, 128k chunk, algorithm 2 [6/6]
[UUUUUU]
md3 : active raid6 sdy2[4] md4[2] sdx3[1] sdt3[0]
1875411968 blocks super 1.2 level 6, 128k chunk, algorithm 2 [4/3]
[UUU_]
resync=DELAYED
md2 : active raid6 sdy1[11] sdz2[0] sdt2[10] sdx2[9] sdu2[8] sds2[7]
sdw2[6] sdv2[5] sdr2[4] sdac2[3] sdaa2[2] sdab2[1]
6641912320 blocks super 0.91 level 6, 128k chunk, algorithm 18
[12/11] [UUUUUUUUUUU_]
[===============>.....] reshape = 77.4% (514551296/664191232)
finish=1030.3min speed=2420K/sec
md1 : active raid5 sdj1[0] sdu1[14] sdx1[13] sdt1[12] sdv1[11] sdw1[10]
sdh1[9] sdac1[8] sdaa1[7] sdr1[6] sdab1[5] sdz1[4] sdk1[3] sds1[2] sdl1[1]
4375960064 blocks level 5, 64k chunk, algorithm 2 [15/15]
[UUUUUUUUUUUUUUU]
md4 : active raid0 sdi1[1] sdg1[0]
976769024 blocks super 1.2 128k chunks
md0 : active raid1 sdb1[1] sda1[0]
41941944 blocks super 1.2 [2/2] [UU]
unused devices: <none>
Kernel: 3.2.9-1.fc16.x86_64
mdadm: v3.2.3
resize2fs: 1.41.14
--Larkin
On 1/8/2012 6:26 PM, NeilBrown wrote:
On Sun, 08 Jan 2012 16:03:10 -0600 Larkin Lowrey
[off-list ref]
wrote:
quoted
Suggestions?
# echo t > /proc/sysrq-trigger
and capture that messages that go to 'dmesg'. Post them.
Hopefully your message ring buffer is big enough to collect the entire
output. If it isn't you might need to boot with
log_buf_len=1M
or similar.
That should show what process is blocking on what.
NeilBrown
...
Interestingly, to me, when in this state, 'iostat -dx 1' shows the root
...
Do you have any "avgqu-sz" stuck at nonzero value in iostat -dx 1?
BTW this bug could be related to the recent post by Milan Broz, subject:
"md raid5 fsync deadlock" .
Because also in your case fsyncs are not likely to complete... correct?
Observation:
Setting vm/dirty_background_bytes to 1MB increased my reshape speed by
50% and reduced the resize2fs write interval from once per 5-6 seconds
to once per 3-4 seconds. Changing vm/dirty_bytes didn't have any
noticeable affect until it got below 50MB at which point performance
dropped dramatically.
Prior to dialing the knobs, dirty_ratio was 20% and
dirty_background_ratio was 10%. The system has 8GB installed.
On 3/11/2012 6:29 PM, Asdo wrote:
On 01/08/12 23:03, Larkin Lowrey wrote:
quoted
...
Interestingly, to me, when in this state, 'iostat -dx 1' shows the root
...
Do you have any "avgqu-sz" stuck at nonzero value in iostat -dx 1?
Yes, avgqu-sz is 1.00.
BTW this bug could be related to the recent post by Milan Broz,
subject: "md raid5 fsync deadlock" .
Because also in your case fsyncs are not likely to complete... correct?
I do get writes, now about one 4k block every 3-4 seconds. It is quite
possible that our two issues are related.
--Larkin