Lockup in wait_transaction_locked under memory pressure

Hello,

On a fairly busy server, running LXC I'm observing that sometimes the processes for a particular container lock up by going into D (uninterruptible sleep) state. Obtaining backtraces for those processes one thing which stands out is that they are all blocked in wait_transaction_locked (part of JBD2).
This occurs sporadically when the particular container is under memory pressure and a process is selected by OOM for killing. I'm running kernel 4.0.0 and oom_kill_allocating_task is enabled.

Here are backtraces from multiple such processes:

alxc9 kernel: nginx D ffff8820a90b39a8 11496 9331 30627
0x00000004
alxc9 kernel: ffff8820a90b39a8 ffff881ff284f010 ffff88396c6d1e90 0000000000000282
alxc9 kernel: ffff8820a90b0010 ffff883ff12f3870 ffff883ff12f3800 0000000000027df1
alxc9 kernel: ffff880413c08000 ffff8820a90b39c8 ffffffff815ab76e ffff883ff12f3870
alxc9 kernel: Call Trace:
alxc9 kernel: [<ffffffff815ab76e>] schedule+0x3e/0x90
alxc9 kernel: [<ffffffff81264265>] wait_transaction_locked+0x85/0xc0 alxc9 kernel: [<ffffffff810910d0>] ? woken_wake_function+0x20/0x20 alxc9 kernel: [<ffffffff815ab18a>] ? __schedule+0x39a/0x870 alxc9 kernel: [<ffffffff81264540>] add_transaction_credits+0xf0/0x250 alxc9 kernel: [<ffffffff815ab76e>] ? schedule+0x3e/0x90 alxc9 kernel: [<ffffffff815ae5e5>] ? schedule_timeout+0x165/0x1f0 alxc9 kernel: [<ffffffff81264824>] start_this_handle+0x184/0x420 alxc9 kernel: [<ffffffff810e0880>] ? __delayacct_blkio_end+0x30/0x50 alxc9 kernel: [<ffffffff8117a48e>] ? kmem_cache_alloc+0xee/0x1c0 alxc9 kernel: [<ffffffff81265220>] jbd2__journal_start+0x100/0x200 alxc9 kernel: [<ffffffff8121da5c>] ? ext4_dirty_inode+0x3c/0x80 alxc9 kernel: [<ffffffff8124bb49>] __ext4_journal_start_sb+0x79/0x100 alxc9 kernel: [<ffffffff8121da5c>] ext4_dirty_inode+0x3c/0x80 alxc9 kernel: [<ffffffff811be5c3>] __mark_inode_dirty+0x173/0x400 alxc9 kernel: [<ffffffff811ae9c5>] generic_update_time+0x85/0xd0 alxc9 kernel: [<ffffffff81120f5a>] ? filemap_map_pages+0x1ca/0x210 alxc9 kernel: [<ffffffff811ae632>] file_update_time+0xb2/0x110 alxc9 kernel: [<ffffffff811226c2>] __generic_file_write_iter+0x172/0x3a0 alxc9 kernel: [<ffffffff81214814>] ext4_file_write_iter+0x134/0x460 alxc9 kernel: [<ffffffff810ad910>] ? update_rmtp+0x80/0x80 alxc9 kernel: [<ffffffff81194047>] new_sync_write+0x97/0xc0 alxc9 kernel: [<ffffffff8119445e>] vfs_write+0xce/0x180 alxc9 kernel: [<ffffffff81194bda>] SyS_write+0x5a/0xd0
alxc9 kernel: [<ffffffff815afa89>] system_call_fastpath+0x12/0x17

alxc9 kernel: mysqld D ffff8821352638d8 11936 5176 30627
0x00000006
alxc9 kernel: ffff8821352638d8 ffff881ff2848000 ffff8812d3d28a30 0000000000000286
alxc9 kernel: ffff882135260010 ffff883ff12f3870 ffff883ff12f3800 0000000000027df1
alxc9 kernel: ffff880413c08000 ffff8821352638f8 ffffffff815ab76e ffff883ff12f3870
alxc9 kernel: Call Trace:
alxc9 kernel: [<ffffffff815ab76e>] schedule+0x3e/0x90 alxc9 kernel: [<ffffffff81264265>] wait_transaction_locked+0x85/0xc0 alxc9 kernel: [<ffffffff810910d0>] ? woken_wake_function+0x20/0x20 alxc9 kernel: [<ffffffff81264540>] add_transaction_credits+0xf0/0x250 alxc9 kernel: [<ffffffff81264824>] start_this_handle+0x184/0x420 alxc9 kernel: [<ffffffff8117a48e>] ? kmem_cache_alloc+0xee/0x1c0 alxc9 kernel: [<ffffffff81265220>] jbd2__journal_start+0x100/0x200 alxc9 kernel: [<ffffffff8121fa70>] ? ext4_evict_inode+0x190/0x490 alxc9 kernel: [<ffffffff8124bb49>] __ext4_journal_start_sb+0x79/0x100 alxc9 kernel: [<ffffffff8121fa70>] ext4_evict_inode+0x190/0x490 alxc9 kernel: [<ffffffff811af6d8>] evict+0xb8/0x1a0
alxc9 kernel: [<ffffffff811af8b6>] iput_final+0xf6/0x190 alxc9 kernel: [<ffffffff811b0230>] iput+0xa0/0xe0
alxc9 kernel: [<ffffffff811ab068>] dentry_iput+0xa8/0xf0 alxc9 kernel: [<ffffffff811ac1c5>] __dentry_kill+0x85/0x130 alxc9 kernel: [<ffffffff811ac42c>] dput+0x1bc/0x220
alxc9 kernel: [<ffffffff811966b4>] __fput+0x144/0x200 alxc9 kernel: [<ffffffff8119681e>] ____fput+0xe/0x10
alxc9 kernel: [<ffffffff8106dc85>] task_work_run+0xd5/0x120 alxc9 kernel: [<ffffffff810537d9>] do_exit+0x1b9/0x560 alxc9 kernel: [<ffffffff810aebc2>] ? hrtimer_cancel+0x22/0x30 alxc9 kernel: [<ffffffff81053bd6>] do_group_exit+0x56/0x100 alxc9 kernel: [<ffffffff81061787>] get_signal+0x237/0x530 alxc9 kernel: [<ffffffff81002d45>] do_signal+0x25/0x130 alxc9 kernel: [<ffffffff810a57d9>] ? rcu_eqs_exit+0x79/0xb0 alxc9 kernel: [<ffffffff810a5823>] ? rcu_user_exit+0x13/0x20 alxc9 kernel: [<ffffffff81002ec8>] do_notify_resume+0x78/0xb0 alxc9 kernel: [<ffffffff815afce3>] int_signal+0x12/0x17

My hypotheses is that the OOM is killing a process while its performing a write to a transaction without it having a chance to complete it which leaves all other processes waiting to be woken up, which naturally never happens. I wonder whether such a failure scenario is even possible? If not then what could possibly force a transaction to stall for hours?

Regards,
Nikolay

[Resending to linux-ext4 as the first try failed]

Quoted 11 lines · Nikolay Borisov

Hello,

On a fairly busy server, running LXC I'm observing that sometimes the processes for a particular container lock up by going into D (uninterruptible sleep) state. Obtaining backtraces for those processes one thing which stands out is that they are all blocked in wait_transaction_locked (part of JBD2).
This occurs sporadically when the particular container is under memory pressure and a process is selected by OOM for killing. I'm running kernel 4.0.0 and oom_kill_allocating_task is enabled.

Quoted 76 lines

Here are backtraces from multiple such processes:

alxc9 kernel: nginx D ffff8820a90b39a8 11496 9331 30627
0x00000004
alxc9 kernel: ffff8820a90b39a8 ffff881ff284f010 ffff88396c6d1e90 0000000000000282
alxc9 kernel: ffff8820a90b0010 ffff883ff12f3870 ffff883ff12f3800 0000000000027df1
alxc9 kernel: ffff880413c08000 ffff8820a90b39c8 ffffffff815ab76e ffff883ff12f3870
alxc9 kernel: Call Trace:
alxc9 kernel: [<ffffffff815ab76e>] schedule+0x3e/0x90
alxc9 kernel: [<ffffffff81264265>] wait_transaction_locked+0x85/0xc0 alxc9 kernel: [<ffffffff810910d0>] ? woken_wake_function+0x20/0x20 alxc9 kernel: [<ffffffff815ab18a>] ? __schedule+0x39a/0x870 alxc9 kernel: [<ffffffff81264540>] add_transaction_credits+0xf0/0x250 alxc9 kernel: [<ffffffff815ab76e>] ? schedule+0x3e/0x90 alxc9 kernel: [<ffffffff815ae5e5>] ? schedule_timeout+0x165/0x1f0 alxc9 kernel: [<ffffffff81264824>] start_this_handle+0x184/0x420 alxc9 kernel: [<ffffffff810e0880>] ? __delayacct_blkio_end+0x30/0x50 alxc9 kernel: [<ffffffff8117a48e>] ? kmem_cache_alloc+0xee/0x1c0 alxc9 kernel: [<ffffffff81265220>] jbd2__journal_start+0x100/0x200 alxc9 kernel: [<ffffffff8121da5c>] ? ext4_dirty_inode+0x3c/0x80 alxc9 kernel: [<ffffffff8124bb49>] __ext4_journal_start_sb+0x79/0x100 alxc9 kernel: [<ffffffff8121da5c>] ext4_dirty_inode+0x3c/0x80 alxc9 kernel: [<ffffffff811be5c3>] __mark_inode_dirty+0x173/0x400 alxc9 kernel: [<ffffffff811ae9c5>] generic_update_time+0x85/0xd0 alxc9 kernel: [<ffffffff81120f5a>] ? filemap_map_pages+0x1ca/0x210 alxc9 kernel: [<ffffffff811ae632>] file_update_time+0xb2/0x110 alxc9 kernel: [<ffffffff811226c2>] __generic_file_write_iter+0x172/0x3a0 alxc9 kernel: [<ffffffff81214814>] ext4_file_write_iter+0x134/0x460 alxc9 kernel: [<ffffffff810ad910>] ? update_rmtp+0x80/0x80 alxc9 kernel: [<ffffffff81194047>] new_sync_write+0x97/0xc0 alxc9 kernel: [<ffffffff8119445e>] vfs_write+0xce/0x180 alxc9 kernel: [<ffffffff81194bda>] SyS_write+0x5a/0xd0
alxc9 kernel: [<ffffffff815afa89>] system_call_fastpath+0x12/0x17

