Re: INFO: task pdflush:393 blocked for more than 120 seconds. & Call traces ... (fwd)

6 messages, 5 authors, 2008-07-27 · open the first message on its own page

Re: INFO: task pdflush:393 blocked for more than 120 seconds. & Call traces ... (fwd)

From: Neil Brown <hidden>
Date: 2008-07-21 23:12:15

On Monday July 21, babydr@baby-dragons.com wrote:
INFO: task pdflush:393 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
pdflush       D c8209f80  4748   393      2
         f75e5e58 00000046 f7f7ad50 c8209f80 f7f7a8a0 f75e5e24 c014fc57 00000000
         f7f7a8a0 e5d0dd00 c8209f80 f75e4000 c0819e00 c8209f80 f7f7aaf4 f75e5e44
         00000286 f75e5e80 f510de30 f75e5e58 c0142233 f510de00 f75e5e80 f510de30
Call Trace:
   [<c014fc57>] ? mark_held_locks+0x67/0x80
   [<c0142233>] ? add_wait_queue+0x33/0x50
   [<c03a7f85>] xfs_buf_wait_unpin+0xb5/0xe0
   [<c0127a60>] ? default_wake_function+0x0/0x10
   [<c0127a60>] ? default_wake_function+0x0/0x10
   [<c03a84fb>] xfs_buf_iorequest+0x4b/0x80
   [<c03adeee>] xfs_bdstrat_cb+0x3e/0x50
   [<c03a495c>] xfs_bwrite+0x5c/0xe0
   [<c039e941>] xfs_syncsub+0x121/0x2b0
   [<c018a43b>] ? lock_super+0x1b/0x20
   [<c018a43b>] ? lock_super+0x1b/0x20
   [<c039e1d8>] xfs_sync+0x48/0x70
   [<c03af833>] xfs_fs_write_super+0x23/0x30
   [<c018a80f>] sync_supers+0xaf/0xc0
Looks a lot like an XFS problem to me.
Or at least, XFS people would be able to interpret this stack the
best.
   [<c0169259>] wb_kupdate+0x29/0x100
   [<c016a0cc>] ? __pdflush+0xcc/0x1a0
   [<c016a0d2>] __pdflush+0xd2/0x1a0
   [<c016a1a0>] ? pdflush+0x0/0x40
   [<c016a1d1>] pdflush+0x31/0x40
   [<c0169230>] ? wb_kupdate+0x0/0x100
   [<c016a1a0>] ? pdflush+0x0/0x40
   [<c0141e2c>] kthread+0x5c/0xa0
   [<c0141dd0>] ? kthread+0x0/0xa0
   [<c0103d67>] kernel_thread_helper+0x7/0x10
   =======================
2 locks held by pdflush/393:
   #0:  (&type->s_umount_key#17){----}, at: [<c018a7b2>] sync_supers+0x52/0xc0
   #1:  (&type->s_lock_key#7){--..}, at: [<c018a43b>] lock_super+0x1b/0x20

    ...snip... Repeats of above message ad-infintum .

Hmm... I guess I clipped a bit too much for our XFS friends to know
the context.
bonnie is being run on an XFS filesystem on md/raid6. and it gets
this warning a lot and essentially hangs.

NeilBrown

Re: INFO: task pdflush:393 blocked for more than 120 seconds. & Call traces ... (fwd)

From: Mr. James W. Laferriere <hidden>
Date: 2008-07-21 23:43:03

 	Hello Neil ,

On Tue, 22 Jul 2008, Neil Brown wrote:
On Monday July 21, babydr@baby-dragons.com wrote:
quoted
INFO: task pdflush:393 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
pdflush       D c8209f80  4748   393      2
         f75e5e58 00000046 f7f7ad50 c8209f80 f7f7a8a0 f75e5e24 c014fc57 00000000
         f7f7a8a0 e5d0dd00 c8209f80 f75e4000 c0819e00 c8209f80 f7f7aaf4 f75e5e44
         00000286 f75e5e80 f510de30 f75e5e58 c0142233 f510de00 f75e5e80 f510de30
