Skip to contentSkip to conversation

livelock when run out of swap space

livelock, 3.13.0 Dave Chinner 2 participants 2 messages Feb 2, 2014 – Feb 3, 2014 Memory management

lore
Share & tools
lore
#0 lore raw

Hi folks,

I just had a test machine livelock when running a concurrent rm -rf workload on an XFS filesystem with 64k directory block sizes. The buffer allocation code started reporting this 5 times a second:

XFS: possible memory allocation deadlock in kmem_alloc (mode:0x8250)

Which is in GFP_NOFS|GFP_ZERO context. It is likely to have been a high order allocation (up to 64k), but there was still lenty of free memory available (2.8GB of 16GB):

$ free
             total       used       free     shared    buffers     cached
Mem:      16424296   13593732    2830564          0        136       3184
-/+ buffers/cache:   13590412    2833884
Swap:       497976     497976          0
$

But clearly there was no page cache being used. All of the memory in use was in the inode/dentry caches:

OBJS ACTIVE USE OBJ SIZE SLABS OBJ/SLAB CACHE SIZE NAME

  9486678 9483271  99%    1.19K 364874       26  11675968K xfs_inode
  4820508 4820508 100%    0.21K 130284       37   1042272K dentry
  4820224 4820224 100%    0.06K  75316       64    301264K kmalloc-64

The issue is that memory allocation was not making progress - the shrinkers we not doing anything because they were under GFP_NOFS allocation context, and kswapd was never woken to take over. The system was compeltely out of swap space, and all the CPU was being burnt in this function:

44.91% [kernel] [k] scan_swap_map

The typical stack trace of a looping memory allocation is this:

[211699.924006] CPU: 2 PID: 21939 Comm: rm Not tainted 3.13.0-dgc+ #172
[211699.924006] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
[211699.924006] task: ffff88041a7dde40 ti: ffff8803bbeec000 task.ti: ffff8803bbeec000
[211699.924006] RIP: 0010:[<ffffffff81187dd8>]  [<ffffffff81187dd8>] scan_swap_map+0x118/0x520
[211699.924006] RSP: 0018:ffff8803bbeed508  EFLAGS: 00000297
[211699.924006] RAX: 000000000000a1ba RBX: 0000000000000032 RCX: 0000000000000000
[211699.924006] RDX: 0000000000000001 RSI: 000000000001e64e RDI: 0000000000019def
[211699.924006] RBP: ffff8803bbeed558 R08: 00000000002c6ba0 R09: 0000000000000000
[211699.924006] R10: 57ffb90ace3d4f80 R11: 0000000000019def R12: ffff88041a682900
[211699.924006] R13: 01ffffffffffffff R14: 0000000000000040 R15: ffff88041a6829a0
[211699.924006] FS:  00007fae682c8700(0000) GS:ffff88031bc00000(0000) knlGS:0000000000000000
[211699.924006] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[211699.924006] CR2: 00000000004353b0 CR3: 00000002ea498000 CR4: 00000000000006e0
[211699.924006] Stack:
[211699.924006]  ffff8803bbeed538 ffff88031a9dc720 000000000000a1ba 0000000000004893
[211699.924006]  0000000000000000 ffff88041a682900 0000000000000000 0000000000000001
[211699.924006]  0000000000000000 ffff88041a6829a0 ffff8803bbeed598 ffffffff8118837f
[211699.924006] Call Trace:
[211699.924006]  [<ffffffff8118837f>] get_swap_page+0xef/0x1e0
[211699.924006]  [<ffffffff81184e34>] add_to_swap+0x24/0x70
[211699.924006]  [<ffffffff8115f110>] shrink_page_list+0x300/0xa20
[211699.924006]  [<ffffffff81169089>] ? __mod_zone_page_state+0x49/0x50
[211699.924006]  [<ffffffff8116a3b9>] ? wait_iff_congested+0xa9/0x150
[211699.924006]  [<ffffffff8115fe03>] shrink_inactive_list+0x243/0x480
[211699.924006]  [<ffffffff811606f1>] shrink_lruvec+0x371/0x670
[211699.924006]  [<ffffffff81cdb4ce>] ? _raw_spin_unlock+0xe/0x10
[211699.924006]  [<ffffffff81160dea>] do_try_to_free_pages+0x11a/0x360
[211699.924006]  [<ffffffff81161220>] try_to_free_pages+0x110/0x190
[211699.924006]  [<ffffffff81156422>] __alloc_pages_nodemask+0x5a2/0x8a0
[211699.924006]  [<ffffffff8118fac2>] alloc_pages_current+0xb2/0x170
[211699.924006]  [<ffffffff81151bde>] __get_free_pages+0xe/0x50
[211699.924006]  [<ffffffff8116d199>] kmalloc_order_trace+0x39/0xb0
[211699.924006]  [<ffffffff810cf4c3>] ? finish_wait+0x63/0x80
[211699.924006]  [<ffffffff81197156>] __kmalloc+0x176/0x180
[211699.924006]  [<ffffffff810cf520>] ? __init_waitqueue_head+0x40/0x40
[211699.924006]  [<ffffffff814a74f7>] kmem_alloc+0x77/0xf0
[211699.924006]  [<ffffffff814feb54>] xfs_log_commit_cil+0x3c4/0x5a0
[211699.924006]  [<ffffffff814a6be3>] xfs_trans_commit+0xc3/0x2d0
[211699.924006]  [<ffffffff814e913e>] xfs_remove+0x3be/0x440
[211699.924006]  [<ffffffff811b7d8d>] ? __d_lookup+0x11d/0x170
[211699.924006]  [<ffffffff8149b842>] xfs_vn_unlink+0x52/0xa0
[211699.924006]  [<ffffffff811acc22>] vfs_unlink+0xf2/0x160
[211699.924006]  [<ffffffff811acef0>] do_unlinkat+0x260/0x2a0
[211699.924006]  [<ffffffff811b003b>] SyS_unlinkat+0x1b/0x40
[211699.924006]  [<ffffffff81ce3ea9>] system_call_fastpath+0x16/0x1b

