livelock in __writeback_inodes_wb ?

DISCUSSION Dave Jones 4 participants 6 messages Nov 28, 2012 – Dec 14, 2012

Subsystems (2)

Memory management VFS

lore

Share & tools

lore

Dave Jones

author

2012-11-28 14:55 UTC #0 lore raw

We had a user report the soft lockup detector kicked after 22 seconds of no progress, with this trace..

:BUG: soft lockup - CPU#1 stuck for 22s! [flush-8:16:3137]
:Pid: 3137, comm: flush-8:16 Not tainted 3.6.7-4.fc17.x86_64 #1 :RIP: 0010:[<ffffffff812eeb8c>] [<ffffffff812eeb8c>] __list_del_entry+0x2c/0xd0 :Call Trace:
: [<ffffffff811b783e>] redirty_tail+0x5e/0x80
: [<ffffffff811b8212>] __writeback_inodes_wb+0x72/0xd0
: [<ffffffff811b980b>] wb_writeback+0x23b/0x2d0
: [<ffffffff811b9b5c>] wb_do_writeback+0xac/0x1f0
: [<ffffffff8106c0e0>] ? __internal_add_timer+0x130/0x130
: [<ffffffff811b9d2b>] bdi_writeback_thread+0x8b/0x230
: [<ffffffff811b9ca0>] ? wb_do_writeback+0x1f0/0x1f0
: [<ffffffff8107fde3>] kthread+0x93/0xa0
: [<ffffffff81627e04>] kernel_thread_helper+0x4/0x10
: [<ffffffff8107fd50>] ? kthread_freezable_should_stop+0x70/0x70
: [<ffffffff81627e00>] ? gs_change+0x13/0x13

Looking over the code, is it possible that something could be dirtying pages faster than writeback can get them written out, keeping us in this loop indefitely ?

Should there be something in this loop periodically poking the watchdog perhaps ?

Dave

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>

Fengguang Wu

2012-12-11 08:23 UTC #1 lore raw

Quoted 2 lines · Dave Jones

We had a user report the soft lockup detector kicked after 22 seconds of no progress, with this trace..

Where is the original report? The reporter may help provide some clues on the workload that triggered the bug.

Quoted 16 lines

:BUG: soft lockup - CPU#1 stuck for 22s! [flush-8:16:3137]
:Pid: 3137, comm: flush-8:16 Not tainted 3.6.7-4.fc17.x86_64 #1 :RIP: 0010:[<ffffffff812eeb8c>] [<ffffffff812eeb8c>] __list_del_entry+0x2c/0xd0 :Call Trace:
: [<ffffffff811b783e>] redirty_tail+0x5e/0x80
: [<ffffffff811b8212>] __writeback_inodes_wb+0x72/0xd0
: [<ffffffff811b980b>] wb_writeback+0x23b/0x2d0
: [<ffffffff811b9b5c>] wb_do_writeback+0xac/0x1f0
: [<ffffffff8106c0e0>] ? __internal_add_timer+0x130/0x130
: [<ffffffff811b9d2b>] bdi_writeback_thread+0x8b/0x230
: [<ffffffff811b9ca0>] ? wb_do_writeback+0x1f0/0x1f0
: [<ffffffff8107fde3>] kthread+0x93/0xa0
: [<ffffffff81627e04>] kernel_thread_helper+0x4/0x10
: [<ffffffff8107fd50>] ? kthread_freezable_should_stop+0x70/0x70
: [<ffffffff81627e00>] ? gs_change+0x13/0x13

Quoted 3 lines

Looking over the code, is it possible that something could be dirtying pages faster than writeback can get them written out, keeping us in this loop indefitely ?

The bug reporter should know best whether there are heavy IO.

However I suspect it's not directly caused by heavy IO: we will release &wb->list_lock before each __writeback_single_inode() call, which starts writeback IO for each inode.

Quoted 2 lines

Should there be something in this loop periodically poking the watchdog perhaps ?

It seems we failed to release &wb->list_lock in wb_writeback() for long time (dozens of seconds). That is, the inode_sleep_on_writeback() is somehow not called. However it's not obvious to me how come this can happen..

Thanks,
Fengguang

Jan Kara

reviewer

2012-12-11 13:41 UTC #2 lore raw

Quoted 27 lines · Wu Fengguang

