Scenario:

1. raid6 (software - 6 1Tb sata drives) doing a resync (multi core enabled)
2. rebuilding kernel (rc8)
3. system became sluggish - top & vmstat showed all 12Gb ram used - 
albeit 10g of fs cache. It seemed as though relcaim of fs cache became 
really slow once there were no more "free" pages.
vmstat <after hung task reported - don't have from before>
procs -----------memory---------- ---swap-- -----io---- --system-- 
-----cpu-----
    r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us 
sy id wa st
    0  1    808 112476 347592 9556952    0    0    39   388  158  189  1 
18 77  4  0
4. Worrying a bit about the looming instability, I typed, "sync."
5. sync took a long time, and was reported by the kernel as a hung task 
(repeatedly) - see below.
6. entering additional sync commands also hang (unsuprising, but figured 
I'd try as non-root).
7. The running sync (pid 11975) cannot be killed.
8. echo 1 > drop_caches does clear the fs cache. System behaves better 
after this (but sync is still hung).

config attached.

Running with sky2 dma patches (in rc8) and increased the audit name 
space to avoid the flood of name space maxed warnings.

My current plan is to let the raid rebuild complete and then reboot (to 
rc8 if the bits made it to disk)... maybe with a backup of recently 
changed files to an external system.

Feb 13 10:54:13 mail kernel: INFO: task sync:11975 blocked for more than 
120 seconds.
Feb 13 10:54:13 mail kernel: "echo 0 > 
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Feb 13 10:54:13 mail kernel: sync          D 0000000000000002     0 
11975   6433 0x00000000
Feb 13 10:54:13 mail kernel: ffff8801c45f3da8 0000000000000082 
ffff8800282f5948 ffff8800282f5920
Feb 13 10:54:13 mail kernel: ffff88032f785d78 ffff88032f785d40 
000000030c37a771 0000000000000282
Feb 13 10:54:13 mail kernel: ffff8801c45f3fd8 000000000000f888 
ffff88032ca00000 ffff8801c61c9750
Feb 13 10:54:13 mail kernel: Call Trace:
Feb 13 10:54:13 ...
[ message continues ]

On 2/13/2010 11:51 AM, Michael Breuer wrote:
Apologies for the repetition... sendmail/mimedefang had some issues and 
I thought the first two messages didn't make it out.
--

[ message continues ]

Note: this cleared after about 90 minutes - sync eventually completed. 
I'm thinking that with multicore enabled the resync is able to starve 
out normal system activities that weren't starved w/o multicore.

raid speed_limit_min was originally set to 5000 - reported speed was 
between 15k and 30k. I did play around with speed_limit_min, but didn't 
seen any noticeable result. Max was never reached. Fwiw, without 
multicore, I saw slightly lower reported speeds, however time to rebuild 
was significantly faster with multicore enabled. I'm guessing that the 
reported speed is either wrong, or it's an instantaneous number that is 
affected by the act of typing "cat /proc/mdstat"

I also believe from what I saw that inordinate system resources are 
being consumed when file system cache needs to be reclaimed to satisfy 
memory allocation requests... at least while a resync is under way. As 
manual dropping of the cache is painless, I'm guessing that too much 
time is being spent looking for pages to reclaim on demand. Perhaps this 
is function of the amount of physical RAM (I've got 12G and 10G was fs 
cache).

I can't recreate the hang with available free pages.


--

[ message continues ]

Ok - will do. On rc8 now - and up about 3 days without any issues. If I 
have some time tomorrow I'll force a raid resync and see what happens.
--

[ message continues ]

Hmm, it is a bug in writeback code. But as Linus pointed out, it's not really
clear why it's *so* slow. So when it happens again, could you please sample for
a while (like every second for 30 seconds) stacks of blocked tasks via
Alt-Sysrq-W? I'd like to see where flusher threads are hanging... Thanks.

								Honza
-- 
Jan Kara <jack@suse.cz>
SuSE CR Labs
--

[ message continues ]

Ok - got it. Sync is still spinning, btw... attaching log extract as 
well as dmesg output.

[ message continues ]

This is probably where the barrier IOs are coming from.  With a RAID
resync going on (so all IO is going to be slow to begin with) and
writeback is causing barriers to be issued (which are really slow on
software RAID5/6), having sync take so long is not out of the
question if you have lots of dirty inodes to write back. A kernel
compile will generate lots of dirty inodes.

Even taking the barrier IOs out of the question, I've seen reports
of sync or unmount taking over 10 hours to complete on software
RAID5 because there were hundreds of thousands of dirty inodes to
write back and each inode being written back caused a synchronous
RAID5 RMW cycle to occur. Hence writeback could only clean 50
inodes/sec because as soon as RMW cycles RAID5/6 devices start
they go slower than single spindle devices.  This sounds very
similar to what you are seeing here,

i.e. The reports don't indicate to me that there is a bug in the
writeback code, just your disk subsystem has very, very low
throughput in these conditions....

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com
--

[ message continues ]

Probably true... and the system does recover. The only thing I'd point 
out is that the subsystem isn't (or perhaps shouldn't) be this sluggish. 
I hypothesize that the low throughput under these condition is a result of:
1) multicore raid support (pushing the resync at higher rates)
2) time spent in fs cache reclaim. The sync slowdown only occurs when fs 
cache is in heavy (10Gb) use.

I actually could not recreate the issue until I did a grep -R foo /usr/ 
 >/dev/null to force high fs cache utilization. For what it's worth, two 
kernel rebuilds (many dirty inodes) and then a sync with about 12Mb 
dirty (/proc/meminfo) didn't cause an issue. The issue only happens when 
fs cache is heavily used. I also never saw this before enabling 
multicore raid.


--

[ message continues ]

"grep -R foo /usr/" will dirty every inode that touchs (atime) and
they have to be written back out. That's almost certainly creating
more dirty inodes than a kernel build - there are about 400,000
inodes under /usr on my system. That would be enough to trigger very
long sync times if inode writeback is slow.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com
--

[ message continues ]

My filesystems are mounted relatime. Just confirmed that dirty pages 
doesn't climb all that much with the grep -R foo /usr > /dev/null. The 
only apparant impact is to fs cache.
--

[ message continues ]

If the inode atime is older than a day, then they will still
have atime updated (i.e. be dirtied) and need writing out. Relatime
only reduces the number of atime updates; it doesn't prevent them
entirely like noatime does.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com
--

[ message continues ]

Hi all,

Was there any solution for this problem? We seem to be hitting the same 
problem with kernel 2.6.33.1, 12G RAM, and raid10. Noatime does not 
help.

Thanks
Balazs Pozsar




--

[ message continues ]

I reported that I was unable to recreate as op 2.6.33-rc6. I am now on
2.6.34-rc3 and have not seen a recurrence.


--

[ message continues ]