Re: Possible deadlock in v4.14.15 contention on shrinker_rwsem in shrink_slab()
From: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
Date: 2018-02-03 07:48:36
Michal, what do you think? If no comment, let's try page_owner + SystemTap and check whether there are some characteristics with stalling pages. Tetsuo Handa wrote:
Eric Wheeler wrote:quoted
I just tried v4.9.78 and we still get the deadlock. I've backported your MemAlloc timing patch and yout timing is included in the output. Both full sysrq traces (30 seconds apart) are available here and I made sure it includes both "Showing busy workqueues and worker pools" sections: https://www.linuxglobal.com/static/2018-01-27-hv1-deadlock-v4.9.78 # ps -eo pid,lstart,cmd,stat |grep D PID STARTED CMD STAT 16127 Sat Jan 27 05:24:29 2018 crm_node -N 2 D << Both in D state 22444 Sat Jan 27 05:39:50 2018 rsync --server --sender -vl DNs << Both in D stateThank you. Although the capture is still incomplete, I noticed that there was a surprising entry. crm_node was stalling at page fault for 33950 seconds! That is, crm_node already started stalling at uptime = 45375. ---------- [79325.124062] MemAlloc: crm_node(16127) flags=0xc00900 switches=10 seq=441 gfp=0x24200ca(GFP_HIGHUSER_MOVABLE) order=0 delay=33950065 uninterruptible [79325.125113] ffff8cf6d750dd00 0000000000000000 ffff8cf74b9d5800 ffff8cf76fd19940 [79325.125684] ffff8cf6c3d84200 ffffada2a17af6c8 ffffffff8e7178f5 0000000000000000 [79325.126245] 0000000000000000 0000000000000000 ffff8cf6c3d84200 7fffffffffffffff [79325.126800] Call Trace: [79325.127339] [<ffffffff8e7178f5>] ? __schedule+0x195/0x630 [79325.127985] [<ffffffff8e718630>] ? bit_wait+0x50/0x50 [79325.128519] [<ffffffff8e717dc6>] schedule+0x36/0x80 [79325.129040] [<ffffffff8e71afa6>] schedule_timeout+0x1e6/0x320 [79325.129560] [<ffffffff8e718630>] ? bit_wait+0x50/0x50 [79325.130100] [<ffffffff8e7176f6>] io_schedule_timeout+0xa6/0x110 [79325.130683] [<ffffffff8e71864b>] bit_wait_io+0x1b/0x60 [79325.131199] [<ffffffff8e718286>] __wait_on_bit_lock+0x86/0xd0 [79325.131723] [<ffffffff8e1acb22>] __lock_page+0x82/0xb0 [79325.132238] [<ffffffff8e0e9e00>] ? autoremove_wake_function+0x40/0x40 [79325.132765] [<ffffffff8e1ae63b>] pagecache_get_page+0x16b/0x230 [79325.133284] [<ffffffff8e1ca3da>] shmem_unused_huge_shrink+0x28a/0x330 [79325.133814] [<ffffffff8e1ca4a7>] shmem_unused_huge_scan+0x27/0x30 [79325.134338] [<ffffffff8e23f941>] super_cache_scan+0x181/0x190 [79325.134875] [<ffffffff8e1c1ab1>] shrink_slab+0x261/0x470 [79325.135386] [<ffffffff8e1c6588>] shrink_node+0x108/0x310 [79325.135904] [<ffffffff8e1c6927>] node_reclaim+0x197/0x210 [79325.136458] [<ffffffff8e1b5dd8>] get_page_from_freelist+0x168/0x9f0 [79325.137023] [<ffffffff8e1adc8e>] ? find_get_entry+0x1e/0x100 [79325.137560] [<ffffffff8e1ca9c5>] ? shmem_getpage_gfp+0xf5/0xbb0 [79325.138061] [<ffffffff8e1b77ae>] __alloc_pages_nodemask+0x10e/0x2d0 [79325.138619] [<ffffffff8e207d08>] alloc_pages_current+0x88/0x120 [79325.139117] [<ffffffff8e070287>] pte_alloc_one+0x17/0x40 [79325.139626] [<ffffffff8e1e117e>] __pte_alloc+0x1e/0x100 [79325.140138] [<ffffffff8e1e3622>] alloc_set_pte+0x4f2/0x560 [79325.140698] [<ffffffff8e1e3770>] do_fault+0xe0/0x620 [79325.141168] [<ffffffff8e1e5504>] handle_mm_fault+0x644/0xdd0 [79325.141667] [<ffffffff8e06a96e>] __do_page_fault+0x25e/0x4f0 [79325.142163] [<ffffffff8e06ac30>] do_page_fault+0x30/0x80 [79325.142660] [<ffffffff8e003b55>] ? do_syscall_64+0x175/0x180 [79325.143132] [<ffffffff8e71dae8>] page_fault+0x28/0x30 ---------- You took SysRq-t after multiple processes (in this case, crm_node and rsync) got stuck, didn't you? I feel anxious about LIST_POISON1 (dead000000000100) and LIST_POISON2 (dead000000000200) are showing up at rsync side. ---------- [79325.156361] rsync D 0 22444 22441 0x00000080 [79325.156871] ffff8cf3b8437440 0000000000000000 ffff8cf74b9d1600 ffff8cf76fc59940 [79325.157307] ffff8cf3eef74200 ffffada2a0e17b18 ffffffff8e7178f5 dead000000000100 [79325.157764] dead000000000200 ffff8cf6db9101a8 ffff8cf3eef74200 7fffffffffffffff [79325.158225] Call Trace: [79325.158690] [<ffffffff8e7178f5>] ? __schedule+0x195/0x630 [79325.159142] [<ffffffff8e718630>] ? bit_wait+0x50/0x50 [79325.159604] [<ffffffff8e717dc6>] schedule+0x36/0x80 [79325.160053] [<ffffffff8e71afa6>] schedule_timeout+0x1e6/0x320 [79325.160536] [<ffffffff8e0de21c>] ? enqueue_entity+0x3bc/0x570 [79325.160984] [<ffffffff8e11bf5b>] ? ktime_get+0x3b/0xb0 [79325.161450] [<ffffffff8e718630>] ? bit_wait+0x50/0x50 [79325.161891] [<ffffffff8e7176f6>] io_schedule_timeout+0xa6/0x110 [79325.162337] [<ffffffff8e71864b>] bit_wait_io+0x1b/0x60 [79325.162787] [<ffffffff8e718286>] __wait_on_bit_lock+0x86/0xd0 [79325.163231] [<ffffffff8e1acb22>] __lock_page+0x82/0xb0 [79325.163681] [<ffffffff8e0e9e00>] ? autoremove_wake_function+0x40/0x40 [79325.164133] [<ffffffff8e1addd1>] find_lock_entry+0x61/0x80 [79325.164597] [<ffffffff8e1ca9c5>] shmem_getpage_gfp+0xf5/0xbb0 [79325.165053] [<ffffffff8e1cb9b9>] shmem_file_read_iter+0x159/0x310 [79325.165516] [<ffffffff8e23b2ff>] __vfs_read+0xdf/0x130 [79325.165966] [<ffffffff8e23ba2c>] vfs_read+0x8c/0x130 [79325.166430] [<ffffffff8e23cf95>] SyS_read+0x55/0xc0 [79325.166865] [<ffffffff8e003a47>] do_syscall_64+0x67/0x180 [79325.167292] [<ffffffff8e71c530>] entry_SYSCALL64_slow_path+0x25/0x25 ----------quoted
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. crm_node D 0 16127 16126 0x00000080 MemAlloc: crm_node(16127) flags=0xc00900 switches=10 seq=441 gfp=0x24200ca(GFP_HIGHUSER_MOVABLE) order=0 delay=209469 uninterruptibleAt this point, crm_node already stalled for 209 seconds. Since switches= and seq= did not change until you took SysRq-t, crm_node kept sleeping.quoted
ffff8cf6d750dd00 0000000000000000 ffff8cf74b9d5800 ffff8cf76fd19940 ffff8cf6c3d84200 ffffada2a17af6c8 ffffffff8e7178f5 0000000000000000 0000000000000000 0000000000000000 ffff8cf6c3d84200 7fffffffffffffff Call Trace: [<ffffffff8e7178f5>] ? __schedule+0x195/0x630 [<ffffffff8e718630>] ? bit_wait+0x50/0x50 [<ffffffff8e717dc6>] schedule+0x36/0x80 [<ffffffff8e71afa6>] schedule_timeout+0x1e6/0x320 [<ffffffff8e718630>] ? bit_wait+0x50/0x50 [<ffffffff8e7176f6>] io_schedule_timeout+0xa6/0x110 [<ffffffff8e71864b>] bit_wait_io+0x1b/0x60 [<ffffffff8e718286>] __wait_on_bit_lock+0x86/0xd0 [<ffffffff8e1acb22>] __lock_page+0x82/0xb0 [<ffffffff8e0e9e00>] ? autoremove_wake_function+0x40/0x40 [<ffffffff8e1ae63b>] pagecache_get_page+0x16b/0x230 [<ffffffff8e1ca3da>] shmem_unused_huge_shrink+0x28a/0x330 [<ffffffff8e1ca4a7>] shmem_unused_huge_scan+0x27/0x30 [<ffffffff8e23f941>] super_cache_scan+0x181/0x190 [<ffffffff8e1c1ab1>] shrink_slab+0x261/0x470 [<ffffffff8e1c6588>] shrink_node+0x108/0x310 [<ffffffff8e1c6927>] node_reclaim+0x197/0x210 [<ffffffff8e1b5dd8>] get_page_from_freelist+0x168/0x9f0 [<ffffffff8e1adc8e>] ? find_get_entry+0x1e/0x100 [<ffffffff8e1ca9c5>] ? shmem_getpage_gfp+0xf5/0xbb0 [<ffffffff8e1b77ae>] __alloc_pages_nodemask+0x10e/0x2d0 [<ffffffff8e207d08>] alloc_pages_current+0x88/0x120 [<ffffffff8e070287>] pte_alloc_one+0x17/0x40 [<ffffffff8e1e117e>] __pte_alloc+0x1e/0x100 [<ffffffff8e1e3622>] alloc_set_pte+0x4f2/0x560 [<ffffffff8e1e3770>] do_fault+0xe0/0x620 [<ffffffff8e1e5504>] handle_mm_fault+0x644/0xdd0 [<ffffffff8e06a96e>] __do_page_fault+0x25e/0x4f0 [<ffffffff8e06ac30>] do_page_fault+0x30/0x80 [<ffffffff8e003b55>] ? do_syscall_64+0x175/0x180 [<ffffffff8e71dae8>] page_fault+0x28/0x30 Pid 22444 didn't show up in the hung_task warning like crm_node did, but its /proc/pid/stack looks like so: ~]# cat /proc/22444/stack [<ffffffff8e1acb22>] __lock_page+0x82/0xb0 [<ffffffff8e1addd1>] find_lock_entry+0x61/0x80 [<ffffffff8e1ca9c5>] shmem_getpage_gfp+0xf5/0xbb0 [<ffffffff8e1cb9b9>] shmem_file_read_iter+0x159/0x310 [<ffffffff8e23b2ff>] __vfs_read+0xdf/0x130 [<ffffffff8e23ba2c>] vfs_read+0x8c/0x130 [<ffffffff8e23cf95>] SyS_read+0x55/0xc0 [<ffffffff8e003a47>] do_syscall_64+0x67/0x180 [<ffffffff8e71c530>] entry_SYSCALL64_slow_path+0x25/0x25 [<ffffffffffffffff>] 0xffffffffffffffffI guess that /proc/sys/kernel/hung_task_warnings already became 0. Since the default value of /proc/sys/kernel/hung_task_warnings is 10, only first 10 warnings are shown. You can set -1 to /proc/sys/kernel/hung_task_warnings so that all hung_task warnings are shown.quoted
==================== 4.14.15 ==================== On the other server running 4.14.15 the stacks look the same as you've seen before. Both full sysrq traces (30 seconds apart) are available here and I made sure it includes both "Showing busy workqueues and worker pools" sections: https://www.linuxglobal.com/static/2018-01-28-hv2-deadlock-v4.14.15 ~]# ps -eo pid,lstart,cmd,stat |grep D PID STARTED CMD STAT 27163 Sat Jan 27 05:15:48 2018 crm_node -N 2 D 1125 Sat Jan 27 14:34:40 2018 /usr/sbin/libvirtd Dcrm_node was stalling at page fault for 119634 seconds (more than one day)! ---------- crm_node D 0 27163 1 0x00000084 MemAlloc: crm_node(27163) flags=0xc00900 switches=3 seq=438 gfp=0x14200ca(GFP_HIGHUSER_MOVABLE) order=0 delay=119634513 uninterruptible Call Trace: ? __schedule+0x1dc/0x770 schedule+0x32/0x80 io_schedule+0x12/0x40 __lock_page+0x105/0x150 ? page_cache_tree_insert+0xb0/0xb0 pagecache_get_page+0x161/0x210 shmem_unused_huge_shrink+0x334/0x3f0 super_cache_scan+0x176/0x180 shrink_slab+0x275/0x460 shrink_node+0x10e/0x320 node_reclaim+0x19d/0x250 get_page_from_freelist+0x16a/0xac0 ? radix_tree_lookup_slot+0x1e/0x50 ? find_lock_entry+0x45/0x80 ? shmem_getpage_gfp.isra.34+0xe5/0xc80 __alloc_pages_nodemask+0x111/0x2c0 pte_alloc_one+0x13/0x40 __pte_alloc+0x19/0x100 alloc_set_pte+0x468/0x4c0 finish_fault+0x3a/0x70 __handle_mm_fault+0x94a/0x1190 handle_mm_fault+0xf2/0x210 __do_page_fault+0x253/0x4d0 do_page_fault+0x33/0x120 ? page_fault+0x36/0x60 page_fault+0x4c/0x60 crm_node D 0 27163 1 0x00000084 MemAlloc: crm_node(27163) flags=0xc00900 switches=3 seq=438 gfp=0x14200ca(GFP_HIGHUSER_MOVABLE) order=0 delay=119682540 uninterruptible Call Trace: ? __schedule+0x1dc/0x770 schedule+0x32/0x80 io_schedule+0x12/0x40 __lock_page+0x105/0x150 ? page_cache_tree_insert+0xb0/0xb0 pagecache_get_page+0x161/0x210 shmem_unused_huge_shrink+0x334/0x3f0 super_cache_scan+0x176/0x180 shrink_slab+0x275/0x460 shrink_node+0x10e/0x320 node_reclaim+0x19d/0x250 get_page_from_freelist+0x16a/0xac0 ? radix_tree_lookup_slot+0x1e/0x50 ? find_lock_entry+0x45/0x80 ? shmem_getpage_gfp.isra.34+0xe5/0xc80 __alloc_pages_nodemask+0x111/0x2c0 pte_alloc_one+0x13/0x40 __pte_alloc+0x19/0x100 alloc_set_pte+0x468/0x4c0 finish_fault+0x3a/0x70 __handle_mm_fault+0x94a/0x1190 handle_mm_fault+0xf2/0x210 __do_page_fault+0x253/0x4d0 do_page_fault+0x33/0x120 ? page_fault+0x36/0x60 page_fault+0x4c/0x60 ---------- And since switches= and seq= did not change, crm_node kept sleeping. libvirtd remained stuck waiting for crm_node. But something already went wrong more than one day ago. ---------- libvirtd D 0 1125 1 0x00000080 Call Trace: ? __schedule+0x1dc/0x770 schedule+0x32/0x80 rwsem_down_write_failed+0x20d/0x380 ? ida_get_new_above+0x110/0x3b0 call_rwsem_down_write_failed+0x13/0x20 down_write+0x29/0x40 register_shrinker+0x45/0xa0 sget_userns+0x468/0x4a0 ? get_anon_bdev+0x100/0x100 ? shmem_create+0x20/0x20 mount_nodev+0x2a/0xa0 mount_fs+0x34/0x150 vfs_kern_mount+0x62/0x120 do_mount+0x1ee/0xc50 SyS_mount+0x7e/0xd0 do_syscall_64+0x61/0x1a0 entry_SYSCALL64_slow_path+0x25/0x25 ----------quoted
I'm not sure if this is relevant, but the load average is wrong on the 4.14.15 machine: load average: 1308.46, 1246.69, 1078.29 There is no way those numbers are correct, top shows nothing spinning and vmstat only shows 1-4 processes in a running or blocked state.If I recall correctly, insanely growing load average is a possible sign of processes getting stuck one by one as one is created (by e.g. crond).quoted
Here are the pid stacks in D states from ps above: ~]# cat /proc/27163/stack [<ffffffff900cd0d2>] io_schedule+0x12/0x40 [<ffffffff901b4735>] __lock_page+0x105/0x150 [<ffffffff901b4e61>] pagecache_get_page+0x161/0x210 [<ffffffff901d4c74>] shmem_unused_huge_shrink+0x334/0x3f0 [<ffffffff90251746>] super_cache_scan+0x176/0x180 [<ffffffff901cb885>] shrink_slab+0x275/0x460 [<ffffffff901d0d4e>] shrink_node+0x10e/0x320 [<ffffffff901d10fd>] node_reclaim+0x19d/0x250 [<ffffffff901be1ca>] get_page_from_freelist+0x16a/0xac0 [<ffffffff901bef81>] __alloc_pages_nodemask+0x111/0x2c0 [<ffffffff9006dbc3>] pte_alloc_one+0x13/0x40 [<ffffffff901ef4e9>] __pte_alloc+0x19/0x100 [<ffffffff901f1978>] alloc_set_pte+0x468/0x4c0 [<ffffffff901f1a0a>] finish_fault+0x3a/0x70 [<ffffffff901f385a>] __handle_mm_fault+0x94a/0x1190 [<ffffffff901f4192>] handle_mm_fault+0xf2/0x210 [<ffffffff900682a3>] __do_page_fault+0x253/0x4d0 [<ffffffff90068553>] do_page_fault+0x33/0x120 [<ffffffff908019dc>] page_fault+0x4c/0x60 [<ffffffffffffffff>] 0xffffffffffffffff ~]# cat /proc/1125/stack [<ffffffff907538d3>] call_rwsem_down_write_failed+0x13/0x20 [<ffffffff901cbb45>] register_shrinker+0x45/0xa0 [<ffffffff90251168>] sget_userns+0x468/0x4a0 [<ffffffff9025126a>] mount_nodev+0x2a/0xa0 [<ffffffff90251de4>] mount_fs+0x34/0x150 [<ffffffff902703f2>] vfs_kern_mount+0x62/0x120 [<ffffffff90272c0e>] do_mount+0x1ee/0xc50 [<ffffffff9027397e>] SyS_mount+0x7e/0xd0 [<ffffffff90003831>] do_syscall_64+0x61/0x1a0 [<ffffffff9080012c>] entry_SYSCALL64_slow_path+0x25/0x25 [<ffffffffffffffff>] 0xffffffffffffffffquoted
quoted
If you have any ideas on creating an easy way to reproduce the problem, then I can bisect---but bisecting one day at a time will take a long time, and could be prone to bugs which I would like to avoid on this production system.Thinking from SysRq-t output, I feel that some disk read is stuck.Possibly. I would not expect a hardware problem since we see this on two different systems with different kernel versions.quoted
Since rsyslogd failed to catch portion of SysRq-t output, I can't confirm whether register_shrinker() was in progress (nor all kernel worker threads were reported).As linked above, I was able to get the full trace with netconsole.quoted
But what I was surprised is number of kernel worker threads. "grep ^kworker/ | sort" matched 314 threads and "grep ^kworker/0:" matched 244.We have many DRBD volumes and LVM volumes, most of which are dm-thin, so that might be why. Also these servers have both scsi-mq and dm-mq enabled.Ideally you could reproduce without DRBD, LVM, bcache etc. , for Marc MERLIN's report ( http://lkml.kernel.org/r/20170502041235.zqmywvj5tiiom3jk@merlins.org ) was using (at least) bcache. It might be a bug which fails to submit I/O request.quoted
quoted
One of workqueue threads was waiting at ---------- static void *new_read(struct dm_bufio_client *c, sector_t block, enum new_flag nf, struct dm_buffer **bp) { int need_submit; struct dm_buffer *b; LIST_HEAD(write_list); dm_bufio_lock(c); b = __bufio_new(c, block, nf, &need_submit, &write_list); #ifdef CONFIG_DM_DEBUG_BLOCK_STACK_TRACING if (b && b->hold_count == 1) buffer_record_stack(b); #endif dm_bufio_unlock(c); __flush_write_list(&write_list); if (!b) return NULL; if (need_submit) submit_io(b, READ, read_endio); wait_on_bit_io(&b->state, B_READING, TASK_UNINTERRUPTIBLE); // <= here if (b->read_error) { int error = blk_status_to_errno(b->read_error); dm_bufio_release(b); return ERR_PTR(error); } *bp = b; return b->data; } ---------- but what are possible reasons? Does this request depend on workqueue availability?We are using dm-thin which uses dm-bufio. The dm-thin pools are working properly, so I don't think this is the problem---or at least if it is the problem, it isn't affecting the thin pool.Some suggestions: You can enlarge kernel printk() buffer size using log_buf_len= kernel command line parameter. As your system is large, you could allocate e.g. log_buf_len=67108864 . Then, you can read kernel buffer using dmesg command (e.g. /usr/bin/dmesg ). You can add timestamp to printk() messages by doing below command. ---------- # echo Y > /sys/module/printk/parameters/time ---------- Since crm_node starts stalling rather early, you can watch out for kernel messages and userspace messages which were printed around crm_node started stalling, for there might be some events (e.g. error recovery) occurring. I'm not sure but maybe page_owner gives us some clue. (Michal, what do you think?) You can compile your kernel with CONFIG_PAGE_OWNER=y and boot your kernel with page_owner=on kernel command line option added. But that alone does not tell on which "struct page *" processes got stuck. We will need to call dump_page() for reporting specific "struct page *". One of approaches would be to run a SystemTap script shown below (in background using -F option) and check how stalling pages has been allocated. There might be some characteristics with stalling pages. ---------- # stap -DSTP_NO_OVERLOAD=1 -F -g - << "EOF" global waiting_pages; probe kernel.function("__lock_page").call { waiting_pages[$__page] = gettimeofday_s(); } probe kernel.function("__lock_page").return { delete waiting_pages[@entry($__page)]; } function my_dump_page(page:long) %{ dump_page((struct page *) STAP_ARG_page, "lock_page() stalling"); %} probe timer.s(60) { now = gettimeofday_s(); foreach (page in waiting_pages) if (now - waiting_pages[page] >= 30) my_dump_page(page); } EOF ---------- An example allocated by plain write() (though this is without stall period because I can't reproduce your problem) is shown below. ---------- [ 164.573566] page:fffff3a9024b17c0 count:4 mapcount:0 mapping:ffff8811e2876d68 index:0x5827 [ 164.584758] flags: 0x1fffff800010a9(locked|waiters|uptodate|lru|private) [ 164.593678] raw: 001fffff800010a9 ffff8811e2876d68 0000000000005827 00000004ffffffff [ 164.603410] raw: fffff3a9024b17a0 fffff3a9024cc420 ffff8811e2be27b8 ffff881269fdf800 [ 164.608676] page dumped because: lock_page() stalling [ 164.612558] page->mem_cgroup:ffff881269fdf800 [ 164.615770] page allocated via order 0, migratetype Movable, gfp_mask 0x1c2004a(GFP_NOFS|__GFP_HIGHMEM|__GFP_HARDWALL|__GFP_MOVABLE|__GFP_WRITE) [ 164.623143] __alloc_pages_nodemask+0x184/0x470 [ 164.626939] pagecache_get_page+0xbe/0x310 [ 164.630028] grab_cache_page_write_begin+0x1f/0x40 [ 164.633436] iomap_write_begin.constprop.15+0x5a/0x150 [ 164.636013] iomap_write_actor+0x95/0x180 [ 164.637955] iomap_apply+0xa4/0x110 [ 164.639710] iomap_file_buffered_write+0x61/0x80 [ 164.641796] xfs_file_buffered_aio_write+0xfe/0x3b0 [xfs] [ 164.643945] xfs_file_write_iter+0xfc/0x150 [xfs] [ 164.646290] __vfs_write+0xfc/0x170 [ 164.648048] vfs_write+0xc5/0x1b0 [ 164.649760] SyS_write+0x55/0xc0 [ 164.651317] do_syscall_64+0x66/0x210 [ 164.652994] return_from_SYSCALL_64+0x0/0x75 ----------
-- To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to majordomo@kvack.org. For more info on Linux MM, see: http://www.linux-mm.org/ . Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>