Quoted 2 lines · Dave Jones
We had a user report the soft lockup detector kicked after 22 seconds of no progress, with this trace..
Where is the original report? The reporter may help provide some clues on the workload that triggered the bug.
Quoted 16 lines
:BUG: soft lockup - CPU#1 stuck for 22s! [flush-8:16:3137]
:Pid: 3137, comm: flush-8:16 Not tainted 3.6.7-4.fc17.x86_64 #1 :RIP: 0010:[<ffffffff812eeb8c>] [<ffffffff812eeb8c>] __list_del_entry+0x2c/0xd0 :Call Trace:
: [<ffffffff811b783e>] redirty_tail+0x5e/0x80
: [<ffffffff811b8212>] __writeback_inodes_wb+0x72/0xd0
: [<ffffffff811b980b>] wb_writeback+0x23b/0x2d0
: [<ffffffff811b9b5c>] wb_do_writeback+0xac/0x1f0
: [<ffffffff8106c0e0>] ? __internal_add_timer+0x130/0x130
: [<ffffffff811b9d2b>] bdi_writeback_thread+0x8b/0x230
: [<ffffffff811b9ca0>] ? wb_do_writeback+0x1f0/0x1f0
: [<ffffffff8107fde3>] kthread+0x93/0xa0
: [<ffffffff81627e04>] kernel_thread_helper+0x4/0x10
: [<ffffffff8107fd50>] ? kthread_freezable_should_stop+0x70/0x70
: [<ffffffff81627e00>] ? gs_change+0x13/0x13
Quoted 3 lines
Looking over the code, is it possible that something could be dirtying pages faster than writeback can get them written out, keeping us in this loop indefitely ?

Quoted 5 lines

The bug reporter should know best whether there are heavy IO.
However I suspect it's not directly caused by heavy IO: we will release &wb->list_lock before each __writeback_single_inode() call, which starts writeback IO for each inode.

Umm, it's not about releasing wb->list_lock I think. Softlockup will
trigger whenever we are looping in a kernel for more than given timeout (e.g. those 22 s) without sleeping.

Quoted 7 lines

Quoted 2 lines
Should there be something in this loop periodically poking the watchdog perhaps ?
It seems we failed to release &wb->list_lock in wb_writeback() for long time (dozens of seconds). That is, the inode_sleep_on_writeback() is somehow not called. However it's not obvious to me how come this can happen..

Maybe, progress is always non-zero but small and nr_pages is high (e.g.
when writeback is triggered by wakeup_flusher_threads()). What filesystem is the guy using? I remember e.g. btrfs used to have always-dirty inodes which could confuse us.

Quoted 1 line

From the backtrace it is clear there's some superblock which has s_umount

locked and we cannot writeback inodes there. So if this superblock contains most of the dirty pages we need to write and there's another superblock with always dirty inode we would livelock like observed... So my question would be about what filesystems are there in the system (/proc/mounts), what load does trigger this, trigger sysrq-w when the lockup happens.

Honza

Signature · 8 lines

Jan Kara <[email protected]>
SUSE Labs, CR

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to [email protected].  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>

Fengguang Wu

2012-12-14 09:13 UTC #3 lore raw

Quoted 28 lines · Jan Kara

Quoted 27 lines · Wu Fengguang
Quoted 2 lines · Dave Jones
We had a user report the soft lockup detector kicked after 22 seconds of no progress, with this trace..
Where is the original report? The reporter may help provide some clues on the workload that triggered the bug.
Quoted 19 lines
:BUG: soft lockup - CPU#1 stuck for 22s! [flush-8:16:3137]
:Pid: 3137, comm: flush-8:16 Not tainted 3.6.7-4.fc17.x86_64 #1 :RIP: 0010:[<ffffffff812eeb8c>] [<ffffffff812eeb8c>] __list_del_entry+0x2c/0xd0 :Call Trace:
: [<ffffffff811b783e>] redirty_tail+0x5e/0x80
: [<ffffffff811b8212>] __writeback_inodes_wb+0x72/0xd0
: [<ffffffff811b980b>] wb_writeback+0x23b/0x2d0
: [<ffffffff811b9b5c>] wb_do_writeback+0xac/0x1f0
: [<ffffffff8106c0e0>] ? __internal_add_timer+0x130/0x130
: [<ffffffff811b9d2b>] bdi_writeback_thread+0x8b/0x230
: [<ffffffff811b9ca0>] ? wb_do_writeback+0x1f0/0x1f0
: [<ffffffff8107fde3>] kthread+0x93/0xa0
: [<ffffffff81627e04>] kernel_thread_helper+0x4/0x10
: [<ffffffff8107fd50>] ? kthread_freezable_should_stop+0x70/0x70
: [<ffffffff81627e00>] ? gs_change+0x13/0x13
Looking over the code, is it possible that something could be dirtying pages faster than writeback can get them written out, keeping us in this loop indefitely ?

