New: OOM on system with just rsync running 32GB of ram 30GB of pagecache
Subsystems (2)
Andrew Morton
maintainer(switched to email. Please respond via emailed reply-to-all, not via the bugzilla web interface).
Quoted 19 lines · On Wed, 02 Nov 2016 13:02:39 +0000 [email protected] wrote:
https://bugzilla.kernel.org/show_bug.cgi?id=186671
Bug ID: 186671 Summary: OOM on system with just rsync running 32GB of ram 30GB of pagecache Product: Memory Management Version: 2.5 Kernel Version: 4.9-rc3 Hardware: x86-64 OS: Linux Tree: Mainline Status: NEW Severity: high Priority: P1 Component: Page Allocator Assignee: [email protected] Reporter: [email protected] Regression: No
Quoted 6 lines
Running rsync on a debian jessie system with 32GB of RAM and a big 250TB btrfs filesystem. 30 GB of ram show up as cached, not much else running on the system. Lots of page alloction stalls in dmesg before hand, and several OOM's after this one as well until it finally killed the rsync. So more traces available if desired. Started with the 4.7 series kernels, thought it was going to be fixed in 4.9:
OK, this looks bad. Please let's work it via email so do remember the reply-to-alls.
Quoted 205 lines
[93428.029768] irqbalance invoked oom-killer: gfp_mask=0x24280ca(GFP_HIGHUSER_MOVABLE|__GFP_ZERO), nodemask=0-1, order=0, oom_score_adj=0 [93428.029824] irqbalance cpuset=/ mems_allowed=0-1 [93428.029857] CPU: 11 PID: 2992 Comm: irqbalance Tainted: G W 4.9.0-rc3 #1 [93428.029945] 0000000000000000 ffffffff812946c9 ffffc90003d8bb10 ffffc90003d8bb10 [93428.029997] ffffffff81190dd5 0000000000000000 0000000000000000 ffff88081db051c0 [93428.030049] ffffc90003d8bb10 ffffffff81711866 0000000000000002 0000000000000213 [93428.030101] Call Trace: [93428.030127] [<ffffffff812946c9>] ? dump_stack+0x46/0x5d [93428.030157] [<ffffffff81190dd5>] ? dump_header.isra.20+0x75/0x1a6 [93428.030189] [<ffffffff8112e589>] ? oom_kill_process+0x219/0x3d0 [93428.030218] [<ffffffff8112e999>] ? out_of_memory+0xd9/0x570 [93428.030246] [<ffffffff811339fb>] ? __alloc_pages_slowpath+0xa4b/0xa80 [93428.030276] [<ffffffff81133cb8>] ? __alloc_pages_nodemask+0x288/0x2c0 [93428.030306] [<ffffffff8117a4c1>] ? alloc_pages_vma+0xc1/0x240 [93428.030337] [<ffffffff8115ba2b>] ? handle_mm_fault+0xccb/0xe60 [93428.030367] [<ffffffff8104a245>] ? __do_page_fault+0x1c5/0x490 [93428.030397] [<ffffffff81506e22>] ? page_fault+0x22/0x30 [93428.030425] [<ffffffff812a090c>] ? copy_user_generic_string+0x2c/0x40 [93428.030455] [<ffffffff811b7095>] ? seq_read+0x305/0x370 [93428.030483] [<ffffffff811f48ee>] ? proc_reg_read+0x3e/0x60 [93428.030511] [<ffffffff81193abe>] ? __vfs_read+0x1e/0x110 [93428.030538] [<ffffffff811941d9>] ? vfs_read+0x89/0x130 [93428.030564] [<ffffffff811954fd>] ? SyS_read+0x3d/0x90 [93428.030591] [<ffffffff815051a0>] ? entry_SYSCALL_64_fastpath+0x13/0x94 [93428.030620] Mem-Info: [93428.030647] active_anon:9283 inactive_anon:9905 isolated_anon:0 [93428.030647] active_file:6752598 inactive_file:999166 isolated_file:288 [93428.030647] unevictable:0 dirty:997857 writeback:1665 unstable:0 [93428.030647] slab_reclaimable:203122 slab_unreclaimable:202102 [93428.030647] mapped:7933 shmem:3170 pagetables:1752 bounce:0 [93428.030647] free:39250 free_pcp:954 free_cma:0 [93428.030800] Node 0 active_anon:24984kB inactive_anon:26704kBactive_file:14365920kB inactive_file:1341120kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:15852kB dirty:1338044kB writeback:3072kB shmem:0kB
shmem_thp: 0kBshmem_pmdmapped: 0kBanon_thp: 9484kB writeback_tmp:0kB unstable:0kB pages_scanned:23811175all_unreclaimable? yes[93428.030933] Node 1 active_anon:12148kB inactive_anon:12916kBactive_file:12644472kB inactive_file:2655544kB unevictable:0kB isolated(anon):0kB isolated(file):1152kB mapped:15880kB dirty:2653384kB writeback:3588kB shmem:0kB
shmem_thp: 0kBshmem_pmdmapped: 0kBanon_thp: 3196kB writeback_tmp:0kB unstable:0kB pages_scanned:23178917all_unreclaimable? yes[93428.031059] Node 0 Normal free:44968kB min:45192kB low:61736kBhigh:78280kB active_anon:24984kB inactive_anon:26704kB active_file:14365920kB inactive_file:1341120kB unevictable:0kB writepending:1341116kB present:16777216kB managed:16546296kB mlocked:0kB slab_reclaimable:413824kB slab_unreclaimable:253144kB kernel_stack:3496kB pagetables:4104kB bounce:0kB free_pcp:1388kB local_pcp:0kB free_cma:0kB
[93428.031211] lowmem_reserve[]: 0 0 0 0 [93428.031245] Node 1 DMA free:15896kB min:40kB low:52kB high:64kBactive_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15996kB managed:15896kB mlocked:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[93428.031373] lowmem_reserve[]: 0 3216 16045 16045 [93428.031408] Node 1 DMA32 free:60288kB min:8996kB low:12288kBhigh:15580kB active_anon:1360kB inactive_anon:1692kB active_file:2735200kB inactive_file:427992kB unevictable:0kB writepending:426716kB present:3378660kB managed:3304640kB mlocked:0kB slab_reclaimable:55012kB slab_unreclaimable:17160kB kernel_stack:176kB pagetables:132kB bounce:0kB free_pcp:120kB local_pcp:0kB free_cma:0kB
[93428.031544] lowmem_reserve[]: 0 0 12828 12828 [93428.031579] Node 1 Normal free:35848kB min:35880kB low:49016kBhigh:62152kB active_anon:10788kB inactive_anon:11224kB active_file:9909272kB inactive_file:2227552kB unevictable:0kB writepending:2230256kB present:13369344kB managed:13136800kB mlocked:0kB slab_reclaimable:343652kB slab_unreclaimable:538104kB kernel_stack:3112kB pagetables:2772kB bounce:0kB free_pcp:2308kB local_pcp:148kB free_cma:0kB
[93428.031730] lowmem_reserve[]: 0 0 0 0 [93428.031764] Node 0 Normal: 11132*4kB (UMH) 31*8kB (H) 12*16kB (H) 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 44968kB [93428.031853] Node 1 DMA: 0*4kB 1*8kB (U) 1*16kB (U) 0*32kB 2*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15896kB [93428.031956] Node 1 DMA32: 14990*4kB (UME) 41*8kB (UM) 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 60288kB [93428.032043] Node 1 Normal: 8958*4kB (M) 2*8kB (M) 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 35848kB [93428.032130] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB [93428.032176] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB [93428.032222] Node 1 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB [93428.032267] Node 1 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB [93428.032313] 7758107 total pagecache pages [93428.032336] 2885 pages in swap cache [93428.032360] Swap cache stats: add 609178, delete 606293, find 331548/559119 [93428.032388] Free swap = 48055104kB [93428.032411] Total swap = 48300028kB [93428.032434] 8385304 pages RAM [93428.032455] 0 pages HighMem/MovableOnly [93428.032478] 134396 pages reserved [93428.032500] 0 pages hwpoisoned [93428.032522] [ pid ] uid tgid total_vm rss nr_ptes nr_pmds swapents oom_score_adj name [93428.032573] [ 1912] 0 1912 10572 1903 27 3 58 0 systemd-journal [93428.032622] [ 1915] 0 1915 9953 482 22 4 304 -1000 systemd-udevd [93428.032670] [ 2813] 0 2813 9270 432 24 3 114 0 rpcbind [93428.032717] [ 2832] 102 2832 9320 438 23 3 150 0 rpc.statd [93428.032765] [ 2848] 0 2848 5839 282 16 3 75 0 rpc.idmapd [93428.032812] [ 2851] 104 2851 88525 1167 44 3 2225 0 apt-cacher-ng [93428.032860] [ 2852] 0 2852 13796 754 32 3 168 -1000 sshd [93428.032906] [ 2853] 0 2853 64668 751 28 3 153 0 rsyslogd [93428.032954] [ 2854] 0 2854 6876 473 17 3 62 0 cron [93428.033000] [ 2855] 0 2855 4756 389 15 3 45 0 atd [93428.033046] [ 2856] 0 2856 7059 520 19 3 592 0 smartd [93428.033093] [ 2860] 0 2860 7089 554 19 3 96 0 systemd-logind [93428.033141] [ 2861] 106 2861 10531 549 26 3 102 -900 dbus-daemon [93428.033194] [ 2990] 107 2990 7293 729 19 3 150 0 ntpd [93428.033241] [ 2992] 0 2992 4853 417 16 3 31 0 irqbalance [93428.033289] [ 3013] 0 3013 26571 387 43 3 258 0 sfcbd [93428.033336] [ 3017] 0 3017 20392 270 40 3 235 0 sfcbd [93428.033383] [ 3020] 0 3020 3180 229 9 3 39 0 mcelog [93428.033429] [ 3050] 0 3050 22441 0 41 3 237 0 sfcbd [93428.033476] [ 3051] 0 3051 57809 318 45 3 379 0 sfcbd [93428.033523] [ 3371] 105 3371 18063 770 36 3 5046 0 snmpd [93428.033569] [ 3473] 0 3473 39377 263 44 3 243 0 sfcbd [93428.033616] [ 3479] 0 3479 58324 448 46 3 283 0 sfcbd [93428.033663] [ 3561] 0 3561 262687 975 65 4 3828 0 dsm_sa_datamgrd [93428.033711] [ 3565] 101 3565 13312 606 29 3 184 0 exim4 [93428.033758] [ 3580] 0 3580 61531 1209 115 3 467 0 winbindd [93428.033805] [ 3581] 0 3581 61531 1226 118 3 433 0 winbindd [93428.033852] [ 3647] 0 3647 48584 826 37 4 260 0 dsm_sa_eventmgr [93428.033900] [ 3670] 0 3670 99593 919 47 3 1346 0 dsm_sa_snmpd [93428.033948] [ 3713] 0 3713 7923 307 16 3 116 0 dsm_om_connsvcd [93428.033996] [ 3714] 0 3714 961001 15661 261 8 33671 0 dsm_om_connsvcd [93428.036621] [ 3719] 0 3719 178651 0 57 4 3787 0 dsm_sa_datamgrd [93428.036669] [ 3825] 0 3825 3604 403 12 3 38 0 agetty [93428.036716] [ 3977] 0 3977 26472 831 54 3 252 0 sshd [93428.036762] [ 3979] 1000 3979 8941 665 23 3 182 0 systemd [93428.036809] [ 3980] 1000 3980 15684 0 34 3 542 0 (sd-pam) [93428.036857] [ 3982] 1000 3982 26472 637 52 3 239 0 sshd [93428.036903] [ 3983] 1000 3983 6041 701 16 3 686 0 bash [93428.036950] [ 3998] 1000 3998 16853 517 37 3 127 0 su [93428.036996] [ 3999] 0 3999 5483 820 15 3 65 0 bash [93428.037043] [ 4534] 0 4534 3311 584 11 3 58 0 run_mirror.sh [93428.037091] [14179] 0 14179 1450 49 8 3 23 0 flock [93428.037137] [14180] 0 14180 9289 1293 23 3 3217 0 rsync [93428.037188] [14181] 0 14181 7616 584 20 3 821 0 rsync [93428.037237] [14182] 0 14182 9171 598 23 3 2352 0 rsync [93428.037287] [15616] 0 15616 2050 535 9 3 0 0 less [93428.037332] Out of memory: Kill process 3714 (dsm_om_connsvcd) score 2 or sacrifice child [93428.037455] Killed process 3714 (dsm_om_connsvcd) total-vm:3844004kB, anon-rss:49616kB, file-rss:13028kB, shmem-rss:0kB [93428.068402] oom_reaper: reaped process 3714 (dsm_om_connsvcd), now
Quoted 5 lines
anon-rss:0kB, file-rss:20kB, shmem-rss:0kB
Signature · 2 lines
You are receiving this mail because: You are the assignee for the bug.
--
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>
Quoted 3 lines · Andrew Morton
(switched to email. Please respond via emailed reply-to-all, not via the bugzilla web interface).
+CC also btrfs just in case it's a problem in page reclaim there
Quoted 28 lines · On Wed, 02 Nov 2016 13:02:39 +0000 [email protected] wrote:
Quoted 20 lines
https://bugzilla.kernel.org/show_bug.cgi?id=186671
Bug ID: 186671 Summary: OOM on system with just rsync running 32GB of ram 30GB of pagecache Product: Memory Management Version: 2.5 Kernel Version: 4.9-rc3 Hardware: x86-64 OS: Linux Tree: Mainline Status: NEW Severity: high Priority: P1 Component: Page Allocator Assignee: [email protected] Reporter: [email protected] Regression: NoQuoted 6 lines
Running rsync on a debian jessie system with 32GB of RAM and a big 250TB btrfs filesystem. 30 GB of ram show up as cached, not much else running on the system. Lots of page alloction stalls in dmesg before hand, and several OOM's after this one as well until it finally killed the rsync. So more traces available if desired. Started with the 4.7 series kernels, thought it was going to be fixed in 4.9:
Quoted 2 lines
OK, this looks bad. Please let's work it via email so do remember the reply-to-alls.
It's bad but note the "started with 4.7" so it's not a 4.9 regression. Also not a high-order OOM (phew!).
Quoted 41 lines
Quoted 41 lines
[93428.029768] irqbalance invoked oom-killer: gfp_mask=0x24280ca(GFP_HIGHUSER_MOVABLE|__GFP_ZERO), nodemask=0-1, order=0, oom_score_adj=0 [93428.029824] irqbalance cpuset=/ mems_allowed=0-1 [93428.029857] CPU: 11 PID: 2992 Comm: irqbalance Tainted: G W 4.9.0-rc3 #1 [93428.029945] 0000000000000000 ffffffff812946c9 ffffc90003d8bb10 ffffc90003d8bb10 [93428.029997] ffffffff81190dd5 0000000000000000 0000000000000000 ffff88081db051c0 [93428.030049] ffffc90003d8bb10 ffffffff81711866 0000000000000002 0000000000000213 [93428.030101] Call Trace: [93428.030127] [<ffffffff812946c9>] ? dump_stack+0x46/0x5d [93428.030157] [<ffffffff81190dd5>] ? dump_header.isra.20+0x75/0x1a6 [93428.030189] [<ffffffff8112e589>] ? oom_kill_process+0x219/0x3d0 [93428.030218] [<ffffffff8112e999>] ? out_of_memory+0xd9/0x570 [93428.030246] [<ffffffff811339fb>] ? __alloc_pages_slowpath+0xa4b/0xa80 [93428.030276] [<ffffffff81133cb8>] ? __alloc_pages_nodemask+0x288/0x2c0 [93428.030306] [<ffffffff8117a4c1>] ? alloc_pages_vma+0xc1/0x240 [93428.030337] [<ffffffff8115ba2b>] ? handle_mm_fault+0xccb/0xe60 [93428.030367] [<ffffffff8104a245>] ? __do_page_fault+0x1c5/0x490 [93428.030397] [<ffffffff81506e22>] ? page_fault+0x22/0x30 [93428.030425] [<ffffffff812a090c>] ? copy_user_generic_string+0x2c/0x40 [93428.030455] [<ffffffff811b7095>] ? seq_read+0x305/0x370 [93428.030483] [<ffffffff811f48ee>] ? proc_reg_read+0x3e/0x60 [93428.030511] [<ffffffff81193abe>] ? __vfs_read+0x1e/0x110 [93428.030538] [<ffffffff811941d9>] ? vfs_read+0x89/0x130 [93428.030564] [<ffffffff811954fd>] ? SyS_read+0x3d/0x90 [93428.030591] [<ffffffff815051a0>] ? entry_SYSCALL_64_fastpath+0x13/0x94 [93428.030620] Mem-Info: [93428.030647] active_anon:9283 inactive_anon:9905 isolated_anon:0 [93428.030647] active_file:6752598 inactive_file:999166 isolated_file:288 [93428.030647] unevictable:0 dirty:997857 writeback:1665 unstable:0 [93428.030647] slab_reclaimable:203122 slab_unreclaimable:202102 [93428.030647] mapped:7933 shmem:3170 pagetables:1752 bounce:0 [93428.030647] free:39250 free_pcp:954 free_cma:0 [93428.030800] Node 0 active_anon:24984kB inactive_anon:26704kBactive_file:14365920kB inactive_file:1341120kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:15852kB dirty:1338044kB writeback:3072kB shmem:0kB
shmem_thp: 0kBshmem_pmdmapped: 0kB
Quoted 8 lines
Quoted 8 lines
anon_thp: 9484kB writeback_tmp:0kB unstable:0kB pages_scanned:23811175all_unreclaimable? yes[93428.030933] Node 1 active_anon:12148kB inactive_anon:12916kBactive_file:12644472kB inactive_file:2655544kB unevictable:0kB isolated(anon):0kB isolated(file):1152kB mapped:15880kB dirty:2653384kB writeback:3588kB shmem:0kB
shmem_thp: 0kBshmem_pmdmapped: 0kBanon_thp: 3196kB writeback_tmp:0kB unstable:0kB pages_scanned:23178917all_unreclaimable? yes
Note the high pages_scanned and all_unreclaimable. I suspect something is pinning the memory. Can you post /proc/vmstat from the system with an uptime after it experiences the OOM?
There's /proc/kpagecount file that could confirm that. Could you provide it too? Try running something like this and provide the output please.
xxd -e -g8 -c8 /proc/kpagecount | cut -d" " -f2 | sort | uniq -c
Quoted 168 lines
Quoted 156 lines
[93428.031059] Node 0 Normal free:44968kB min:45192kB low:61736kBhigh:78280kB active_anon:24984kB inactive_anon:26704kB active_file:14365920kB inactive_file:1341120kB unevictable:0kB writepending:1341116kB present:16777216kB managed:16546296kB mlocked:0kB slab_reclaimable:413824kB slab_unreclaimable:253144kB kernel_stack:3496kB pagetables:4104kB bounce:0kB free_pcp:1388kB local_pcp:0kB free_cma:0kB
[93428.031211] lowmem_reserve[]: 0 0 0 0 [93428.031245] Node 1 DMA free:15896kB min:40kB low:52kB high:64kBactive_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15996kB managed:15896kB mlocked:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[93428.031373] lowmem_reserve[]: 0 3216 16045 16045 [93428.031408] Node 1 DMA32 free:60288kB min:8996kB low:12288kBhigh:15580kB active_anon:1360kB inactive_anon:1692kB active_file:2735200kB inactive_file:427992kB unevictable:0kB writepending:426716kB present:3378660kB managed:3304640kB mlocked:0kB slab_reclaimable:55012kB slab_unreclaimable:17160kB kernel_stack:176kB pagetables:132kB bounce:0kB free_pcp:120kB local_pcp:0kB free_cma:0kB
[93428.031544] lowmem_reserve[]: 0 0 12828 12828 [93428.031579] Node 1 Normal free:35848kB min:35880kB low:49016kBhigh:62152kB active_anon:10788kB inactive_anon:11224kB active_file:9909272kB inactive_file:2227552kB unevictable:0kB writepending:2230256kB present:13369344kB managed:13136800kB mlocked:0kB slab_reclaimable:343652kB slab_unreclaimable:538104kB kernel_stack:3112kB pagetables:2772kB bounce:0kB free_pcp:2308kB local_pcp:148kB free_cma:0kB
[93428.031730] lowmem_reserve[]: 0 0 0 0 [93428.031764] Node 0 Normal: 11132*4kB (UMH) 31*8kB (H) 12*16kB (H) 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 44968kB [93428.031853] Node 1 DMA: 0*4kB 1*8kB (U) 1*16kB (U) 0*32kB 2*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15896kB [93428.031956] Node 1 DMA32: 14990*4kB (UME) 41*8kB (UM) 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 60288kB [93428.032043] Node 1 Normal: 8958*4kB (M) 2*8kB (M) 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 35848kB [93428.032130] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB [93428.032176] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB [93428.032222] Node 1 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB [93428.032267] Node 1 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB [93428.032313] 7758107 total pagecache pages [93428.032336] 2885 pages in swap cache [93428.032360] Swap cache stats: add 609178, delete 606293, find 331548/559119 [93428.032388] Free swap = 48055104kB [93428.032411] Total swap = 48300028kB [93428.032434] 8385304 pages RAM [93428.032455] 0 pages HighMem/MovableOnly [93428.032478] 134396 pages reserved [93428.032500] 0 pages hwpoisoned [93428.032522] [ pid ] uid tgid total_vm rss nr_ptes nr_pmds swapents oom_score_adj name [93428.032573] [ 1912] 0 1912 10572 1903 27 3 58 0 systemd-journal [93428.032622] [ 1915] 0 1915 9953 482 22 4 304 -1000 systemd-udevd [93428.032670] [ 2813] 0 2813 9270 432 24 3 114 0 rpcbind [93428.032717] [ 2832] 102 2832 9320 438 23 3 150 0 rpc.statd [93428.032765] [ 2848] 0 2848 5839 282 16 3 75 0 rpc.idmapd [93428.032812] [ 2851] 104 2851 88525 1167 44 3 2225 0 apt-cacher-ng [93428.032860] [ 2852] 0 2852 13796 754 32 3 168 -1000 sshd [93428.032906] [ 2853] 0 2853 64668 751 28 3 153 0 rsyslogd [93428.032954] [ 2854] 0 2854 6876 473 17 3 62 0 cron [93428.033000] [ 2855] 0 2855 4756 389 15 3 45 0 atd [93428.033046] [ 2856] 0 2856 7059 520 19 3 592 0 smartd [93428.033093] [ 2860] 0 2860 7089 554 19 3 96 0 systemd-logind [93428.033141] [ 2861] 106 2861 10531 549 26 3 102 -900 dbus-daemon [93428.033194] [ 2990] 107 2990 7293 729 19 3 150 0 ntpd [93428.033241] [ 2992] 0 2992 4853 417 16 3 31 0 irqbalance [93428.033289] [ 3013] 0 3013 26571 387 43 3 258 0 sfcbd [93428.033336] [ 3017] 0 3017 20392 270 40 3 235 0 sfcbd [93428.033383] [ 3020] 0 3020 3180 229 9 3 39 0 mcelog [93428.033429] [ 3050] 0 3050 22441 0 41 3 237 0 sfcbd [93428.033476] [ 3051] 0 3051 57809 318 45 3 379 0 sfcbd [93428.033523] [ 3371] 105 3371 18063 770 36 3 5046 0 snmpd [93428.033569] [ 3473] 0 3473 39377 263 44 3 243 0 sfcbd [93428.033616] [ 3479] 0 3479 58324 448 46 3 283 0 sfcbd [93428.033663] [ 3561] 0 3561 262687 975 65 4 3828 0 dsm_sa_datamgrd [93428.033711] [ 3565] 101 3565 13312 606 29 3 184 0 exim4 [93428.033758] [ 3580] 0 3580 61531 1209 115 3 467 0 winbindd [93428.033805] [ 3581] 0 3581 61531 1226 118 3 433 0 winbindd [93428.033852] [ 3647] 0 3647 48584 826 37 4 260 0 dsm_sa_eventmgr [93428.033900] [ 3670] 0 3670 99593 919 47 3 1346 0 dsm_sa_snmpd [93428.033948] [ 3713] 0 3713 7923 307 16 3 116 0 dsm_om_connsvcd [93428.033996] [ 3714] 0 3714 961001 15661 261 8 33671 0 dsm_om_connsvcd [93428.036621] [ 3719] 0 3719 178651 0 57 4 3787 0 dsm_sa_datamgrd [93428.036669] [ 3825] 0 3825 3604 403 12 3 38 0 agetty [93428.036716] [ 3977] 0 3977 26472 831 54 3 252 0 sshd [93428.036762] [ 3979] 1000 3979 8941 665 23 3 182 0 systemd [93428.036809] [ 3980] 1000 3980 15684 0 34 3 542 0 (sd-pam) [93428.036857] [ 3982] 1000 3982 26472 637 52 3 239 0 sshd [93428.036903] [ 3983] 1000 3983 6041 701 16 3 686 0 bash [93428.036950] [ 3998] 1000 3998 16853 517 37 3 127 0 su [93428.036996] [ 3999] 0 3999 5483 820 15 3 65 0 bash [93428.037043] [ 4534] 0 4534 3311 584 11 3 58 0 run_mirror.sh [93428.037091] [14179] 0 14179 1450 49 8 3 23 0 flock [93428.037137] [14180] 0 14180 9289 1293 23 3 3217 0 rsync [93428.037188] [14181] 0 14181 7616 584 20 3 821 0 rsync [93428.037237] [14182] 0 14182 9171 598 23 3 2352 0 rsync [93428.037287] [15616] 0 15616 2050 535 9 3 0 0 less [93428.037332] Out of memory: Kill process 3714 (dsm_om_connsvcd) score 2 or sacrifice child [93428.037455] Killed process 3714 (dsm_om_connsvcd) total-vm:3844004kB, anon-rss:49616kB, file-rss:13028kB, shmem-rss:0kB [93428.068402] oom_reaper: reaped process 3714 (dsm_om_connsvcd), nowQuoted 5 lines
anon-rss:0kB, file-rss:20kB, shmem-rss:0kB
Signature · 2 lines
You are receiving this mail because: You are the assignee for the bug.--
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>
After the system panic'd yesterday I booted back into 4.8.4 and restarted the rsync's. I'm away on vacation next week, so when I get back I'll get rc4 or rc5 and try again. In the mean time here's data from the system running 4.8.4 without problems for about a day. I'm not familiar with xxd and didn't see a -e option, so used -E:
xxd -E -g8 -c8 /proc/kpagecount | cut -d" " -f2 | sort | uniq -c 8258633 0000000000000000
216440 0100000000000000
5576 0200000000000000
592 0300000000000000
195 0400000000000000
184 0500000000000000
171 0600000000000000
70 0700000000000000
3 0800000000000000
17 0900000000000000
48 0a00000000000000
78 0b00000000000000
33 0c00000000000000
23 0d00000000000000
18 0e00000000000000
3 0f00000000000000
5 1000000000000000
2 1100000000000000
7 1200000000000000
5 1300000000000000
2 1400000000000000
36 1500000000000000
10 1600000000000000
6 1700000000000000
3 1800000000000000
8 1900000000000000
4 1a00000000000000
7 1b00000000000000
4 1c00000000000000
5 1d00000000000000
3 1e00000000000000
18 1f00000000000000
9 2000000000000000
9 2100000000000000
9 2200000000000000
19 2300000000000000
13 2400000000000000
6 2500000000000000
13 2600000000000000
13 2700000000000000
3 2800000000000000
16 2900000000000000
7 2a00000000000000
21 2b00000000000000
33 2c00000000000000
19 2d00000000000000
54 2e00000000000000
29 2f00000000000000
72 3000000000000000
27 3100000000000000 102635 81ffffffffffffff
cat /proc/vmstatnr_free_pages 106970nr_zone_inactive_anon 110034nr_zone_active_anon 108424nr_zone_inactive_file 350017nr_zone_active_file 2158161nr_zone_unevictable 0nr_zone_write_pending 114nr_mlock 0nr_slab_reclaimable 4962990nr_slab_unreclaimable 415089nr_page_table_pages 2149nr_kernel_stack 6176nr_bounce 0numa_hit 403780590numa_miss 176970926numa_foreign 176970926numa_interleave 19415numa_local 403780590numa_other 0nr_free_cma 0nr_inactive_anon 110034nr_active_anon 108424nr_inactive_file 350017nr_active_file 2158161nr_unevictable 0nr_isolated_anon 0nr_isolated_file 0nr_pages_scanned 0workingset_refault 1443060workingset_activate 558143workingset_nodereclaim 6879280nr_anon_pages 216243nr_mapped 6462nr_file_pages 2510544nr_dirty 114nr_writeback 0nr_writeback_temp 0nr_shmem 2179nr_shmem_hugepages 0nr_shmem_pmdmapped 0nr_anon_transparent_hugepages 0nr_unstable 0nr_vmscan_write 1127nr_vmscan_immediate_reclaim 19056nr_dirtied 254716641nr_written 254532248nr_dirty_threshold 383652nr_dirty_background_threshold 50612
pgpgin 21962903
pgpgout 1024651087
pswpin 214
pswpout 1127pgalloc_dma 0pgalloc_dma32 87690791pgalloc_normal 806119097pgalloc_movable 0allocstall_dma 0allocstall_dma32 0allocstall_normal 210allocstall_movable 0pgskip_dma 0pgskip_dma32 0pgskip_normal 0pgskip_movable 0
pgfree 894694404
pgactivate 5513535
pgdeactivate 7989719
pgfault 4748538
pgmajfault 2528
pglazyfreed 0
pgrefill 7999038pgsteal_kswapd 504125672pgsteal_direct 36130pgscan_kswapd 504479233pgscan_direct 36142pgscan_direct_throttle 0zone_reclaim_failed 0
pginodesteal 1074slabs_scanned 61625344kswapd_inodesteal 1956613kswapd_low_wmark_hit_quickly 49386kswapd_high_wmark_hit_quickly 79880
pageoutrun 211656
pgrotated 203832drop_pagecache 0drop_slab 0pgmigrate_success 684523pgmigrate_fail 1189249compact_migrate_scanned 94848219compact_free_scanned 2329620072compact_isolated 2648057compact_stall 38compact_fail 0compact_success 38compact_daemon_wake 9682htlb_buddy_alloc_success 0htlb_buddy_alloc_fail 0unevictable_pgs_culled 12473unevictable_pgs_scanned 0unevictable_pgs_rescued 11979unevictable_pgs_mlocked 14556unevictable_pgs_munlocked 14556unevictable_pgs_cleared 0unevictable_pgs_stranded 0thp_fault_alloc 0thp_fault_fallback 0thp_collapse_alloc 0thp_collapse_alloc_failed 0thp_file_alloc 0thp_file_mapped 0thp_split_page 0thp_split_page_failed 0thp_deferred_split_page 0thp_split_pmd 0thp_zero_page_alloc 0thp_zero_page_alloc_failed 0
Quoted 269 lines · Vlastimil Babka
Quoted 3 lines · Andrew Morton
(switched to email. Please respond via emailed reply-to-all, not via the bugzilla web interface).
+CC also btrfs just in case it's a problem in page reclaim there
Quoted 28 lines · On Wed, 02 Nov 2016 13:02:39 +0000 [email protected] wrote:
Quoted 20 lines
https://bugzilla.kernel.org/show_bug.cgi?id=186671
Bug ID: 186671 Summary: OOM on system with just rsync running 32GB of ram 30GB of pagecache Product: Memory Management Version: 2.5 Kernel Version: 4.9-rc3 Hardware: x86-64 OS: Linux Tree: Mainline Status: NEW Severity: high Priority: P1 Component: Page Allocator Assignee: [email protected] Reporter: [email protected] Regression: NoQuoted 6 lines
Running rsync on a debian jessie system with 32GB of RAM and a big 250TB btrfs filesystem. 30 GB of ram show up as cached, not much else running on the system. Lots of page alloction stalls in dmesg before hand, and several OOM's after this one as well until it finally killed the rsync. So more traces available if desired. Started with the 4.7 series kernels, thought it was going to be fixed in 4.9:
Quoted 2 lines
OK, this looks bad. Please let's work it via email so do remember the reply-to-alls.
It's bad but note the "started with 4.7" so it's not a 4.9 regression. Also not a high-order OOM (phew!).
Quoted 41 lines
Quoted 41 lines
[93428.029768] irqbalance invoked oom-killer: gfp_mask=0x24280ca(GFP_HIGHUSER_MOVABLE|__GFP_ZERO), nodemask=0-1, order=0, oom_score_adj=0 [93428.029824] irqbalance cpuset=/ mems_allowed=0-1 [93428.029857] CPU: 11 PID: 2992 Comm: irqbalance Tainted: G W 4.9.0-rc3 #1 [93428.029945] 0000000000000000 ffffffff812946c9 ffffc90003d8bb10 ffffc90003d8bb10 [93428.029997] ffffffff81190dd5 0000000000000000 0000000000000000 ffff88081db051c0 [93428.030049] ffffc90003d8bb10 ffffffff81711866 0000000000000002 0000000000000213 [93428.030101] Call Trace: [93428.030127] [<ffffffff812946c9>] ? dump_stack+0x46/0x5d [93428.030157] [<ffffffff81190dd5>] ? dump_header.isra.20+0x75/0x1a6 [93428.030189] [<ffffffff8112e589>] ? oom_kill_process+0x219/0x3d0 [93428.030218] [<ffffffff8112e999>] ? out_of_memory+0xd9/0x570 [93428.030246] [<ffffffff811339fb>] ? __alloc_pages_slowpath+0xa4b/0xa80 [93428.030276] [<ffffffff81133cb8>] ? __alloc_pages_nodemask+0x288/0x2c0 [93428.030306] [<ffffffff8117a4c1>] ? alloc_pages_vma+0xc1/0x240 [93428.030337] [<ffffffff8115ba2b>] ? handle_mm_fault+0xccb/0xe60 [93428.030367] [<ffffffff8104a245>] ? __do_page_fault+0x1c5/0x490 [93428.030397] [<ffffffff81506e22>] ? page_fault+0x22/0x30 [93428.030425] [<ffffffff812a090c>] ? copy_user_generic_string+0x2c/0x40 [93428.030455] [<ffffffff811b7095>] ? seq_read+0x305/0x370 [93428.030483] [<ffffffff811f48ee>] ? proc_reg_read+0x3e/0x60 [93428.030511] [<ffffffff81193abe>] ? __vfs_read+0x1e/0x110 [93428.030538] [<ffffffff811941d9>] ? vfs_read+0x89/0x130 [93428.030564] [<ffffffff811954fd>] ? SyS_read+0x3d/0x90 [93428.030591] [<ffffffff815051a0>] ? entry_SYSCALL_64_fastpath+0x13/0x94 [93428.030620] Mem-Info: [93428.030647] active_anon:9283 inactive_anon:9905 isolated_anon:0 [93428.030647] active_file:6752598 inactive_file:999166 isolated_file:288 [93428.030647] unevictable:0 dirty:997857 writeback:1665 unstable:0 [93428.030647] slab_reclaimable:203122 slab_unreclaimable:202102 [93428.030647] mapped:7933 shmem:3170 pagetables:1752 bounce:0 [93428.030647] free:39250 free_pcp:954 free_cma:0 [93428.030800] Node 0 active_anon:24984kB inactive_anon:26704kBactive_file:14365920kB inactive_file:1341120kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:15852kB dirty:1338044kB writeback:3072kB shmem:0kB
shmem_thp: 0kBshmem_pmdmapped: 0kBQuoted 8 lines
Quoted 8 lines
anon_thp: 9484kB writeback_tmp:0kB unstable:0kB pages_scanned:23811175all_unreclaimable? yes[93428.030933] Node 1 active_anon:12148kB inactive_anon:12916kBactive_file:12644472kB inactive_file:2655544kB unevictable:0kB isolated(anon):0kB isolated(file):1152kB mapped:15880kB dirty:2653384kB writeback:3588kB shmem:0kB
shmem_thp: 0kBshmem_pmdmapped: 0kBanon_thp: 3196kB writeback_tmp:0kB unstable:0kB pages_scanned:23178917all_unreclaimable? yesNote the high
pages_scannedandall_unreclaimable. I suspect something is pinning the memory. Can you post/proc/vmstatfrom the system with an uptime after it experiences the OOM?There's
/proc/kpagecountfile that could confirm that. Could you provide it too? Try running something like this and provide the output please.xxd -e -g8 -c8
/proc/kpagecount| cut -d" " -f2 | sort | uniq -cQuoted 168 lines
Quoted 156 lines
[93428.031059] Node 0 Normal free:44968kB min:45192kB low:61736kBhigh:78280kB active_anon:24984kB inactive_anon:26704kB active_file:14365920kB inactive_file:1341120kB unevictable:0kB writepending:1341116kB present:16777216kB managed:16546296kB mlocked:0kB slab_reclaimable:413824kB slab_unreclaimable:253144kB kernel_stack:3496kB pagetables:4104kB bounce:0kB free_pcp:1388kB local_pcp:0kB free_cma:0kB
[93428.031211] lowmem_reserve[]: 0 0 0 0 [93428.031245] Node 1 DMA free:15896kB min:40kB low:52kB high:64kBactive_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15996kB managed:15896kB mlocked:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[93428.031373] lowmem_reserve[]: 0 3216 16045 16045 [93428.031408] Node 1 DMA32 free:60288kB min:8996kB low:12288kBhigh:15580kB active_anon:1360kB inactive_anon:1692kB active_file:2735200kB inactive_file:427992kB unevictable:0kB writepending:426716kB present:3378660kB managed:3304640kB mlocked:0kB slab_reclaimable:55012kB slab_unreclaimable:17160kB kernel_stack:176kB pagetables:132kB bounce:0kB free_pcp:120kB local_pcp:0kB free_cma:0kB
[93428.031544] lowmem_reserve[]: 0 0 12828 12828 [93428.031579] Node 1 Normal free:35848kB min:35880kB low:49016kBhigh:62152kB active_anon:10788kB inactive_anon:11224kB active_file:9909272kB inactive_file:2227552kB unevictable:0kB writepending:2230256kB present:13369344kB managed:13136800kB mlocked:0kB slab_reclaimable:343652kB slab_unreclaimable:538104kB kernel_stack:3112kB pagetables:2772kB bounce:0kB free_pcp:2308kB local_pcp:148kB free_cma:0kB
[93428.031730] lowmem_reserve[]: 0 0 0 0 [93428.031764] Node 0 Normal: 11132*4kB (UMH) 31*8kB (H) 12*16kB (H) 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 44968kB [93428.031853] Node 1 DMA: 0*4kB 1*8kB (U) 1*16kB (U) 0*32kB 2*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15896kB [93428.031956] Node 1 DMA32: 14990*4kB (UME) 41*8kB (UM) 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 60288kB [93428.032043] Node 1 Normal: 8958*4kB (M) 2*8kB (M) 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 35848kB [93428.032130] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB [93428.032176] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB [93428.032222] Node 1 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB [93428.032267] Node 1 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB [93428.032313] 7758107 total pagecache pages [93428.032336] 2885 pages in swap cache [93428.032360] Swap cache stats: add 609178, delete 606293, find 331548/559119 [93428.032388] Free swap = 48055104kB [93428.032411] Total swap = 48300028kB [93428.032434] 8385304 pages RAM [93428.032455] 0 pages HighMem/MovableOnly [93428.032478] 134396 pages reserved [93428.032500] 0 pages hwpoisoned [93428.032522] [ pid ] uid tgid total_vm rss nr_ptes nr_pmds swapents oom_score_adj name [93428.032573] [ 1912] 0 1912 10572 1903 27 3 58 0 systemd-journal [93428.032622] [ 1915] 0 1915 9953 482 22 4 304 -1000 systemd-udevd [93428.032670] [ 2813] 0 2813 9270 432 24 3 114 0 rpcbind [93428.032717] [ 2832] 102 2832 9320 438 23 3 150 0 rpc.statd [93428.032765] [ 2848] 0 2848 5839 282 16 3 75 0 rpc.idmapd [93428.032812] [ 2851] 104 2851 88525 1167 44 3 2225 0 apt-cacher-ng [93428.032860] [ 2852] 0 2852 13796 754 32 3 168 -1000 sshd [93428.032906] [ 2853] 0 2853 64668 751 28 3 153 0 rsyslogd [93428.032954] [ 2854] 0 2854 6876 473 17 3 62 0 cron [93428.033000] [ 2855] 0 2855 4756 389 15 3 45 0 atd [93428.033046] [ 2856] 0 2856 7059 520 19 3 592 0 smartd [93428.033093] [ 2860] 0 2860 7089 554 19 3 96 0 systemd-logind [93428.033141] [ 2861] 106 2861 10531 549 26 3 102 -900 dbus-daemon [93428.033194] [ 2990] 107 2990 7293 729 19 3 150 0 ntpd [93428.033241] [ 2992] 0 2992 4853 417 16 3 31 0 irqbalance [93428.033289] [ 3013] 0 3013 26571 387 43 3 258 0 sfcbd [93428.033336] [ 3017] 0 3017 20392 270 40 3 235 0 sfcbd [93428.033383] [ 3020] 0 3020 3180 229 9 3 39 0 mcelog [93428.033429] [ 3050] 0 3050 22441 0 41 3 237 0 sfcbd [93428.033476] [ 3051] 0 3051 57809 318 45 3 379 0 sfcbd [93428.033523] [ 3371] 105 3371 18063 770 36 3 5046 0 snmpd [93428.033569] [ 3473] 0 3473 39377 263 44 3 243 0 sfcbd [93428.033616] [ 3479] 0 3479 58324 448 46 3 283 0 sfcbd [93428.033663] [ 3561] 0 3561 262687 975 65 4 3828 0 dsm_sa_datamgrd [93428.033711] [ 3565] 101 3565 13312 606 29 3 184 0 exim4 [93428.033758] [ 3580] 0 3580 61531 1209 115 3 467 0 winbindd [93428.033805] [ 3581] 0 3581 61531 1226 118 3 433 0 winbindd [93428.033852] [ 3647] 0 3647 48584 826 37 4 260 0 dsm_sa_eventmgr [93428.033900] [ 3670] 0 3670 99593 919 47 3 1346 0 dsm_sa_snmpd [93428.033948] [ 3713] 0 3713 7923 307 16 3 116 0 dsm_om_connsvcd [93428.033996] [ 3714] 0 3714 961001 15661 261 8 33671 0 dsm_om_connsvcd [93428.036621] [ 3719] 0 3719 178651 0 57 4 3787 0 dsm_sa_datamgrd [93428.036669] [ 3825] 0 3825 3604 403 12 3 38 0 agetty [93428.036716] [ 3977] 0 3977 26472 831 54 3 252 0 sshd [93428.036762] [ 3979] 1000 3979 8941 665 23 3 182 0 systemd [93428.036809] [ 3980] 1000 3980 15684 0 34 3 542 0 (sd-pam) [93428.036857] [ 3982] 1000 3982 26472 637 52 3 239 0 sshd [93428.036903] [ 3983] 1000 3983 6041 701 16 3 686 0 bash [93428.036950] [ 3998] 1000 3998 16853 517 37 3 127 0 su [93428.036996] [ 3999] 0 3999 5483 820 15 3 65 0 bash [93428.037043] [ 4534] 0 4534 3311 584 11 3 58 0 run_mirror.sh [93428.037091] [14179] 0 14179 1450 49 8 3 23 0 flock [93428.037137] [14180] 0 14180 9289 1293 23 3 3217 0 rsync [93428.037188] [14181] 0 14181 7616 584 20 3 821 0 rsync [93428.037237] [14182] 0 14182 9171 598 23 3 2352 0 rsync [93428.037287] [15616] 0 15616 2050 535 9 3 0 0 less [93428.037332] Out of memory: Kill process 3714 (dsm_om_connsvcd) score 2 or sacrifice child [93428.037455] Killed process 3714 (dsm_om_connsvcd) total-vm:3844004kB, anon-rss:49616kB, file-rss:13028kB, shmem-rss:0kB [93428.068402] oom_reaper: reaped process 3714 (dsm_om_connsvcd), nowQuoted 5 lines
anon-rss:0kB, file-rss:20kB, shmem-rss:0kB
--
You are receiving this mail because:
You are the assignee for the bug.--
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>
Quoted 8 lines · E V
After the system panic'd yesterday I booted back into 4.8.4 and restarted the rsync's. I'm away on vacation next week, so when I get back I'll get rc4 or rc5 and try again. In the mean time here's data from the system running 4.8.4 without problems for about a day. I'm not familiar with xxd and didn't see a -e option, so used -E:
xxd -E -g8 -c8/proc/kpagecount| cut -d" " -f2 | sort | uniq -c 8258633 0000000000000000
216440 0100000000000000
The lack of -e means it's big endian, which is not a big issue. So here most of memory is free, some pages have just one pin, and only relatively few have more. The vmstats also doesn't show anything bad, so we'll have to wait if something appears within the week, or after you try 4.9 again. Thanks.
System is an intel dual socket Xeon E5620, 7500/5520/5500/X58 ICH10 family according to lspci. Anyways 4.8.4 OOM'd while I was gone. I'll download the current 4.9rc and reboot, but in the mean time here's xxd, vmstat & kern.log output:
8532039 0000000000000000
9324 0100000000000000
2226 0200000000000000
405 0300000000000000
80 0400000000000000
34 0500000000000000
48 0600000000000000
17 0700000000000000
17 0800000000000000
32 0900000000000000
19 0a00000000000000
1 0c00000000000000
1 0d00000000000000
1 0e00000000000000
12 1000000000000000
8 1100000000000000
32 1200000000000000
10 1300000000000000
2 1400000000000000
11 1500000000000000
12 1600000000000000
7 1700000000000000
3 1800000000000000
5 1900000000000000
6 1a00000000000000
11 1b00000000000000
22 1c00000000000000
3 1d00000000000000
19 1e00000000000000
21 1f00000000000000
18 2000000000000000
28 2100000000000000
40 2200000000000000
38 2300000000000000
85 2400000000000000
59 2500000000000000 40520 81ffffffffffffff
/proc/vmstat:nr_free_pages 60965nr_zone_inactive_anon 4646nr_zone_active_anon 3265nr_zone_inactive_file 633882nr_zone_active_file 7017458nr_zone_unevictable 0nr_zone_write_pending 0nr_mlock 0nr_slab_reclaimable 299205nr_slab_unreclaimable 195497nr_page_table_pages 935nr_kernel_stack 4976nr_bounce 0numa_hit 3577063288numa_miss 541393191numa_foreign 541393191numa_interleave 19415numa_local 3577063288numa_other 0nr_free_cma 0nr_inactive_anon 4646nr_active_anon 3265nr_inactive_file 633882nr_active_file 7017458nr_unevictable 0nr_isolated_anon 0nr_isolated_file 0nr_pages_scanned 0workingset_refault 42685891workingset_activate 15247281workingset_nodereclaim 26375216nr_anon_pages 5067nr_mapped 5630nr_file_pages 7654746nr_dirty 0nr_writeback 0nr_writeback_temp 0nr_shmem 2504nr_shmem_hugepages 0nr_shmem_pmdmapped 0nr_anon_transparent_hugepages 0nr_unstable 0nr_vmscan_write 5243750485nr_vmscan_immediate_reclaim 4207633857nr_dirtied 1839143430nr_written 1832626107nr_dirty_threshold 1147728nr_dirty_background_threshold 151410
pgpgin 166731189
pgpgout 7328142335
pswpin 98608
pswpout 117794pgalloc_dma 29504pgalloc_dma32 1006726216pgalloc_normal 5275218188pgalloc_movable 0allocstall_dma 0allocstall_dma32 0allocstall_normal 36461allocstall_movable 5867pgskip_dma 0pgskip_dma32 0pgskip_normal 6417890pgskip_movable 0
pgfree 6309223401
pgactivate 35076483
pgdeactivate 63556974
pgfault 35753842
pgmajfault 69126
pglazyfreed 0
pgrefill 70008598pgsteal_kswapd 3567289713pgsteal_direct 5878057pgscan_kswapd 9059309872pgscan_direct 4239367903pgscan_direct_throttle 0zone_reclaim_failed 0
pginodesteal 102916slabs_scanned 460790262kswapd_inodesteal 9130243kswapd_low_wmark_hit_quickly 10634373kswapd_high_wmark_hit_quickly 7348173
pageoutrun 18349115
pgrotated 16291322drop_pagecache 0drop_slab 0pgmigrate_success 18912908pgmigrate_fail 63382146compact_migrate_scanned 2986269789compact_free_scanned 190451505123compact_isolated 109549437compact_stall 3544compact_fail 8compact_success 3536compact_daemon_wake 1403515htlb_buddy_alloc_success 0htlb_buddy_alloc_fail 0unevictable_pgs_culled 12473unevictable_pgs_scanned 0unevictable_pgs_rescued 11979unevictable_pgs_mlocked 14556unevictable_pgs_munlocked 14556unevictable_pgs_cleared 0unevictable_pgs_stranded 0thp_fault_alloc 0thp_fault_fallback 0thp_collapse_alloc 0thp_collapse_alloc_failed 0thp_file_alloc 0thp_file_mapped 0thp_split_page 0thp_split_page_failed 0thp_deferred_split_page 0thp_split_pmd 0thp_zero_page_alloc 0thp_zero_page_alloc_failed 0
kern.log OOM message:
[737778.724194] snmpd invoked oom-killer: gfp_mask=0x24200ca(GFP_HIGHUSER_MOVABLE), order=0, oom_score_adj=0 [737778.724246] snmpd cpuset=/ mems_allowed=0-1 [737778.724278] CPU: 15 PID: 2976 Comm: snmpd Tainted: G W I 4.8.4 #1 [737778.724352] 0000000000000000 ffffffff81292069 ffff88041e043c48 ffff88041e043c48 [737778.724403] ffffffff8118d1f6 ffff88041dd70fc0 ffff88041e043c48 000000000136236f [737778.724454] ffffffff8170e11e 0000000000000001 ffffffff8112a700 000000000000030f [737778.724505] Call Trace: [737778.724533] [<ffffffff81292069>] ? dump_stack+0x46/0x5d [737778.727077] [<ffffffff8118d1f6>] ? dump_header.isra.16+0x56/0x185 [737778.727108] [<ffffffff8112a700>] ? oom_kill_process+0x210/0x3c0 [737778.727136] [<ffffffff8112ac4b>] ? out_of_memory+0x34b/0x420 [737778.727165] [<ffffffff8112fcca>] ? __alloc_pages_nodemask+0xd9a/0xde0 [737778.727195] [<ffffffff811768e1>] ? alloc_pages_vma+0xc1/0x240 [737778.727223] [<ffffffff81126512>] ? pagecache_get_page+0x22/0x230 [737778.727253] [<ffffffff81169f44>] ? __read_swap_cache_async+0x104/0x180 [737778.727282] [<ffffffff81169fcf>] ? read_swap_cache_async+0xf/0x30 [737778.727311] [<ffffffff8116a0dc>] ? swapin_readahead+0xec/0x1a0 [737778.727340] [<ffffffff81156270>] ? do_swap_page+0x420/0x5c0 [737778.727369] [<ffffffff813f36d8>] ? SYSC_recvfrom+0xa8/0x110 [737778.727397] [<ffffffff81157a39>] ? handle_mm_fault+0x629/0xe30 [737778.727426] [<ffffffff81048fc5>] ? __do_page_fault+0x1b5/0x480 [737778.727456] [<ffffffff814fbaa2>] ? page_fault+0x22/0x30 [737778.727497] Mem-Info: [737778.727524] active_anon:24 inactive_anon:49 isolated_anon:0 [737778.727524] active_file:6920154 inactive_file:798043 isolated_file:576 [737778.727524] unevictable:0 dirty:800528 writeback:1307 unstable:0 [737778.727524] slab_reclaimable:264367 slab_unreclaimable:193348 [737778.727524] mapped:4063 shmem:0 pagetables:1719 bounce:0 [737778.727524] free:39225 free_pcp:47 free_cma:0 [737778.727677] Node 0 active_anon:16kB inactive_anon:76kB
active_file:14249324kB inactive_file:1296908kB unevictable:0kB isolated(anon):0kB isolated(file):1920kB mapped:10432kB dirty:1308528kB writeback:0kB shmem:0kB shmem_thp: 0kBshmem_pmdmapped: 0kB anon_thp: 0kB writeback_tmp:0kB unstable:0kB pages_scanned:23557303 all_unreclaimable? yes
[737778.727806] Node 1 active_anon:80kB inactive_anon:120kB
active_file:13431292kB inactive_file:1895264kB unevictable:0kB isolated(anon):0kB isolated(file):384kB mapped:5820kB dirty:1893584kB writeback:5228kB shmem:0kB shmem_thp: 0kB shmem_pmdmapped: 0kBanon_thp: 0kB writeback_tmp:0kB unstable:0kB pages_scanned:25598673 all_unreclaimable? yes
[737778.727930] Node 0 Normal free:44864kB min:45192kB low:61736kB
high:78280kB active_anon:16kB inactive_anon:76kB active_file:14249324kB inactive_file:1296908kB unevictable:0kB writepending:1308528kB present:16777216kB managed:16544856kB mlocked:0kB slab_reclaimable:562644kB slab_unreclaimable:317504kB kernel_stack:3840kB pagetables:3672kB bounce:0kB free_pcp:20kB local_pcp:0kB free_cma:0kB
[737778.728066] lowmem_reserve[]: 0 0 0 0 [737778.728100] Node 1 DMA free:15896kB min:40kB low:52kB high:64kB
active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15996kB managed:15896kB mlocked:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[737778.728228] lowmem_reserve[]: 0 3216 16044 16044 [737778.728263] Node 1 DMA32 free:60300kB min:8996kB low:12288kB
high:15580kB active_anon:4kB inactive_anon:4kB active_file:2660988kB inactive_file:474956kB unevictable:0kB writepending:475116kB present:3378660kB managed:3304720kB mlocked:0kB slab_reclaimable:83612kB slab_unreclaimable:16668kB kernel_stack:320kB pagetables:16kB bounce:0kB free_pcp:4kB local_pcp:4kB free_cma:0kB
[737778.728397] lowmem_reserve[]: 0 0 12827 12827 [737778.728431] Node 1 Normal free:35840kB min:35876kB low:49008kB
high:62140kB active_anon:76kB inactive_anon:116kB active_file:10770304kB inactive_file:1420308kB unevictable:0kB writepending:1423696kB present:13369344kB managed:13135424kB mlocked:0kB slab_reclaimable:411212kB slab_unreclaimable:439220kB kernel_stack:2864kB pagetables:3188kB bounce:0kB free_pcp:164kB local_pcp:36kB free_cma:0kB
[737778.728568] lowmem_reserve[]: 0 0 0 0
[737778.728601] Node 0 Normal: 11208*4kB (UME) 4*8kB (U) 0*16kB 0*32kB
0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 44864kB
[737778.728686] Node 1 DMA: 0*4kB 1*8kB (U) 1*16kB (U) 0*32kB 2*64kB
(U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB
(M) = 15896kB
[737778.728786] Node 1 DMA32: 11759*4kB (UME) 1658*8kB (UM) 0*16kB
0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB =
60300kB
[737778.728875] Node 1 Normal: 7984*4kB (UME) 470*8kB (UME) 3*16kB (U)
3*32kB (UM) 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB
= 35840kB
[737778.728973] Node 0 hugepages_total=0 hugepages_free=0
hugepages_surp=0 hugepages_size=1048576kB
[737778.729019] Node 0 hugepages_total=0 hugepages_free=0
hugepages_surp=0 hugepages_size=2048kB
[737778.729065] Node 1 hugepages_total=0 hugepages_free=0
hugepages_surp=0 hugepages_size=1048576kB
[737778.729111] Node 1 hugepages_total=0 hugepages_free=0
hugepages_surp=0 hugepages_size=2048kB
[737778.729156] 7718841 total pagecache pages
[737778.729179] 68 pages in swap cache
[737778.729202] Swap cache stats: add 193888, delete 193820, find 160188/213014
[737778.729231] Free swap = 48045076kB
[737778.729254] Total swap = 48300028kB
[737778.729277] 8385304 pages RAM
[737778.729299] 0 pages HighMem/MovableOnly
[737778.729322] 135080 pages reserved
[737778.729344] 0 pages hwpoisoned
[737778.729365] [ pid ] uid tgid total_vm rss nr_ptes nr_pmds
swapents oom_score_adj name
[737778.729417] [ 1927] 0 1927 9941 447 22 3
299 -1000 systemd-udevd
[737778.729465] [ 2812] 0 2812 9289 412 23 4
161 0 rpcbind
[737778.729512] [ 2836] 102 2836 9320 414 23 3
151 0 rpc.statd
[737778.729560] [ 2851] 104 2851 162257 276 75 3
7489 0 apt-cacher-ng
[737778.729608] [ 2856] 0 2856 13796 345 31 3
167 -1000 sshd
[737778.729655] [ 2857] 0 2857 64668 504 27 4
355 0 rsyslogd
[737778.729702] [ 2858] 0 2858 6876 518 18 3
83 0 cron
[737778.729748] [ 2859] 0 2859 4756 360 14 3
44 0 atd
[737778.729795] [ 2860] 0 2860 7059 523 18 3
591 0 smartd
[737778.729842] [ 2864] 0 2864 7082 559 19 4
96 0 systemd-logind
[737778.729890] [ 2865] 106 2865 10563 528 24 3
110 -900 dbus-daemon
[737778.729938] [ 2925] 0 2925 3604 421 12 3
38 0 agetty
[737778.729985] [ 2974] 0 2974 4852 365 13 3
73 0 irqbalance
[737778.730032] [ 2976] 105 2976 14299 496 29 3
1534 0 snmpd
[737778.730078] [ 2992] 0 2992 3180 227 11 3
38 0 mcelog
[737778.730125] [ 3095] 0 3095 26571 344 43 3
259 0 sfcbd
[737778.730172] [ 3172] 0 3172 20392 261 40 3
236 0 sfcbd
[737778.730219] [ 3248] 0 3248 22441 0 41 3
238 0 sfcbd
[737778.730265] [ 3249] 0 3249 39376 155 44 3
357 0 sfcbd
[737778.730312] [ 3450] 0 3450 39377 104 44 3
244 0 sfcbd
[737778.730359] [ 3467] 0 3467 58324 301 46 3
284 0 sfcbd
[737778.730405] [ 3548] 0 3548 262686 643 66 4
4097 0 dsm_sa_datamgrd
[737778.730453] [ 3563] 101 3563 13312 403 29 3
162 0 exim4
[737778.730499] [ 3576] 107 3576 7293 493 19 3
148 0 ntpd
[737778.730546] [ 3585] 0 3585 61531 577 117 3
496 0 winbindd
[737778.730593] [ 3586] 0 3586 61531 578 118 3
512 0 winbindd
[737778.730640] [ 3651] 0 3651 48584 566 36 3
487 0 dsm_sa_eventmgr
[737778.730688] [ 3674] 0 3674 99593 576 47 3
1402 0 dsm_sa_snmpd
[737778.730736] [ 3717] 0 3717 7923 285 18 3
115 0 dsm_om_connsvcd
[737778.730784] [ 3718] 0 3718 740234 1744 202 7
30685 0 dsm_om_connsvcd
[737778.730832] [ 3736] 0 3736 178651 0 55 3
3789 0 dsm_sa_datamgrd
[737778.730880] [ 4056] 0 4056 26472 498 57 3
252 0 sshd
[737778.730926] [ 4060] 1000 4060 8973 501 23 3
184 0 systemd
[737778.730973] [ 4061] 1000 4061 15702 0 34 4
612 0 (sd-pam)
[737778.731020] [ 4063] 1000 4063 26472 158 54 3
260 0 sshd
[737778.731067] [ 4064] 1000 4064 6041 739 16 3
686 0 bash
[737778.731113] [ 4083] 1000 4083 16853 493 37 3
128 0 su
[737778.731160] [ 4084] 0 4084 5501 756 15 3
160 0 bash
[737778.731207] [15150] 0 15150 3309 678 10 3
57 0 run_mirror.sh
[737778.731256] [24296] 0 24296 1450 139 8 3
23 0 flock
[737778.731302] [24297] 0 24297 9576 622 22 3
3990 0 rsync
[737778.731349] [24298] 0 24298 7552 541 18 3
1073 0 rsync
[737778.731395] [24299] 0 24299 9522 401 22 3
2416 0 rsync
[737778.731445] [25910] 0 25910 10257 522 23 3
81 0 systemd-journal
[737778.731494] [25940] 0 25940 16365 617 37 3
126 0 cron
[737778.731540] Out of memory: Kill process 3718 (dsm_om_connsvcd)
score 1 or sacrifice child
[737778.731644] Killed process 3718 (dsm_om_connsvcd)
total-vm:2960936kB, anon-rss:0kB, file-rss:6976kB, shmem-rss:0kB
[737778.768375] oom_reaper: reaped process 3718 (dsm_om_connsvcd), nowanon-rss:0kB, file-rss:0kB, shmem-rss:0kB
Quoted 15 lines · Vlastimil Babka
Quoted 8 lines · E V
After the system panic'd yesterday I booted back into 4.8.4 and restarted the rsync's. I'm away on vacation next week, so when I get back I'll get rc4 or rc5 and try again. In the mean time here's data from the system running 4.8.4 without problems for about a day. I'm not familiar with xxd and didn't see a -e option, so used -E:
xxd -E -g8 -c8/proc/kpagecount| cut -d" " -f2 | sort | uniq -c 8258633 0000000000000000
216440 0100000000000000The lack of -e means it's big endian, which is not a big issue. So here most of memory is free, some pages have just one pin, and only relatively few have more. The vmstats also doesn't show anything bad, so we'll have to wait if something appears within the week, or after you try 4.9 again. Thanks.
Quoted 5 lines · E V
System is an intel dual socket Xeon E5620, 7500/5520/5500/X58 ICH10 family according to lspci. Anyways 4.8.4 OOM'd while I was gone. I'll download the current 4.9rc and reboot, but in the mean time here's xxd, vmstat & kern.log output:
8532039 0000000000000000
Hmm this would suggest that the memory is mostly free. But not according to vmstat. Is it possible you mistakenly provided the xxd from a fresh boot, but vmstat from after the OOM?
But sure, a page_count() of zero is a reason why __isolate_lru_page() would fail due to its get_page_unless_zero(). The question is then how could it drop to zero without being freed at the same time, as put_page() does.
I was going to suspect commit 83929372f6 and a page_ref_sub() it adds to delete_from_page_cache(), but that's since 4.8 and you mention problems since 4.7.
Anyway it might be worth enabling CONFIG_DEBUG_VM as the relevant code usually has VM_BUG_ONs.
Vlastimil
Quoted 374 lines
9324 0100000000000000 2226 0200000000000000 405 0300000000000000 80 0400000000000000 34 0500000000000000 48 0600000000000000 17 0700000000000000 17 0800000000000000 32 0900000000000000 19 0a00000000000000 1 0c00000000000000 1 0d00000000000000 1 0e00000000000000 12 1000000000000000 8 1100000000000000 32 1200000000000000 10 1300000000000000 2 1400000000000000 11 1500000000000000 12 1600000000000000 7 1700000000000000 3 1800000000000000 5 1900000000000000 6 1a00000000000000 11 1b00000000000000 22 1c00000000000000 3 1d00000000000000 19 1e00000000000000 21 1f00000000000000 18 2000000000000000 28 2100000000000000 40 2200000000000000 38 2300000000000000 85 2400000000000000 59 250000000000000040520
81ffffffffffffff
/proc/vmstat:nr_free_pages60965nr_zone_inactive_anon4646nr_zone_active_anon3265nr_zone_inactive_file633882nr_zone_active_file7017458nr_zone_unevictable0nr_zone_write_pending0nr_mlock0nr_slab_reclaimable299205nr_slab_unreclaimable195497nr_page_table_pages935nr_kernel_stack4976nr_bounce0numa_hit3577063288numa_miss541393191numa_foreign541393191numa_interleave19415numa_local3577063288numa_other0nr_free_cma0nr_inactive_anon4646nr_active_anon3265nr_inactive_file633882nr_active_file7017458nr_unevictable0nr_isolated_anon0nr_isolated_file0nr_pages_scanned0workingset_refault42685891workingset_activate15247281workingset_nodereclaim26375216nr_anon_pages5067nr_mapped5630nr_file_pages7654746nr_dirty0nr_writeback0nr_writeback_temp0nr_shmem2504nr_shmem_hugepages0nr_shmem_pmdmapped0nr_anon_transparent_hugepages0nr_unstable0nr_vmscan_write5243750485nr_vmscan_immediate_reclaim4207633857nr_dirtied1839143430nr_written1832626107nr_dirty_threshold1147728nr_dirty_background_threshold151410
pgpgin 166731189
pgpgout 7328142335
pswpin 98608
pswpout 117794pgalloc_dma29504pgalloc_dma321006726216pgalloc_normal5275218188pgalloc_movable0allocstall_dma0allocstall_dma320allocstall_normal36461allocstall_movable5867pgskip_dma0pgskip_dma320pgskip_normal6417890pgskip_movable0
pgfree 6309223401
pgactivate 35076483
pgdeactivate 63556974
pgfault 35753842
pgmajfault 69126
pglazyfreed 0
pgrefill 70008598pgsteal_kswapd3567289713pgsteal_direct5878057pgscan_kswapd9059309872pgscan_direct4239367903pgscan_direct_throttle0zone_reclaim_failed0
pginodesteal 102916slabs_scanned460790262kswapd_inodesteal9130243kswapd_low_wmark_hit_quickly10634373kswapd_high_wmark_hit_quickly7348173
pageoutrun 18349115
pgrotated 16291322drop_pagecache0drop_slab0pgmigrate_success18912908pgmigrate_fail63382146compact_migrate_scanned2986269789compact_free_scanned190451505123compact_isolated109549437compact_stall3544compact_fail8compact_success3536compact_daemon_wake1403515htlb_buddy_alloc_success0htlb_buddy_alloc_fail0unevictable_pgs_culled12473unevictable_pgs_scanned0unevictable_pgs_rescued11979unevictable_pgs_mlocked14556unevictable_pgs_munlocked14556unevictable_pgs_cleared0unevictable_pgs_stranded0thp_fault_alloc0thp_fault_fallback0thp_collapse_alloc0thp_collapse_alloc_failed0thp_file_alloc0thp_file_mapped0thp_split_page0thp_split_page_failed0thp_deferred_split_page0thp_split_pmd0thp_zero_page_alloc0thp_zero_page_alloc_failed0kern.log OOM message:
[737778.724194] snmpd invoked oom-killer: gfp_mask=0x24200ca(GFP_HIGHUSER_MOVABLE), order=0, oom_score_adj=0 [737778.724246] snmpd cpuset=/ mems_allowed=0-1 [737778.724278] CPU: 15 PID: 2976 Comm: snmpd Tainted: G W I 4.8.4 #1 [737778.724352] 0000000000000000 ffffffff81292069 ffff88041e043c48 ffff88041e043c48 [737778.724403] ffffffff8118d1f6 ffff88041dd70fc0 ffff88041e043c48 000000000136236f [737778.724454] ffffffff8170e11e 0000000000000001 ffffffff8112a700 000000000000030f [737778.724505] Call Trace: [737778.724533] [<ffffffff81292069>] ? dump_stack+0x46/0x5d [737778.727077] [<ffffffff8118d1f6>] ? dump_header.isra.16+0x56/0x185 [737778.727108] [<ffffffff8112a700>] ? oom_kill_process+0x210/0x3c0 [737778.727136] [<ffffffff8112ac4b>] ? out_of_memory+0x34b/0x420 [737778.727165] [<ffffffff8112fcca>] ? __alloc_pages_nodemask+0xd9a/0xde0 [737778.727195] [<ffffffff811768e1>] ? alloc_pages_vma+0xc1/0x240 [737778.727223] [<ffffffff81126512>] ? pagecache_get_page+0x22/0x230 [737778.727253] [<ffffffff81169f44>] ? __read_swap_cache_async+0x104/0x180 [737778.727282] [<ffffffff81169fcf>] ? read_swap_cache_async+0xf/0x30 [737778.727311] [<ffffffff8116a0dc>] ? swapin_readahead+0xec/0x1a0 [737778.727340] [<ffffffff81156270>] ? do_swap_page+0x420/0x5c0 [737778.727369] [<ffffffff813f36d8>] ? SYSC_recvfrom+0xa8/0x110 [737778.727397] [<ffffffff81157a39>] ? handle_mm_fault+0x629/0xe30 [737778.727426] [<ffffffff81048fc5>] ? __do_page_fault+0x1b5/0x480 [737778.727456] [<ffffffff814fbaa2>] ? page_fault+0x22/0x30 [737778.727497] Mem-Info: [737778.727524] active_anon:24 inactive_anon:49 isolated_anon:0 [737778.727524] active_file:6920154 inactive_file:798043 isolated_file:576 [737778.727524] unevictable:0 dirty:800528 writeback:1307 unstable:0 [737778.727524] slab_reclaimable:264367 slab_unreclaimable:193348 [737778.727524] mapped:4063 shmem:0 pagetables:1719 bounce:0 [737778.727524] free:39225 free_pcp:47 free_cma:0 [737778.727677] Node 0 active_anon:16kB inactive_anon:76kBactive_file:14249324kB inactive_file:1296908kB unevictable:0kB isolated(anon):0kB isolated(file):1920kB mapped:10432kB dirty:1308528kB writeback:0kB shmem:0kB
shmem_thp: 0kBshmem_pmdmapped: 0kBanon_thp: 0kB writeback_tmp:0kB unstable:0kB pages_scanned:23557303all_unreclaimable? yes[737778.727806] Node 1 active_anon:80kB inactive_anon:120kBactive_file:13431292kB inactive_file:1895264kB unevictable:0kB isolated(anon):0kB isolated(file):384kB mapped:5820kB dirty:1893584kB writeback:5228kB shmem:0kB
shmem_thp: 0kBshmem_pmdmapped: 0kBanon_thp: 0kB writeback_tmp:0kB unstable:0kB pages_scanned:25598673all_unreclaimable? yes[737778.727930] Node 0 Normal free:44864kB min:45192kB low:61736kBhigh:78280kB active_anon:16kB inactive_anon:76kB active_file:14249324kB inactive_file:1296908kB unevictable:0kB writepending:1308528kB present:16777216kB managed:16544856kB mlocked:0kB slab_reclaimable:562644kB slab_unreclaimable:317504kB kernel_stack:3840kB pagetables:3672kB bounce:0kB free_pcp:20kB local_pcp:0kB free_cma:0kB
[737778.728066] lowmem_reserve[]: 0 0 0 0 [737778.728100] Node 1 DMA free:15896kB min:40kB low:52kB high:64kBactive_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15996kB managed:15896kB mlocked:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[737778.728228] lowmem_reserve[]: 0 3216 16044 16044 [737778.728263] Node 1 DMA32 free:60300kB min:8996kB low:12288kBhigh:15580kB active_anon:4kB inactive_anon:4kB active_file:2660988kB inactive_file:474956kB unevictable:0kB writepending:475116kB present:3378660kB managed:3304720kB mlocked:0kB slab_reclaimable:83612kB slab_unreclaimable:16668kB kernel_stack:320kB pagetables:16kB bounce:0kB free_pcp:4kB local_pcp:4kB free_cma:0kB
[737778.728397] lowmem_reserve[]: 0 0 12827 12827 [737778.728431] Node 1 Normal free:35840kB min:35876kB low:49008kBhigh:62140kB active_anon:76kB inactive_anon:116kB active_file:10770304kB inactive_file:1420308kB unevictable:0kB writepending:1423696kB present:13369344kB managed:13135424kB mlocked:0kB slab_reclaimable:411212kB slab_unreclaimable:439220kB kernel_stack:2864kB pagetables:3188kB bounce:0kB free_pcp:164kB local_pcp:36kB free_cma:0kB
[737778.728568] lowmem_reserve[]: 0 0 0 0 [737778.728601] Node 0 Normal: 11208*4kB (UME) 4*8kB (U) 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 44864kB [737778.728686] Node 1 DMA: 0*4kB 1*8kB (U) 1*16kB (U) 0*32kB 2*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15896kB [737778.728786] Node 1 DMA32: 11759*4kB (UME) 1658*8kB (UM) 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 60300kB [737778.728875] Node 1 Normal: 7984*4kB (UME) 470*8kB (UME) 3*16kB (U) 3*32kB (UM) 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 35840kB [737778.728973] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB [737778.729019] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB [737778.729065] Node 1 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB [737778.729111] Node 1 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB [737778.729156] 7718841 total pagecache pages [737778.729179] 68 pages in swap cache [737778.729202] Swap cache stats: add 193888, delete 193820, find 160188/213014 [737778.729231] Free swap = 48045076kB [737778.729254] Total swap = 48300028kB [737778.729277] 8385304 pages RAM [737778.729299] 0 pages HighMem/MovableOnly [737778.729322] 135080 pages reserved [737778.729344] 0 pages hwpoisoned [737778.729365] [ pid ] uid tgid total_vm rss nr_ptes nr_pmds swapents oom_score_adj name [737778.729417] [ 1927] 0 1927 9941 447 22 3 299 -1000 systemd-udevd [737778.729465] [ 2812] 0 2812 9289 412 23 4 161 0 rpcbind [737778.729512] [ 2836] 102 2836 9320 414 23 3 151 0 rpc.statd [737778.729560] [ 2851] 104 2851 162257 276 75 3 7489 0 apt-cacher-ng [737778.729608] [ 2856] 0 2856 13796 345 31 3 167 -1000 sshd [737778.729655] [ 2857] 0 2857 64668 504 27 4 355 0 rsyslogd [737778.729702] [ 2858] 0 2858 6876 518 18 3 83 0 cron [737778.729748] [ 2859] 0 2859 4756 360 14 3 44 0 atd [737778.729795] [ 2860] 0 2860 7059 523 18 3 591 0 smartd [737778.729842] [ 2864] 0 2864 7082 559 19 4 96 0 systemd-logind [737778.729890] [ 2865] 106 2865 10563 528 24 3 110 -900 dbus-daemon [737778.729938] [ 2925] 0 2925 3604 421 12 3 38 0 agetty [737778.729985] [ 2974] 0 2974 4852 365 13 3 73 0 irqbalance [737778.730032] [ 2976] 105 2976 14299 496 29 3 1534 0 snmpd [737778.730078] [ 2992] 0 2992 3180 227 11 3 38 0 mcelog [737778.730125] [ 3095] 0 3095 26571 344 43 3 259 0 sfcbd [737778.730172] [ 3172] 0 3172 20392 261 40 3 236 0 sfcbd [737778.730219] [ 3248] 0 3248 22441 0 41 3 238 0 sfcbd [737778.730265] [ 3249] 0 3249 39376 155 44 3 357 0 sfcbd [737778.730312] [ 3450] 0 3450 39377 104 44 3 244 0 sfcbd [737778.730359] [ 3467] 0 3467 58324 301 46 3 284 0 sfcbd [737778.730405] [ 3548] 0 3548 262686 643 66 4 4097 0 dsm_sa_datamgrd [737778.730453] [ 3563] 101 3563 13312 403 29 3 162 0 exim4 [737778.730499] [ 3576] 107 3576 7293 493 19 3 148 0 ntpd [737778.730546] [ 3585] 0 3585 61531 577 117 3 496 0 winbindd [737778.730593] [ 3586] 0 3586 61531 578 118 3 512 0 winbindd [737778.730640] [ 3651] 0 3651 48584 566 36 3 487 0 dsm_sa_eventmgr [737778.730688] [ 3674] 0 3674 99593 576 47 3 1402 0 dsm_sa_snmpd [737778.730736] [ 3717] 0 3717 7923 285 18 3 115 0 dsm_om_connsvcd [737778.730784] [ 3718] 0 3718 740234 1744 202 7 30685 0 dsm_om_connsvcd [737778.730832] [ 3736] 0 3736 178651 0 55 3 3789 0 dsm_sa_datamgrd [737778.730880] [ 4056] 0 4056 26472 498 57 3 252 0 sshd [737778.730926] [ 4060] 1000 4060 8973 501 23 3 184 0 systemd [737778.730973] [ 4061] 1000 4061 15702 0 34 4 612 0 (sd-pam) [737778.731020] [ 4063] 1000 4063 26472 158 54 3 260 0 sshd [737778.731067] [ 4064] 1000 4064 6041 739 16 3 686 0 bash [737778.731113] [ 4083] 1000 4083 16853 493 37 3 128 0 su [737778.731160] [ 4084] 0 4084 5501 756 15 3 160 0 bash [737778.731207] [15150] 0 15150 3309 678 10 3 57 0 run_mirror.sh [737778.731256] [24296] 0 24296 1450 139 8 3 23 0 flock [737778.731302] [24297] 0 24297 9576 622 22 3 3990 0 rsync [737778.731349] [24298] 0 24298 7552 541 18 3 1073 0 rsync [737778.731395] [24299] 0 24299 9522 401 22 3 2416 0 rsync [737778.731445] [25910] 0 25910 10257 522 23 3 81 0 systemd-journal [737778.731494] [25940] 0 25940 16365 617 37 3 126 0 cron [737778.731540] Out of memory: Kill process 3718 (dsm_om_connsvcd) score 1 or sacrifice child [737778.731644] Killed process 3718 (dsm_om_connsvcd) total-vm:2960936kB, anon-rss:0kB, file-rss:6976kB, shmem-rss:0kB [737778.768375] oom_reaper: reaped process 3718 (dsm_om_connsvcd), nowanon-rss:0kB, file-rss:0kB, shmem-rss:0kB
Quoted 15 lines · Vlastimil Babka
Quoted 8 lines · E V
After the system panic'd yesterday I booted back into 4.8.4 and restarted the rsync's. I'm away on vacation next week, so when I get back I'll get rc4 or rc5 and try again. In the mean time here's data from the system running 4.8.4 without problems for about a day. I'm not familiar with xxd and didn't see a -e option, so used -E:
xxd -E -g8 -c8/proc/kpagecount| cut -d" " -f2 | sort | uniq -c 8258633 0000000000000000
216440 0100000000000000The lack of -e means it's big endian, which is not a big issue. So here most of memory is free, some pages have just one pin, and only relatively few have more. The vmstats also doesn't show anything bad, so we'll have to wait if something appears within the week, or after you try 4.9 again. Thanks.
Pretty sure it was the system after the OOM just did a history search to check, though it is 3 days afterwards and several OOMs killed several processes in somewhat rapid succession, I just listed the 1st. I'll turn on CONFIG_DEBUG_VM and reboot again.
Quoted 400 lines · Vlastimil Babka
Quoted 5 lines · E V
System is an intel dual socket Xeon E5620, 7500/5520/5500/X58 ICH10 family according to lspci. Anyways 4.8.4 OOM'd while I was gone. I'll download the current 4.9rc and reboot, but in the mean time here's xxd, vmstat & kern.log output:
8532039 0000000000000000Hmm this would suggest that the memory is mostly free. But not according to vmstat. Is it possible you mistakenly provided the xxd from a fresh boot, but vmstat from after the OOM?
But sure, a
page_count()of zero is a reason why__isolate_lru_page()would fail due to itsget_page_unless_zero(). The question is then how could it drop to zero without being freed at the same time, asput_page()does.I was going to suspect commit
83929372f6and apage_ref_sub()it adds todelete_from_page_cache(), but that's since 4.8 and you mention problems since 4.7.Anyway it might be worth enabling
CONFIG_DEBUG_VMas the relevant code usually hasVM_BUG_ONs.Vlastimil
Quoted 374 lines
9324 0100000000000000 2226 0200000000000000 405 0300000000000000 80 0400000000000000 34 0500000000000000 48 0600000000000000 17 0700000000000000 17 0800000000000000 32 0900000000000000 19 0a00000000000000 1 0c00000000000000 1 0d00000000000000 1 0e00000000000000 12 1000000000000000 8 1100000000000000 32 1200000000000000 10 1300000000000000 2 1400000000000000 11 1500000000000000 12 1600000000000000 7 1700000000000000 3 1800000000000000 5 1900000000000000 6 1a00000000000000 11 1b00000000000000 22 1c00000000000000 3 1d00000000000000 19 1e00000000000000 21 1f00000000000000 18 2000000000000000 28 2100000000000000 40 2200000000000000 38 2300000000000000 85 2400000000000000 59 250000000000000040520
81ffffffffffffff
/proc/vmstat:nr_free_pages60965nr_zone_inactive_anon4646nr_zone_active_anon3265nr_zone_inactive_file633882nr_zone_active_file7017458nr_zone_unevictable0nr_zone_write_pending0nr_mlock0nr_slab_reclaimable299205nr_slab_unreclaimable195497nr_page_table_pages935nr_kernel_stack4976nr_bounce0numa_hit3577063288numa_miss541393191numa_foreign541393191numa_interleave19415numa_local3577063288numa_other0nr_free_cma0nr_inactive_anon4646nr_active_anon3265nr_inactive_file633882nr_active_file7017458nr_unevictable0nr_isolated_anon0nr_isolated_file0nr_pages_scanned0workingset_refault42685891workingset_activate15247281workingset_nodereclaim26375216nr_anon_pages5067nr_mapped5630nr_file_pages7654746nr_dirty0nr_writeback0nr_writeback_temp0nr_shmem2504nr_shmem_hugepages0nr_shmem_pmdmapped0nr_anon_transparent_hugepages0nr_unstable0nr_vmscan_write5243750485nr_vmscan_immediate_reclaim4207633857nr_dirtied1839143430nr_written1832626107nr_dirty_threshold1147728nr_dirty_background_threshold151410
pgpgin 166731189
pgpgout 7328142335
pswpin 98608
pswpout 117794pgalloc_dma29504pgalloc_dma321006726216pgalloc_normal5275218188pgalloc_movable0allocstall_dma0allocstall_dma320allocstall_normal36461allocstall_movable5867pgskip_dma0pgskip_dma320pgskip_normal6417890pgskip_movable0
pgfree 6309223401
pgactivate 35076483
pgdeactivate 63556974
pgfault 35753842
pgmajfault 69126
pglazyfreed 0
pgrefill 70008598pgsteal_kswapd3567289713pgsteal_direct5878057pgscan_kswapd9059309872pgscan_direct4239367903pgscan_direct_throttle0zone_reclaim_failed0
pginodesteal 102916slabs_scanned460790262kswapd_inodesteal9130243kswapd_low_wmark_hit_quickly10634373kswapd_high_wmark_hit_quickly7348173
pageoutrun 18349115
pgrotated 16291322drop_pagecache0drop_slab0pgmigrate_success18912908pgmigrate_fail63382146compact_migrate_scanned2986269789compact_free_scanned190451505123compact_isolated109549437compact_stall3544compact_fail8compact_success3536compact_daemon_wake1403515htlb_buddy_alloc_success0htlb_buddy_alloc_fail0unevictable_pgs_culled12473unevictable_pgs_scanned0unevictable_pgs_rescued11979unevictable_pgs_mlocked14556unevictable_pgs_munlocked14556unevictable_pgs_cleared0unevictable_pgs_stranded0thp_fault_alloc0thp_fault_fallback0thp_collapse_alloc0thp_collapse_alloc_failed0thp_file_alloc0thp_file_mapped0thp_split_page0thp_split_page_failed0thp_deferred_split_page0thp_split_pmd0thp_zero_page_alloc0thp_zero_page_alloc_failed0kern.log OOM message:
[737778.724194] snmpd invoked oom-killer: gfp_mask=0x24200ca(GFP_HIGHUSER_MOVABLE), order=0, oom_score_adj=0 [737778.724246] snmpd cpuset=/ mems_allowed=0-1 [737778.724278] CPU: 15 PID: 2976 Comm: snmpd Tainted: G W I 4.8.4 #1 [737778.724352] 0000000000000000 ffffffff81292069 ffff88041e043c48 ffff88041e043c48 [737778.724403] ffffffff8118d1f6 ffff88041dd70fc0 ffff88041e043c48 000000000136236f [737778.724454] ffffffff8170e11e 0000000000000001 ffffffff8112a700 000000000000030f [737778.724505] Call Trace: [737778.724533] [<ffffffff81292069>] ? dump_stack+0x46/0x5d [737778.727077] [<ffffffff8118d1f6>] ? dump_header.isra.16+0x56/0x185 [737778.727108] [<ffffffff8112a700>] ? oom_kill_process+0x210/0x3c0 [737778.727136] [<ffffffff8112ac4b>] ? out_of_memory+0x34b/0x420 [737778.727165] [<ffffffff8112fcca>] ? __alloc_pages_nodemask+0xd9a/0xde0 [737778.727195] [<ffffffff811768e1>] ? alloc_pages_vma+0xc1/0x240 [737778.727223] [<ffffffff81126512>] ? pagecache_get_page+0x22/0x230 [737778.727253] [<ffffffff81169f44>] ? __read_swap_cache_async+0x104/0x180 [737778.727282] [<ffffffff81169fcf>] ? read_swap_cache_async+0xf/0x30 [737778.727311] [<ffffffff8116a0dc>] ? swapin_readahead+0xec/0x1a0 [737778.727340] [<ffffffff81156270>] ? do_swap_page+0x420/0x5c0 [737778.727369] [<ffffffff813f36d8>] ? SYSC_recvfrom+0xa8/0x110 [737778.727397] [<ffffffff81157a39>] ? handle_mm_fault+0x629/0xe30 [737778.727426] [<ffffffff81048fc5>] ? __do_page_fault+0x1b5/0x480 [737778.727456] [<ffffffff814fbaa2>] ? page_fault+0x22/0x30 [737778.727497] Mem-Info: [737778.727524] active_anon:24 inactive_anon:49 isolated_anon:0 [737778.727524] active_file:6920154 inactive_file:798043 isolated_file:576 [737778.727524] unevictable:0 dirty:800528 writeback:1307 unstable:0 [737778.727524] slab_reclaimable:264367 slab_unreclaimable:193348 [737778.727524] mapped:4063 shmem:0 pagetables:1719 bounce:0 [737778.727524] free:39225 free_pcp:47 free_cma:0 [737778.727677] Node 0 active_anon:16kB inactive_anon:76kBactive_file:14249324kB inactive_file:1296908kB unevictable:0kB isolated(anon):0kB isolated(file):1920kB mapped:10432kB dirty:1308528kB writeback:0kB shmem:0kB
shmem_thp: 0kBshmem_pmdmapped: 0kBanon_thp: 0kB writeback_tmp:0kB unstable:0kB pages_scanned:23557303all_unreclaimable? yes[737778.727806] Node 1 active_anon:80kB inactive_anon:120kBactive_file:13431292kB inactive_file:1895264kB unevictable:0kB isolated(anon):0kB isolated(file):384kB mapped:5820kB dirty:1893584kB writeback:5228kB shmem:0kB
shmem_thp: 0kBshmem_pmdmapped: 0kBanon_thp: 0kB writeback_tmp:0kB unstable:0kB pages_scanned:25598673all_unreclaimable? yes[737778.727930] Node 0 Normal free:44864kB min:45192kB low:61736kBhigh:78280kB active_anon:16kB inactive_anon:76kB active_file:14249324kB inactive_file:1296908kB unevictable:0kB writepending:1308528kB present:16777216kB managed:16544856kB mlocked:0kB slab_reclaimable:562644kB slab_unreclaimable:317504kB kernel_stack:3840kB pagetables:3672kB bounce:0kB free_pcp:20kB local_pcp:0kB free_cma:0kB
[737778.728066] lowmem_reserve[]: 0 0 0 0 [737778.728100] Node 1 DMA free:15896kB min:40kB low:52kB high:64kBactive_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15996kB managed:15896kB mlocked:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[737778.728228] lowmem_reserve[]: 0 3216 16044 16044 [737778.728263] Node 1 DMA32 free:60300kB min:8996kB low:12288kBhigh:15580kB active_anon:4kB inactive_anon:4kB active_file:2660988kB inactive_file:474956kB unevictable:0kB writepending:475116kB present:3378660kB managed:3304720kB mlocked:0kB slab_reclaimable:83612kB slab_unreclaimable:16668kB kernel_stack:320kB pagetables:16kB bounce:0kB free_pcp:4kB local_pcp:4kB free_cma:0kB
[737778.728397] lowmem_reserve[]: 0 0 12827 12827 [737778.728431] Node 1 Normal free:35840kB min:35876kB low:49008kBhigh:62140kB active_anon:76kB inactive_anon:116kB active_file:10770304kB inactive_file:1420308kB unevictable:0kB writepending:1423696kB present:13369344kB managed:13135424kB mlocked:0kB slab_reclaimable:411212kB slab_unreclaimable:439220kB kernel_stack:2864kB pagetables:3188kB bounce:0kB free_pcp:164kB local_pcp:36kB free_cma:0kB
[737778.728568] lowmem_reserve[]: 0 0 0 0 [737778.728601] Node 0 Normal: 11208*4kB (UME) 4*8kB (U) 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 44864kB [737778.728686] Node 1 DMA: 0*4kB 1*8kB (U) 1*16kB (U) 0*32kB 2*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15896kB [737778.728786] Node 1 DMA32: 11759*4kB (UME) 1658*8kB (UM) 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 60300kB [737778.728875] Node 1 Normal: 7984*4kB (UME) 470*8kB (UME) 3*16kB (U) 3*32kB (UM) 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 35840kB [737778.728973] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB [737778.729019] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB [737778.729065] Node 1 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB [737778.729111] Node 1 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB [737778.729156] 7718841 total pagecache pages [737778.729179] 68 pages in swap cache [737778.729202] Swap cache stats: add 193888, delete 193820, find 160188/213014 [737778.729231] Free swap = 48045076kB [737778.729254] Total swap = 48300028kB [737778.729277] 8385304 pages RAM [737778.729299] 0 pages HighMem/MovableOnly [737778.729322] 135080 pages reserved [737778.729344] 0 pages hwpoisoned [737778.729365] [ pid ] uid tgid total_vm rss nr_ptes nr_pmds swapents oom_score_adj name [737778.729417] [ 1927] 0 1927 9941 447 22 3 299 -1000 systemd-udevd [737778.729465] [ 2812] 0 2812 9289 412 23 4 161 0 rpcbind [737778.729512] [ 2836] 102 2836 9320 414 23 3 151 0 rpc.statd [737778.729560] [ 2851] 104 2851 162257 276 75 3 7489 0 apt-cacher-ng [737778.729608] [ 2856] 0 2856 13796 345 31 3 167 -1000 sshd [737778.729655] [ 2857] 0 2857 64668 504 27 4 355 0 rsyslogd [737778.729702] [ 2858] 0 2858 6876 518 18 3 83 0 cron [737778.729748] [ 2859] 0 2859 4756 360 14 3 44 0 atd [737778.729795] [ 2860] 0 2860 7059 523 18 3 591 0 smartd [737778.729842] [ 2864] 0 2864 7082 559 19 4 96 0 systemd-logind [737778.729890] [ 2865] 106 2865 10563 528 24 3 110 -900 dbus-daemon [737778.729938] [ 2925] 0 2925 3604 421 12 3 38 0 agetty [737778.729985] [ 2974] 0 2974 4852 365 13 3 73 0 irqbalance [737778.730032] [ 2976] 105 2976 14299 496 29 3 1534 0 snmpd [737778.730078] [ 2992] 0 2992 3180 227 11 3 38 0 mcelog [737778.730125] [ 3095] 0 3095 26571 344 43 3 259 0 sfcbd [737778.730172] [ 3172] 0 3172 20392 261 40 3 236 0 sfcbd [737778.730219] [ 3248] 0 3248 22441 0 41 3 238 0 sfcbd [737778.730265] [ 3249] 0 3249 39376 155 44 3 357 0 sfcbd [737778.730312] [ 3450] 0 3450 39377 104 44 3 244 0 sfcbd [737778.730359] [ 3467] 0 3467 58324 301 46 3 284 0 sfcbd [737778.730405] [ 3548] 0 3548 262686 643 66 4 4097 0 dsm_sa_datamgrd [737778.730453] [ 3563] 101 3563 13312 403 29 3 162 0 exim4 [737778.730499] [ 3576] 107 3576 7293 493 19 3 148 0 ntpd [737778.730546] [ 3585] 0 3585 61531 577 117 3 496 0 winbindd [737778.730593] [ 3586] 0 3586 61531 578 118 3 512 0 winbindd [737778.730640] [ 3651] 0 3651 48584 566 36 3 487 0 dsm_sa_eventmgr [737778.730688] [ 3674] 0 3674 99593 576 47 3 1402 0 dsm_sa_snmpd [737778.730736] [ 3717] 0 3717 7923 285 18 3 115 0 dsm_om_connsvcd [737778.730784] [ 3718] 0 3718 740234 1744 202 7 30685 0 dsm_om_connsvcd [737778.730832] [ 3736] 0 3736 178651 0 55 3 3789 0 dsm_sa_datamgrd [737778.730880] [ 4056] 0 4056 26472 498 57 3 252 0 sshd [737778.730926] [ 4060] 1000 4060 8973 501 23 3 184 0 systemd [737778.730973] [ 4061] 1000 4061 15702 0 34 4 612 0 (sd-pam) [737778.731020] [ 4063] 1000 4063 26472 158 54 3 260 0 sshd [737778.731067] [ 4064] 1000 4064 6041 739 16 3 686 0 bash [737778.731113] [ 4083] 1000 4083 16853 493 37 3 128 0 su [737778.731160] [ 4084] 0 4084 5501 756 15 3 160 0 bash [737778.731207] [15150] 0 15150 3309 678 10 3 57 0 run_mirror.sh [737778.731256] [24296] 0 24296 1450 139 8 3 23 0 flock [737778.731302] [24297] 0 24297 9576 622 22 3 3990 0 rsync [737778.731349] [24298] 0 24298 7552 541 18 3 1073 0 rsync [737778.731395] [24299] 0 24299 9522 401 22 3 2416 0 rsync [737778.731445] [25910] 0 25910 10257 522 23 3 81 0 systemd-journal [737778.731494] [25940] 0 25940 16365 617 37 3 126 0 cron [737778.731540] Out of memory: Kill process 3718 (dsm_om_connsvcd) score 1 or sacrifice child [737778.731644] Killed process 3718 (dsm_om_connsvcd) total-vm:2960936kB, anon-rss:0kB, file-rss:6976kB, shmem-rss:0kB [737778.768375] oom_reaper: reaped process 3718 (dsm_om_connsvcd), nowanon-rss:0kB, file-rss:0kB, shmem-rss:0kB
Quoted 15 lines · Vlastimil Babka
Quoted 8 lines · E V
After the system panic'd yesterday I booted back into 4.8.4 and restarted the rsync's. I'm away on vacation next week, so when I get back I'll get rc4 or rc5 and try again. In the mean time here's data from the system running 4.8.4 without problems for about a day. I'm not familiar with xxd and didn't see a -e option, so used -E:
xxd -E -g8 -c8/proc/kpagecount| cut -d" " -f2 | sort | uniq -c 8258633 0000000000000000
216440 0100000000000000The lack of -e means it's big endian, which is not a big issue. So here most of memory is free, some pages have just one pin, and only relatively few have more. The vmstats also doesn't show anything bad, so we'll have to wait if something appears within the week, or after you try 4.9 again. Thanks.
System panic'd overnight running 4.9rc5 & rsync. Attached a photo of the stack trace, and the 38 call traces in a 2 minute window shortly before, to the bugzilla case for those not on it's e-mail list:
https://bugzilla.kernel.org/show_bug.cgi?id=186671
Quoted 406 lines · E V
Pretty sure it was the system after the OOM just did a history search to check, though it is 3 days afterwards and several OOMs killed several processes in somewhat rapid succession, I just listed the 1st. I'll turn on
CONFIG_DEBUG_VMand reboot again.Quoted 400 lines · Vlastimil Babka
Quoted 5 lines · E V
System is an intel dual socket Xeon E5620, 7500/5520/5500/X58 ICH10 family according to lspci. Anyways 4.8.4 OOM'd while I was gone. I'll download the current 4.9rc and reboot, but in the mean time here's xxd, vmstat & kern.log output:
8532039 0000000000000000Hmm this would suggest that the memory is mostly free. But not according to vmstat. Is it possible you mistakenly provided the xxd from a fresh boot, but vmstat from after the OOM?
But sure, a
page_count()of zero is a reason why__isolate_lru_page()would fail due to itsget_page_unless_zero(). The question is then how could it drop to zero without being freed at the same time, asput_page()does.I was going to suspect commit
83929372f6and apage_ref_sub()it adds todelete_from_page_cache(), but that's since 4.8 and you mention problems since 4.7.Anyway it might be worth enabling
CONFIG_DEBUG_VMas the relevant code usually hasVM_BUG_ONs.Vlastimil
Quoted 374 lines
9324 0100000000000000 2226 0200000000000000 405 0300000000000000 80 0400000000000000 34 0500000000000000 48 0600000000000000 17 0700000000000000 17 0800000000000000 32 0900000000000000 19 0a00000000000000 1 0c00000000000000 1 0d00000000000000 1 0e00000000000000 12 1000000000000000 8 1100000000000000 32 1200000000000000 10 1300000000000000 2 1400000000000000 11 1500000000000000 12 1600000000000000 7 1700000000000000 3 1800000000000000 5 1900000000000000 6 1a00000000000000 11 1b00000000000000 22 1c00000000000000 3 1d00000000000000 19 1e00000000000000 21 1f00000000000000 18 2000000000000000 28 2100000000000000 40 2200000000000000 38 2300000000000000 85 2400000000000000 59 250000000000000040520
81ffffffffffffff
/proc/vmstat:nr_free_pages60965nr_zone_inactive_anon4646nr_zone_active_anon3265nr_zone_inactive_file633882nr_zone_active_file7017458nr_zone_unevictable0nr_zone_write_pending0nr_mlock0nr_slab_reclaimable299205nr_slab_unreclaimable195497nr_page_table_pages935nr_kernel_stack4976nr_bounce0numa_hit3577063288numa_miss541393191numa_foreign541393191numa_interleave19415numa_local3577063288numa_other0nr_free_cma0nr_inactive_anon4646nr_active_anon3265nr_inactive_file633882nr_active_file7017458nr_unevictable0nr_isolated_anon0nr_isolated_file0nr_pages_scanned0workingset_refault42685891workingset_activate15247281workingset_nodereclaim26375216nr_anon_pages5067nr_mapped5630nr_file_pages7654746nr_dirty0nr_writeback0nr_writeback_temp0nr_shmem2504nr_shmem_hugepages0nr_shmem_pmdmapped0nr_anon_transparent_hugepages0nr_unstable0nr_vmscan_write5243750485nr_vmscan_immediate_reclaim4207633857nr_dirtied1839143430nr_written1832626107nr_dirty_threshold1147728nr_dirty_background_threshold151410
pgpgin 166731189
pgpgout 7328142335
pswpin 98608
pswpout 117794pgalloc_dma29504pgalloc_dma321006726216pgalloc_normal5275218188pgalloc_movable0allocstall_dma0allocstall_dma320allocstall_normal36461allocstall_movable5867pgskip_dma0pgskip_dma320pgskip_normal6417890pgskip_movable0
pgfree 6309223401
pgactivate 35076483
pgdeactivate 63556974
pgfault 35753842
pgmajfault 69126
pglazyfreed 0
pgrefill 70008598pgsteal_kswapd3567289713pgsteal_direct5878057pgscan_kswapd9059309872pgscan_direct4239367903pgscan_direct_throttle0zone_reclaim_failed0
pginodesteal 102916slabs_scanned460790262kswapd_inodesteal9130243kswapd_low_wmark_hit_quickly10634373kswapd_high_wmark_hit_quickly7348173
pageoutrun 18349115
pgrotated 16291322drop_pagecache0drop_slab0pgmigrate_success18912908pgmigrate_fail63382146compact_migrate_scanned2986269789compact_free_scanned190451505123compact_isolated109549437compact_stall3544compact_fail8compact_success3536compact_daemon_wake1403515htlb_buddy_alloc_success0htlb_buddy_alloc_fail0unevictable_pgs_culled12473unevictable_pgs_scanned0unevictable_pgs_rescued11979unevictable_pgs_mlocked14556unevictable_pgs_munlocked14556unevictable_pgs_cleared0unevictable_pgs_stranded0thp_fault_alloc0thp_fault_fallback0thp_collapse_alloc0thp_collapse_alloc_failed0thp_file_alloc0thp_file_mapped0thp_split_page0thp_split_page_failed0thp_deferred_split_page0thp_split_pmd0thp_zero_page_alloc0thp_zero_page_alloc_failed0kern.log OOM message:
[737778.724194] snmpd invoked oom-killer: gfp_mask=0x24200ca(GFP_HIGHUSER_MOVABLE), order=0, oom_score_adj=0 [737778.724246] snmpd cpuset=/ mems_allowed=0-1 [737778.724278] CPU: 15 PID: 2976 Comm: snmpd Tainted: G W I 4.8.4 #1 [737778.724352] 0000000000000000 ffffffff81292069 ffff88041e043c48 ffff88041e043c48 [737778.724403] ffffffff8118d1f6 ffff88041dd70fc0 ffff88041e043c48 000000000136236f [737778.724454] ffffffff8170e11e 0000000000000001 ffffffff8112a700 000000000000030f [737778.724505] Call Trace: [737778.724533] [<ffffffff81292069>] ? dump_stack+0x46/0x5d [737778.727077] [<ffffffff8118d1f6>] ? dump_header.isra.16+0x56/0x185 [737778.727108] [<ffffffff8112a700>] ? oom_kill_process+0x210/0x3c0 [737778.727136] [<ffffffff8112ac4b>] ? out_of_memory+0x34b/0x420 [737778.727165] [<ffffffff8112fcca>] ? __alloc_pages_nodemask+0xd9a/0xde0 [737778.727195] [<ffffffff811768e1>] ? alloc_pages_vma+0xc1/0x240 [737778.727223] [<ffffffff81126512>] ? pagecache_get_page+0x22/0x230 [737778.727253] [<ffffffff81169f44>] ? __read_swap_cache_async+0x104/0x180 [737778.727282] [<ffffffff81169fcf>] ? read_swap_cache_async+0xf/0x30 [737778.727311] [<ffffffff8116a0dc>] ? swapin_readahead+0xec/0x1a0 [737778.727340] [<ffffffff81156270>] ? do_swap_page+0x420/0x5c0 [737778.727369] [<ffffffff813f36d8>] ? SYSC_recvfrom+0xa8/0x110 [737778.727397] [<ffffffff81157a39>] ? handle_mm_fault+0x629/0xe30 [737778.727426] [<ffffffff81048fc5>] ? __do_page_fault+0x1b5/0x480 [737778.727456] [<ffffffff814fbaa2>] ? page_fault+0x22/0x30 [737778.727497] Mem-Info: [737778.727524] active_anon:24 inactive_anon:49 isolated_anon:0 [737778.727524] active_file:6920154 inactive_file:798043 isolated_file:576 [737778.727524] unevictable:0 dirty:800528 writeback:1307 unstable:0 [737778.727524] slab_reclaimable:264367 slab_unreclaimable:193348 [737778.727524] mapped:4063 shmem:0 pagetables:1719 bounce:0 [737778.727524] free:39225 free_pcp:47 free_cma:0 [737778.727677] Node 0 active_anon:16kB inactive_anon:76kBactive_file:14249324kB inactive_file:1296908kB unevictable:0kB isolated(anon):0kB isolated(file):1920kB mapped:10432kB dirty:1308528kB writeback:0kB shmem:0kB
shmem_thp: 0kBshmem_pmdmapped: 0kBanon_thp: 0kB writeback_tmp:0kB unstable:0kB pages_scanned:23557303all_unreclaimable? yes[737778.727806] Node 1 active_anon:80kB inactive_anon:120kBactive_file:13431292kB inactive_file:1895264kB unevictable:0kB isolated(anon):0kB isolated(file):384kB mapped:5820kB dirty:1893584kB writeback:5228kB shmem:0kB
shmem_thp: 0kBshmem_pmdmapped: 0kBanon_thp: 0kB writeback_tmp:0kB unstable:0kB pages_scanned:25598673all_unreclaimable? yes[737778.727930] Node 0 Normal free:44864kB min:45192kB low:61736kBhigh:78280kB active_anon:16kB inactive_anon:76kB active_file:14249324kB inactive_file:1296908kB unevictable:0kB writepending:1308528kB present:16777216kB managed:16544856kB mlocked:0kB slab_reclaimable:562644kB slab_unreclaimable:317504kB kernel_stack:3840kB pagetables:3672kB bounce:0kB free_pcp:20kB local_pcp:0kB free_cma:0kB
[737778.728066] lowmem_reserve[]: 0 0 0 0 [737778.728100] Node 1 DMA free:15896kB min:40kB low:52kB high:64kBactive_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15996kB managed:15896kB mlocked:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[737778.728228] lowmem_reserve[]: 0 3216 16044 16044 [737778.728263] Node 1 DMA32 free:60300kB min:8996kB low:12288kBhigh:15580kB active_anon:4kB inactive_anon:4kB active_file:2660988kB inactive_file:474956kB unevictable:0kB writepending:475116kB present:3378660kB managed:3304720kB mlocked:0kB slab_reclaimable:83612kB slab_unreclaimable:16668kB kernel_stack:320kB pagetables:16kB bounce:0kB free_pcp:4kB local_pcp:4kB free_cma:0kB
[737778.728397] lowmem_reserve[]: 0 0 12827 12827 [737778.728431] Node 1 Normal free:35840kB min:35876kB low:49008kBhigh:62140kB active_anon:76kB inactive_anon:116kB active_file:10770304kB inactive_file:1420308kB unevictable:0kB writepending:1423696kB present:13369344kB managed:13135424kB mlocked:0kB slab_reclaimable:411212kB slab_unreclaimable:439220kB kernel_stack:2864kB pagetables:3188kB bounce:0kB free_pcp:164kB local_pcp:36kB free_cma:0kB
[737778.728568] lowmem_reserve[]: 0 0 0 0 [737778.728601] Node 0 Normal: 11208*4kB (UME) 4*8kB (U) 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 44864kB [737778.728686] Node 1 DMA: 0*4kB 1*8kB (U) 1*16kB (U) 0*32kB 2*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15896kB [737778.728786] Node 1 DMA32: 11759*4kB (UME) 1658*8kB (UM) 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 60300kB [737778.728875] Node 1 Normal: 7984*4kB (UME) 470*8kB (UME) 3*16kB (U) 3*32kB (UM) 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 35840kB [737778.728973] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB [737778.729019] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB [737778.729065] Node 1 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB [737778.729111] Node 1 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB [737778.729156] 7718841 total pagecache pages [737778.729179] 68 pages in swap cache [737778.729202] Swap cache stats: add 193888, delete 193820, find 160188/213014 [737778.729231] Free swap = 48045076kB [737778.729254] Total swap = 48300028kB [737778.729277] 8385304 pages RAM [737778.729299] 0 pages HighMem/MovableOnly [737778.729322] 135080 pages reserved [737778.729344] 0 pages hwpoisoned [737778.729365] [ pid ] uid tgid total_vm rss nr_ptes nr_pmds swapents oom_score_adj name [737778.729417] [ 1927] 0 1927 9941 447 22 3 299 -1000 systemd-udevd [737778.729465] [ 2812] 0 2812 9289 412 23 4 161 0 rpcbind [737778.729512] [ 2836] 102 2836 9320 414 23 3 151 0 rpc.statd [737778.729560] [ 2851] 104 2851 162257 276 75 3 7489 0 apt-cacher-ng [737778.729608] [ 2856] 0 2856 13796 345 31 3 167 -1000 sshd [737778.729655] [ 2857] 0 2857 64668 504 27 4 355 0 rsyslogd [737778.729702] [ 2858] 0 2858 6876 518 18 3 83 0 cron [737778.729748] [ 2859] 0 2859 4756 360 14 3 44 0 atd [737778.729795] [ 2860] 0 2860 7059 523 18 3 591 0 smartd [737778.729842] [ 2864] 0 2864 7082 559 19 4 96 0 systemd-logind [737778.729890] [ 2865] 106 2865 10563 528 24 3 110 -900 dbus-daemon [737778.729938] [ 2925] 0 2925 3604 421 12 3 38 0 agetty [737778.729985] [ 2974] 0 2974 4852 365 13 3 73 0 irqbalance [737778.730032] [ 2976] 105 2976 14299 496 29 3 1534 0 snmpd [737778.730078] [ 2992] 0 2992 3180 227 11 3 38 0 mcelog [737778.730125] [ 3095] 0 3095 26571 344 43 3 259 0 sfcbd [737778.730172] [ 3172] 0 3172 20392 261 40 3 236 0 sfcbd [737778.730219] [ 3248] 0 3248 22441 0 41 3 238 0 sfcbd [737778.730265] [ 3249] 0 3249 39376 155 44 3 357 0 sfcbd [737778.730312] [ 3450] 0 3450 39377 104 44 3 244 0 sfcbd [737778.730359] [ 3467] 0 3467 58324 301 46 3 284 0 sfcbd [737778.730405] [ 3548] 0 3548 262686 643 66 4 4097 0 dsm_sa_datamgrd [737778.730453] [ 3563] 101 3563 13312 403 29 3 162 0 exim4 [737778.730499] [ 3576] 107 3576 7293 493 19 3 148 0 ntpd [737778.730546] [ 3585] 0 3585 61531 577 117 3 496 0 winbindd [737778.730593] [ 3586] 0 3586 61531 578 118 3 512 0 winbindd [737778.730640] [ 3651] 0 3651 48584 566 36 3 487 0 dsm_sa_eventmgr [737778.730688] [ 3674] 0 3674 99593 576 47 3 1402 0 dsm_sa_snmpd [737778.730736] [ 3717] 0 3717 7923 285 18 3 115 0 dsm_om_connsvcd [737778.730784] [ 3718] 0 3718 740234 1744 202 7 30685 0 dsm_om_connsvcd [737778.730832] [ 3736] 0 3736 178651 0 55 3 3789 0 dsm_sa_datamgrd [737778.730880] [ 4056] 0 4056 26472 498 57 3 252 0 sshd [737778.730926] [ 4060] 1000 4060 8973 501 23 3 184 0 systemd [737778.730973] [ 4061] 1000 4061 15702 0 34 4 612 0 (sd-pam) [737778.731020] [ 4063] 1000 4063 26472 158 54 3 260 0 sshd [737778.731067] [ 4064] 1000 4064 6041 739 16 3 686 0 bash [737778.731113] [ 4083] 1000 4083 16853 493 37 3 128 0 su [737778.731160] [ 4084] 0 4084 5501 756 15 3 160 0 bash [737778.731207] [15150] 0 15150 3309 678 10 3 57 0 run_mirror.sh [737778.731256] [24296] 0 24296 1450 139 8 3 23 0 flock [737778.731302] [24297] 0 24297 9576 622 22 3 3990 0 rsync [737778.731349] [24298] 0 24298 7552 541 18 3 1073 0 rsync [737778.731395] [24299] 0 24299 9522 401 22 3 2416 0 rsync [737778.731445] [25910] 0 25910 10257 522 23 3 81 0 systemd-journal [737778.731494] [25940] 0 25940 16365 617 37 3 126 0 cron [737778.731540] Out of memory: Kill process 3718 (dsm_om_connsvcd) score 1 or sacrifice child [737778.731644] Killed process 3718 (dsm_om_connsvcd) total-vm:2960936kB, anon-rss:0kB, file-rss:6976kB, shmem-rss:0kB [737778.768375] oom_reaper: reaped process 3718 (dsm_om_connsvcd), nowanon-rss:0kB, file-rss:0kB, shmem-rss:0kB
Quoted 15 lines · Vlastimil Babka
Quoted 8 lines · E V
After the system panic'd yesterday I booted back into 4.8.4 and restarted the rsync's. I'm away on vacation next week, so when I get back I'll get rc4 or rc5 and try again. In the mean time here's data from the system running 4.8.4 without problems for about a day. I'm not familiar with xxd and didn't see a -e option, so used -E:
xxd -E -g8 -c8/proc/kpagecount| cut -d" " -f2 | sort | uniq -c 8258633 0000000000000000
216440 0100000000000000The lack of -e means it's big endian, which is not a big issue. So here most of memory is free, some pages have just one pin, and only relatively few have more. The vmstats also doesn't show anything bad, so we'll have to wait if something appears within the week, or after you try 4.9 again. Thanks.
Quoted 5 lines · E V
System panic'd overnight running 4.9rc5 & rsync. Attached a photo of the stack trace, and the 38 call traces in a 2 minute window shortly before, to the bugzilla case for those not on it's e-mail list:
The panic screenshot has only the last part, but the end marker says it's OOM with no killable processes. The DEBUG_VM config thus didn't trigger anything, and still there's tons of pagecache, mostly clean, that's not being reclaimed.
Could you now try this?
- enable CONFIG_PAGE_OWNER
- boot with kernel option: page_owner=on
- after the first oom, "cat /sys/kernel/debug/page_owner > file"
- provide the file (compressed, it will be quite large)
Vlastimil
Quoted 12 lines · Vlastimil Babka
Quoted 5 lines · E V
System panic'd overnight running 4.9rc5 & rsync. Attached a photo of the stack trace, and the 38 call traces in a 2 minute window shortly before, to the bugzilla case for those not on it's e-mail list:
The panic screenshot has only the last part, but the end marker says it's OOM with no killable processes. The
DEBUG_VMconfig thus didn't trigger anything, and still there's tons of pagecache, mostly clean, that's not being reclaimed.
Quoted 5 lines
Could you now try this?
- enableCONFIG_PAGE_OWNER
- boot with kernel option: page_owner=on
- after the first oom, "cat/sys/kernel/debug/page_owner> file"
- provide the file (compressed, it will be quite large)
Excuse me for a noise, but do we really need to do
"cat /sys/kernel/debug/page_owner > file" after the first OOM killer invocation? I worry that it might be too difficult to do. Shouldn't we rather do "cat /sys/kernel/debug/page_owner > file" hourly and compare tendency between the latest one and previous one?
This system has swap, and /var/log/messages before panic reports that swapin was stalling at memory allocation.
----------------------------------------
[130346.262510] dsm_sa_datamgrd: page allocation stalls for 52400ms, order:0, mode:0x24200ca(GFP_HIGHUSER_MOVABLE) [130346.262572] CPU: 1 PID: 3622 Comm: dsm_sa_datamgrd Tainted: G W I 4.9.0-rc5 #2 [130346.262662] 0000000000000000 ffffffff8129ba69 ffffffff8170e4c8 ffffc90003ccb8d8 [130346.262714] ffffffff8113449f 024200ca1ca11b40 ffffffff8170e4c8 ffffc90003ccb880 [130346.262765] ffffffff00000010 ffffc90003ccb8e8 ffffc90003ccb898 ffff88041f226e80 [130346.262817] Call Trace: [130346.262843] [<ffffffff8129ba69>] ? dump_stack+0x46/0x5d [130346.262872] [<ffffffff8113449f>] ? warn_alloc+0x11f/0x140 [130346.262899] [<ffffffff81134d7b>] ? __alloc_pages_slowpath+0x84b/0xa80 [130346.262929] [<ffffffff81135260>] ? __alloc_pages_nodemask+0x2b0/0x2f0 [130346.262960] [<ffffffff8117f1be>] ? alloc_pages_vma+0xbe/0x260 [130346.262989] [<ffffffff8112af02>] ? pagecache_get_page+0x22/0x280 [130346.263019] [<ffffffff81171b68>] ? __read_swap_cache_async+0x118/0x1a0 [130346.263048] [<ffffffff81171bff>] ? read_swap_cache_async+0xf/0x30 [130346.263077] [<ffffffff81171d8e>] ? swapin_readahead+0x16e/0x1c0 [130346.263106] [<ffffffff812a0f6e>] ? radix_tree_lookup_slot+0xe/0x20 [130346.263135] [<ffffffff8112ac84>] ? find_get_entry+0x14/0x130 [130346.263162] [<ffffffff8112af02>] ? pagecache_get_page+0x22/0x280 [130346.263193] [<ffffffff8115cb1f>] ? do_swap_page+0x44f/0x5f0 [130346.263220] [<ffffffff812a0f02>] ? __radix_tree_lookup+0x62/0xc0 [130346.263249] [<ffffffff8115e91a>] ? handle_mm_fault+0x66a/0xf00 [130346.263277] [<ffffffff8112ac84>] ? find_get_entry+0x14/0x130 [130346.263305] [<ffffffff8104a245>] ? __do_page_fault+0x1c5/0x490 [130346.263336] [<ffffffff8150e322>] ? page_fault+0x22/0x30 [130346.263364] [<ffffffff812a7cac>] ? copy_user_generic_string+0x2c/0x40 [130346.263395] [<ffffffff811adc1d>] ? set_fd_set+0x1d/0x30 [130346.263422] [<ffffffff811ae905>] ? core_sys_select+0x1a5/0x260 [130346.263450] [<ffffffff811a913a>] ? getname_flags+0x6a/0x1e0 [130346.263479] [<ffffffff8119ef25>] ? cp_new_stat+0x115/0x130 [130346.263509] [<ffffffff810bf01f>] ? ktime_get_ts64+0x3f/0xf0 [130346.263537] [<ffffffff811aea65>] ? SyS_select+0xa5/0xe0 [130346.263564] [<ffffffff8150c6a0>] ? entry_SYSCALL_64_fastpath+0x13/0x94
----------------------------------------
Under such situation, trying to login and execute /bin/cat could take minutes. Also, writing to btrfs and ext4 seems to be stalling. The btrfs one is a situation where WQ_MEM_RECLAIM kernel workqueue is unable to make progress.
----------------------------------------
[130420.008231] kworker/u34:21: page allocation stalls for 35028ms, order:0, mode:0x2400840(GFP_NOFS|__GFP_NOFAIL) [130420.008287] CPU: 5 PID: 24286 Comm: kworker/u34:21 Tainted: G W I 4.9.0-rc5 #2 [130420.008401] Workqueue: btrfs-extent-refs btrfs_extent_refs_helper [btrfs] [130420.008432] 0000000000000000 ffffffff8129ba69 ffffffff8170e4c8 ffffc900087836a0 [130420.008483] ffffffff8113449f 024008401e3f1b40 ffffffff8170e4c8 ffffc90008783648 [130420.008534] ffffffff00000010 ffffc900087836b0 ffffc90008783660 ffff88041ecc4340 [130420.008586] Call Trace: [130420.008611] [<ffffffff8129ba69>] ? dump_stack+0x46/0x5d [130420.008640] [<ffffffff8113449f>] ? warn_alloc+0x11f/0x140 [130420.008667] [<ffffffff81134d7b>] ? __alloc_pages_slowpath+0x84b/0xa80 [130420.008707] [<ffffffffa020c432>] ? search_bitmap+0xc2/0x140 [btrfs] [130420.008736] [<ffffffff81135260>] ? __alloc_pages_nodemask+0x2b0/0x2f0 [130420.008766] [<ffffffff8117dbda>] ? alloc_pages_current+0x8a/0x110 [130420.008796] [<ffffffff8112afcc>] ? pagecache_get_page+0xec/0x280 [130420.008836] [<ffffffffa01e9aa8>] ? alloc_extent_buffer+0x108/0x430 [btrfs] [130420.008875] [<ffffffffa01b4108>] ? btrfs_alloc_tree_block+0x118/0x4d0 [btrfs] [130420.008927] [<ffffffffa019ae38>] ? __btrfs_cow_block+0x148/0x5d0 [btrfs] [130420.008964] [<ffffffffa019b464>] ? btrfs_cow_block+0x114/0x1d0 [btrfs] [130420.009001] [<ffffffffa019f1d6>] ? btrfs_search_slot+0x206/0xa40 [btrfs] [130420.009039] [<ffffffffa01a6089>] ? lookup_inline_extent_backref+0xd9/0x620 [btrfs] [130420.009095] [<ffffffffa01e4e74>] ? set_extent_bit+0x24/0x30 [btrfs] [130420.009124] [<ffffffff8118567f>] ? kmem_cache_alloc+0x17f/0x1b0 [130420.009161] [<ffffffffa01a7b1f>] ? __btrfs_free_extent.isra.69+0xef/0xd10 [btrfs] [130420.009215] [<ffffffffa0214346>] ? btrfs_merge_delayed_refs+0x56/0x6f0 [btrfs] [130420.009269] [<ffffffffa01ac545>] ? __btrfs_run_delayed_refs+0x745/0x1320 [btrfs] [130420.009314] [<ffffffff810801ef>] ? ttwu_do_wakeup+0xf/0xe0 [130420.009351] [<ffffffffa01b0000>] ? btrfs_run_delayed_refs+0x90/0x2b0 [btrfs] [130420.009404] [<ffffffffa01b02a4>] ? delayed_ref_async_start+0x84/0xa0 [btrfs] [130420.009459] [<ffffffffa01f82a3>] ? normal_work_helper+0xc3/0x2f0 [btrfs] [130420.009490] [<ffffffff81071efb>] ? process_one_work+0x14b/0x400 [130420.009518] [<ffffffff8107251d>] ? worker_thread+0x5d/0x470 [130420.009546] [<ffffffff810724c0>] ? rescuer_thread+0x310/0x310 [130420.009573] [<ffffffff8105ed54>] ? do_group_exit+0x34/0xb0 [130420.009601] [<ffffffff810772bb>] ? kthread+0xcb/0xf0 [130420.009627] [<ffffffff810771f0>] ? kthread_park+0x50/0x50 [130420.009655] [<ffffffff8150c8d2>] ? ret_from_fork+0x22/0x30
----------------------------------------
----------------------------------------
[130438.436025] jbd2/dm-0-8: page allocation stalls for 10492ms, order:0, mode:0x2420848(GFP_NOFS|__GFP_NOFAIL|__GFP_HARDWALL|__GFP_MOVABLE) [130438.436095] CPU: 2 PID: 1838 Comm: jbd2/dm-0-8 Tainted: G W I 4.9.0-rc5 #2 [130438.436184] 0000000000000000 ffffffff8129ba69 ffffffff8170e4c8 ffffc90003e13728 [130438.436237] ffffffff8113449f 0242084800000200 ffffffff8170e4c8 ffffc90003e136d0 [130438.436289] 0000000100000010 ffffc90003e13738 ffffc90003e136e8 0000000000000001 [130438.436340] Call Trace: [130438.436368] [<ffffffff8129ba69>] ? dump_stack+0x46/0x5d [130438.436399] [<ffffffff8113449f>] ? warn_alloc+0x11f/0x140 [130438.436426] [<ffffffff81134d7b>] ? __alloc_pages_slowpath+0x84b/0xa80 [130438.436455] [<ffffffff81135260>] ? __alloc_pages_nodemask+0x2b0/0x2f0 [130438.436488] [<ffffffff8117dbda>] ? alloc_pages_current+0x8a/0x110 [130438.436518] [<ffffffff8112afcc>] ? pagecache_get_page+0xec/0x280 [130438.436549] [<ffffffff811cc051>] ? __getblk_gfp+0xf1/0x320 [130438.436593] [<ffffffffa02bc774>] ? ext4_get_branch+0xa4/0x130 [ext4] [130438.436628] [<ffffffffa02bd24b>] ? ext4_ind_map_blocks+0xcb/0xb10 [ext4] [130438.436658] [<ffffffff8108807e>] ? update_curr+0x7e/0x100 [130438.436688] [<ffffffff810bfe61>] ? ktime_get+0x31/0xa0 [130438.436716] [<ffffffff8112e329>] ? mempool_alloc+0x59/0x170 [130438.436743] [<ffffffff8108807e>] ? update_curr+0x7e/0x100 [130438.436775] [<ffffffffa0280813>] ? ext4_map_blocks+0x3c3/0x630 [ext4] [130438.436808] [<ffffffffa0280ae4>] ? _ext4_get_block+0x64/0xc0 [ext4] [130438.436838] [<ffffffff811ca6a7>] ? generic_block_bmap+0x37/0x50 [130438.436870] [<ffffffffa027fc57>] ? ext4_bmap+0x37/0xd0 [ext4] [130438.436901] [<ffffffffa008a5e1>] ? jbd2_journal_bmap+0x21/0x70 [jbd2] [130438.436932] [<ffffffffa008a6be>] ? jbd2_journal_get_descriptor_buffer+0x1e/0xc0 [jbd2] [130438.436979] [<ffffffffa0086aa8>] ? jbd2_journal_write_revoke_records+0x198/0x2b0 [jbd2] [130438.437026] [<ffffffffa0083236>] ? jbd2_journal_commit_transaction+0x5d6/0x19f0 [jbd2] [130438.437071] [<ffffffff8108807e>] ? update_curr+0x7e/0x100 [130438.437099] [<ffffffff8108c8fc>] ? dequeue_task_fair+0x5dc/0x1120 [130438.437127] [<ffffffff8108f61c>] ? pick_next_task_fair+0x12c/0x420 [130438.437157] [<ffffffffa00884e8>] ? kjournald2+0xc8/0x250 [jbd2] [130438.437187] [<ffffffff810948e0>] ? wake_up_atomic_t+0x30/0x30 [130438.437216] [<ffffffffa0088420>] ? commit_timeout+0x10/0x10 [jbd2] [130438.437247] [<ffffffff810772bb>] ? kthread+0xcb/0xf0 [130438.437273] [<ffffffff810771f0>] ? kthread_park+0x50/0x50 [130438.437304] [<ffffffff8150c8d2>] ? ret_from_fork+0x22/0x30
----------------------------------------
Under such situation, saving /sys/kernel/debug/page_owner to a file might be impossible. And, once the stalling started, it took less than 5 minutes before the kernel panics due to "Out of memory and no killable process". This could happen when E V is offline.
Since rsyslogd is likely be killed by the OOM killer for situations like this, E V might want to try serial console or netconsole for saving kernel messages reliably.
I don't know what we will find by analyzing /sys/kernel/debug/page_owner , but if something is wrong, can't we try whether
"echo 3 > /proc/sys/vm/drop_caches" before the stalling starts helps.
I guess that this problem became visible by OOM detection rework which went to Linux 4.7. I don't know what "free_pcp:0kB local_pcp:0kB" means (get_page_from_freelist() for any order is failng?), but in general I think this /var/log/messages showed that free_pcp: and local_pcp: remains small.
It could be totally unrelated but I have a similar problem: processes get randomly OOM'd when I am doing anything "sort of heavy" on my Btrfs filesystems.
I did some "evil tuning", so I assumed that must be the problem (even if the values looked sane for my system). Thus, I kept cutting back on the manually set values (mostly dirty/background ratio, io scheduler request queue size and such tunables) but it seems to be a dead end. I guess anything I change in order to try and cut back on the related memory footprint just makes the OOMs less frequent but it's only a matter of time and coincidence (lots of things randomly happen to do some notable amount of IO) until OOMs happen anyway.
It seems to be plenty enough to start a defrag or balance on more than a single filesystem (in parallel) and pretty much any notable "useful" user load will have a high change of triggering OOMs (and get killed) sooner or later. It's just my limited observation but database-like loads [like that of bitcoind] (sync writes and/or frequent flushes?) or high priority buffered writes (ffmpeg running with higher than default priority and saving live video streams into files without recoding) seem to have higher chance of triggering this (more so than simply reading or writing files sequentially and asynchronously, either locally or through Samba).
I am on gentoo-sources 4.8.8 right now but it was there with 4.7.x as well.
Quoted 24 lines · Vlastimil Babka
Quoted 5 lines · E V
System panic'd overnight running 4.9rc5 & rsync. Attached a photo of the stack trace, and the 38 call traces in a 2 minute window shortly before, to the bugzilla case for those not on it's e-mail list:
The panic screenshot has only the last part, but the end marker says it's OOM with no killable processes. The
DEBUG_VMconfig thus didn't trigger anything, and still there's tons of pagecache, mostly clean, that's not being reclaimed.Could you now try this?
- enableCONFIG_PAGE_OWNER
- boot with kernel option: page_owner=on
- after the first oom, "cat/sys/kernel/debug/page_owner> file"
- provide the file (compressed, it will be quite large)Vlastimil
--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Yes, the short window between the stalls and the panic makes it difficult to manually check much. I could setup a cron every 5 minutes or so if you want. Also, I see the OOM's in 4.8, but it has yet to panic on me. Where as 4.9rc has panic'd both times I've booted it, so depending on what you want to look at it might be easier to investigate on 4.8. Let me know, I can turn on a couple of the DEBUG config's and build a new 4.8.8. Never looked into a netconsole or serial console. I think just getting the system to use a higher res console would be an improvement, but the OOM's seemed to be the root cause of the panic so I haven't spent any time looking into that as of yet,
Thanks,
-Eli
Quoted 163 lines · Tetsuo Handa
Quoted 12 lines · Vlastimil Babka
Quoted 5 lines · E V
System panic'd overnight running 4.9rc5 & rsync. Attached a photo of the stack trace, and the 38 call traces in a 2 minute window shortly before, to the bugzilla case for those not on it's e-mail list:
The panic screenshot has only the last part, but the end marker says it's OOM with no killable processes. The
DEBUG_VMconfig thus didn't trigger anything, and still there's tons of pagecache, mostly clean, that's not being reclaimed.Quoted 5 lines
Could you now try this?
- enableCONFIG_PAGE_OWNER
- boot with kernel option: page_owner=on
- after the first oom, "cat/sys/kernel/debug/page_owner> file"
- provide the file (compressed, it will be quite large)Excuse me for a noise, but do we really need to do
"cat/sys/kernel/debug/page_owner> file" after the first OOM killer invocation? I worry that it might be too difficult to do. Shouldn't we rather do "cat/sys/kernel/debug/page_owner> file" hourly and compare tendency between the latest one and previous one?This system has swap, and
/var/log/messagesbefore panic reports that swapin was stalling at memory allocation.----------------------------------------
[130346.262510] dsm_sa_datamgrd: page allocation stalls for 52400ms, order:0, mode:0x24200ca(GFP_HIGHUSER_MOVABLE) [130346.262572] CPU: 1 PID: 3622 Comm: dsm_sa_datamgrd Tainted: G W I 4.9.0-rc5 #2 [130346.262662] 0000000000000000 ffffffff8129ba69 ffffffff8170e4c8 ffffc90003ccb8d8 [130346.262714] ffffffff8113449f 024200ca1ca11b40 ffffffff8170e4c8 ffffc90003ccb880 [130346.262765] ffffffff00000010 ffffc90003ccb8e8 ffffc90003ccb898 ffff88041f226e80 [130346.262817] Call Trace: [130346.262843] [<ffffffff8129ba69>] ? dump_stack+0x46/0x5d [130346.262872] [<ffffffff8113449f>] ? warn_alloc+0x11f/0x140 [130346.262899] [<ffffffff81134d7b>] ? __alloc_pages_slowpath+0x84b/0xa80 [130346.262929] [<ffffffff81135260>] ? __alloc_pages_nodemask+0x2b0/0x2f0 [130346.262960] [<ffffffff8117f1be>] ? alloc_pages_vma+0xbe/0x260 [130346.262989] [<ffffffff8112af02>] ? pagecache_get_page+0x22/0x280 [130346.263019] [<ffffffff81171b68>] ? __read_swap_cache_async+0x118/0x1a0 [130346.263048] [<ffffffff81171bff>] ? read_swap_cache_async+0xf/0x30 [130346.263077] [<ffffffff81171d8e>] ? swapin_readahead+0x16e/0x1c0 [130346.263106] [<ffffffff812a0f6e>] ? radix_tree_lookup_slot+0xe/0x20 [130346.263135] [<ffffffff8112ac84>] ? find_get_entry+0x14/0x130 [130346.263162] [<ffffffff8112af02>] ? pagecache_get_page+0x22/0x280 [130346.263193] [<ffffffff8115cb1f>] ? do_swap_page+0x44f/0x5f0 [130346.263220] [<ffffffff812a0f02>] ? __radix_tree_lookup+0x62/0xc0 [130346.263249] [<ffffffff8115e91a>] ? handle_mm_fault+0x66a/0xf00 [130346.263277] [<ffffffff8112ac84>] ? find_get_entry+0x14/0x130 [130346.263305] [<ffffffff8104a245>] ? __do_page_fault+0x1c5/0x490 [130346.263336] [<ffffffff8150e322>] ? page_fault+0x22/0x30 [130346.263364] [<ffffffff812a7cac>] ? copy_user_generic_string+0x2c/0x40 [130346.263395] [<ffffffff811adc1d>] ? set_fd_set+0x1d/0x30 [130346.263422] [<ffffffff811ae905>] ? core_sys_select+0x1a5/0x260 [130346.263450] [<ffffffff811a913a>] ? getname_flags+0x6a/0x1e0 [130346.263479] [<ffffffff8119ef25>] ? cp_new_stat+0x115/0x130 [130346.263509] [<ffffffff810bf01f>] ? ktime_get_ts64+0x3f/0xf0 [130346.263537] [<ffffffff811aea65>] ? SyS_select+0xa5/0xe0 [130346.263564] [<ffffffff8150c6a0>] ? entry_SYSCALL_64_fastpath+0x13/0x94----------------------------------------
Under such situation, trying to login and execute
/bin/catcould take minutes. Also, writing to btrfs and ext4 seems to be stalling. The btrfs one is a situation whereWQ_MEM_RECLAIMkernel workqueue is unable to make progress.----------------------------------------
[130420.008231] kworker/u34:21: page allocation stalls for 35028ms, order:0, mode:0x2400840(GFP_NOFS|__GFP_NOFAIL) [130420.008287] CPU: 5 PID: 24286 Comm: kworker/u34:21 Tainted: G W I 4.9.0-rc5 #2 [130420.008401] Workqueue: btrfs-extent-refs btrfs_extent_refs_helper [btrfs] [130420.008432] 0000000000000000 ffffffff8129ba69 ffffffff8170e4c8 ffffc900087836a0 [130420.008483] ffffffff8113449f 024008401e3f1b40 ffffffff8170e4c8 ffffc90008783648 [130420.008534] ffffffff00000010 ffffc900087836b0 ffffc90008783660 ffff88041ecc4340 [130420.008586] Call Trace: [130420.008611] [<ffffffff8129ba69>] ? dump_stack+0x46/0x5d [130420.008640] [<ffffffff8113449f>] ? warn_alloc+0x11f/0x140 [130420.008667] [<ffffffff81134d7b>] ? __alloc_pages_slowpath+0x84b/0xa80 [130420.008707] [<ffffffffa020c432>] ? search_bitmap+0xc2/0x140 [btrfs] [130420.008736] [<ffffffff81135260>] ? __alloc_pages_nodemask+0x2b0/0x2f0 [130420.008766] [<ffffffff8117dbda>] ? alloc_pages_current+0x8a/0x110 [130420.008796] [<ffffffff8112afcc>] ? pagecache_get_page+0xec/0x280 [130420.008836] [<ffffffffa01e9aa8>] ? alloc_extent_buffer+0x108/0x430 [btrfs] [130420.008875] [<ffffffffa01b4108>] ? btrfs_alloc_tree_block+0x118/0x4d0 [btrfs] [130420.008927] [<ffffffffa019ae38>] ? __btrfs_cow_block+0x148/0x5d0 [btrfs] [130420.008964] [<ffffffffa019b464>] ? btrfs_cow_block+0x114/0x1d0 [btrfs] [130420.009001] [<ffffffffa019f1d6>] ? btrfs_search_slot+0x206/0xa40 [btrfs] [130420.009039] [<ffffffffa01a6089>] ? lookup_inline_extent_backref+0xd9/0x620 [btrfs] [130420.009095] [<ffffffffa01e4e74>] ? set_extent_bit+0x24/0x30 [btrfs] [130420.009124] [<ffffffff8118567f>] ? kmem_cache_alloc+0x17f/0x1b0 [130420.009161] [<ffffffffa01a7b1f>] ? __btrfs_free_extent.isra.69+0xef/0xd10 [btrfs] [130420.009215] [<ffffffffa0214346>] ? btrfs_merge_delayed_refs+0x56/0x6f0 [btrfs] [130420.009269] [<ffffffffa01ac545>] ? __btrfs_run_delayed_refs+0x745/0x1320 [btrfs] [130420.009314] [<ffffffff810801ef>] ? ttwu_do_wakeup+0xf/0xe0 [130420.009351] [<ffffffffa01b0000>] ? btrfs_run_delayed_refs+0x90/0x2b0 [btrfs] [130420.009404] [<ffffffffa01b02a4>] ? delayed_ref_async_start+0x84/0xa0 [btrfs] [130420.009459] [<ffffffffa01f82a3>] ? normal_work_helper+0xc3/0x2f0 [btrfs] [130420.009490] [<ffffffff81071efb>] ? process_one_work+0x14b/0x400 [130420.009518] [<ffffffff8107251d>] ? worker_thread+0x5d/0x470 [130420.009546] [<ffffffff810724c0>] ? rescuer_thread+0x310/0x310 [130420.009573] [<ffffffff8105ed54>] ? do_group_exit+0x34/0xb0 [130420.009601] [<ffffffff810772bb>] ? kthread+0xcb/0xf0 [130420.009627] [<ffffffff810771f0>] ? kthread_park+0x50/0x50 [130420.009655] [<ffffffff8150c8d2>] ? ret_from_fork+0x22/0x30----------------------------------------
----------------------------------------
[130438.436025] jbd2/dm-0-8: page allocation stalls for 10492ms, order:0, mode:0x2420848(GFP_NOFS|__GFP_NOFAIL|__GFP_HARDWALL|__GFP_MOVABLE) [130438.436095] CPU: 2 PID: 1838 Comm: jbd2/dm-0-8 Tainted: G W I 4.9.0-rc5 #2 [130438.436184] 0000000000000000 ffffffff8129ba69 ffffffff8170e4c8 ffffc90003e13728 [130438.436237] ffffffff8113449f 0242084800000200 ffffffff8170e4c8 ffffc90003e136d0 [130438.436289] 0000000100000010 ffffc90003e13738 ffffc90003e136e8 0000000000000001 [130438.436340] Call Trace: [130438.436368] [<ffffffff8129ba69>] ? dump_stack+0x46/0x5d [130438.436399] [<ffffffff8113449f>] ? warn_alloc+0x11f/0x140 [130438.436426] [<ffffffff81134d7b>] ? __alloc_pages_slowpath+0x84b/0xa80 [130438.436455] [<ffffffff81135260>] ? __alloc_pages_nodemask+0x2b0/0x2f0 [130438.436488] [<ffffffff8117dbda>] ? alloc_pages_current+0x8a/0x110 [130438.436518] [<ffffffff8112afcc>] ? pagecache_get_page+0xec/0x280 [130438.436549] [<ffffffff811cc051>] ? __getblk_gfp+0xf1/0x320 [130438.436593] [<ffffffffa02bc774>] ? ext4_get_branch+0xa4/0x130 [ext4] [130438.436628] [<ffffffffa02bd24b>] ? ext4_ind_map_blocks+0xcb/0xb10 [ext4] [130438.436658] [<ffffffff8108807e>] ? update_curr+0x7e/0x100 [130438.436688] [<ffffffff810bfe61>] ? ktime_get+0x31/0xa0 [130438.436716] [<ffffffff8112e329>] ? mempool_alloc+0x59/0x170 [130438.436743] [<ffffffff8108807e>] ? update_curr+0x7e/0x100 [130438.436775] [<ffffffffa0280813>] ? ext4_map_blocks+0x3c3/0x630 [ext4] [130438.436808] [<ffffffffa0280ae4>] ? _ext4_get_block+0x64/0xc0 [ext4] [130438.436838] [<ffffffff811ca6a7>] ? generic_block_bmap+0x37/0x50 [130438.436870] [<ffffffffa027fc57>] ? ext4_bmap+0x37/0xd0 [ext4] [130438.436901] [<ffffffffa008a5e1>] ? jbd2_journal_bmap+0x21/0x70 [jbd2] [130438.436932] [<ffffffffa008a6be>] ? jbd2_journal_get_descriptor_buffer+0x1e/0xc0 [jbd2] [130438.436979] [<ffffffffa0086aa8>] ? jbd2_journal_write_revoke_records+0x198/0x2b0 [jbd2] [130438.437026] [<ffffffffa0083236>] ? jbd2_journal_commit_transaction+0x5d6/0x19f0 [jbd2] [130438.437071] [<ffffffff8108807e>] ? update_curr+0x7e/0x100 [130438.437099] [<ffffffff8108c8fc>] ? dequeue_task_fair+0x5dc/0x1120 [130438.437127] [<ffffffff8108f61c>] ? pick_next_task_fair+0x12c/0x420 [130438.437157] [<ffffffffa00884e8>] ? kjournald2+0xc8/0x250 [jbd2] [130438.437187] [<ffffffff810948e0>] ? wake_up_atomic_t+0x30/0x30 [130438.437216] [<ffffffffa0088420>] ? commit_timeout+0x10/0x10 [jbd2] [130438.437247] [<ffffffff810772bb>] ? kthread+0xcb/0xf0 [130438.437273] [<ffffffff810771f0>] ? kthread_park+0x50/0x50 [130438.437304] [<ffffffff8150c8d2>] ? ret_from_fork+0x22/0x30----------------------------------------
Under such situation, saving
/sys/kernel/debug/page_ownerto a file might be impossible. And, once the stalling started, it took less than 5 minutes before the kernel panics due to "Out of memory and no killable process". This could happen when E V is offline.Since rsyslogd is likely be killed by the OOM killer for situations like this, E V might want to try serial console or netconsole for saving kernel messages reliably.
I don't know what we will find by analyzing
/sys/kernel/debug/page_owner, but if something is wrong, can't we try whether
"echo 3 >/proc/sys/vm/drop_caches" before the stalling starts helps.I guess that this problem became visible by OOM detection rework which went to Linux 4.7. I don't know what "free_pcp:0kB local_pcp:0kB" means (
get_page_from_freelist()for any order is failng?), but in general I think this/var/log/messagesshowed thatfree_pcp: andlocal_pcp: remains small.
System OOM'd several times last night with 4.8.10, I attached the page_owner output from a morning cat ~8 hours after OOM's to the bugzilla case, split and compressed to fit under the 5M attachment limit. Let me know if you need anything else.
Quoted 180 lines · E V
Yes, the short window between the stalls and the panic makes it difficult to manually check much. I could setup a cron every 5 minutes or so if you want. Also, I see the OOM's in 4.8, but it has yet to panic on me. Where as 4.9rc has panic'd both times I've booted it, so depending on what you want to look at it might be easier to investigate on 4.8. Let me know, I can turn on a couple of the DEBUG config's and build a new 4.8.8. Never looked into a netconsole or serial console. I think just getting the system to use a higher res console would be an improvement, but the OOM's seemed to be the root cause of the panic so I haven't spent any time looking into that as of yet,
Thanks,
-EliQuoted 163 lines · Tetsuo Handa
Quoted 12 lines · Vlastimil Babka
Quoted 5 lines · E V
System panic'd overnight running 4.9rc5 & rsync. Attached a photo of the stack trace, and the 38 call traces in a 2 minute window shortly before, to the bugzilla case for those not on it's e-mail list:
The panic screenshot has only the last part, but the end marker says it's OOM with no killable processes. The
DEBUG_VMconfig thus didn't trigger anything, and still there's tons of pagecache, mostly clean, that's not being reclaimed.Quoted 5 lines
Could you now try this?
- enableCONFIG_PAGE_OWNER
- boot with kernel option: page_owner=on
- after the first oom, "cat/sys/kernel/debug/page_owner> file"
- provide the file (compressed, it will be quite large)Excuse me for a noise, but do we really need to do
"cat/sys/kernel/debug/page_owner> file" after the first OOM killer invocation? I worry that it might be too difficult to do. Shouldn't we rather do "cat/sys/kernel/debug/page_owner> file" hourly and compare tendency between the latest one and previous one?This system has swap, and
/var/log/messagesbefore panic reports that swapin was stalling at memory allocation.----------------------------------------
[130346.262510] dsm_sa_datamgrd: page allocation stalls for 52400ms, order:0, mode:0x24200ca(GFP_HIGHUSER_MOVABLE) [130346.262572] CPU: 1 PID: 3622 Comm: dsm_sa_datamgrd Tainted: G W I 4.9.0-rc5 #2 [130346.262662] 0000000000000000 ffffffff8129ba69 ffffffff8170e4c8 ffffc90003ccb8d8 [130346.262714] ffffffff8113449f 024200ca1ca11b40 ffffffff8170e4c8 ffffc90003ccb880 [130346.262765] ffffffff00000010 ffffc90003ccb8e8 ffffc90003ccb898 ffff88041f226e80 [130346.262817] Call Trace: [130346.262843] [<ffffffff8129ba69>] ? dump_stack+0x46/0x5d [130346.262872] [<ffffffff8113449f>] ? warn_alloc+0x11f/0x140 [130346.262899] [<ffffffff81134d7b>] ? __alloc_pages_slowpath+0x84b/0xa80 [130346.262929] [<ffffffff81135260>] ? __alloc_pages_nodemask+0x2b0/0x2f0 [130346.262960] [<ffffffff8117f1be>] ? alloc_pages_vma+0xbe/0x260 [130346.262989] [<ffffffff8112af02>] ? pagecache_get_page+0x22/0x280 [130346.263019] [<ffffffff81171b68>] ? __read_swap_cache_async+0x118/0x1a0 [130346.263048] [<ffffffff81171bff>] ? read_swap_cache_async+0xf/0x30 [130346.263077] [<ffffffff81171d8e>] ? swapin_readahead+0x16e/0x1c0 [130346.263106] [<ffffffff812a0f6e>] ? radix_tree_lookup_slot+0xe/0x20 [130346.263135] [<ffffffff8112ac84>] ? find_get_entry+0x14/0x130 [130346.263162] [<ffffffff8112af02>] ? pagecache_get_page+0x22/0x280 [130346.263193] [<ffffffff8115cb1f>] ? do_swap_page+0x44f/0x5f0 [130346.263220] [<ffffffff812a0f02>] ? __radix_tree_lookup+0x62/0xc0 [130346.263249] [<ffffffff8115e91a>] ? handle_mm_fault+0x66a/0xf00 [130346.263277] [<ffffffff8112ac84>] ? find_get_entry+0x14/0x130 [130346.263305] [<ffffffff8104a245>] ? __do_page_fault+0x1c5/0x490 [130346.263336] [<ffffffff8150e322>] ? page_fault+0x22/0x30 [130346.263364] [<ffffffff812a7cac>] ? copy_user_generic_string+0x2c/0x40 [130346.263395] [<ffffffff811adc1d>] ? set_fd_set+0x1d/0x30 [130346.263422] [<ffffffff811ae905>] ? core_sys_select+0x1a5/0x260 [130346.263450] [<ffffffff811a913a>] ? getname_flags+0x6a/0x1e0 [130346.263479] [<ffffffff8119ef25>] ? cp_new_stat+0x115/0x130 [130346.263509] [<ffffffff810bf01f>] ? ktime_get_ts64+0x3f/0xf0 [130346.263537] [<ffffffff811aea65>] ? SyS_select+0xa5/0xe0 [130346.263564] [<ffffffff8150c6a0>] ? entry_SYSCALL_64_fastpath+0x13/0x94----------------------------------------
Under such situation, trying to login and execute
/bin/catcould take minutes. Also, writing to btrfs and ext4 seems to be stalling. The btrfs one is a situation whereWQ_MEM_RECLAIMkernel workqueue is unable to make progress.----------------------------------------
[130420.008231] kworker/u34:21: page allocation stalls for 35028ms, order:0, mode:0x2400840(GFP_NOFS|__GFP_NOFAIL) [130420.008287] CPU: 5 PID: 24286 Comm: kworker/u34:21 Tainted: G W I 4.9.0-rc5 #2 [130420.008401] Workqueue: btrfs-extent-refs btrfs_extent_refs_helper [btrfs] [130420.008432] 0000000000000000 ffffffff8129ba69 ffffffff8170e4c8 ffffc900087836a0 [130420.008483] ffffffff8113449f 024008401e3f1b40 ffffffff8170e4c8 ffffc90008783648 [130420.008534] ffffffff00000010 ffffc900087836b0 ffffc90008783660 ffff88041ecc4340 [130420.008586] Call Trace: [130420.008611] [<ffffffff8129ba69>] ? dump_stack+0x46/0x5d [130420.008640] [<ffffffff8113449f>] ? warn_alloc+0x11f/0x140 [130420.008667] [<ffffffff81134d7b>] ? __alloc_pages_slowpath+0x84b/0xa80 [130420.008707] [<ffffffffa020c432>] ? search_bitmap+0xc2/0x140 [btrfs] [130420.008736] [<ffffffff81135260>] ? __alloc_pages_nodemask+0x2b0/0x2f0 [130420.008766] [<ffffffff8117dbda>] ? alloc_pages_current+0x8a/0x110 [130420.008796] [<ffffffff8112afcc>] ? pagecache_get_page+0xec/0x280 [130420.008836] [<ffffffffa01e9aa8>] ? alloc_extent_buffer+0x108/0x430 [btrfs] [130420.008875] [<ffffffffa01b4108>] ? btrfs_alloc_tree_block+0x118/0x4d0 [btrfs] [130420.008927] [<ffffffffa019ae38>] ? __btrfs_cow_block+0x148/0x5d0 [btrfs] [130420.008964] [<ffffffffa019b464>] ? btrfs_cow_block+0x114/0x1d0 [btrfs] [130420.009001] [<ffffffffa019f1d6>] ? btrfs_search_slot+0x206/0xa40 [btrfs] [130420.009039] [<ffffffffa01a6089>] ? lookup_inline_extent_backref+0xd9/0x620 [btrfs] [130420.009095] [<ffffffffa01e4e74>] ? set_extent_bit+0x24/0x30 [btrfs] [130420.009124] [<ffffffff8118567f>] ? kmem_cache_alloc+0x17f/0x1b0 [130420.009161] [<ffffffffa01a7b1f>] ? __btrfs_free_extent.isra.69+0xef/0xd10 [btrfs] [130420.009215] [<ffffffffa0214346>] ? btrfs_merge_delayed_refs+0x56/0x6f0 [btrfs] [130420.009269] [<ffffffffa01ac545>] ? __btrfs_run_delayed_refs+0x745/0x1320 [btrfs] [130420.009314] [<ffffffff810801ef>] ? ttwu_do_wakeup+0xf/0xe0 [130420.009351] [<ffffffffa01b0000>] ? btrfs_run_delayed_refs+0x90/0x2b0 [btrfs] [130420.009404] [<ffffffffa01b02a4>] ? delayed_ref_async_start+0x84/0xa0 [btrfs] [130420.009459] [<ffffffffa01f82a3>] ? normal_work_helper+0xc3/0x2f0 [btrfs] [130420.009490] [<ffffffff81071efb>] ? process_one_work+0x14b/0x400 [130420.009518] [<ffffffff8107251d>] ? worker_thread+0x5d/0x470 [130420.009546] [<ffffffff810724c0>] ? rescuer_thread+0x310/0x310 [130420.009573] [<ffffffff8105ed54>] ? do_group_exit+0x34/0xb0 [130420.009601] [<ffffffff810772bb>] ? kthread+0xcb/0xf0 [130420.009627] [<ffffffff810771f0>] ? kthread_park+0x50/0x50 [130420.009655] [<ffffffff8150c8d2>] ? ret_from_fork+0x22/0x30----------------------------------------
----------------------------------------
[130438.436025] jbd2/dm-0-8: page allocation stalls for 10492ms, order:0, mode:0x2420848(GFP_NOFS|__GFP_NOFAIL|__GFP_HARDWALL|__GFP_MOVABLE) [130438.436095] CPU: 2 PID: 1838 Comm: jbd2/dm-0-8 Tainted: G W I 4.9.0-rc5 #2 [130438.436184] 0000000000000000 ffffffff8129ba69 ffffffff8170e4c8 ffffc90003e13728 [130438.436237] ffffffff8113449f 0242084800000200 ffffffff8170e4c8 ffffc90003e136d0 [130438.436289] 0000000100000010 ffffc90003e13738 ffffc90003e136e8 0000000000000001 [130438.436340] Call Trace: [130438.436368] [<ffffffff8129ba69>] ? dump_stack+0x46/0x5d [130438.436399] [<ffffffff8113449f>] ? warn_alloc+0x11f/0x140 [130438.436426] [<ffffffff81134d7b>] ? __alloc_pages_slowpath+0x84b/0xa80 [130438.436455] [<ffffffff81135260>] ? __alloc_pages_nodemask+0x2b0/0x2f0 [130438.436488] [<ffffffff8117dbda>] ? alloc_pages_current+0x8a/0x110 [130438.436518] [<ffffffff8112afcc>] ? pagecache_get_page+0xec/0x280 [130438.436549] [<ffffffff811cc051>] ? __getblk_gfp+0xf1/0x320 [130438.436593] [<ffffffffa02bc774>] ? ext4_get_branch+0xa4/0x130 [ext4] [130438.436628] [<ffffffffa02bd24b>] ? ext4_ind_map_blocks+0xcb/0xb10 [ext4] [130438.436658] [<ffffffff8108807e>] ? update_curr+0x7e/0x100 [130438.436688] [<ffffffff810bfe61>] ? ktime_get+0x31/0xa0 [130438.436716] [<ffffffff8112e329>] ? mempool_alloc+0x59/0x170 [130438.436743] [<ffffffff8108807e>] ? update_curr+0x7e/0x100 [130438.436775] [<ffffffffa0280813>] ? ext4_map_blocks+0x3c3/0x630 [ext4] [130438.436808] [<ffffffffa0280ae4>] ? _ext4_get_block+0x64/0xc0 [ext4] [130438.436838] [<ffffffff811ca6a7>] ? generic_block_bmap+0x37/0x50 [130438.436870] [<ffffffffa027fc57>] ? ext4_bmap+0x37/0xd0 [ext4] [130438.436901] [<ffffffffa008a5e1>] ? jbd2_journal_bmap+0x21/0x70 [jbd2] [130438.436932] [<ffffffffa008a6be>] ? jbd2_journal_get_descriptor_buffer+0x1e/0xc0 [jbd2] [130438.436979] [<ffffffffa0086aa8>] ? jbd2_journal_write_revoke_records+0x198/0x2b0 [jbd2] [130438.437026] [<ffffffffa0083236>] ? jbd2_journal_commit_transaction+0x5d6/0x19f0 [jbd2] [130438.437071] [<ffffffff8108807e>] ? update_curr+0x7e/0x100 [130438.437099] [<ffffffff8108c8fc>] ? dequeue_task_fair+0x5dc/0x1120 [130438.437127] [<ffffffff8108f61c>] ? pick_next_task_fair+0x12c/0x420 [130438.437157] [<ffffffffa00884e8>] ? kjournald2+0xc8/0x250 [jbd2] [130438.437187] [<ffffffff810948e0>] ? wake_up_atomic_t+0x30/0x30 [130438.437216] [<ffffffffa0088420>] ? commit_timeout+0x10/0x10 [jbd2] [130438.437247] [<ffffffff810772bb>] ? kthread+0xcb/0xf0 [130438.437273] [<ffffffff810771f0>] ? kthread_park+0x50/0x50 [130438.437304] [<ffffffff8150c8d2>] ? ret_from_fork+0x22/0x30----------------------------------------
Under such situation, saving
/sys/kernel/debug/page_ownerto a file might be impossible. And, once the stalling started, it took less than 5 minutes before the kernel panics due to "Out of memory and no killable process". This could happen when E V is offline.Since rsyslogd is likely be killed by the OOM killer for situations like this, E V might want to try serial console or netconsole for saving kernel messages reliably.
I don't know what we will find by analyzing
/sys/kernel/debug/page_owner, but if something is wrong, can't we try whether
"echo 3 >/proc/sys/vm/drop_caches" before the stalling starts helps.I guess that this problem became visible by OOM detection rework which went to Linux 4.7. I don't know what "free_pcp:0kB local_pcp:0kB" means (
get_page_from_freelist()for any order is failng?), but in general I think this/var/log/messagesshowed thatfree_pcp: andlocal_pcp: remains small.
Quoted 4 lines · E V
System OOM'd several times last night with 4.8.10, I attached the
page_owneroutput from a morning cat ~8 hours after OOM's to the bugzilla case, split and compressed to fit under the 5M attachment limit. Let me know if you need anything else.
Looks like for some reason, the stack saving produces garbage stacks that only repeat save_stack_trace and save_stack functions :/
But judging from gfp flags and page flags, most pages seem to be allocated with:
mask 0x2400840(GFP_NOFS|__GFP_NOFAIL)
and page flags:
0x20000000000006c(referenced|uptodate|lru|active)
or 0x20000000000016c(referenced|uptodate|lru|active|owner_priv_1) or 0x20000000000086c(referenced|uptodate|lru|active|private)
While GFP_HIGHUSER_MOVABLE (which I would expect on lru) are less frequent.
Example:
Quoted 1 line
grep
GFP_NOFSpage_owner_after_af| wc -l
973596
Quoted 1 line
grep
GFP_HIGHUSER_MOVABLEpage_owner_after_af| wc -l
158879
Quoted 1 line
grep
GFP_NOFAILpage_owner_after_af| wc -l
971442
grepping for btrfs shows that at least some stacks for NOFS/NOFAIL pages imply it:clear_state_bit+0x135/0x1c0 [btrfs]
oradd_delayed_tree_ref+0xbf/0x170 [btrfs]
or__btrfs_map_block+0x6a8/0x1200 [btrfs]
orbtrfs_buffer_uptodate+0x48/0x70 [btrfs]
orbtrfs_set_path_blocking+0x34/0x60 [btrfs]
and some more variants.
So looks like the pages contain btrfs metadata, are on file lru and from previous checks of /proc/kpagecount we know that they most likely have page_count() == 0 but are not freed. Could btrfs guys provide some insight here?
Quoted 181 lines · E V
Quoted 180 lines
Yes, the short window between the stalls and the panic makes it difficult to manually check much. I could setup a cron every 5 minutes or so if you want. Also, I see the OOM's in 4.8, but it has yet to panic on me. Where as 4.9rc has panic'd both times I've booted it, so depending on what you want to look at it might be easier to investigate on 4.8. Let me know, I can turn on a couple of the DEBUG config's and build a new 4.8.8. Never looked into a netconsole or serial console. I think just getting the system to use a higher res console would be an improvement, but the OOM's seemed to be the root cause of the panic so I haven't spent any time looking into that as of yet,
Thanks,
-EliQuoted 163 lines · Tetsuo Handa
Quoted 12 lines · Vlastimil Babka
Quoted 5 lines · E V
System panic'd overnight running 4.9rc5 & rsync. Attached a photo of the stack trace, and the 38 call traces in a 2 minute window shortly before, to the bugzilla case for those not on it's e-mail list:
The panic screenshot has only the last part, but the end marker says it's OOM with no killable processes. The
DEBUG_VMconfig thus didn't trigger anything, and still there's tons of pagecache, mostly clean, that's not being reclaimed.Quoted 5 lines
Could you now try this?
- enableCONFIG_PAGE_OWNER
- boot with kernel option: page_owner=on
- after the first oom, "cat/sys/kernel/debug/page_owner> file"
- provide the file (compressed, it will be quite large)Excuse me for a noise, but do we really need to do
"cat/sys/kernel/debug/page_owner> file" after the first OOM killer invocation? I worry that it might be too difficult to do. Shouldn't we rather do "cat/sys/kernel/debug/page_owner> file" hourly and compare tendency between the latest one and previous one?This system has swap, and
/var/log/messagesbefore panic reports that swapin was stalling at memory allocation.----------------------------------------
[130346.262510] dsm_sa_datamgrd: page allocation stalls for 52400ms, order:0, mode:0x24200ca(GFP_HIGHUSER_MOVABLE) [130346.262572] CPU: 1 PID: 3622 Comm: dsm_sa_datamgrd Tainted: G W I 4.9.0-rc5 #2 [130346.262662] 0000000000000000 ffffffff8129ba69 ffffffff8170e4c8 ffffc90003ccb8d8 [130346.262714] ffffffff8113449f 024200ca1ca11b40 ffffffff8170e4c8 ffffc90003ccb880 [130346.262765] ffffffff00000010 ffffc90003ccb8e8 ffffc90003ccb898 ffff88041f226e80 [130346.262817] Call Trace: [130346.262843] [<ffffffff8129ba69>] ? dump_stack+0x46/0x5d [130346.262872] [<ffffffff8113449f>] ? warn_alloc+0x11f/0x140 [130346.262899] [<ffffffff81134d7b>] ? __alloc_pages_slowpath+0x84b/0xa80 [130346.262929] [<ffffffff81135260>] ? __alloc_pages_nodemask+0x2b0/0x2f0 [130346.262960] [<ffffffff8117f1be>] ? alloc_pages_vma+0xbe/0x260 [130346.262989] [<ffffffff8112af02>] ? pagecache_get_page+0x22/0x280 [130346.263019] [<ffffffff81171b68>] ? __read_swap_cache_async+0x118/0x1a0 [130346.263048] [<ffffffff81171bff>] ? read_swap_cache_async+0xf/0x30 [130346.263077] [<ffffffff81171d8e>] ? swapin_readahead+0x16e/0x1c0 [130346.263106] [<ffffffff812a0f6e>] ? radix_tree_lookup_slot+0xe/0x20 [130346.263135] [<ffffffff8112ac84>] ? find_get_entry+0x14/0x130 [130346.263162] [<ffffffff8112af02>] ? pagecache_get_page+0x22/0x280 [130346.263193] [<ffffffff8115cb1f>] ? do_swap_page+0x44f/0x5f0 [130346.263220] [<ffffffff812a0f02>] ? __radix_tree_lookup+0x62/0xc0 [130346.263249] [<ffffffff8115e91a>] ? handle_mm_fault+0x66a/0xf00 [130346.263277] [<ffffffff8112ac84>] ? find_get_entry+0x14/0x130 [130346.263305] [<ffffffff8104a245>] ? __do_page_fault+0x1c5/0x490 [130346.263336] [<ffffffff8150e322>] ? page_fault+0x22/0x30 [130346.263364] [<ffffffff812a7cac>] ? copy_user_generic_string+0x2c/0x40 [130346.263395] [<ffffffff811adc1d>] ? set_fd_set+0x1d/0x30 [130346.263422] [<ffffffff811ae905>] ? core_sys_select+0x1a5/0x260 [130346.263450] [<ffffffff811a913a>] ? getname_flags+0x6a/0x1e0 [130346.263479] [<ffffffff8119ef25>] ? cp_new_stat+0x115/0x130 [130346.263509] [<ffffffff810bf01f>] ? ktime_get_ts64+0x3f/0xf0 [130346.263537] [<ffffffff811aea65>] ? SyS_select+0xa5/0xe0 [130346.263564] [<ffffffff8150c6a0>] ? entry_SYSCALL_64_fastpath+0x13/0x94----------------------------------------
Under such situation, trying to login and execute
/bin/catcould take minutes. Also, writing to btrfs and ext4 seems to be stalling. The btrfs one is a situation whereWQ_MEM_RECLAIMkernel workqueue is unable to make progress.----------------------------------------
[130420.008231] kworker/u34:21: page allocation stalls for 35028ms, order:0, mode:0x2400840(GFP_NOFS|__GFP_NOFAIL) [130420.008287] CPU: 5 PID: 24286 Comm: kworker/u34:21 Tainted: G W I 4.9.0-rc5 #2 [130420.008401] Workqueue: btrfs-extent-refs btrfs_extent_refs_helper [btrfs] [130420.008432] 0000000000000000 ffffffff8129ba69 ffffffff8170e4c8 ffffc900087836a0 [130420.008483] ffffffff8113449f 024008401e3f1b40 ffffffff8170e4c8 ffffc90008783648 [130420.008534] ffffffff00000010 ffffc900087836b0 ffffc90008783660 ffff88041ecc4340 [130420.008586] Call Trace: [130420.008611] [<ffffffff8129ba69>] ? dump_stack+0x46/0x5d [130420.008640] [<ffffffff8113449f>] ? warn_alloc+0x11f/0x140 [130420.008667] [<ffffffff81134d7b>] ? __alloc_pages_slowpath+0x84b/0xa80 [130420.008707] [<ffffffffa020c432>] ? search_bitmap+0xc2/0x140 [btrfs] [130420.008736] [<ffffffff81135260>] ? __alloc_pages_nodemask+0x2b0/0x2f0 [130420.008766] [<ffffffff8117dbda>] ? alloc_pages_current+0x8a/0x110 [130420.008796] [<ffffffff8112afcc>] ? pagecache_get_page+0xec/0x280 [130420.008836] [<ffffffffa01e9aa8>] ? alloc_extent_buffer+0x108/0x430 [btrfs] [130420.008875] [<ffffffffa01b4108>] ? btrfs_alloc_tree_block+0x118/0x4d0 [btrfs] [130420.008927] [<ffffffffa019ae38>] ? __btrfs_cow_block+0x148/0x5d0 [btrfs] [130420.008964] [<ffffffffa019b464>] ? btrfs_cow_block+0x114/0x1d0 [btrfs] [130420.009001] [<ffffffffa019f1d6>] ? btrfs_search_slot+0x206/0xa40 [btrfs] [130420.009039] [<ffffffffa01a6089>] ? lookup_inline_extent_backref+0xd9/0x620 [btrfs] [130420.009095] [<ffffffffa01e4e74>] ? set_extent_bit+0x24/0x30 [btrfs] [130420.009124] [<ffffffff8118567f>] ? kmem_cache_alloc+0x17f/0x1b0 [130420.009161] [<ffffffffa01a7b1f>] ? __btrfs_free_extent.isra.69+0xef/0xd10 [btrfs] [130420.009215] [<ffffffffa0214346>] ? btrfs_merge_delayed_refs+0x56/0x6f0 [btrfs] [130420.009269] [<ffffffffa01ac545>] ? __btrfs_run_delayed_refs+0x745/0x1320 [btrfs] [130420.009314] [<ffffffff810801ef>] ? ttwu_do_wakeup+0xf/0xe0 [130420.009351] [<ffffffffa01b0000>] ? btrfs_run_delayed_refs+0x90/0x2b0 [btrfs] [130420.009404] [<ffffffffa01b02a4>] ? delayed_ref_async_start+0x84/0xa0 [btrfs] [130420.009459] [<ffffffffa01f82a3>] ? normal_work_helper+0xc3/0x2f0 [btrfs] [130420.009490] [<ffffffff81071efb>] ? process_one_work+0x14b/0x400 [130420.009518] [<ffffffff8107251d>] ? worker_thread+0x5d/0x470 [130420.009546] [<ffffffff810724c0>] ? rescuer_thread+0x310/0x310 [130420.009573] [<ffffffff8105ed54>] ? do_group_exit+0x34/0xb0 [130420.009601] [<ffffffff810772bb>] ? kthread+0xcb/0xf0 [130420.009627] [<ffffffff810771f0>] ? kthread_park+0x50/0x50 [130420.009655] [<ffffffff8150c8d2>] ? ret_from_fork+0x22/0x30----------------------------------------
----------------------------------------
[130438.436025] jbd2/dm-0-8: page allocation stalls for 10492ms, order:0, mode:0x2420848(GFP_NOFS|__GFP_NOFAIL|__GFP_HARDWALL|__GFP_MOVABLE) [130438.436095] CPU: 2 PID: 1838 Comm: jbd2/dm-0-8 Tainted: G W I 4.9.0-rc5 #2 [130438.436184] 0000000000000000 ffffffff8129ba69 ffffffff8170e4c8 ffffc90003e13728 [130438.436237] ffffffff8113449f 0242084800000200 ffffffff8170e4c8 ffffc90003e136d0 [130438.436289] 0000000100000010 ffffc90003e13738 ffffc90003e136e8 0000000000000001 [130438.436340] Call Trace: [130438.436368] [<ffffffff8129ba69>] ? dump_stack+0x46/0x5d [130438.436399] [<ffffffff8113449f>] ? warn_alloc+0x11f/0x140 [130438.436426] [<ffffffff81134d7b>] ? __alloc_pages_slowpath+0x84b/0xa80 [130438.436455] [<ffffffff81135260>] ? __alloc_pages_nodemask+0x2b0/0x2f0 [130438.436488] [<ffffffff8117dbda>] ? alloc_pages_current+0x8a/0x110 [130438.436518] [<ffffffff8112afcc>] ? pagecache_get_page+0xec/0x280 [130438.436549] [<ffffffff811cc051>] ? __getblk_gfp+0xf1/0x320 [130438.436593] [<ffffffffa02bc774>] ? ext4_get_branch+0xa4/0x130 [ext4] [130438.436628] [<ffffffffa02bd24b>] ? ext4_ind_map_blocks+0xcb/0xb10 [ext4] [130438.436658] [<ffffffff8108807e>] ? update_curr+0x7e/0x100 [130438.436688] [<ffffffff810bfe61>] ? ktime_get+0x31/0xa0 [130438.436716] [<ffffffff8112e329>] ? mempool_alloc+0x59/0x170 [130438.436743] [<ffffffff8108807e>] ? update_curr+0x7e/0x100 [130438.436775] [<ffffffffa0280813>] ? ext4_map_blocks+0x3c3/0x630 [ext4] [130438.436808] [<ffffffffa0280ae4>] ? _ext4_get_block+0x64/0xc0 [ext4] [130438.436838] [<ffffffff811ca6a7>] ? generic_block_bmap+0x37/0x50 [130438.436870] [<ffffffffa027fc57>] ? ext4_bmap+0x37/0xd0 [ext4] [130438.436901] [<ffffffffa008a5e1>] ? jbd2_journal_bmap+0x21/0x70 [jbd2] [130438.436932] [<ffffffffa008a6be>] ? jbd2_journal_get_descriptor_buffer+0x1e/0xc0 [jbd2] [130438.436979] [<ffffffffa0086aa8>] ? jbd2_journal_write_revoke_records+0x198/0x2b0 [jbd2] [130438.437026] [<ffffffffa0083236>] ? jbd2_journal_commit_transaction+0x5d6/0x19f0 [jbd2] [130438.437071] [<ffffffff8108807e>] ? update_curr+0x7e/0x100 [130438.437099] [<ffffffff8108c8fc>] ? dequeue_task_fair+0x5dc/0x1120 [130438.437127] [<ffffffff8108f61c>] ? pick_next_task_fair+0x12c/0x420 [130438.437157] [<ffffffffa00884e8>] ? kjournald2+0xc8/0x250 [jbd2] [130438.437187] [<ffffffff810948e0>] ? wake_up_atomic_t+0x30/0x30 [130438.437216] [<ffffffffa0088420>] ? commit_timeout+0x10/0x10 [jbd2] [130438.437247] [<ffffffff810772bb>] ? kthread+0xcb/0xf0 [130438.437273] [<ffffffff810771f0>] ? kthread_park+0x50/0x50 [130438.437304] [<ffffffff8150c8d2>] ? ret_from_fork+0x22/0x30----------------------------------------
Under such situation, saving
/sys/kernel/debug/page_ownerto a file might be impossible. And, once the stalling started, it took less than 5 minutes before the kernel panics due to "Out of memory and no killable process". This could happen when E V is offline.Since rsyslogd is likely be killed by the OOM killer for situations like this, E V might want to try serial console or netconsole for saving kernel messages reliably.
I don't know what we will find by analyzing
/sys/kernel/debug/page_owner, but if something is wrong, can't we try whether
"echo 3 >/proc/sys/vm/drop_caches" before the stalling starts helps.I guess that this problem became visible by OOM detection rework which went to Linux 4.7. I don't know what "free_pcp:0kB local_pcp:0kB" means (
get_page_from_freelist()for any order is failng?), but in general I think this/var/log/messagesshowed thatfree_pcp: andlocal_pcp: remains small.
So I rebooted with 4.9rc6 with the patch inspired by the thread "[PATCH] btrfs: limit the number of asynchronous delalloc pages to reasonable value", but at 512K pages, ie:
diff -u2 fs/btrfs/inode.c ../linux-4.9-rc6/fs/btrfs/
linux-4.9-rc6/fs/btrfs/inode.c 2016-11-23 08:31:02.145669550 -0500 renamed from btrfs/inode.c 2016-11-13 13:32:32.000000000 -0500 +1 -1
@@ -1159,5 +1159,5 @@ unsigned long nr_pages; u64 cur_end; - int limit = 10 * SZ_1M; + int limit = SZ_512K; clear_extent_bit(&BTRFS_I(inode)->io_tree, start, end, EXTENT_LOCKED,
System still OOM'd after a few hours of rsync copying & deleting files, but it didn't panic this time which was nice ;-) I then set:
echo 500 >> /proc/sys/vm/watermark_scale_factor
echo 3 >> /proc/sys/vm/dirty_background_ratio
and system has been running rsync fine for most of a day. system memory load is noticably different in sar -r after changing the vm params, rsync during OOM:
12:00:01 AM kbmemfree kbmemused %memused kbbuffers kbcached
kbcommit %commit kbactive kbinact kbdirty
03:25:05 AM 158616 32836640 99.52 72376 30853268
2942644 3.62 26048876 4977872 4936488
03:30:36 AM 157700 32837556 99.52 72468 30944468
2940028 3.62 26070084 4957328 4957432
03:35:02 AM 1802144 31193112 94.54 72560 29266432
2944352 3.62 26184324 3182048 187784
03:40:32 AM 157272 32837984 99.52 72648 30934432
3007244 3.70 26102636 4930744 4927832
03:45:05 AM 158288 32836968 99.52 72896 30980504
412108 0.51 26089920 4959668 4977556
running rsync after tuning VM params:
08:35:01 AM 1903352 31091904 94.23 232772 26603624
2680952 3.30 24133864 5019748 1229964
08:40:01 AM 2878552 30116704 91.28 232800 25641520
2697356 3.32 24158248 4039372 2864656
08:45:01 AM 3482616 29512640 89.45 232656 25043068
2696144 3.32 24087376 3526164 1897192
08:50:01 AM 3590672 29404584 89.12 232856 24962856
2704196 3.33 24078188 3451400 666760
08:55:01 AM 2064900 30930356 93.74 234800 26480996
2730384 3.36 24009244 5044012 50028
Quoted 233 lines · Vlastimil Babka
Quoted 4 lines · E V
System OOM'd several times last night with 4.8.10, I attached the
page_owneroutput from a morning cat ~8 hours after OOM's to the bugzilla case, split and compressed to fit under the 5M attachment limit. Let me know if you need anything else.Looks like for some reason, the stack saving produces garbage stacks that only repeat
save_stack_traceandsave_stackfunctions :/But judging from gfp flags and page flags, most pages seem to be allocated with:
mask 0x2400840(GFP_NOFS|__GFP_NOFAIL)
and page flags:
0x20000000000006c(referenced|uptodate|lru|active)
or 0x20000000000016c(referenced|uptodate|lru|active|owner_priv_1) or 0x20000000000086c(referenced|uptodate|lru|active|private)While
GFP_HIGHUSER_MOVABLE(which I would expect on lru) are less frequent.Example:
Quoted 1 line
grep
GFP_NOFSpage_owner_after_af| wc -l973596
Quoted 1 line
grep
GFP_HIGHUSER_MOVABLEpage_owner_after_af| wc -l158879
Quoted 1 line
grep
GFP_NOFAILpage_owner_after_af| wc -l971442
grepping for btrfs shows that at least some stacks for NOFS/NOFAIL pages imply it:
clear_state_bit+0x135/0x1c0[btrfs]
oradd_delayed_tree_ref+0xbf/0x170[btrfs]
or__btrfs_map_block+0x6a8/0x1200[btrfs]
orbtrfs_buffer_uptodate+0x48/0x70[btrfs]
orbtrfs_set_path_blocking+0x34/0x60[btrfs]and some more variants.
So looks like the pages contain btrfs metadata, are on file lru and from previous checks of
/proc/kpagecountwe know that they most likely havepage_count()== 0 but are not freed. Could btrfs guys provide some insight here?Quoted 181 lines · E V
Quoted 180 lines
Yes, the short window between the stalls and the panic makes it difficult to manually check much. I could setup a cron every 5 minutes or so if you want. Also, I see the OOM's in 4.8, but it has yet to panic on me. Where as 4.9rc has panic'd both times I've booted it, so depending on what you want to look at it might be easier to investigate on 4.8. Let me know, I can turn on a couple of the DEBUG config's and build a new 4.8.8. Never looked into a netconsole or serial console. I think just getting the system to use a higher res console would be an improvement, but the OOM's seemed to be the root cause of the panic so I haven't spent any time looking into that as of yet,
Thanks,
-EliQuoted 163 lines · Tetsuo Handa
Quoted 12 lines · Vlastimil Babka
Quoted 5 lines · E V
System panic'd overnight running 4.9rc5 & rsync. Attached a photo of the stack trace, and the 38 call traces in a 2 minute window shortly before, to the bugzilla case for those not on it's e-mail list:
The panic screenshot has only the last part, but the end marker says it's OOM with no killable processes. The
DEBUG_VMconfig thus didn't trigger anything, and still there's tons of pagecache, mostly clean, that's not being reclaimed.Quoted 5 lines
Could you now try this?
- enableCONFIG_PAGE_OWNER
- boot with kernel option: page_owner=on
- after the first oom, "cat/sys/kernel/debug/page_owner> file"
- provide the file (compressed, it will be quite large)Excuse me for a noise, but do we really need to do
"cat/sys/kernel/debug/page_owner> file" after the first OOM killer invocation? I worry that it might be too difficult to do. Shouldn't we rather do "cat/sys/kernel/debug/page_owner> file" hourly and compare tendency between the latest one and previous one?This system has swap, and
/var/log/messagesbefore panic reports that swapin was stalling at memory allocation.----------------------------------------
[130346.262510] dsm_sa_datamgrd: page allocation stalls for 52400ms, order:0, mode:0x24200ca(GFP_HIGHUSER_MOVABLE) [130346.262572] CPU: 1 PID: 3622 Comm: dsm_sa_datamgrd Tainted: G W I 4.9.0-rc5 #2 [130346.262662] 0000000000000000 ffffffff8129ba69 ffffffff8170e4c8 ffffc90003ccb8d8 [130346.262714] ffffffff8113449f 024200ca1ca11b40 ffffffff8170e4c8 ffffc90003ccb880 [130346.262765] ffffffff00000010 ffffc90003ccb8e8 ffffc90003ccb898 ffff88041f226e80 [130346.262817] Call Trace: [130346.262843] [<ffffffff8129ba69>] ? dump_stack+0x46/0x5d [130346.262872] [<ffffffff8113449f>] ? warn_alloc+0x11f/0x140 [130346.262899] [<ffffffff81134d7b>] ? __alloc_pages_slowpath+0x84b/0xa80 [130346.262929] [<ffffffff81135260>] ? __alloc_pages_nodemask+0x2b0/0x2f0 [130346.262960] [<ffffffff8117f1be>] ? alloc_pages_vma+0xbe/0x260 [130346.262989] [<ffffffff8112af02>] ? pagecache_get_page+0x22/0x280 [130346.263019] [<ffffffff81171b68>] ? __read_swap_cache_async+0x118/0x1a0 [130346.263048] [<ffffffff81171bff>] ? read_swap_cache_async+0xf/0x30 [130346.263077] [<ffffffff81171d8e>] ? swapin_readahead+0x16e/0x1c0 [130346.263106] [<ffffffff812a0f6e>] ? radix_tree_lookup_slot+0xe/0x20 [130346.263135] [<ffffffff8112ac84>] ? find_get_entry+0x14/0x130 [130346.263162] [<ffffffff8112af02>] ? pagecache_get_page+0x22/0x280 [130346.263193] [<ffffffff8115cb1f>] ? do_swap_page+0x44f/0x5f0 [130346.263220] [<ffffffff812a0f02>] ? __radix_tree_lookup+0x62/0xc0 [130346.263249] [<ffffffff8115e91a>] ? handle_mm_fault+0x66a/0xf00 [130346.263277] [<ffffffff8112ac84>] ? find_get_entry+0x14/0x130 [130346.263305] [<ffffffff8104a245>] ? __do_page_fault+0x1c5/0x490 [130346.263336] [<ffffffff8150e322>] ? page_fault+0x22/0x30 [130346.263364] [<ffffffff812a7cac>] ? copy_user_generic_string+0x2c/0x40 [130346.263395] [<ffffffff811adc1d>] ? set_fd_set+0x1d/0x30 [130346.263422] [<ffffffff811ae905>] ? core_sys_select+0x1a5/0x260 [130346.263450] [<ffffffff811a913a>] ? getname_flags+0x6a/0x1e0 [130346.263479] [<ffffffff8119ef25>] ? cp_new_stat+0x115/0x130 [130346.263509] [<ffffffff810bf01f>] ? ktime_get_ts64+0x3f/0xf0 [130346.263537] [<ffffffff811aea65>] ? SyS_select+0xa5/0xe0 [130346.263564] [<ffffffff8150c6a0>] ? entry_SYSCALL_64_fastpath+0x13/0x94----------------------------------------
Under such situation, trying to login and execute
/bin/catcould take minutes. Also, writing to btrfs and ext4 seems to be stalling. The btrfs one is a situation whereWQ_MEM_RECLAIMkernel workqueue is unable to make progress.----------------------------------------
[130420.008231] kworker/u34:21: page allocation stalls for 35028ms, order:0, mode:0x2400840(GFP_NOFS|__GFP_NOFAIL) [130420.008287] CPU: 5 PID: 24286 Comm: kworker/u34:21 Tainted: G W I 4.9.0-rc5 #2 [130420.008401] Workqueue: btrfs-extent-refs btrfs_extent_refs_helper [btrfs] [130420.008432] 0000000000000000 ffffffff8129ba69 ffffffff8170e4c8 ffffc900087836a0 [130420.008483] ffffffff8113449f 024008401e3f1b40 ffffffff8170e4c8 ffffc90008783648 [130420.008534] ffffffff00000010 ffffc900087836b0 ffffc90008783660 ffff88041ecc4340 [130420.008586] Call Trace: [130420.008611] [<ffffffff8129ba69>] ? dump_stack+0x46/0x5d [130420.008640] [<ffffffff8113449f>] ? warn_alloc+0x11f/0x140 [130420.008667] [<ffffffff81134d7b>] ? __alloc_pages_slowpath+0x84b/0xa80 [130420.008707] [<ffffffffa020c432>] ? search_bitmap+0xc2/0x140 [btrfs] [130420.008736] [<ffffffff81135260>] ? __alloc_pages_nodemask+0x2b0/0x2f0 [130420.008766] [<ffffffff8117dbda>] ? alloc_pages_current+0x8a/0x110 [130420.008796] [<ffffffff8112afcc>] ? pagecache_get_page+0xec/0x280 [130420.008836] [<ffffffffa01e9aa8>] ? alloc_extent_buffer+0x108/0x430 [btrfs] [130420.008875] [<ffffffffa01b4108>] ? btrfs_alloc_tree_block+0x118/0x4d0 [btrfs] [130420.008927] [<ffffffffa019ae38>] ? __btrfs_cow_block+0x148/0x5d0 [btrfs] [130420.008964] [<ffffffffa019b464>] ? btrfs_cow_block+0x114/0x1d0 [btrfs] [130420.009001] [<ffffffffa019f1d6>] ? btrfs_search_slot+0x206/0xa40 [btrfs] [130420.009039] [<ffffffffa01a6089>] ? lookup_inline_extent_backref+0xd9/0x620 [btrfs] [130420.009095] [<ffffffffa01e4e74>] ? set_extent_bit+0x24/0x30 [btrfs] [130420.009124] [<ffffffff8118567f>] ? kmem_cache_alloc+0x17f/0x1b0 [130420.009161] [<ffffffffa01a7b1f>] ? __btrfs_free_extent.isra.69+0xef/0xd10 [btrfs] [130420.009215] [<ffffffffa0214346>] ? btrfs_merge_delayed_refs+0x56/0x6f0 [btrfs] [130420.009269] [<ffffffffa01ac545>] ? __btrfs_run_delayed_refs+0x745/0x1320 [btrfs] [130420.009314] [<ffffffff810801ef>] ? ttwu_do_wakeup+0xf/0xe0 [130420.009351] [<ffffffffa01b0000>] ? btrfs_run_delayed_refs+0x90/0x2b0 [btrfs] [130420.009404] [<ffffffffa01b02a4>] ? delayed_ref_async_start+0x84/0xa0 [btrfs] [130420.009459] [<ffffffffa01f82a3>] ? normal_work_helper+0xc3/0x2f0 [btrfs] [130420.009490] [<ffffffff81071efb>] ? process_one_work+0x14b/0x400 [130420.009518] [<ffffffff8107251d>] ? worker_thread+0x5d/0x470 [130420.009546] [<ffffffff810724c0>] ? rescuer_thread+0x310/0x310 [130420.009573] [<ffffffff8105ed54>] ? do_group_exit+0x34/0xb0 [130420.009601] [<ffffffff810772bb>] ? kthread+0xcb/0xf0 [130420.009627] [<ffffffff810771f0>] ? kthread_park+0x50/0x50 [130420.009655] [<ffffffff8150c8d2>] ? ret_from_fork+0x22/0x30----------------------------------------
----------------------------------------
[130438.436025] jbd2/dm-0-8: page allocation stalls for 10492ms, order:0, mode:0x2420848(GFP_NOFS|__GFP_NOFAIL|__GFP_HARDWALL|__GFP_MOVABLE) [130438.436095] CPU: 2 PID: 1838 Comm: jbd2/dm-0-8 Tainted: G W I 4.9.0-rc5 #2 [130438.436184] 0000000000000000 ffffffff8129ba69 ffffffff8170e4c8 ffffc90003e13728 [130438.436237] ffffffff8113449f 0242084800000200 ffffffff8170e4c8 ffffc90003e136d0 [130438.436289] 0000000100000010 ffffc90003e13738 ffffc90003e136e8 0000000000000001 [130438.436340] Call Trace: [130438.436368] [<ffffffff8129ba69>] ? dump_stack+0x46/0x5d [130438.436399] [<ffffffff8113449f>] ? warn_alloc+0x11f/0x140 [130438.436426] [<ffffffff81134d7b>] ? __alloc_pages_slowpath+0x84b/0xa80 [130438.436455] [<ffffffff81135260>] ? __alloc_pages_nodemask+0x2b0/0x2f0 [130438.436488] [<ffffffff8117dbda>] ? alloc_pages_current+0x8a/0x110 [130438.436518] [<ffffffff8112afcc>] ? pagecache_get_page+0xec/0x280 [130438.436549] [<ffffffff811cc051>] ? __getblk_gfp+0xf1/0x320 [130438.436593] [<ffffffffa02bc774>] ? ext4_get_branch+0xa4/0x130 [ext4] [130438.436628] [<ffffffffa02bd24b>] ? ext4_ind_map_blocks+0xcb/0xb10 [ext4] [130438.436658] [<ffffffff8108807e>] ? update_curr+0x7e/0x100 [130438.436688] [<ffffffff810bfe61>] ? ktime_get+0x31/0xa0 [130438.436716] [<ffffffff8112e329>] ? mempool_alloc+0x59/0x170 [130438.436743] [<ffffffff8108807e>] ? update_curr+0x7e/0x100 [130438.436775] [<ffffffffa0280813>] ? ext4_map_blocks+0x3c3/0x630 [ext4] [130438.436808] [<ffffffffa0280ae4>] ? _ext4_get_block+0x64/0xc0 [ext4] [130438.436838] [<ffffffff811ca6a7>] ? generic_block_bmap+0x37/0x50 [130438.436870] [<ffffffffa027fc57>] ? ext4_bmap+0x37/0xd0 [ext4] [130438.436901] [<ffffffffa008a5e1>] ? jbd2_journal_bmap+0x21/0x70 [jbd2] [130438.436932] [<ffffffffa008a6be>] ? jbd2_journal_get_descriptor_buffer+0x1e/0xc0 [jbd2] [130438.436979] [<ffffffffa0086aa8>] ? jbd2_journal_write_revoke_records+0x198/0x2b0 [jbd2] [130438.437026] [<ffffffffa0083236>] ? jbd2_journal_commit_transaction+0x5d6/0x19f0 [jbd2] [130438.437071] [<ffffffff8108807e>] ? update_curr+0x7e/0x100 [130438.437099] [<ffffffff8108c8fc>] ? dequeue_task_fair+0x5dc/0x1120 [130438.437127] [<ffffffff8108f61c>] ? pick_next_task_fair+0x12c/0x420 [130438.437157] [<ffffffffa00884e8>] ? kjournald2+0xc8/0x250 [jbd2] [130438.437187] [<ffffffff810948e0>] ? wake_up_atomic_t+0x30/0x30 [130438.437216] [<ffffffffa0088420>] ? commit_timeout+0x10/0x10 [jbd2] [130438.437247] [<ffffffff810772bb>] ? kthread+0xcb/0xf0 [130438.437273] [<ffffffff810771f0>] ? kthread_park+0x50/0x50 [130438.437304] [<ffffffff8150c8d2>] ? ret_from_fork+0x22/0x30----------------------------------------
Under such situation, saving
/sys/kernel/debug/page_ownerto a file might be impossible. And, once the stalling started, it took less than 5 minutes before the kernel panics due to "Out of memory and no killable process". This could happen when E V is offline.Since rsyslogd is likely be killed by the OOM killer for situations like this, E V might want to try serial console or netconsole for saving kernel messages reliably.
I don't know what we will find by analyzing
/sys/kernel/debug/page_owner, but if something is wrong, can't we try whether
"echo 3 >/proc/sys/vm/drop_caches" before the stalling starts helps.I guess that this problem became visible by OOM detection rework which went to Linux 4.7. I don't know what "free_pcp:0kB local_pcp:0kB" means (
get_page_from_freelist()for any order is failng?), but in general I think this/var/log/messagesshowed thatfree_pcp: andlocal_pcp: remains small.