Call Trace:
   [<c014fc57>] ? mark_held_locks+0x67/0x80
   [<c0142233>] ? add_wait_queue+0x33/0x50
   [<c03a7f85>] xfs_buf_wait_unpin+0xb5/0xe0
   [<c0127a60>] ? default_wake_function+0x0/0x10
   [<c0127a60>] ? default_wake_function+0x0/0x10
   [<c03a84fb>] xfs_buf_iorequest+0x4b/0x80
   [<c03adeee>] xfs_bdstrat_cb+0x3e/0x50
   [<c03a495c>] xfs_bwrite+0x5c/0xe0
   [<c039e941>] xfs_syncsub+0x121/0x2b0
   [<c018a43b>] ? lock_super+0x1b/0x20
   [<c018a43b>] ? lock_super+0x1b/0x20
   [<c039e1d8>] xfs_sync+0x48/0x70
   [<c03af833>] xfs_fs_write_super+0x23/0x30
   [<c018a80f>] sync_supers+0xaf/0xc0
Looks a lot like an XFS problem to me.
Or at least, XFS people would be able to interpret this stack the
best.
 	Hmm ,  Ok ,  I'll post there ,  I can provide a -complete- boot -> 
renboot log of the actions ,  But it ain't small ~ 649K .  So I'll post that on 
the back of my website , ie:

http://www.baby-dragons.com/bonnie++1.03c-2.6.26-rc9.console.trace.log

 	This includes the Sysrq-w & sysrq-b outputs at the bottom .
 	If you're interested in that kind of thing ;-) .

quoted
   [<c0169259>] wb_kupdate+0x29/0x100
   [<c016a0cc>] ? __pdflush+0xcc/0x1a0
   [<c016a0d2>] __pdflush+0xd2/0x1a0
   [<c016a1a0>] ? pdflush+0x0/0x40
   [<c016a1d1>] pdflush+0x31/0x40
   [<c0169230>] ? wb_kupdate+0x0/0x100
   [<c016a1a0>] ? pdflush+0x0/0x40
   [<c0141e2c>] kthread+0x5c/0xa0
   [<c0141dd0>] ? kthread+0x0/0xa0
   [<c0103d67>] kernel_thread_helper+0x7/0x10
   =======================
2 locks held by pdflush/393:
   #0:  (&type->s_umount_key#17){----}, at: [<c018a7b2>] sync_supers+0x52/0xc0
   #1:  (&type->s_lock_key#7){--..}, at: [<c018a43b>] lock_super+0x1b/0x20

    ...snip... Repeats of above message ad-infintum .

Hmm... I guess I clipped a bit too much for our XFS friends to know
the context.
bonnie is being run on an XFS filesystem on md/raid6. and it gets
this warning a lot and essentially hangs.
NeilBrown
 	Nah ,  wasn't you who did the clipping t'was me .  in order to get the 
size of the original message below ~ 80K .

 		Tnx ,  JimL
-- 
+------------------------------------------------------------------+
| James   W.   Laferriere | System    Techniques | Give me VMS     |
| Network&System Engineer | 2133    McCullam Ave |  Give me Linux  |
| babydr@baby-dragons.com | Fairbanks, AK. 99701 |   only  on  AXP |
+------------------------------------------------------------------+

Re: INFO: task pdflush:393 blocked for more than 120 seconds. & Call traces ... (fwd)

From: Richard Scobie <hidden>
Date: 2008-07-22 00:57:18

Mr. James W. Laferriere wrote:
quoted
quoted
INFO: task pdflush:393 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this 
message.
I see similar things now during resyncs and a few times during md RAID 
"checks", since kernel 2.6.25.6-55.fc9.x86_64 on md RAID6 and XFS.

See : http://marc.info/?l=linux-raid&m=121408071129399&w=2

Regards,

Richard

Re: INFO: task pdflush:393 blocked for more than 120 seconds. & Call traces ... (fwd)

From: Dave Chinner <david@fromorbit.com>
Date: 2008-07-22 02:20:50

On Mon, Jul 21, 2008 at 03:43:03PM -0800, Mr. James W. Laferriere wrote:
	Hello Neil ,

On Tue, 22 Jul 2008, Neil Brown wrote:
quoted
On Monday July 21, babydr@baby-dragons.com wrote:
quoted
INFO: task pdflush:393 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
pdflush       D c8209f80  4748   393      2
         f75e5e58 00000046 f7f7ad50 c8209f80 f7f7a8a0 f75e5e24 c014fc57 00000000
         f7f7a8a0 e5d0dd00 c8209f80 f75e4000 c0819e00 c8209f80 f7f7aaf4 f75e5e44
         00000286 f75e5e80 f510de30 f75e5e58 c0142233 f510de00 f75e5e80 f510de30