Quoted 8 lines

Quoted 5 lines
The bug reporter should know best whether there are heavy IO.
However I suspect it's not directly caused by heavy IO: we will release &wb->list_lock before each __writeback_single_inode() call, which starts writeback IO for each inode.
Umm, it's not about releasing wb->list_lock I think. Softlockup will
trigger whenever we are looping in a kernel for more than given timeout (e.g. those 22 s) without sleeping.

Yes (and the spinlock is the typical reason to prevent it from sleeping).

Quoted 11 lines

Quoted 7 lines
Quoted 2 lines
Should there be something in this loop periodically poking the watchdog perhaps ?
It seems we failed to release &wb->list_lock in wb_writeback() for long time (dozens of seconds). That is, the inode_sleep_on_writeback() is somehow not called. However it's not obvious to me how come this can happen..
Maybe, progress is always non-zero but small and nr_pages is high (e.g.
when writeback is triggered by wakeup_flusher_threads()). What filesystem is the guy using? I remember e.g. btrfs used to have always-dirty inodes which could confuse us.

Judging from the comm "flush-8:16", it's not btrfs. I cannot find the reporter's email address in the original bug report. So we may at best guess it's likely running the fedora's default filesystem. Also device mapper is used judging from the boot param "rd.lvm.lv=vg_san-pc/lv_root".

Quoted 6 lines

Quoted 1 line
From the backtrace it is clear there's some superblock which has s_umount
locked and we cannot writeback inodes there. So if this superblock contains most of the dirty pages we need to write and there's another superblock with always dirty inode we would livelock like observed... So my question would be about what filesystems are there in the system (/proc/mounts), what load does trigger this, trigger sysrq-w when the lockup happens.

Yeah, it's likely related to some busy superblock.

Thanks,
Fengguang

Dave Jones

author

2012-12-11 14:29 UTC #4 lore raw

In reply to Fengguang Wu

Quoted 6 lines · Fengguang Wu

Quoted 2 lines · Dave Jones
We had a user report the soft lockup detector kicked after 22 seconds of no progress, with this trace..
Where is the original report? The reporter may help provide some clues on the workload that triggered the bug.

https://bugzilla.redhat.com/show_bug.cgi?id=880949

Quoted 6 lines

The bug reporter should know best whether there are heavy IO.
However I suspect it's not directly caused by heavy IO: we will release &wb->list_lock before each __writeback_single_inode() call, which starts writeback IO for each inode.

Quoted 7 lines

Quoted 2 lines
Should there be something in this loop periodically poking the watchdog perhaps ?
It seems we failed to release &wb->list_lock in wb_writeback() for long time (dozens of seconds). That is, the inode_sleep_on_writeback() is somehow not called. However it's not obvious to me how come this can happen..

Right, it seems that we only drop the lock when there is more work to do. And if there is no work to do, then we would have bailed from the loop.

mysterious.

Dave

Simon Jeons

2012-12-12 02:26 UTC #5 lore raw

Quoted 19 lines · Dave Jones

Quoted 6 lines · Fengguang Wu
Quoted 2 lines · Dave Jones
We had a user report the soft lockup detector kicked after 22 seconds of no progress, with this trace..
Where is the original report? The reporter may help provide some clues on the workload that triggered the bug.
https://bugzilla.redhat.com/show_bug.cgi?id=880949
Quoted 9 lines
The bug reporter should know best whether there are heavy IO.
However I suspect it's not directly caused by heavy IO: we will release &wb->list_lock before each __writeback_single_inode() call, which starts writeback IO for each inode.
Quoted 2 lines
Should there be something in this loop periodically poking the watchdog perhaps ?

Quoted 7 lines

Quoted 4 lines
It seems we failed to release &wb->list_lock in wb_writeback() for long time (dozens of seconds). That is, the inode_sleep_on_writeback() is somehow not called. However it's not obvious to me how come this can happen..
Right, it seems that we only drop the lock when there is more work to do. And if there is no work to do, then we would have bailed from the loop.

If no work to do, lock will be dropped after for loop.

Quoted 10 lines

mysterious.
Dave
--
To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>