alxc9 kernel: mysqld D ffff8821352638d8 11936 5176 30627
0x00000006
alxc9 kernel: ffff8821352638d8 ffff881ff2848000 ffff8812d3d28a30 0000000000000286
alxc9 kernel: ffff882135260010 ffff883ff12f3870 ffff883ff12f3800 0000000000027df1
alxc9 kernel: ffff880413c08000 ffff8821352638f8 ffffffff815ab76e ffff883ff12f3870
alxc9 kernel: Call Trace:
alxc9 kernel: [<ffffffff815ab76e>] schedule+0x3e/0x90 alxc9 kernel: [<ffffffff81264265>] wait_transaction_locked+0x85/0xc0 alxc9 kernel: [<ffffffff810910d0>] ? woken_wake_function+0x20/0x20 alxc9 kernel: [<ffffffff81264540>] add_transaction_credits+0xf0/0x250 alxc9 kernel: [<ffffffff81264824>] start_this_handle+0x184/0x420 alxc9 kernel: [<ffffffff8117a48e>] ? kmem_cache_alloc+0xee/0x1c0 alxc9 kernel: [<ffffffff81265220>] jbd2__journal_start+0x100/0x200 alxc9 kernel: [<ffffffff8121fa70>] ? ext4_evict_inode+0x190/0x490 alxc9 kernel: [<ffffffff8124bb49>] __ext4_journal_start_sb+0x79/0x100 alxc9 kernel: [<ffffffff8121fa70>] ext4_evict_inode+0x190/0x490 alxc9 kernel: [<ffffffff811af6d8>] evict+0xb8/0x1a0
alxc9 kernel: [<ffffffff811af8b6>] iput_final+0xf6/0x190 alxc9 kernel: [<ffffffff811b0230>] iput+0xa0/0xe0
alxc9 kernel: [<ffffffff811ab068>] dentry_iput+0xa8/0xf0 alxc9 kernel: [<ffffffff811ac1c5>] __dentry_kill+0x85/0x130 alxc9 kernel: [<ffffffff811ac42c>] dput+0x1bc/0x220
alxc9 kernel: [<ffffffff811966b4>] __fput+0x144/0x200 alxc9 kernel: [<ffffffff8119681e>] ____fput+0xe/0x10
alxc9 kernel: [<ffffffff8106dc85>] task_work_run+0xd5/0x120 alxc9 kernel: [<ffffffff810537d9>] do_exit+0x1b9/0x560 alxc9 kernel: [<ffffffff810aebc2>] ? hrtimer_cancel+0x22/0x30 alxc9 kernel: [<ffffffff81053bd6>] do_group_exit+0x56/0x100 alxc9 kernel: [<ffffffff81061787>] get_signal+0x237/0x530 alxc9 kernel: [<ffffffff81002d45>] do_signal+0x25/0x130 alxc9 kernel: [<ffffffff810a57d9>] ? rcu_eqs_exit+0x79/0xb0 alxc9 kernel: [<ffffffff810a5823>] ? rcu_user_exit+0x13/0x20 alxc9 kernel: [<ffffffff81002ec8>] do_notify_resume+0x78/0xb0 alxc9 kernel: [<ffffffff815afce3>] int_signal+0x12/0x17

Quoted 5 lines

My hypotheses is that the OOM is killing a process while its performing a write to a transaction without it having a chance to complete it which leaves all other processes waiting to be woken up, which naturally never happens. I wonder whether such a failure scenario is even possible? If not then what could possibly force a transaction to stall for hours?

Quoted 14 lines · Nikolay Borisov

[Resending to linux-ext4 as the first try failed]

Quoted 11 lines · Nikolay Borisov

Hello,

On a fairly busy server, running LXC I'm observing that sometimes the processes for a particular container lock up by going into D (uninterruptible sleep) state. Obtaining backtraces for those processes one thing which stands out is that they are all blocked in wait_transaction_locked (part of JBD2).
This occurs sporadically when the particular container is under memory pressure and a process is selected by OOM for killing. I'm running kernel 4.0.0 and oom_kill_allocating_task is enabled.

Do you have the full OOM report?

Quoted 76 lines

Quoted 76 lines

Here are backtraces from multiple such processes:

alxc9 kernel: nginx D ffff8820a90b39a8 11496 9331 30627
0x00000004
alxc9 kernel: ffff8820a90b39a8 ffff881ff284f010 ffff88396c6d1e90 0000000000000282
alxc9 kernel: ffff8820a90b0010 ffff883ff12f3870 ffff883ff12f3800 0000000000027df1
alxc9 kernel: ffff880413c08000 ffff8820a90b39c8 ffffffff815ab76e ffff883ff12f3870
alxc9 kernel: Call Trace:
alxc9 kernel: [<ffffffff815ab76e>] schedule+0x3e/0x90
alxc9 kernel: [<ffffffff81264265>] wait_transaction_locked+0x85/0xc0 alxc9 kernel: [<ffffffff810910d0>] ? woken_wake_function+0x20/0x20 alxc9 kernel: [<ffffffff815ab18a>] ? __schedule+0x39a/0x870 alxc9 kernel: [<ffffffff81264540>] add_transaction_credits+0xf0/0x250 alxc9 kernel: [<ffffffff815ab76e>] ? schedule+0x3e/0x90 alxc9 kernel: [<ffffffff815ae5e5>] ? schedule_timeout+0x165/0x1f0 alxc9 kernel: [<ffffffff81264824>] start_this_handle+0x184/0x420 alxc9 kernel: [<ffffffff810e0880>] ? __delayacct_blkio_end+0x30/0x50 alxc9 kernel: [<ffffffff8117a48e>] ? kmem_cache_alloc+0xee/0x1c0 alxc9 kernel: [<ffffffff81265220>] jbd2__journal_start+0x100/0x200 alxc9 kernel: [<ffffffff8121da5c>] ? ext4_dirty_inode+0x3c/0x80 alxc9 kernel: [<ffffffff8124bb49>] __ext4_journal_start_sb+0x79/0x100 alxc9 kernel: [<ffffffff8121da5c>] ext4_dirty_inode+0x3c/0x80 alxc9 kernel: [<ffffffff811be5c3>] __mark_inode_dirty+0x173/0x400 alxc9 kernel: [<ffffffff811ae9c5>] generic_update_time+0x85/0xd0 alxc9 kernel: [<ffffffff81120f5a>] ? filemap_map_pages+0x1ca/0x210 alxc9 kernel: [<ffffffff811ae632>] file_update_time+0xb2/0x110 alxc9 kernel: [<ffffffff811226c2>] __generic_file_write_iter+0x172/0x3a0 alxc9 kernel: [<ffffffff81214814>] ext4_file_write_iter+0x134/0x460 alxc9 kernel: [<ffffffff810ad910>] ? update_rmtp+0x80/0x80 alxc9 kernel: [<ffffffff81194047>] new_sync_write+0x97/0xc0 alxc9 kernel: [<ffffffff8119445e>] vfs_write+0xce/0x180 alxc9 kernel: [<ffffffff81194bda>] SyS_write+0x5a/0xd0
alxc9 kernel: [<ffffffff815afa89>] system_call_fastpath+0x12/0x17

alxc9 kernel: mysqld D ffff8821352638d8 11936 5176 30627
0x00000006
alxc9 kernel: ffff8821352638d8 ffff881ff2848000 ffff8812d3d28a30 0000000000000286
alxc9 kernel: ffff882135260010 ffff883ff12f3870 ffff883ff12f3800 0000000000027df1
alxc9 kernel: ffff880413c08000 ffff8821352638f8 ffffffff815ab76e ffff883ff12f3870
alxc9 kernel: Call Trace:
alxc9 kernel: [<ffffffff815ab76e>] schedule+0x3e/0x90 alxc9 kernel: [<ffffffff81264265>] wait_transaction_locked+0x85/0xc0 alxc9 kernel: [<ffffffff810910d0>] ? woken_wake_function+0x20/0x20 alxc9 kernel: [<ffffffff81264540>] add_transaction_credits+0xf0/0x250 alxc9 kernel: [<ffffffff81264824>] start_this_handle+0x184/0x420 alxc9 kernel: [<ffffffff8117a48e>] ? kmem_cache_alloc+0xee/0x1c0 alxc9 kernel: [<ffffffff81265220>] jbd2__journal_start+0x100/0x200 alxc9 kernel: [<ffffffff8121fa70>] ? ext4_evict_inode+0x190/0x490 alxc9 kernel: [<ffffffff8124bb49>] __ext4_journal_start_sb+0x79/0x100 alxc9 kernel: [<ffffffff8121fa70>] ext4_evict_inode+0x190/0x490 alxc9 kernel: [<ffffffff811af6d8>] evict+0xb8/0x1a0
alxc9 kernel: [<ffffffff811af8b6>] iput_final+0xf6/0x190 alxc9 kernel: [<ffffffff811b0230>] iput+0xa0/0xe0
alxc9 kernel: [<ffffffff811ab068>] dentry_iput+0xa8/0xf0 alxc9 kernel: [<ffffffff811ac1c5>] __dentry_kill+0x85/0x130 alxc9 kernel: [<ffffffff811ac42c>] dput+0x1bc/0x220
alxc9 kernel: [<ffffffff811966b4>] __fput+0x144/0x200 alxc9 kernel: [<ffffffff8119681e>] ____fput+0xe/0x10
alxc9 kernel: [<ffffffff8106dc85>] task_work_run+0xd5/0x120 alxc9 kernel: [<ffffffff810537d9>] do_exit+0x1b9/0x560 alxc9 kernel: [<ffffffff810aebc2>] ? hrtimer_cancel+0x22/0x30 alxc9 kernel: [<ffffffff81053bd6>] do_group_exit+0x56/0x100 alxc9 kernel: [<ffffffff81061787>] get_signal+0x237/0x530 alxc9 kernel: [<ffffffff81002d45>] do_signal+0x25/0x130 alxc9 kernel: [<ffffffff810a57d9>] ? rcu_eqs_exit+0x79/0xb0 alxc9 kernel: [<ffffffff810a5823>] ? rcu_user_exit+0x13/0x20 alxc9 kernel: [<ffffffff81002ec8>] do_notify_resume+0x78/0xb0 alxc9 kernel: [<ffffffff815afce3>] int_signal+0x12/0x17