Call Trace:
   [<c014fc57>] ? mark_held_locks+0x67/0x80
   [<c0142233>] ? add_wait_queue+0x33/0x50
   [<c03a7f85>] xfs_buf_wait_unpin+0xb5/0xe0
   [<c0127a60>] ? default_wake_function+0x0/0x10
   [<c0127a60>] ? default_wake_function+0x0/0x10
   [<c03a84fb>] xfs_buf_iorequest+0x4b/0x80
   [<c03adeee>] xfs_bdstrat_cb+0x3e/0x50
   [<c03a495c>] xfs_bwrite+0x5c/0xe0
   [<c039e941>] xfs_syncsub+0x121/0x2b0
   [<c018a43b>] ? lock_super+0x1b/0x20
   [<c018a43b>] ? lock_super+0x1b/0x20
   [<c039e1d8>] xfs_sync+0x48/0x70
   [<c03af833>] xfs_fs_write_super+0x23/0x30
   [<c018a80f>] sync_supers+0xaf/0xc0
Looks a lot like an XFS problem to me.
Or at least, XFS people would be able to interpret this stack the
best.
	Hmm ,  Ok ,  I'll post there ,  I can provide a -complete- boot ->  
renboot log of the actions ,  But it ain't small ~ 649K .  So I'll post 
that on the back of my website , ie:

http://www.baby-dragons.com/bonnie++1.03c-2.6.26-rc9.console.trace.log
Given that it's a log hang on 2.6.29-rc9, I'd first say add this commit:

http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commit;h=49641f1acfdfd437ed9b0a70b86bf36626c02afe

to your build (went in after -rc9 but before 2.6.26 was released)
and see if that solves the problem.

In more detail, this stack trace implies log I/O has not completed
after the log force was triggered in xfs_buf_wait_unpin(). The above
patch fixes a bug in log I/o dispatch where an non-atomic compare
and decrement would result in log I/O not being dispatched.

So, you've got a hang waiting for log I/o to complete on a kernel
that has a known problem with log I/O dispatch, so it's likely
that's what you've hit.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

i/O Thruput to devices in a raidset not even .

From: Mr. James W. Laferriere <hidden>
Date: 2008-07-27 01:47:32

 	Hello All (& Dan) ,

 	Unfair I/O thruput ,  Using ...
# uname -a
Linux filesrv2 2.6.26 #1 SMP Wed Jul 23 04:06:23 UTC 2008 i686 pentium4 i386 GNU/Linux

 	While the bonnie runs (ie: 5 of them) completed ,  the thruput just 
pukes @ ~ 17MB/s ,  a single run of bonnie on 2.6.26-rc9 was showing a thruput 
of ~ 107MB/s & 115MB/s on this system .
 	I recorded the outputs from the bonnies & posted them (see below) , 
note the "semop: semop failed.\n: Resource temporarily unavailable" at the printout 
of the time used ,  Maybe something I need to report this to Russel & Tim .

 	Also posted are dmesg output (no errors showing) ,  attached the .config 
for the kernel used .


 	1. dmesg-200807240256-2.6.26
 	   http://www.baby-dragons.com/dmesg-200807240256-2.6.26

 	2. 200807240256-2.6.26.config	<attached>

 	3. 131072MB-bonnie++-run-md3-xfs-15runs.log-200807240256-2.6.26 <5 processes>
 	   http://www.baby-dragons.com/131072MB-bonnie++-run-md3-xfs-15runs.log-200807240256-2.6.26

 	4. 131072MB-bonnie++-run-md3-xfs-15runs.log-200807250222-2.6.26 <1 process>
 	   http://www.baby-dragons.com/131072MB-bonnie++-run-md3-xfs-15runs.log-200807250222-2.6.26

 	5. device-thruput-200807260411-2.6.26.log
 	   http://www.baby-dragons.com/device-thruput-200807260411-2.6.26.log
 	This shows that sda is being driven unmercifully while other drives in 