i.e. trying to do memory allocation during a transaction commit in XFS, and that is looping in kmem_alloc().

THe problem in this case is that kswapd was not being started to free slab cache memory (i.e. to handle the defered GFP_NOFS slab reclaim). It stayed in the livelock state for over an hour before I broke it by running "echo 2 > /proc/sys/vm/drop_caches" manually. That immediately freed up the slab cache as reclaim was not under GFP_NOFS constraints and the livelock went away and the system started to make progress again.

I haven't seen this problem before, so this may be a regression...

Cheers,

Dave.

Signature · 8 lines
Dave Chinner
[email protected]

--
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>
#1 lore raw
Quoted 94 lines · Dave Chinner

Hi folks,

I just had a test machine livelock when running a concurrent rm -rf workload on an XFS filesystem with 64k directory block sizes. The buffer allocation code started reporting this 5 times a second:

XFS: possible memory allocation deadlock in kmem_alloc (mode:0x8250)

Which is in GFP_NOFS|GFP_ZERO context. It is likely to have been a high order allocation (up to 64k), but there was still lenty of free memory available (2.8GB of 16GB):

$ free
             total       used       free     shared    buffers     cached
Mem:      16424296   13593732    2830564          0        136       3184
-/+ buffers/cache:   13590412    2833884
Swap:       497976     497976          0
$

But clearly there was no page cache being used. All of the memory in use was in the inode/dentry caches:

OBJS ACTIVE USE OBJ SIZE SLABS OBJ/SLAB CACHE SIZE NAME

  9486678 9483271  99%    1.19K 364874       26  11675968K xfs_inode
  4820508 4820508 100%    0.21K 130284       37   1042272K dentry
  4820224 4820224 100%    0.06K  75316       64    301264K kmalloc-64

The issue is that memory allocation was not making progress - the shrinkers we not doing anything because they were under GFP_NOFS allocation context, and kswapd was never woken to take over. The system was compeltely out of swap space, and all the CPU was being burnt in this function:

   44.91%  [kernel]  [k] scan_swap_map

The typical stack trace of a looping memory allocation is this:

[211699.924006] CPU: 2 PID: 21939 Comm: rm Not tainted 3.13.0-dgc+ #172
[211699.924006] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
[211699.924006] task: ffff88041a7dde40 ti: ffff8803bbeec000 task.ti: ffff8803bbeec000
[211699.924006] RIP: 0010:[<ffffffff81187dd8>]  [<ffffffff81187dd8>] scan_swap_map+0x118/0x520
[211699.924006] RSP: 0018:ffff8803bbeed508  EFLAGS: 00000297
[211699.924006] RAX: 000000000000a1ba RBX: 0000000000000032 RCX: 0000000000000000
[211699.924006] RDX: 0000000000000001 RSI: 000000000001e64e RDI: 0000000000019def
[211699.924006] RBP: ffff8803bbeed558 R08: 00000000002c6ba0 R09: 0000000000000000
[211699.924006] R10: 57ffb90ace3d4f80 R11: 0000000000019def R12: ffff88041a682900
[211699.924006] R13: 01ffffffffffffff R14: 0000000000000040 R15: ffff88041a6829a0
[211699.924006] FS:  00007fae682c8700(0000) GS:ffff88031bc00000(0000) knlGS:0000000000000000
[211699.924006] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[211699.924006] CR2: 00000000004353b0 CR3: 00000002ea498000 CR4: 00000000000006e0
[211699.924006] Stack:
[211699.924006]  ffff8803bbeed538 ffff88031a9dc720 000000000000a1ba 0000000000004893
[211699.924006]  0000000000000000 ffff88041a682900 0000000000000000 0000000000000001
[211699.924006]  0000000000000000 ffff88041a6829a0 ffff8803bbeed598 ffffffff8118837f
[211699.924006] Call Trace:
[211699.924006]  [<ffffffff8118837f>] get_swap_page+0xef/0x1e0
[211699.924006]  [<ffffffff81184e34>] add_to_swap+0x24/0x70
[211699.924006]  [<ffffffff8115f110>] shrink_page_list+0x300/0xa20
[211699.924006]  [<ffffffff81169089>] ? __mod_zone_page_state+0x49/0x50
[211699.924006]  [<ffffffff8116a3b9>] ? wait_iff_congested+0xa9/0x150
[211699.924006]  [<ffffffff8115fe03>] shrink_inactive_list+0x243/0x480
[211699.924006]  [<ffffffff811606f1>] shrink_lruvec+0x371/0x670
[211699.924006]  [<ffffffff81cdb4ce>] ? _raw_spin_unlock+0xe/0x10
[211699.924006]  [<ffffffff81160dea>] do_try_to_free_pages+0x11a/0x360
[211699.924006]  [<ffffffff81161220>] try_to_free_pages+0x110/0x190
[211699.924006]  [<ffffffff81156422>] __alloc_pages_nodemask+0x5a2/0x8a0
[211699.924006]  [<ffffffff8118fac2>] alloc_pages_current+0xb2/0x170
[211699.924006]  [<ffffffff81151bde>] __get_free_pages+0xe/0x50
[211699.924006]  [<ffffffff8116d199>] kmalloc_order_trace+0x39/0xb0
[211699.924006]  [<ffffffff810cf4c3>] ? finish_wait+0x63/0x80
[211699.924006]  [<ffffffff81197156>] __kmalloc+0x176/0x180
[211699.924006]  [<ffffffff810cf520>] ? __init_waitqueue_head+0x40/0x40
[211699.924006]  [<ffffffff814a74f7>] kmem_alloc+0x77/0xf0
[211699.924006]  [<ffffffff814feb54>] xfs_log_commit_cil+0x3c4/0x5a0
[211699.924006]  [<ffffffff814a6be3>] xfs_trans_commit+0xc3/0x2d0
[211699.924006]  [<ffffffff814e913e>] xfs_remove+0x3be/0x440
[211699.924006]  [<ffffffff811b7d8d>] ? __d_lookup+0x11d/0x170
[211699.924006]  [<ffffffff8149b842>] xfs_vn_unlink+0x52/0xa0
[211699.924006]  [<ffffffff811acc22>] vfs_unlink+0xf2/0x160
[211699.924006]  [<ffffffff811acef0>] do_unlinkat+0x260/0x2a0
[211699.924006]  [<ffffffff811b003b>] SyS_unlinkat+0x1b/0x40
[211699.924006]  [<ffffffff81ce3ea9>] system_call_fastpath+0x16/0x1b

i.e. trying to do memory allocation during a transaction commit in XFS, and that is looping in kmem_alloc().

THe problem in this case is that kswapd was not being started to free slab cache memory (i.e. to handle the defered GFP_NOFS slab reclaim). It stayed in the livelock state for over an hour before I broke it by running "echo 2 > /proc/sys/vm/drop_caches" manually. That immediately freed up the slab cache as reclaim was not under GFP_NOFS constraints and the livelock went away and the system started to make progress again.

Quoted 1 line

I haven't seen this problem before, so this may be a regression...

This could well be what Jamie Liu just fixed in 3.14-rc1 a5998061daab "mm/swapfile.c: do not skip lowest_bit in scan_swap_map() scan loop".

He found it on a 3.3-based system, but it was my mistake in 2.6.29. Funny if you are finding it independently just now, but sometimes things do work out like that. Most of the time we're saved by pages duplicated between swap and cache, or background stuff going on, but a load can end up here in scan_swap_map() knowing there's a free slot but forever missing it.

I thought we'd tagged that commit for stable, but apparently not:
if you're able to reproduce your livelock, and then find this patch fixes it (or even if you just agree that it looks like a good fit for what you saw), please do ask for it to be added to stable.

Hugh

--
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>