Quoted 5 lines

Quoted 5 lines

My hypotheses is that the OOM is killing a process while its performing a write to a transaction without it having a chance to complete it which leaves all other processes waiting to be woken up, which naturally never happens. I wonder whether such a failure scenario is even possible? If not then what could possibly force a transaction to stall for hours?

I am not familiar with ext4 code much but I assume that even if the oom victim was writing to the transaction and the allocation had failed then the transaction should have failed as well.
It would be a bit different if that allocation was GFP_NOFAIL and the memory reserves were completely depleted then it would loop inside the allocator and never finish the write (until something else releases memory). You can increase min_free_kbytes to increase memory reserves.

But this is just a wild guess. sysrq+m would tell us more about the current state of the memory. It would be also good to check whether the OOM victim managed to die (oom report and sysrq+t).

I do have several OOM reports unfortunately I don't think I can correlate them in any sensible way to be able to answer the question "Which was the process that was writing prior to the D state occuring". Maybe you can be more specific as to what am I likely looking for?

Quoted 4 lines · Nikolay Borisov

I do have several OOM reports unfortunately I don't think I can correlate them in any sensible way to be able to answer the question "Which was the process that was writing prior to the D state occuring". Maybe you can be more specific as to what am I likely looking for?

Is the system still in this state? If yes I would check the last few OOM reports which will tell you the pid of the oom victim and then I would check sysrq+t whether they are still alive. And if yes check their stack traces to see whether they are still in the allocation path or they got stuck somewhere else or maybe they are not related at all...

sysrq+t might be useful even when this is not oom related because it can pinpoint the task which is blocking your waiters.

Quoted 4 lines · Nikolay Borisov

I do have several OOM reports unfortunately I don't think I can correlate them in any sensible way to be able to answer the question "Which was the process that was writing prior to the D state occuring". Maybe you can be more specific as to what am I likely looking for?

Is the system still in this state? If yes I would check the last few OOM reports which will tell you the pid of the oom victim and then I would check sysrq+t whether they are still alive. And if yes check their stack traces to see whether they are still in the allocation path or they got stuck somewhere else or maybe they are not related at all...

sysrq+t might be useful even when this is not oom related because it can pinpoint the task which is blocking your waiters.

I couldn't find any particular OOM which stands out, here how a typical one looks like:

alxc9 kernel: Memory cgroup out of memory (oom_kill_allocating_task): Kill process 9703 (postmaster) score 0 or sacrifice child alxc9 kernel: Killed process 9703 (postmaster) total-vm:205800kB, anon-rss:1128kB, file-rss:0kB
alxc9 kernel: php invoked oom-killer: gfp_mask=0xd0, order=0, oom_score_adj=0
alxc9 kernel: php cpuset=cXXXX mems_allowed=0-1
alxc9 kernel: CPU: 12 PID: 1000 Comm: php Not tainted 4.0.0-clouder9+ #31
alxc9 kernel: Hardware name: Supermicro X9DRD-7LN4F(-JBOD)/X9DRD-EF/X9DRD-7LN4F, BIOS 3.2 01/16/2015
alxc9 kernel: ffff8805d8440400 ffff88208d863c78 ffffffff815aaca3 ffff8820b947c750
alxc9 kernel: ffff8820b947c750 ffff88208d863cc8 ffffffff81123b2e ffff882000000000
alxc9 kernel: ffffffff000000d0 ffff8805d8440400 ffff8820b947c750 ffff8820b947cee0
alxc9 kernel: Call Trace:
alxc9 kernel: [<ffffffff815aaca3>] dump_stack+0x48/0x5d
alxc9 kernel: [<ffffffff81123b2e>] dump_header+0x8e/0xe0
alxc9 kernel: [<ffffffff81123fa7>] oom_kill_process+0x1d7/0x3c0
alxc9 kernel: [<ffffffff810d85a1>] ? cpuset_mems_allowed_intersects+0x21/0x30
alxc9 kernel: [<ffffffff8118c2bd>] mem_cgroup_out_of_memory+0x2bd/0x370
alxc9 kernel: [<ffffffff81189b37>] ? mem_cgroup_iter+0x177/0x390
alxc9 kernel: [<ffffffff8118c5d7>] mem_cgroup_oom_synchronize+0x267/0x290
alxc9 kernel: [<ffffffff811874f0>] ? mem_cgroup_wait_acct_move+0x140/0x140
alxc9 kernel: [<ffffffff81124504>] pagefault_out_of_memory+0x24/0xe0
alxc9 kernel: [<ffffffff81041927>] mm_fault_error+0x47/0x160
alxc9 kernel: [<ffffffff81041db0>] __do_page_fault+0x340/0x3c0
alxc9 kernel: [<ffffffff81041e6c>] do_page_fault+0x3c/0x90
alxc9 kernel: [<ffffffff815b1758>] page_fault+0x28/0x30
alxc9 kernel: Task in /lxc/cXXXX killed as a result of limit of /lxc/cXXXX
alxc9 kernel: memory: usage 2097152kB, limit 2097152kB, failcnt 7832302
alxc9 kernel: memory+swap: usage 2097152kB, limit 2621440kB, failcnt 0
alxc9 kernel: kmem: usage 0kB, limit 9007199254740988kB, failcnt 0
alxc9 kernel: Memory cgroup stats for /lxc/cXXXX: cache:22708KB rss:2074444KB rss_huge:0KB mapped_file:19960KB writeback:4KB swap:0KB inactive_anon:20364KB active_anon:2074896KB inactive_file:1236KB active_file:464KB unevictable:0KB

The backtrace for other processes is exactly the same.

Quoted 34 lines · Nikolay Borisov

I couldn't find any particular OOM which stands out, here how a typical one looks like:

alxc9 kernel: Memory cgroup out of memory (oom_kill_allocating_task): Kill process 9703 (postmaster) score 0 or sacrifice child alxc9 kernel: Killed process 9703 (postmaster) total-vm:205800kB, anon-rss:1128kB, file-rss:0kB
alxc9 kernel: php invoked oom-killer: gfp_mask=0xd0, order=0, oom_score_adj=0
alxc9 kernel: php cpuset=cXXXX mems_allowed=0-1
alxc9 kernel: CPU: 12 PID: 1000 Comm: php Not tainted 4.0.0-clouder9+ #31
alxc9 kernel: Hardware name: Supermicro X9DRD-7LN4F(-JBOD)/X9DRD-EF/X9DRD-7LN4F, BIOS 3.2 01/16/2015
alxc9 kernel: ffff8805d8440400 ffff88208d863c78 ffffffff815aaca3 ffff8820b947c750
alxc9 kernel: ffff8820b947c750 ffff88208d863cc8 ffffffff81123b2e ffff882000000000
alxc9 kernel: ffffffff000000d0 ffff8805d8440400 ffff8820b947c750 ffff8820b947cee0
alxc9 kernel: Call Trace:
alxc9 kernel: [<ffffffff815aaca3>] dump_stack+0x48/0x5d
alxc9 kernel: [<ffffffff81123b2e>] dump_header+0x8e/0xe0
alxc9 kernel: [<ffffffff81123fa7>] oom_kill_process+0x1d7/0x3c0
alxc9 kernel: [<ffffffff810d85a1>] ? cpuset_mems_allowed_intersects+0x21/0x30
alxc9 kernel: [<ffffffff8118c2bd>] mem_cgroup_out_of_memory+0x2bd/0x370
alxc9 kernel: [<ffffffff81189b37>] ? mem_cgroup_iter+0x177/0x390
alxc9 kernel: [<ffffffff8118c5d7>] mem_cgroup_oom_synchronize+0x267/0x290
alxc9 kernel: [<ffffffff811874f0>] ? mem_cgroup_wait_acct_move+0x140/0x140
alxc9 kernel: [<ffffffff81124504>] pagefault_out_of_memory+0x24/0xe0
alxc9 kernel: [<ffffffff81041927>] mm_fault_error+0x47/0x160
alxc9 kernel: [<ffffffff81041db0>] __do_page_fault+0x340/0x3c0
alxc9 kernel: [<ffffffff81041e6c>] do_page_fault+0x3c/0x90
alxc9 kernel: [<ffffffff815b1758>] page_fault+0x28/0x30
alxc9 kernel: Task in /lxc/cXXXX killed as a result of limit of /lxc/cXXXX
alxc9 kernel: memory: usage 2097152kB, limit 2097152kB, failcnt 7832302
alxc9 kernel: memory+swap: usage 2097152kB, limit 2621440kB, failcnt 0
alxc9 kernel: kmem: usage 0kB, limit 9007199254740988kB, failcnt 0
alxc9 kernel: Memory cgroup stats for /lxc/cXXXX: cache:22708KB rss:2074444KB rss_huge:0KB mapped_file:19960KB writeback:4KB swap:0KB inactive_anon:20364KB active_anon:2074896KB inactive_file:1236KB active_file:464KB unevictable:0KB

Quoted 1 line

The backtrace for other processes is exactly the same.

OK, so this is not the global OOM killer. That wasn't clear from your previous description. It makes a difference because it means that the system is still healthy globaly and allocation requests will not loop for ever in the allocator. Memcg charging path will not get blocked until the OOM resolves and return ENOMEM when not called from the page fault path.

memcg oom killer ignores oom_kill_allocating_task so the victim might be different from the current task. That means the victim might get stuck behind a lock held by somebody else. If the ext4 journaling code depends on memcg charges and retry endlessly then the waiters would get stuck as well.