the array aren't getting anywhere near the expected I/O ,  Very uneven .

 		Tia ,  JimL
-- 
+------------------------------------------------------------------+
| James   W.   Laferriere | System    Techniques | Give me VMS     |
| Network&System Engineer | 2133    McCullam Ave |  Give me Linux  |
| babydr@baby-dragons.com | Fairbanks, AK. 99701 |   only  on  AXP |
+------------------------------------------------------------------+

Re: INFO: task pdflush:393 blocked for more than 120 seconds. & Call traces ... (fwd)

From: Timothy Shimmin <hidden>
Date: 2008-07-22 01:25:35

Neil Brown wrote:
On Monday July 21, babydr@baby-dragons.com wrote:
quoted
INFO: task pdflush:393 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
pdflush       D c8209f80  4748   393      2
         f75e5e58 00000046 f7f7ad50 c8209f80 f7f7a8a0 f75e5e24 c014fc57 00000000
         f7f7a8a0 e5d0dd00 c8209f80 f75e4000 c0819e00 c8209f80 f7f7aaf4 f75e5e44
         00000286 f75e5e80 f510de30 f75e5e58 c0142233 f510de00 f75e5e80 f510de30
Call Trace:
   [<c014fc57>] ? mark_held_locks+0x67/0x80
   [<c0142233>] ? add_wait_queue+0x33/0x50
   [<c03a7f85>] xfs_buf_wait_unpin+0xb5/0xe0
   [<c0127a60>] ? default_wake_function+0x0/0x10
   [<c0127a60>] ? default_wake_function+0x0/0x10
   [<c03a84fb>] xfs_buf_iorequest+0x4b/0x80
   [<c03adeee>] xfs_bdstrat_cb+0x3e/0x50
   [<c03a495c>] xfs_bwrite+0x5c/0xe0
   [<c039e941>] xfs_syncsub+0x121/0x2b0
   [<c018a43b>] ? lock_super+0x1b/0x20
   [<c018a43b>] ? lock_super+0x1b/0x20
   [<c039e1d8>] xfs_sync+0x48/0x70
   [<c03af833>] xfs_fs_write_super+0x23/0x30
   [<c018a80f>] sync_supers+0xaf/0xc0
Looks a lot like an XFS problem to me.
Or at least, XFS people would be able to interpret this stack the
best.
I presume if it is waiting in xfs_buf_wait_unpin() for a long
time (>2min) then maybe a journal-log io completion hasn't come
back to say that the matching buffer item has made to the ondisk log.
i.e the buffer hasn't been unpinned yet (pincount>0) which is supposed
to happen when its data hits the ondisk log.
 
quoted
   [<c0169259>] wb_kupdate+0x29/0x100
   [<c016a0cc>] ? __pdflush+0xcc/0x1a0
   [<c016a0d2>] __pdflush+0xd2/0x1a0
   [<c016a1a0>] ? pdflush+0x0/0x40
   [<c016a1d1>] pdflush+0x31/0x40
   [<c0169230>] ? wb_kupdate+0x0/0x100
   [<c016a1a0>] ? pdflush+0x0/0x40
   [<c0141e2c>] kthread+0x5c/0xa0
   [<c0141dd0>] ? kthread+0x0/0xa0
   [<c0103d67>] kernel_thread_helper+0x7/0x10
   =======================
2 locks held by pdflush/393:
   #0:  (&type->s_umount_key#17){----}, at: [<c018a7b2>] sync_supers+0x52/0xc0
   #1:  (&type->s_lock_key#7){--..}, at: [<c018a43b>] lock_super+0x1b/0x20

    ...snip... Repeats of above message ad-infintum .

Hmm... I guess I clipped a bit too much for our XFS friends to know
the context.
bonnie is being run on an XFS filesystem on md/raid6. and it gets
this warning a lot and essentially hangs.
Just for the record,
in rc-9 we hadn't removed the QUEUE_ORDERED tag check yet and
so I presume for md/raid6, barriers will be disabled.
So barrier writes on the log won't be being issued.
I don't see that as anything to do with the problem here -
that is more of an issue on replay if we have the cache on
and no barrier support - I just thought I'd mention it.

--Tim
Keyboard shortcuts
hback out one level
jnext message in thread
kprevious message in thread
ldrill in
Escclose help / fold thread tree
?toggle this help