I can see some calls to find_or_create_page from fs/ext4/mballoc.c but AFAIU they are handling ENOMEM and lead to transaction abort - but I am not familiar with this code enough so somebody familiar with ext4 should double check that.

This all suggests that your lockup is caused by something else than OOM most probably.

On 06/25/2015 04:45 PM, Michal Hocko wrote:

Quoted 5 lines

memcg oom killer ignores oom_kill_allocating_task so the victim might be different from the current task. That means the victim might get stuck behind a lock held by somebody else. If the ext4 journaling code depends on memcg charges and retry endlessly then the waiters would get stuck as well.

I've patched the cgroup OOM so that it takes into account the oom_kill_allocating_task.

Quoted 4 lines · Nikolay Borisov

I do have several OOM reports unfortunately I don't think I can correlate them in any sensible way to be able to answer the question "Which was the process that was writing prior to the D state occuring". Maybe you can be more specific as to what am I likely looking for?

Is the system still in this state? If yes I would check the last few OOM reports which will tell you the pid of the oom victim and then I would check sysrq+t whether they are still alive. And if yes check their stack traces to see whether they are still in the allocation path or they got stuck somewhere else or maybe they are not related at all...

sysrq+t might be useful even when this is not oom related because it can pinpoint the task which is blocking your waiters.

Quoted 6 lines · Michal Hocko

Quoted 4 lines · Nikolay Borisov

I do have several OOM reports unfortunately I don't think I can correlate them in any sensible way to be able to answer the question "Which was the process that was writing prior to the D state occuring". Maybe you can be more specific as to what am I likely looking for?

Quoted 8 lines

Is the system still in this state? If yes I would check the last few OOM reports which will tell you the pid of the oom victim and then I would check sysrq+t whether they are still alive. And if yes check their stack traces to see whether they are still in the allocation path or they got stuck somewhere else or maybe they are not related at all...

sysrq+t might be useful even when this is not oom related because it can pinpoint the task which is blocking your waiters.

In addition to sysrq+t, the other thing to do is to sample sysrq-p a few half-dozen times so we can see if there are any processes in some memory allocation retry loop. Also useful is to enable soft lockup detection.

Something that perhaps we should have (and maybe GFP_NOFAIL should imply this) is for places where your choices are either (a) let the memory allocation succeed eventually, or (b) remount the file system read-only and/or panic the system, is in the case where we're under severe memory pressure due to cgroup settings, to simply allow the kmalloc to bypass the cgroup allocation limits, since otherwise the stall could end up impacting processes in other cgroups.

This is basically the same issue as a misconfigured cgroup which as very tiny disk I/O and memory allocated to it, such that when a process in that cgroup does a directory lookup, VFS locks the directory *before* calling into the file system layer, and then if cgroup isn't allow much in the way of memory and disk time, it's likely that the directory block has been pushed out of memory, and on a sufficiently busy system, the directory read might not happen for minutes or *hours* (both because of the disk I/O limits as well as the time needed to clean memory to allow the necessary memory allocation to succeed).

In the meantime, if a process in another cgroup, with plenty of disk-time and memory, tries to do anything else with that directory, it will run into locked directory mutex, and *wham*. Priority inversion. It gets even more amusing if this process is the overall docker or other cgroup manager, since then the entire system is out to lunch, and so then a watchdog daemon fires, and reboots the entire system....

- Ted
--
To unsubscribe from this list: send the line "unsubscribe linux-ext4" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

How would you advise to rectify such situation?

On Thu 25-06-15 16:49:43, Nikolay Borisov wrote:
[...]

Quoted 1 line

How would you advise to rectify such situation?

As I've said. Check the oom victim traces and see if it is holding any of those locks.

Quoted 6 lines · Michal Hocko

On Thu 25-06-15 16:49:43, Nikolay Borisov wrote:
[...]

Quoted 1 line

How would you advise to rectify such situation?

As I've said. Check the oom victim traces and see if it is holding any of those locks.

As mentioned previously all OOM traces are identical to the one I've sent - OOM being called form the page fault path.

Quoted 8 lines · Nikolay Borisov

Quoted 6 lines · Michal Hocko

On Thu 25-06-15 16:49:43, Nikolay Borisov wrote:
[...]

Quoted 1 line

How would you advise to rectify such situation?

As I've said. Check the oom victim traces and see if it is holding any of those locks.

Quoted 2 lines

As mentioned previously all OOM traces are identical to the one I've sent - OOM being called form the page fault path.

By identical you mean that all of them kill the same task? Or just that the path is same (which wouldn't be surprising as this is the only path which triggers memcg oom killer)?

Quoted 9 lines · Michal Hocko

Quoted 8 lines · Nikolay Borisov

Quoted 6 lines · Michal Hocko

On Thu 25-06-15 16:49:43, Nikolay Borisov wrote:
[...]

Quoted 1 line

How would you advise to rectify such situation?

As I've said. Check the oom victim traces and see if it is holding any of those locks.

Quoted 6 lines

Quoted 2 lines

As mentioned previously all OOM traces are identical to the one I've sent - OOM being called form the page fault path.

By identical you mean that all of them kill the same task? Or just that the path is same (which wouldn't be surprising as this is the only path which triggers memcg oom killer)?

The code path is the same, the tasks being killed are different

Quoted 15 lines · Nikolay Borisov

Quoted 12 lines · Michal Hocko

Quoted 10 lines · Nikolay Borisov

Quoted 6 lines · Michal Hocko

On Thu 25-06-15 16:49:43, Nikolay Borisov wrote:
[...]

Quoted 1 line

How would you advise to rectify such situation?

As I've said. Check the oom victim traces and see if it is holding any of those locks.

As mentioned previously all OOM traces are identical to the one I've sent - OOM being called form the page fault path.

Quoted 5 lines

Quoted 3 lines

By identical you mean that all of them kill the same task? Or just that the path is same (which wouldn't be surprising as this is the only path which triggers memcg oom killer)?

The code path is the same, the tasks being killed are different

Is the OOM killer triggered only for a singe memcg or others misbehave as well?

Quoted 20 lines · Michal Hocko

Quoted 19 lines · Nikolay Borisov

Quoted 15 lines · Michal Hocko

Quoted 10 lines · Nikolay Borisov

Quoted 6 lines · Michal Hocko

On Thu 25-06-15 16:49:43, Nikolay Borisov wrote:
[...]

Quoted 1 line

How would you advise to rectify such situation?

As I've said. Check the oom victim traces and see if it is holding any of those locks.

As mentioned previously all OOM traces are identical to the one I've sent - OOM being called form the page fault path.

By identical you mean that all of them kill the same task? Or just that the path is same (which wouldn't be surprising as this is the only path which triggers memcg oom killer)?

Quoted 4 lines

Quoted 1 line

The code path is the same, the tasks being killed are different

Is the OOM killer triggered only for a singe memcg or others misbehave as well?

Generally OOM would be triggered for whichever memcg runs out of resources but so far I've only observed that the D state issue happens in a single containers.

However, this in turn might affect other processes if they try to sleep on the same jbd2 journal .

Quoted 28 lines · Nikolay Borisov

Quoted 24 lines · Michal Hocko

Quoted 12 lines · Nikolay Borisov

Quoted 9 lines · Michal Hocko

Quoted 8 lines · Nikolay Borisov

Quoted 6 lines · Michal Hocko

On Thu 25-06-15 16:49:43, Nikolay Borisov wrote:
[...]

Quoted 1 line

How would you advise to rectify such situation?

As I've said. Check the oom victim traces and see if it is holding any of those locks.

Quoted 8 lines

Quoted 6 lines

Quoted 2 lines

As mentioned previously all OOM traces are identical to the one I've sent - OOM being called form the page fault path.

By identical you mean that all of them kill the same task? Or just that the path is same (which wouldn't be surprising as this is the only path which triggers memcg oom killer)?

The code path is the same, the tasks being killed are different

Is the OOM killer triggered only for a singe memcg or others misbehave as well?

Quoted 3 lines

Generally OOM would be triggered for whichever memcg runs out of resources but so far I've only observed that the D state issue happens in a single containers.

It is not clear whether it is the OOM memcg which has tasks in the D state. Anyway I think it all smells like one memcg is throttling others on another shared resource - journal in your case.

Quoted 3 lines

However, this in turn might affect other processes if they try to sleep on the same jbd2 journal .

Sure, if the journal is shared then this is an inherent problem. Memcg restrictions can easily cause priority inheritance problems as Ted has already mentioned.

Quoted 33 lines · Michal Hocko

Quoted 31 lines · Nikolay Borisov

Quoted 16 lines · Michal Hocko

Quoted 15 lines · Nikolay Borisov

Quoted 12 lines · Michal Hocko

Quoted 10 lines · Nikolay Borisov

Quoted 6 lines · Michal Hocko

On Thu 25-06-15 16:49:43, Nikolay Borisov wrote:
[...]

Quoted 1 line

How would you advise to rectify such situation?

As I've said. Check the oom victim traces and see if it is holding any of those locks.

As mentioned previously all OOM traces are identical to the one I've sent - OOM being called form the page fault path.

Quoted 8 lines

Quoted 5 lines

Quoted 3 lines

By identical you mean that all of them kill the same task? Or just that the path is same (which wouldn't be surprising as this is the only path which triggers memcg oom killer)?

The code path is the same, the tasks being killed are different

Is the OOM killer triggered only for a singe memcg or others misbehave as well?

Generally OOM would be triggered for whichever memcg runs out of resources but so far I've only observed that the D state issue happens in a single containers.

Quoted 3 lines

It is not clear whether it is the OOM memcg which has tasks in the D state. Anyway I think it all smells like one memcg is throttling others on another shared resource - journal in your case.

Be that as it may, how do I find which cgroup is the culprit?

Quoted 40 lines · Nikolay Borisov

Quoted 36 lines · Michal Hocko

Quoted 23 lines · Nikolay Borisov

Quoted 20 lines · Michal Hocko

Quoted 19 lines · Nikolay Borisov

Quoted 15 lines · Michal Hocko

Quoted 10 lines · Nikolay Borisov

Quoted 6 lines · Michal Hocko

On Thu 25-06-15 16:49:43, Nikolay Borisov wrote:
[...]

Quoted 1 line

How would you advise to rectify such situation?

As I've said. Check the oom victim traces and see if it is holding any of those locks.

As mentioned previously all OOM traces are identical to the one I've sent - OOM being called form the page fault path.

By identical you mean that all of them kill the same task? Or just that the path is same (which wouldn't be surprising as this is the only path which triggers memcg oom killer)?

Quoted 8 lines

Quoted 4 lines

Quoted 1 line

The code path is the same, the tasks being killed are different

Is the OOM killer triggered only for a singe memcg or others misbehave as well?

Generally OOM would be triggered for whichever memcg runs out of resources but so far I've only observed that the D state issue happens in a single containers.

It is not clear whether it is the OOM memcg which has tasks in the D state. Anyway I think it all smells like one memcg is throttling others on another shared resource - journal in your case.

Quoted 1 line

Be that as it may, how do I find which cgroup is the culprit?

Ted has already described that. You have to check all the running tasks and try to find which of them is doing the operation which blocks others. Transaction commit sounds like the first one to check.

Quoted 43 lines · Michal Hocko

Quoted 41 lines · Nikolay Borisov

Quoted 29 lines · Michal Hocko

Quoted 28 lines · Nikolay Borisov

Quoted 24 lines · Michal Hocko

Quoted 12 lines · Nikolay Borisov

Quoted 9 lines · Michal Hocko

Quoted 8 lines · Nikolay Borisov

Quoted 6 lines · Michal Hocko

On Thu 25-06-15 16:49:43, Nikolay Borisov wrote:
[...]

Quoted 1 line

How would you advise to rectify such situation?

As I've said. Check the oom victim traces and see if it is holding any of those locks.

Quoted 8 lines

Quoted 6 lines

Quoted 2 lines

As mentioned previously all OOM traces are identical to the one I've sent - OOM being called form the page fault path.

By identical you mean that all of them kill the same task? Or just that the path is same (which wouldn't be surprising as this is the only path which triggers memcg oom killer)?

The code path is the same, the tasks being killed are different

Is the OOM killer triggered only for a singe memcg or others misbehave as well?

Quoted 7 lines

Quoted 3 lines

Generally OOM would be triggered for whichever memcg runs out of resources but so far I've only observed that the D state issue happens in a single containers.

It is not clear whether it is the OOM memcg which has tasks in the D state. Anyway I think it all smells like one memcg is throttling others on another shared resource - journal in your case.

Be that as it may, how do I find which cgroup is the culprit?

Quoted 3 lines

Ted has already described that. You have to check all the running tasks and try to find which of them is doing the operation which blocks others. Transaction commit sounds like the first one to check.

One other, fairly crucial detail - each and every container is on a separate block device, meaning the journals for different block devices is not being shared, since the journal is per-block device.

I guess this
means that whatever is happening is more or less constrained to the block device and thus the possibility that different memcg competing for the journal can be eliminated?

You know it might be possible that I'm observing exactly this, since the other places where processes are blocked (but I omitted initially since I thought it's inconsequential) is in the following code path:

Jun 24 11:22:59 alxc9 kernel: crond           D ffff8820b8affe58 14784 30568  30627 0x00000004
Jun 24 11:22:59 alxc9 kernel: ffff8820b8affe58 ffff8820ca72b2f0 ffff882c3534b2f0 000000000000fe4e
Jun 24 11:22:59 alxc9 kernel: ffff8820b8afc010 ffff882c3534b2f0 ffff8808d2d7e34c 00000000ffffffff
Jun 24 11:22:59 alxc9 kernel: ffff8808d2d7e350 ffff8820b8affe78 ffffffff815ab76e ffff882c3534b2f0
Jun 24 11:22:59 alxc9 kernel: Call Trace:
Jun 24 11:22:59 alxc9 kernel: [<ffffffff815ab76e>] schedule+0x3e/0x90
Jun 24 11:22:59 alxc9 kernel: [<ffffffff815ab9de>] schedule_preempt_disabled+0xe/0x10
Jun 24 11:22:59 alxc9 kernel: [<ffffffff815ad505>] __mutex_lock_slowpath+0x95/0x110
Jun 24 11:22:59 alxc9 kernel: [<ffffffff810a57d9>] ? rcu_eqs_exit+0x79/0xb0
Jun 24 11:22:59 alxc9 kernel: [<ffffffff815ad59b>] mutex_lock+0x1b/0x30
Jun 24 11:22:59 alxc9 kernel: [<ffffffff811b1fbd>] __fdget_pos+0x3d/0x50
Jun 24 11:22:59 alxc9 kernel: [<ffffffff810119d7>] ? syscall_trace_leave+0xa7/0xf0
Jun 24 11:22:59 alxc9 kernel: [<ffffffff81194bb3>] SyS_write+0x33/0xd0
Jun 24 11:22:59 alxc9 kernel: [<ffffffff815afcc8>] ? int_check_syscall_exit_work+0x34/0x3d
Jun 24 11:22:59 alxc9 kernel: [<ffffffff815afa89>] system_call_fastpath+0x12/0x17

Particularly, I can see a lot of processes locked up in __fdget_pos -> mutex_lock. And this all sounds very similar to what you just described.

How would you advise to rectify such situation?

Quoted 6 lines · Michal Hocko

Quoted 4 lines · Nikolay Borisov

I do have several OOM reports unfortunately I don't think I can correlate them in any sensible way to be able to answer the question "Which was the process that was writing prior to the D state occuring". Maybe you can be more specific as to what am I likely looking for?

Quoted 8 lines

Is the system still in this state? If yes I would check the last few OOM reports which will tell you the pid of the oom victim and then I would check sysrq+t whether they are still alive. And if yes check their stack traces to see whether they are still in the allocation path or they got stuck somewhere else or maybe they are not related at all...

sysrq+t might be useful even when this is not oom related because it can pinpoint the task which is blocking your waiters.

In addition to sysrq+t, the other thing to do is to sample sysrq-p a few half-dozen times so we can see if there are any processes in some memory allocation retry loop. Also useful is to enable soft lockup detection.

Something that perhaps we should have (and maybe GFP_NOFAIL should imply this) is for places where your choices are either (a) let the memory allocation succeed eventually, or (b) remount the file system read-only and/or panic the system, is in the case where we're under severe memory pressure due to cgroup settings, to simply allow the kmalloc to bypass the cgroup allocation limits, since otherwise the stall could end up impacting processes in other cgroups.

Today I observed the issue again, this time on a different server. What is particularly strange is the fact that the OOM wasn't triggered for the cgroup, whose tasks have entered D state. There were a couple of SSHD processes and an RSYNC performing some backup tasks. Here is what the stacktrace for the rsync looks like:

crash> set 18308

    PID: 18308
COMMAND: "rsync"
   TASK: ffff883d7c9b0a30  [THREAD_INFO: ffff881773748000]
    CPU: 1
  STATE: TASK_UNINTERRUPTIBLE

crash> bt
PID: 18308 TASK: ffff883d7c9b0a30 CPU: 1 COMMAND: "rsync"
#0 [ffff88177374ac60] __schedule at ffffffff815ab152 #1 [ffff88177374acb0] schedule at ffffffff815ab76e #2 [ffff88177374acd0] schedule_timeout at ffffffff815ae5e5 #3 [ffff88177374ad70] io_schedule_timeout at ffffffff815aad6a #4 [ffff88177374ada0] bit_wait_io at ffffffff815abfc6 #5 [ffff88177374adb0] __wait_on_bit at ffffffff815abda5 #6 [ffff88177374ae00] wait_on_page_bit at ffffffff8111fd4f #7 [ffff88177374ae50] shrink_page_list at ffffffff81135445

#8 [ffff88177374af50] shrink_inactive_list at ffffffff81135845 #9 [ffff88177374b060] shrink_lruvec at ffffffff81135ead
#10 [ffff88177374b150] shrink_zone at ffffffff811360c3
#11 [ffff88177374b220] shrink_zones at ffffffff81136eff
#12 [ffff88177374b2a0] do_try_to_free_pages at ffffffff8113712f #13 [ffff88177374b300] try_to_free_mem_cgroup_pages at ffffffff811372be #14 [ffff88177374b380] try_charge at ffffffff81189423
#15 [ffff88177374b430] mem_cgroup_try_charge at ffffffff8118c6f5 #16 [ffff88177374b470] __add_to_page_cache_locked at ffffffff8112137d #17 [ffff88177374b4e0] add_to_page_cache_lru at ffffffff81121618 #18 [ffff88177374b510] pagecache_get_page at ffffffff8112170b #19 [ffff88177374b560] grow_dev_page at ffffffff811c8297
#20 [ffff88177374b5c0] __getblk_slow at ffffffff811c91d6
#21 [ffff88177374b600] __getblk_gfp at ffffffff811c92c1
#22 [ffff88177374b630] ext4_ext_grow_indepth at ffffffff8124565c #23 [ffff88177374b690] ext4_ext_create_new_leaf at ffffffff81246ca8 #24 [ffff88177374b6e0] ext4_ext_insert_extent at ffffffff81246f09 #25 [ffff88177374b750] ext4_ext_map_blocks at ffffffff8124a848 #26 [ffff88177374b870] ext4_map_blocks at ffffffff8121a5b7 #27 [ffff88177374b910] mpage_map_one_extent at ffffffff8121b1fa #28 [ffff88177374b950] mpage_map_and_submit_extent at ffffffff8121f07b #29 [ffff88177374b9b0] ext4_writepages at ffffffff8121f6d5 #30 [ffff88177374bb20] do_writepages at ffffffff8112c490
#31 [ffff88177374bb30] __filemap_fdatawrite_range at ffffffff81120199 #32 [ffff88177374bb80] filemap_flush at ffffffff8112041c
#33 [ffff88177374bb90] ext4_alloc_da_blocks at ffffffff81219da1 #34 [ffff88177374bbb0] ext4_rename at ffffffff81229b91
#35 [ffff88177374bcd0] ext4_rename2 at ffffffff81229e32
#36 [ffff88177374bce0] vfs_rename at ffffffff811a08a5
#37 [ffff88177374bd60] SYSC_renameat2 at ffffffff811a3ffc #38 [ffff88177374bf60] sys_renameat2 at ffffffff811a408e
#39 [ffff88177374bf70] sys_rename at ffffffff8119e51e
#40 [ffff88177374bf80] system_call_fastpath at ffffffff815afa89

    RIP: 00002ba0169b61d7  RSP: 00007ffde830f428  RFLAGS: 00000206
    RAX: ffffffffffffffda  RBX: ffffffff815afa89  RCX: 00002ba016a2e007
    RDX: 0000000000000000  RSI: 00007ffde83126f0  RDI: 00007ffde83106f0
    RBP: 00007ffde83106f0   R8: 0000000000000000   R9: 0000000000000000
    R10: 0000000000000000  R11: 0000000000000202  R12: ffffffff8119e51e
    R13: ffff88177374bf78  R14: ffffffff811a408e  R15: ffff88177374bf68
    ORIG_RAX: 0000000000000052  CS: 0033  SS: 002b

All the other processes in the container have locked up when trying to access file system resources. The SSHD processes for example have blocked on tryng to access /var/log/btmp:

PID: 11919 TASK: ffff8815613c1460 CPU: 2 COMMAND: "sshd"
#0 [ffff880158d03c70] __schedule at ffffffff815ab152
#1 [ffff880158d03cc0] schedule at ffffffff815ab76e
#2 [ffff880158d03ce0] schedule_preempt_disabled at ffffffff815ab9de #3 [ffff880158d03cf0] __mutex_lock_slowpath at ffffffff815ad505 #4 [ffff880158d03d50] mutex_lock at ffffffff815ad59b
#5 [ffff880158d03d70] ext4_file_write_iter at ffffffff8121477b #6 [ffff880158d03e30] new_sync_write at ffffffff81194047 #7 [ffff880158d03f00] vfs_write at ffffffff8119445e
#8 [ffff880158d03f30] sys_write at ffffffff81194bda
#9 [ffff880158d03f80] system_call_fastpath at ffffffff815afa89

    RIP: 00002adf56857790  RSP: 00007fffaf514788  RFLAGS: 00000206
    RAX: ffffffffffffffda  RBX: ffffffff815afa89  RCX: 00002adf568657f7
    RDX: 0000000000000180  RSI: 00007fffaf5147a0  RDI: 0000000000000005
    RBP: 0000000000000005   R8: 00002adf53ebf7a0   R9: 0000000080000000
    R10: 0000000000000001  R11: 0000000000000246  R12: 00007fffaf514740
    R13: 0000000000000180  R14: 0000000000000000  R15: 00007fffaf5147a0
    ORIG_RAX: 0000000000000001  CS: 0033  SS: 002b

Except for one which has blocked with the following stack:
PID: 7833 TASK: ffff88175b3ba8c0 CPU: 3 COMMAND: "sshd"
#0 [ffff88001d983960] __schedule at ffffffff815ab152
#1 [ffff88001d9839b0] schedule at ffffffff815ab76e
#2 [ffff88001d9839d0] wait_transaction_locked at ffffffff81264265 #3 [ffff88001d983a30] add_transaction_credits at ffffffff81264540 #4 [ffff88001d983ab0] start_this_handle at ffffffff81264824 #5 [ffff88001d983b60] jbd2__journal_start at ffffffff81265220 #6 [ffff88001d983bc0] __ext4_journal_start_sb at ffffffff8124bb49 #7 [ffff88001d983c10] ext4_dirty_inode at ffffffff8121da5c #8 [ffff88001d983c30] __mark_inode_dirty at ffffffff811be5c3 #9 [ffff88001d983c70] generic_update_time at ffffffff811ae9c5
#10 [ffff88001d983cb0] file_update_time at ffffffff811ae632 #11 [ffff88001d983d10] __generic_file_write_iter at ffffffff811226c2 #12 [ffff88001d983d70] ext4_file_write_iter at ffffffff81214814 #13 [ffff88001d983e30] new_sync_write at ffffffff81194047 #14 [ffff88001d983f00] vfs_write at ffffffff8119445e
#15 [ffff88001d983f30] sys_write at ffffffff81194bda
#16 [ffff88001d983f80] system_call_fastpath at ffffffff815afa89

    RIP: 00002adf56857790  RSP: 00007fffaf514788  RFLAGS: 00000206
    RAX: ffffffffffffffda  RBX: ffffffff815afa89  RCX: 00002adf568657f7
    RDX: 0000000000000180  RSI: 00007fffaf5147a0  RDI: 0000000000000005
    RBP: 0000000000000005   R8: 00002adf53ebf7a0   R9: 0000000080000000
    R10: 0000000000000001  R11: 0000000000000246  R12: 00007fffaf514740
    R13: 0000000000000180  R14: 0000000000000000  R15: 00007fffaf5147a0
    ORIG_RAX: 0000000000000001  CS: 0033  SS: 002b

So basically what I have managed to determine so far is that "something" (this is the bit which I've yet to uncover, hopefully with your help) starves the file system of resources. Which causes processes to block in the jbd2_journal_start path. The other SSHD processes essentially block on the i_mutex of the /var/log/btmp (nothing unusual).

So I guess the most interesting bit here is the stack of the rsync process, so it is blocking on trying to free some pages, yet the OOM hasn't triggered.

Quoted 12 lines · Nikolay Borisov

Today I observed the issue again, this time on a different server. What is particularly strange is the fact that the OOM wasn't triggered for the cgroup, whose tasks have entered D state. There were a couple of SSHD processes and an RSYNC performing some backup tasks. Here is what the stacktrace for the rsync looks like:

crash> set 18308

    PID: 18308
COMMAND: "rsync"
   TASK: ffff883d7c9b0a30  [THREAD_INFO: ffff881773748000]
    CPU: 1
  STATE: TASK_UNINTERRUPTIBLE

Quoted 10 lines

crash> bt
PID: 18308 TASK: ffff883d7c9b0a30 CPU: 1 COMMAND: "rsync"
#0 [ffff88177374ac60] __schedule at ffffffff815ab152 #1 [ffff88177374acb0] schedule at ffffffff815ab76e #2 [ffff88177374acd0] schedule_timeout at ffffffff815ae5e5 #3 [ffff88177374ad70] io_schedule_timeout at ffffffff815aad6a #4 [ffff88177374ada0] bit_wait_io at ffffffff815abfc6 #5 [ffff88177374adb0] __wait_on_bit at ffffffff815abda5 #6 [ffff88177374ae00] wait_on_page_bit at ffffffff8111fd4f #7 [ffff88177374ae50] shrink_page_list at ffffffff81135445

This is most probably wait_on_page_writeback because the reclaim has encountered a dirty page which is under writeback currently.

Quoted 17 lines

#8 [ffff88177374af50] shrink_inactive_list at ffffffff81135845 #9 [ffff88177374b060] shrink_lruvec at ffffffff81135ead
#10 [ffff88177374b150] shrink_zone at ffffffff811360c3
#11 [ffff88177374b220] shrink_zones at ffffffff81136eff
#12 [ffff88177374b2a0] do_try_to_free_pages at ffffffff8113712f #13 [ffff88177374b300] try_to_free_mem_cgroup_pages at ffffffff811372be #14 [ffff88177374b380] try_charge at ffffffff81189423
#15 [ffff88177374b430] mem_cgroup_try_charge at ffffffff8118c6f5 #16 [ffff88177374b470] __add_to_page_cache_locked at ffffffff8112137d #17 [ffff88177374b4e0] add_to_page_cache_lru at ffffffff81121618 #18 [ffff88177374b510] pagecache_get_page at ffffffff8112170b #19 [ffff88177374b560] grow_dev_page at ffffffff811c8297
#20 [ffff88177374b5c0] __getblk_slow at ffffffff811c91d6
#21 [ffff88177374b600] __getblk_gfp at ffffffff811c92c1
#22 [ffff88177374b630] ext4_ext_grow_indepth at ffffffff8124565c #23 [ffff88177374b690] ext4_ext_create_new_leaf at ffffffff81246ca8 #24 [ffff88177374b6e0] ext4_ext_insert_extent at ffffffff81246f09

Quoted 8 lines

#25 [ffff88177374b750] ext4_ext_map_blocks at ffffffff8124a848 #26 [ffff88177374b870] ext4_map_blocks at ffffffff8121a5b7 #27 [ffff88177374b910] mpage_map_one_extent at ffffffff8121b1fa #28 [ffff88177374b950] mpage_map_and_submit_extent at ffffffff8121f07b #29 [ffff88177374b9b0] ext4_writepages at ffffffff8121f6d5 #30 [ffff88177374bb20] do_writepages at ffffffff8112c490 #31 [ffff88177374bb30] __filemap_fdatawrite_range at ffffffff81120199 #32 [ffff88177374bb80] filemap_flush at ffffffff8112041c

Yes, and looks at the caller path....

Quoted 17 lines

Quoted 17 lines

#8 [ffff88177374af50] shrink_inactive_list at ffffffff81135845 #9 [ffff88177374b060] shrink_lruvec at ffffffff81135ead
#10 [ffff88177374b150] shrink_zone at ffffffff811360c3
#11 [ffff88177374b220] shrink_zones at ffffffff81136eff
#12 [ffff88177374b2a0] do_try_to_free_pages at ffffffff8113712f #13 [ffff88177374b300] try_to_free_mem_cgroup_pages at ffffffff811372be #14 [ffff88177374b380] try_charge at ffffffff81189423
#15 [ffff88177374b430] mem_cgroup_try_charge at ffffffff8118c6f5 #16 [ffff88177374b470] __add_to_page_cache_locked at ffffffff8112137d #17 [ffff88177374b4e0] add_to_page_cache_lru at ffffffff81121618 #18 [ffff88177374b510] pagecache_get_page at ffffffff8112170b #19 [ffff88177374b560] grow_dev_page at ffffffff811c8297
#20 [ffff88177374b5c0] __getblk_slow at ffffffff811c91d6
#21 [ffff88177374b600] __getblk_gfp at ffffffff811c92c1
#22 [ffff88177374b630] ext4_ext_grow_indepth at ffffffff8124565c #23 [ffff88177374b690] ext4_ext_create_new_leaf at ffffffff81246ca8 #24 [ffff88177374b6e0] ext4_ext_insert_extent at ffffffff81246f09

Quoted 8 lines

Quoted 8 lines

#25 [ffff88177374b750] ext4_ext_map_blocks at ffffffff8124a848 #26 [ffff88177374b870] ext4_map_blocks at ffffffff8121a5b7 #27 [ffff88177374b910] mpage_map_one_extent at ffffffff8121b1fa #28 [ffff88177374b950] mpage_map_and_submit_extent at ffffffff8121f07b #29 [ffff88177374b9b0] ext4_writepages at ffffffff8121f6d5 #30 [ffff88177374bb20] do_writepages at ffffffff8112c490 #31 [ffff88177374bb30] __filemap_fdatawrite_range at ffffffff81120199 #32 [ffff88177374bb80] filemap_flush at ffffffff8112041c

That's a potential self deadlocking path, isn't it? i.e. the writeback path has been entered, may hold pages locked in the current bio being built (waiting for submission), then memory reclaim has been entered while trying to map more contiguous blocks to submit, and that waits on page IO to complete on a page in a bio that ext4 hasn't yet submitted?

i.e. shouldn't ext4 be doing GFP_NOFS allocations all through this writeback path?

Quoted 35 lines · Dave Chinner

Yes, and looks at the caller path....

Quoted 17 lines

Quoted 17 lines

#8 [ffff88177374af50] shrink_inactive_list at ffffffff81135845 #9 [ffff88177374b060] shrink_lruvec at ffffffff81135ead
#10 [ffff88177374b150] shrink_zone at ffffffff811360c3
#11 [ffff88177374b220] shrink_zones at ffffffff81136eff
#12 [ffff88177374b2a0] do_try_to_free_pages at ffffffff8113712f #13 [ffff88177374b300] try_to_free_mem_cgroup_pages at ffffffff811372be #14 [ffff88177374b380] try_charge at ffffffff81189423
#15 [ffff88177374b430] mem_cgroup_try_charge at ffffffff8118c6f5 #16 [ffff88177374b470] __add_to_page_cache_locked at ffffffff8112137d #17 [ffff88177374b4e0] add_to_page_cache_lru at ffffffff81121618 #18 [ffff88177374b510] pagecache_get_page at ffffffff8112170b #19 [ffff88177374b560] grow_dev_page at ffffffff811c8297
#20 [ffff88177374b5c0] __getblk_slow at ffffffff811c91d6
#21 [ffff88177374b600] __getblk_gfp at ffffffff811c92c1
#22 [ffff88177374b630] ext4_ext_grow_indepth at ffffffff8124565c #23 [ffff88177374b690] ext4_ext_create_new_leaf at ffffffff81246ca8 #24 [ffff88177374b6e0] ext4_ext_insert_extent at ffffffff81246f09

Quoted 8 lines

Quoted 8 lines

#25 [ffff88177374b750] ext4_ext_map_blocks at ffffffff8124a848 #26 [ffff88177374b870] ext4_map_blocks at ffffffff8121a5b7 #27 [ffff88177374b910] mpage_map_one_extent at ffffffff8121b1fa #28 [ffff88177374b950] mpage_map_and_submit_extent at ffffffff8121f07b #29 [ffff88177374b9b0] ext4_writepages at ffffffff8121f6d5 #30 [ffff88177374bb20] do_writepages at ffffffff8112c490 #31 [ffff88177374bb30] __filemap_fdatawrite_range at ffffffff81120199 #32 [ffff88177374bb80] filemap_flush at ffffffff8112041c

That's a potential self deadlocking path, isn't it? i.e. the writeback path has been entered, may hold pages locked in the current bio being built (waiting for submission), then memory reclaim has been entered while trying to map more contiguous blocks to submit, and that waits on page IO to complete on a page in a bio that ext4 hasn't yet submitted?

Quoted 2 lines

i.e. shouldn't ext4 be doing GFP_NOFS allocations all through this writeback path?

All of the direct allocations in fs/ext4/extents.c are using GFP_NOFS. The problem is that we're calling sb_getblk(), which does _not_ set GFP_NOFS. What we need to do is to add a sb_getblk_gfp() inline function in include/linux/buffer_head.h, and use that in fs/ext4/extents.c.

Thanks for pointing that out! I'll create a patch as soon as I get back from vacation.

- Ted

Quoted 24 lines · Michal Hocko

Quoted 12 lines · Nikolay Borisov

Today I observed the issue again, this time on a different server. What is particularly strange is the fact that the OOM wasn't triggered for the cgroup, whose tasks have entered D state. There were a couple of SSHD processes and an RSYNC performing some backup tasks. Here is what the stacktrace for the rsync looks like:

crash> set 18308

    PID: 18308
COMMAND: "rsync"
   TASK: ffff883d7c9b0a30  [THREAD_INFO: ffff881773748000]
    CPU: 1
  STATE: TASK_UNINTERRUPTIBLE

Quoted 10 lines

crash> bt
PID: 18308 TASK: ffff883d7c9b0a30 CPU: 1 COMMAND: "rsync"
#0 [ffff88177374ac60] __schedule at ffffffff815ab152 #1 [ffff88177374acb0] schedule at ffffffff815ab76e #2 [ffff88177374acd0] schedule_timeout at ffffffff815ae5e5 #3 [ffff88177374ad70] io_schedule_timeout at ffffffff815aad6a #4 [ffff88177374ada0] bit_wait_io at ffffffff815abfc6 #5 [ffff88177374adb0] __wait_on_bit at ffffffff815abda5 #6 [ffff88177374ae00] wait_on_page_bit at ffffffff8111fd4f #7 [ffff88177374ae50] shrink_page_list at ffffffff81135445

Quoted 2 lines

This is most probably wait_on_page_writeback because the reclaim has encountered a dirty page which is under writeback currently.

Yes, and looks at the caller path....

Quoted 17 lines

Quoted 17 lines

#8 [ffff88177374af50] shrink_inactive_list at ffffffff81135845 #9 [ffff88177374b060] shrink_lruvec at ffffffff81135ead
#10 [ffff88177374b150] shrink_zone at ffffffff811360c3
#11 [ffff88177374b220] shrink_zones at ffffffff81136eff
#12 [ffff88177374b2a0] do_try_to_free_pages at ffffffff8113712f #13 [ffff88177374b300] try_to_free_mem_cgroup_pages at ffffffff811372be #14 [ffff88177374b380] try_charge at ffffffff81189423
#15 [ffff88177374b430] mem_cgroup_try_charge at ffffffff8118c6f5 #16 [ffff88177374b470] __add_to_page_cache_locked at ffffffff8112137d #17 [ffff88177374b4e0] add_to_page_cache_lru at ffffffff81121618 #18 [ffff88177374b510] pagecache_get_page at ffffffff8112170b #19 [ffff88177374b560] grow_dev_page at ffffffff811c8297
#20 [ffff88177374b5c0] __getblk_slow at ffffffff811c91d6
#21 [ffff88177374b600] __getblk_gfp at ffffffff811c92c1
#22 [ffff88177374b630] ext4_ext_grow_indepth at ffffffff8124565c #23 [ffff88177374b690] ext4_ext_create_new_leaf at ffffffff81246ca8 #24 [ffff88177374b6e0] ext4_ext_insert_extent at ffffffff81246f09

Quoted 8 lines

Quoted 8 lines

#25 [ffff88177374b750] ext4_ext_map_blocks at ffffffff8124a848 #26 [ffff88177374b870] ext4_map_blocks at ffffffff8121a5b7 #27 [ffff88177374b910] mpage_map_one_extent at ffffffff8121b1fa #28 [ffff88177374b950] mpage_map_and_submit_extent at ffffffff8121f07b #29 [ffff88177374b9b0] ext4_writepages at ffffffff8121f6d5 #30 [ffff88177374bb20] do_writepages at ffffffff8112c490 #31 [ffff88177374bb30] __filemap_fdatawrite_range at ffffffff81120199 #32 [ffff88177374bb80] filemap_flush at ffffffff8112041c

That's a potential self deadlocking path, isn't it? i.e. the writeback path has been entered, may hold pages locked in the current bio being built (waiting for submission), then memory reclaim has been entered while trying to map more contiguous blocks to submit, and that waits on page IO to complete on a page in a bio that ext4 hasn't yet submitted?

i.e. shouldn't ext4 be doing GFP_NOFS allocations all through this writeback path?

Quoted 56 lines · Dave Chinner

Quoted 24 lines · Michal Hocko

Quoted 12 lines · Nikolay Borisov

Today I observed the issue again, this time on a different server. What is particularly strange is the fact that the OOM wasn't triggered for the cgroup, whose tasks have entered D state. There were a couple of SSHD processes and an RSYNC performing some backup tasks. Here is what the stacktrace for the rsync looks like:

crash> set 18308

    PID: 18308
COMMAND: "rsync"
   TASK: ffff883d7c9b0a30  [THREAD_INFO: ffff881773748000]
    CPU: 1
  STATE: TASK_UNINTERRUPTIBLE

Quoted 10 lines

crash> bt
PID: 18308 TASK: ffff883d7c9b0a30 CPU: 1 COMMAND: "rsync"
#0 [ffff88177374ac60] __schedule at ffffffff815ab152 #1 [ffff88177374acb0] schedule at ffffffff815ab76e #2 [ffff88177374acd0] schedule_timeout at ffffffff815ae5e5 #3 [ffff88177374ad70] io_schedule_timeout at ffffffff815aad6a #4 [ffff88177374ada0] bit_wait_io at ffffffff815abfc6 #5 [ffff88177374adb0] __wait_on_bit at ffffffff815abda5 #6 [ffff88177374ae00] wait_on_page_bit at ffffffff8111fd4f #7 [ffff88177374ae50] shrink_page_list at ffffffff81135445

Quoted 2 lines

This is most probably wait_on_page_writeback because the reclaim has encountered a dirty page which is under writeback currently.

Yes, and looks at the caller path....

Quoted 17 lines

Quoted 17 lines

#8 [ffff88177374af50] shrink_inactive_list at ffffffff81135845 #9 [ffff88177374b060] shrink_lruvec at ffffffff81135ead
#10 [ffff88177374b150] shrink_zone at ffffffff811360c3
#11 [ffff88177374b220] shrink_zones at ffffffff81136eff
#12 [ffff88177374b2a0] do_try_to_free_pages at ffffffff8113712f #13 [ffff88177374b300] try_to_free_mem_cgroup_pages at ffffffff811372be #14 [ffff88177374b380] try_charge at ffffffff81189423
#15 [ffff88177374b430] mem_cgroup_try_charge at ffffffff8118c6f5 #16 [ffff88177374b470] __add_to_page_cache_locked at ffffffff8112137d #17 [ffff88177374b4e0] add_to_page_cache_lru at ffffffff81121618 #18 [ffff88177374b510] pagecache_get_page at ffffffff8112170b #19 [ffff88177374b560] grow_dev_page at ffffffff811c8297
#20 [ffff88177374b5c0] __getblk_slow at ffffffff811c91d6
#21 [ffff88177374b600] __getblk_gfp at ffffffff811c92c1
#22 [ffff88177374b630] ext4_ext_grow_indepth at ffffffff8124565c #23 [ffff88177374b690] ext4_ext_create_new_leaf at ffffffff81246ca8 #24 [ffff88177374b6e0] ext4_ext_insert_extent at ffffffff81246f09

Quoted 8 lines

Quoted 8 lines

#25 [ffff88177374b750] ext4_ext_map_blocks at ffffffff8124a848 #26 [ffff88177374b870] ext4_map_blocks at ffffffff8121a5b7 #27 [ffff88177374b910] mpage_map_one_extent at ffffffff8121b1fa #28 [ffff88177374b950] mpage_map_and_submit_extent at ffffffff8121f07b #29 [ffff88177374b9b0] ext4_writepages at ffffffff8121f6d5 #30 [ffff88177374bb20] do_writepages at ffffffff8112c490 #31 [ffff88177374bb30] __filemap_fdatawrite_range at ffffffff81120199 #32 [ffff88177374bb80] filemap_flush at ffffffff8112041c

Quoted 6 lines

That's a potential self deadlocking path, isn't it? i.e. the writeback path has been entered, may hold pages locked in the current bio being built (waiting for submission), then memory reclaim has been entered while trying to map more contiguous blocks to submit, and that waits on page IO to complete on a page in a bio that ext4 hasn't yet submitted?

I am not sure I understand. Pages are marked writeback in ext4_bio_write_page after all of this has been done already and then the IO is submitted and the reclaim shouldn't block it. Or am I missing something?

Quoted 64 lines · Michal Hocko

Quoted 56 lines · Dave Chinner

Quoted 24 lines · Michal Hocko

Quoted 12 lines · Nikolay Borisov

Today I observed the issue again, this time on a different server. What is particularly strange is the fact that the OOM wasn't triggered for the cgroup, whose tasks have entered D state. There were a couple of SSHD processes and an RSYNC performing some backup tasks. Here is what the stacktrace for the rsync looks like:

crash> set 18308

    PID: 18308
COMMAND: "rsync"
   TASK: ffff883d7c9b0a30  [THREAD_INFO: ffff881773748000]
    CPU: 1
  STATE: TASK_UNINTERRUPTIBLE

Quoted 10 lines

crash> bt
PID: 18308 TASK: ffff883d7c9b0a30 CPU: 1 COMMAND: "rsync"
#0 [ffff88177374ac60] __schedule at ffffffff815ab152 #1 [ffff88177374acb0] schedule at ffffffff815ab76e #2 [ffff88177374acd0] schedule_timeout at ffffffff815ae5e5 #3 [ffff88177374ad70] io_schedule_timeout at ffffffff815aad6a #4 [ffff88177374ada0] bit_wait_io at ffffffff815abfc6 #5 [ffff88177374adb0] __wait_on_bit at ffffffff815abda5 #6 [ffff88177374ae00] wait_on_page_bit at ffffffff8111fd4f #7 [ffff88177374ae50] shrink_page_list at ffffffff81135445

Quoted 2 lines

This is most probably wait_on_page_writeback because the reclaim has encountered a dirty page which is under writeback currently.

Yes, and looks at the caller path....

Quoted 17 lines

Quoted 17 lines

#8 [ffff88177374af50] shrink_inactive_list at ffffffff81135845 #9 [ffff88177374b060] shrink_lruvec at ffffffff81135ead
#10 [ffff88177374b150] shrink_zone at ffffffff811360c3
#11 [ffff88177374b220] shrink_zones at ffffffff81136eff
#12 [ffff88177374b2a0] do_try_to_free_pages at ffffffff8113712f #13 [ffff88177374b300] try_to_free_mem_cgroup_pages at ffffffff811372be #14 [ffff88177374b380] try_charge at ffffffff81189423
#15 [ffff88177374b430] mem_cgroup_try_charge at ffffffff8118c6f5 #16 [ffff88177374b470] __add_to_page_cache_locked at ffffffff8112137d #17 [ffff88177374b4e0] add_to_page_cache_lru at ffffffff81121618 #18 [ffff88177374b510] pagecache_get_page at ffffffff8112170b #19 [ffff88177374b560] grow_dev_page at ffffffff811c8297
#20 [ffff88177374b5c0] __getblk_slow at ffffffff811c91d6
#21 [ffff88177374b600] __getblk_gfp at ffffffff811c92c1
#22 [ffff88177374b630] ext4_ext_grow_indepth at ffffffff8124565c #23 [ffff88177374b690] ext4_ext_create_new_leaf at ffffffff81246ca8 #24 [ffff88177374b6e0] ext4_ext_insert_extent at ffffffff81246f09

Quoted 8 lines

Quoted 8 lines

#25 [ffff88177374b750] ext4_ext_map_blocks at ffffffff8124a848 #26 [ffff88177374b870] ext4_map_blocks at ffffffff8121a5b7 #27 [ffff88177374b910] mpage_map_one_extent at ffffffff8121b1fa #28 [ffff88177374b950] mpage_map_and_submit_extent at ffffffff8121f07b #29 [ffff88177374b9b0] ext4_writepages at ffffffff8121f6d5 #30 [ffff88177374bb20] do_writepages at ffffffff8112c490 #31 [ffff88177374bb30] __filemap_fdatawrite_range at ffffffff81120199 #32 [ffff88177374bb80] filemap_flush at ffffffff8112041c

Quoted 6 lines

That's a potential self deadlocking path, isn't it? i.e. the writeback path has been entered, may hold pages locked in the current bio being built (waiting for submission), then memory reclaim has been entered while trying to map more contiguous blocks to submit, and that waits on page IO to complete on a page in a bio that ext4 hasn't yet submitted?

Quoted 4 lines

I am not sure I understand. Pages are marked writeback in ext4_bio_write_page after all of this has been done already and then the IO is submitted and the reclaim shouldn't block it. Or am I missing something?

Thanks to Jan Kara for the off list clarification. I misunderstood the code. You are right ext4 is really deadlock prone. The heuristic in the reclaim code assumes that waiting on page_writeback is guaranteed to make a progress (from memcg POV) and that is not true for ext4 as it

really charge after set_page_writeback (called from ext4_bio_write_page) and before the page is really submitted (when the bio is full or explicitly via ext4_io_submit). I thought that io_submit_add_bh submits the page but it doesn't do that necessarily.

*blink*

/me re-reads again

That assumption is fundamentally broken. Filesystems use GFP_NOFS because the filesystem holds resources that can prevent memory reclaim making forwards progress if it re-enters the filesystem or blocks on anything filesystem related. memcg does not change that, and I'm kinda scared to learn that memcg plays fast and loose like this.

For example: IO completion might require unwritten extent conversion which executes filesystem transactions and GFP_NOFS allocations. The writeback flag on the pages can not be cleared until unwritten extent conversion completes. Hence memory reclaim cannot wait on page writeback to complete in GFP_NOFS context because it is not safe to do so, memcg reclaim or otherwise.

Quoted 4 lines

really charge after set_page_writeback (called from ext4_bio_write_page) and before the page is really submitted (when the bio is full or explicitly via ext4_io_submit). I thought that io_submit_add_bh submits the page but it doesn't do that necessarily.

XFS does exactly the same thing - the underlying alogrithm ext4 uses to build large bios efficiently was copied from XFS. And FWIW XFS has been using this algorithm since 2.6.15....

On Wed 01-07-15 08:58:51, Dave Chinner wrote:
[...]

Quoted 11 lines

*blink*

/me re-reads again

That assumption is fundamentally broken. Filesystems use GFP_NOFS because the filesystem holds resources that can prevent memory reclaim making forwards progress if it re-enters the filesystem or blocks on anything filesystem related. memcg does not change that, and I'm kinda scared to learn that memcg plays fast and loose like this.

Quoted 6 lines

For example: IO completion might require unwritten extent conversion which executes filesystem transactions and GFP_NOFS allocations. The writeback flag on the pages can not be cleared until unwritten extent conversion completes. Hence memory reclaim cannot wait on page writeback to complete in GFP_NOFS context because it is not safe to do so, memcg reclaim or otherwise.

Thanks for the clarification.

Perhaps we need to make the documentation a bit more explicit? All which is stated in include/slab.h:

* %GFP_NOIO - Do not do any I/O at all while trying to get memory. *
* %GFP_NOFS - Do not make any fs calls while trying to get memory.

I thought this was obvious, but these flags are used by code which in the I/O or FS paths, and so it's always possible that they are trying to write back the page which you decide to blocking on when trying to do the memory allocation, at which point, *boom*, deadlock.

So it's just not "do not make any FS or I/O calls", but also "the mm layer must not not wait for any FS or I/O operations from completing, since the operation you block on might be the one they were in the middle of trying to complete --- or they may be holding a lock at the time when they were trying to do a memory allocation which blocks the I/O or FS operation from completing".