* Re: [Bug 186671] New: OOM on system with just rsync running 32GB of ram 30GB of pagecache [not found] ` <20161103115353.de87ff35756a4ca8b21d2c57@linux-foundation.org> @ 2016-11-03 23:58 ` Vlastimil Babka 2016-11-04 14:13 ` E V 0 siblings, 1 reply; 14+ messages in thread From: Vlastimil Babka @ 2016-11-03 23:58 UTC (permalink / raw) To: Andrew Morton, eliventer Cc: bugzilla-daemon, linux-mm, Michal Hocko, linux-btrfs On 11/03/2016 07:53 PM, Andrew Morton wrote: > > (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 > On Wed, 02 Nov 2016 13:02:39 +0000 bugzilla-daemon@bugzilla.kernel.org 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: akpm@linux-foundation.org >> Reporter: eliventer@gmail.com >> Regression: No >> >> 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. 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!). >> [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:26704kB >> active_file:14365920kB inactive_file:1341120kB unevictable:0kB >> isolated(anon):0kB isolated(file):0kB mapped:15852kB dirty:1338044kB >> writeback:3072kB shmem:0kB shmem_thp: 0kB shmem_pmdmapped: 0kB >> anon_thp: 9484kB writeback_tmp:0kB unstable:0kB pages_scanned:23811175 >> all_unreclaimable? yes >> [93428.030933] Node 1 active_anon:12148kB inactive_anon:12916kB >> active_file:12644472kB inactive_file:2655544kB unevictable:0kB >> isolated(anon):0kB isolated(file):1152kB mapped:15880kB >> dirty:2653384kB writeback:3588kB shmem:0kB shmem_thp: 0kB >> shmem_pmdmapped: 0kB anon_thp: 3196kB writeback_tmp:0kB unstable:0kB >> pages_scanned:23178917 all_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 >> [93428.031059] Node 0 Normal free:44968kB min:45192kB low:61736kB >> high: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: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 >> [93428.031373] lowmem_reserve[]: 0 3216 16045 16045 >> [93428.031408] Node 1 DMA32 free:60288kB min:8996kB low:12288kB >> high: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:49016kB >> high: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 >> 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 majordomo@kvack.org. For more info on Linux MM, > see: http://www.linux-mm.org/ . > Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a> > ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: [Bug 186671] New: OOM on system with just rsync running 32GB of ram 30GB of pagecache 2016-11-03 23:58 ` [Bug 186671] New: OOM on system with just rsync running 32GB of ram 30GB of pagecache Vlastimil Babka @ 2016-11-04 14:13 ` E V 2016-11-04 21:00 ` Vlastimil Babka 0 siblings, 1 reply; 14+ messages in thread From: E V @ 2016-11-04 14:13 UTC (permalink / raw) To: Vlastimil Babka Cc: Andrew Morton, bugzilla-daemon, linux-mm, Michal Hocko, linux-btrfs 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/vmstat nr_free_pages 106970 nr_zone_inactive_anon 110034 nr_zone_active_anon 108424 nr_zone_inactive_file 350017 nr_zone_active_file 2158161 nr_zone_unevictable 0 nr_zone_write_pending 114 nr_mlock 0 nr_slab_reclaimable 4962990 nr_slab_unreclaimable 415089 nr_page_table_pages 2149 nr_kernel_stack 6176 nr_bounce 0 numa_hit 403780590 numa_miss 176970926 numa_foreign 176970926 numa_interleave 19415 numa_local 403780590 numa_other 0 nr_free_cma 0 nr_inactive_anon 110034 nr_active_anon 108424 nr_inactive_file 350017 nr_active_file 2158161 nr_unevictable 0 nr_isolated_anon 0 nr_isolated_file 0 nr_pages_scanned 0 workingset_refault 1443060 workingset_activate 558143 workingset_nodereclaim 6879280 nr_anon_pages 216243 nr_mapped 6462 nr_file_pages 2510544 nr_dirty 114 nr_writeback 0 nr_writeback_temp 0 nr_shmem 2179 nr_shmem_hugepages 0 nr_shmem_pmdmapped 0 nr_anon_transparent_hugepages 0 nr_unstable 0 nr_vmscan_write 1127 nr_vmscan_immediate_reclaim 19056 nr_dirtied 254716641 nr_written 254532248 nr_dirty_threshold 383652 nr_dirty_background_threshold 50612 pgpgin 21962903 pgpgout 1024651087 pswpin 214 pswpout 1127 pgalloc_dma 0 pgalloc_dma32 87690791 pgalloc_normal 806119097 pgalloc_movable 0 allocstall_dma 0 allocstall_dma32 0 allocstall_normal 210 allocstall_movable 0 pgskip_dma 0 pgskip_dma32 0 pgskip_normal 0 pgskip_movable 0 pgfree 894694404 pgactivate 5513535 pgdeactivate 7989719 pgfault 4748538 pgmajfault 2528 pglazyfreed 0 pgrefill 7999038 pgsteal_kswapd 504125672 pgsteal_direct 36130 pgscan_kswapd 504479233 pgscan_direct 36142 pgscan_direct_throttle 0 zone_reclaim_failed 0 pginodesteal 1074 slabs_scanned 61625344 kswapd_inodesteal 1956613 kswapd_low_wmark_hit_quickly 49386 kswapd_high_wmark_hit_quickly 79880 pageoutrun 211656 pgrotated 203832 drop_pagecache 0 drop_slab 0 pgmigrate_success 684523 pgmigrate_fail 1189249 compact_migrate_scanned 94848219 compact_free_scanned 2329620072 compact_isolated 2648057 compact_stall 38 compact_fail 0 compact_success 38 compact_daemon_wake 9682 htlb_buddy_alloc_success 0 htlb_buddy_alloc_fail 0 unevictable_pgs_culled 12473 unevictable_pgs_scanned 0 unevictable_pgs_rescued 11979 unevictable_pgs_mlocked 14556 unevictable_pgs_munlocked 14556 unevictable_pgs_cleared 0 unevictable_pgs_stranded 0 thp_fault_alloc 0 thp_fault_fallback 0 thp_collapse_alloc 0 thp_collapse_alloc_failed 0 thp_file_alloc 0 thp_file_mapped 0 thp_split_page 0 thp_split_page_failed 0 thp_deferred_split_page 0 thp_split_pmd 0 thp_zero_page_alloc 0 thp_zero_page_alloc_failed 0 On Thu, Nov 3, 2016 at 7:58 PM, Vlastimil Babka <vbabka@suse.cz> wrote: > On 11/03/2016 07:53 PM, Andrew Morton wrote: >> >> (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 > >> On Wed, 02 Nov 2016 13:02:39 +0000 bugzilla-daemon@bugzilla.kernel.org 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: akpm@linux-foundation.org >>> Reporter: eliventer@gmail.com >>> Regression: No >>> >>> 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. > > 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!). > >>> [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:26704kB >>> active_file:14365920kB inactive_file:1341120kB unevictable:0kB >>> isolated(anon):0kB isolated(file):0kB mapped:15852kB dirty:1338044kB >>> writeback:3072kB shmem:0kB shmem_thp: 0kB shmem_pmdmapped: 0kB >>> anon_thp: 9484kB writeback_tmp:0kB unstable:0kB pages_scanned:23811175 >>> all_unreclaimable? yes >>> [93428.030933] Node 1 active_anon:12148kB inactive_anon:12916kB >>> active_file:12644472kB inactive_file:2655544kB unevictable:0kB >>> isolated(anon):0kB isolated(file):1152kB mapped:15880kB >>> dirty:2653384kB writeback:3588kB shmem:0kB shmem_thp: 0kB >>> shmem_pmdmapped: 0kB anon_thp: 3196kB writeback_tmp:0kB unstable:0kB >>> pages_scanned:23178917 all_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 > >>> [93428.031059] Node 0 Normal free:44968kB min:45192kB low:61736kB >>> high: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: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 >>> [93428.031373] lowmem_reserve[]: 0 3216 16045 16045 >>> [93428.031408] Node 1 DMA32 free:60288kB min:8996kB low:12288kB >>> high: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:49016kB >>> high: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 >>> 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 majordomo@kvack.org. For more info on Linux MM, >> see: http://www.linux-mm.org/ . >> Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a> >> > ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: [Bug 186671] New: OOM on system with just rsync running 32GB of ram 30GB of pagecache 2016-11-04 14:13 ` E V @ 2016-11-04 21:00 ` Vlastimil Babka 2016-11-14 13:27 ` E V 0 siblings, 1 reply; 14+ messages in thread From: Vlastimil Babka @ 2016-11-04 21:00 UTC (permalink / raw) To: E V; +Cc: Andrew Morton, bugzilla-daemon, linux-mm, Michal Hocko, linux-btrfs On 11/04/2016 03:13 PM, E V wrote: > 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. ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: [Bug 186671] New: OOM on system with just rsync running 32GB of ram 30GB of pagecache 2016-11-04 21:00 ` Vlastimil Babka @ 2016-11-14 13:27 ` E V 2016-11-14 17:04 ` Vlastimil Babka 0 siblings, 1 reply; 14+ messages in thread From: E V @ 2016-11-14 13:27 UTC (permalink / raw) To: Vlastimil Babka Cc: Andrew Morton, bugzilla-daemon, linux-mm, Michal Hocko, linux-btrfs 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 60965 nr_zone_inactive_anon 4646 nr_zone_active_anon 3265 nr_zone_inactive_file 633882 nr_zone_active_file 7017458 nr_zone_unevictable 0 nr_zone_write_pending 0 nr_mlock 0 nr_slab_reclaimable 299205 nr_slab_unreclaimable 195497 nr_page_table_pages 935 nr_kernel_stack 4976 nr_bounce 0 numa_hit 3577063288 numa_miss 541393191 numa_foreign 541393191 numa_interleave 19415 numa_local 3577063288 numa_other 0 nr_free_cma 0 nr_inactive_anon 4646 nr_active_anon 3265 nr_inactive_file 633882 nr_active_file 7017458 nr_unevictable 0 nr_isolated_anon 0 nr_isolated_file 0 nr_pages_scanned 0 workingset_refault 42685891 workingset_activate 15247281 workingset_nodereclaim 26375216 nr_anon_pages 5067 nr_mapped 5630 nr_file_pages 7654746 nr_dirty 0 nr_writeback 0 nr_writeback_temp 0 nr_shmem 2504 nr_shmem_hugepages 0 nr_shmem_pmdmapped 0 nr_anon_transparent_hugepages 0 nr_unstable 0 nr_vmscan_write 5243750485 nr_vmscan_immediate_reclaim 4207633857 nr_dirtied 1839143430 nr_written 1832626107 nr_dirty_threshold 1147728 nr_dirty_background_threshold 151410 pgpgin 166731189 pgpgout 7328142335 pswpin 98608 pswpout 117794 pgalloc_dma 29504 pgalloc_dma32 1006726216 pgalloc_normal 5275218188 pgalloc_movable 0 allocstall_dma 0 allocstall_dma32 0 allocstall_normal 36461 allocstall_movable 5867 pgskip_dma 0 pgskip_dma32 0 pgskip_normal 6417890 pgskip_movable 0 pgfree 6309223401 pgactivate 35076483 pgdeactivate 63556974 pgfault 35753842 pgmajfault 69126 pglazyfreed 0 pgrefill 70008598 pgsteal_kswapd 3567289713 pgsteal_direct 5878057 pgscan_kswapd 9059309872 pgscan_direct 4239367903 pgscan_direct_throttle 0 zone_reclaim_failed 0 pginodesteal 102916 slabs_scanned 460790262 kswapd_inodesteal 9130243 kswapd_low_wmark_hit_quickly 10634373 kswapd_high_wmark_hit_quickly 7348173 pageoutrun 18349115 pgrotated 16291322 drop_pagecache 0 drop_slab 0 pgmigrate_success 18912908 pgmigrate_fail 63382146 compact_migrate_scanned 2986269789 compact_free_scanned 190451505123 compact_isolated 109549437 compact_stall 3544 compact_fail 8 compact_success 3536 compact_daemon_wake 1403515 htlb_buddy_alloc_success 0 htlb_buddy_alloc_fail 0 unevictable_pgs_culled 12473 unevictable_pgs_scanned 0 unevictable_pgs_rescued 11979 unevictable_pgs_mlocked 14556 unevictable_pgs_munlocked 14556 unevictable_pgs_cleared 0 unevictable_pgs_stranded 0 thp_fault_alloc 0 thp_fault_fallback 0 thp_collapse_alloc 0 thp_collapse_alloc_failed 0 thp_file_alloc 0 thp_file_mapped 0 thp_split_page 0 thp_split_page_failed 0 thp_deferred_split_page 0 thp_split_pmd 0 thp_zero_page_alloc 0 thp_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: 0kB shmem_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: 0kB anon_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), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB On Fri, Nov 4, 2016 at 5:00 PM, Vlastimil Babka <vbabka@suse.cz> wrote: > On 11/04/2016 03:13 PM, E V wrote: >> 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. ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: [Bug 186671] New: OOM on system with just rsync running 32GB of ram 30GB of pagecache 2016-11-14 13:27 ` E V @ 2016-11-14 17:04 ` Vlastimil Babka 2016-11-14 20:56 ` E V 0 siblings, 1 reply; 14+ messages in thread From: Vlastimil Babka @ 2016-11-14 17:04 UTC (permalink / raw) To: E V Cc: Andrew Morton, bugzilla-daemon, linux-mm, Michal Hocko, linux-btrfs, Kirill A. Shutemov On 11/14/2016 02:27 PM, E V wrote: > 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 > 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 60965 > nr_zone_inactive_anon 4646 > nr_zone_active_anon 3265 > nr_zone_inactive_file 633882 > nr_zone_active_file 7017458 > nr_zone_unevictable 0 > nr_zone_write_pending 0 > nr_mlock 0 > nr_slab_reclaimable 299205 > nr_slab_unreclaimable 195497 > nr_page_table_pages 935 > nr_kernel_stack 4976 > nr_bounce 0 > numa_hit 3577063288 > numa_miss 541393191 > numa_foreign 541393191 > numa_interleave 19415 > numa_local 3577063288 > numa_other 0 > nr_free_cma 0 > nr_inactive_anon 4646 > nr_active_anon 3265 > nr_inactive_file 633882 > nr_active_file 7017458 > nr_unevictable 0 > nr_isolated_anon 0 > nr_isolated_file 0 > nr_pages_scanned 0 > workingset_refault 42685891 > workingset_activate 15247281 > workingset_nodereclaim 26375216 > nr_anon_pages 5067 > nr_mapped 5630 > nr_file_pages 7654746 > nr_dirty 0 > nr_writeback 0 > nr_writeback_temp 0 > nr_shmem 2504 > nr_shmem_hugepages 0 > nr_shmem_pmdmapped 0 > nr_anon_transparent_hugepages 0 > nr_unstable 0 > nr_vmscan_write 5243750485 > nr_vmscan_immediate_reclaim 4207633857 > nr_dirtied 1839143430 > nr_written 1832626107 > nr_dirty_threshold 1147728 > nr_dirty_background_threshold 151410 > pgpgin 166731189 > pgpgout 7328142335 > pswpin 98608 > pswpout 117794 > pgalloc_dma 29504 > pgalloc_dma32 1006726216 > pgalloc_normal 5275218188 > pgalloc_movable 0 > allocstall_dma 0 > allocstall_dma32 0 > allocstall_normal 36461 > allocstall_movable 5867 > pgskip_dma 0 > pgskip_dma32 0 > pgskip_normal 6417890 > pgskip_movable 0 > pgfree 6309223401 > pgactivate 35076483 > pgdeactivate 63556974 > pgfault 35753842 > pgmajfault 69126 > pglazyfreed 0 > pgrefill 70008598 > pgsteal_kswapd 3567289713 > pgsteal_direct 5878057 > pgscan_kswapd 9059309872 > pgscan_direct 4239367903 > pgscan_direct_throttle 0 > zone_reclaim_failed 0 > pginodesteal 102916 > slabs_scanned 460790262 > kswapd_inodesteal 9130243 > kswapd_low_wmark_hit_quickly 10634373 > kswapd_high_wmark_hit_quickly 7348173 > pageoutrun 18349115 > pgrotated 16291322 > drop_pagecache 0 > drop_slab 0 > pgmigrate_success 18912908 > pgmigrate_fail 63382146 > compact_migrate_scanned 2986269789 > compact_free_scanned 190451505123 > compact_isolated 109549437 > compact_stall 3544 > compact_fail 8 > compact_success 3536 > compact_daemon_wake 1403515 > htlb_buddy_alloc_success 0 > htlb_buddy_alloc_fail 0 > unevictable_pgs_culled 12473 > unevictable_pgs_scanned 0 > unevictable_pgs_rescued 11979 > unevictable_pgs_mlocked 14556 > unevictable_pgs_munlocked 14556 > unevictable_pgs_cleared 0 > unevictable_pgs_stranded 0 > thp_fault_alloc 0 > thp_fault_fallback 0 > thp_collapse_alloc 0 > thp_collapse_alloc_failed 0 > thp_file_alloc 0 > thp_file_mapped 0 > thp_split_page 0 > thp_split_page_failed 0 > thp_deferred_split_page 0 > thp_split_pmd 0 > thp_zero_page_alloc 0 > thp_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: 0kB > shmem_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: 0kB > anon_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), now > anon-rss:0kB, file-rss:0kB, shmem-rss:0kB > > On Fri, Nov 4, 2016 at 5:00 PM, Vlastimil Babka <vbabka@suse.cz> wrote: >> On 11/04/2016 03:13 PM, E V wrote: >>> 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. ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: [Bug 186671] New: OOM on system with just rsync running 32GB of ram 30GB of pagecache 2016-11-14 17:04 ` Vlastimil Babka @ 2016-11-14 20:56 ` E V 2016-11-16 13:39 ` E V 0 siblings, 1 reply; 14+ messages in thread From: E V @ 2016-11-14 20:56 UTC (permalink / raw) To: Vlastimil Babka Cc: Andrew Morton, bugzilla-daemon, linux-mm, Michal Hocko, linux-btrfs, Kirill A. Shutemov 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. On Mon, Nov 14, 2016 at 12:04 PM, Vlastimil Babka <vbabka@suse.cz> wrote: > On 11/14/2016 02:27 PM, E V wrote: >> 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 > >> 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 60965 >> nr_zone_inactive_anon 4646 >> nr_zone_active_anon 3265 >> nr_zone_inactive_file 633882 >> nr_zone_active_file 7017458 >> nr_zone_unevictable 0 >> nr_zone_write_pending 0 >> nr_mlock 0 >> nr_slab_reclaimable 299205 >> nr_slab_unreclaimable 195497 >> nr_page_table_pages 935 >> nr_kernel_stack 4976 >> nr_bounce 0 >> numa_hit 3577063288 >> numa_miss 541393191 >> numa_foreign 541393191 >> numa_interleave 19415 >> numa_local 3577063288 >> numa_other 0 >> nr_free_cma 0 >> nr_inactive_anon 4646 >> nr_active_anon 3265 >> nr_inactive_file 633882 >> nr_active_file 7017458 >> nr_unevictable 0 >> nr_isolated_anon 0 >> nr_isolated_file 0 >> nr_pages_scanned 0 >> workingset_refault 42685891 >> workingset_activate 15247281 >> workingset_nodereclaim 26375216 >> nr_anon_pages 5067 >> nr_mapped 5630 >> nr_file_pages 7654746 >> nr_dirty 0 >> nr_writeback 0 >> nr_writeback_temp 0 >> nr_shmem 2504 >> nr_shmem_hugepages 0 >> nr_shmem_pmdmapped 0 >> nr_anon_transparent_hugepages 0 >> nr_unstable 0 >> nr_vmscan_write 5243750485 >> nr_vmscan_immediate_reclaim 4207633857 >> nr_dirtied 1839143430 >> nr_written 1832626107 >> nr_dirty_threshold 1147728 >> nr_dirty_background_threshold 151410 >> pgpgin 166731189 >> pgpgout 7328142335 >> pswpin 98608 >> pswpout 117794 >> pgalloc_dma 29504 >> pgalloc_dma32 1006726216 >> pgalloc_normal 5275218188 >> pgalloc_movable 0 >> allocstall_dma 0 >> allocstall_dma32 0 >> allocstall_normal 36461 >> allocstall_movable 5867 >> pgskip_dma 0 >> pgskip_dma32 0 >> pgskip_normal 6417890 >> pgskip_movable 0 >> pgfree 6309223401 >> pgactivate 35076483 >> pgdeactivate 63556974 >> pgfault 35753842 >> pgmajfault 69126 >> pglazyfreed 0 >> pgrefill 70008598 >> pgsteal_kswapd 3567289713 >> pgsteal_direct 5878057 >> pgscan_kswapd 9059309872 >> pgscan_direct 4239367903 >> pgscan_direct_throttle 0 >> zone_reclaim_failed 0 >> pginodesteal 102916 >> slabs_scanned 460790262 >> kswapd_inodesteal 9130243 >> kswapd_low_wmark_hit_quickly 10634373 >> kswapd_high_wmark_hit_quickly 7348173 >> pageoutrun 18349115 >> pgrotated 16291322 >> drop_pagecache 0 >> drop_slab 0 >> pgmigrate_success 18912908 >> pgmigrate_fail 63382146 >> compact_migrate_scanned 2986269789 >> compact_free_scanned 190451505123 >> compact_isolated 109549437 >> compact_stall 3544 >> compact_fail 8 >> compact_success 3536 >> compact_daemon_wake 1403515 >> htlb_buddy_alloc_success 0 >> htlb_buddy_alloc_fail 0 >> unevictable_pgs_culled 12473 >> unevictable_pgs_scanned 0 >> unevictable_pgs_rescued 11979 >> unevictable_pgs_mlocked 14556 >> unevictable_pgs_munlocked 14556 >> unevictable_pgs_cleared 0 >> unevictable_pgs_stranded 0 >> thp_fault_alloc 0 >> thp_fault_fallback 0 >> thp_collapse_alloc 0 >> thp_collapse_alloc_failed 0 >> thp_file_alloc 0 >> thp_file_mapped 0 >> thp_split_page 0 >> thp_split_page_failed 0 >> thp_deferred_split_page 0 >> thp_split_pmd 0 >> thp_zero_page_alloc 0 >> thp_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: 0kB >> shmem_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: 0kB >> anon_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), now >> anon-rss:0kB, file-rss:0kB, shmem-rss:0kB >> >> On Fri, Nov 4, 2016 at 5:00 PM, Vlastimil Babka <vbabka@suse.cz> wrote: >>> On 11/04/2016 03:13 PM, E V wrote: >>>> 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. > ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: [Bug 186671] New: OOM on system with just rsync running 32GB of ram 30GB of pagecache 2016-11-14 20:56 ` E V @ 2016-11-16 13:39 ` E V 2016-11-17 21:49 ` Vlastimil Babka 0 siblings, 1 reply; 14+ messages in thread From: E V @ 2016-11-16 13:39 UTC (permalink / raw) To: Vlastimil Babka Cc: Andrew Morton, bugzilla-daemon, linux-mm, Michal Hocko, linux-btrfs, Kirill A. Shutemov 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 On Mon, Nov 14, 2016 at 3:56 PM, E V <eliventer@gmail.com> wrote: > 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. > > On Mon, Nov 14, 2016 at 12:04 PM, Vlastimil Babka <vbabka@suse.cz> wrote: >> On 11/14/2016 02:27 PM, E V wrote: >>> 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 >> >>> 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 60965 >>> nr_zone_inactive_anon 4646 >>> nr_zone_active_anon 3265 >>> nr_zone_inactive_file 633882 >>> nr_zone_active_file 7017458 >>> nr_zone_unevictable 0 >>> nr_zone_write_pending 0 >>> nr_mlock 0 >>> nr_slab_reclaimable 299205 >>> nr_slab_unreclaimable 195497 >>> nr_page_table_pages 935 >>> nr_kernel_stack 4976 >>> nr_bounce 0 >>> numa_hit 3577063288 >>> numa_miss 541393191 >>> numa_foreign 541393191 >>> numa_interleave 19415 >>> numa_local 3577063288 >>> numa_other 0 >>> nr_free_cma 0 >>> nr_inactive_anon 4646 >>> nr_active_anon 3265 >>> nr_inactive_file 633882 >>> nr_active_file 7017458 >>> nr_unevictable 0 >>> nr_isolated_anon 0 >>> nr_isolated_file 0 >>> nr_pages_scanned 0 >>> workingset_refault 42685891 >>> workingset_activate 15247281 >>> workingset_nodereclaim 26375216 >>> nr_anon_pages 5067 >>> nr_mapped 5630 >>> nr_file_pages 7654746 >>> nr_dirty 0 >>> nr_writeback 0 >>> nr_writeback_temp 0 >>> nr_shmem 2504 >>> nr_shmem_hugepages 0 >>> nr_shmem_pmdmapped 0 >>> nr_anon_transparent_hugepages 0 >>> nr_unstable 0 >>> nr_vmscan_write 5243750485 >>> nr_vmscan_immediate_reclaim 4207633857 >>> nr_dirtied 1839143430 >>> nr_written 1832626107 >>> nr_dirty_threshold 1147728 >>> nr_dirty_background_threshold 151410 >>> pgpgin 166731189 >>> pgpgout 7328142335 >>> pswpin 98608 >>> pswpout 117794 >>> pgalloc_dma 29504 >>> pgalloc_dma32 1006726216 >>> pgalloc_normal 5275218188 >>> pgalloc_movable 0 >>> allocstall_dma 0 >>> allocstall_dma32 0 >>> allocstall_normal 36461 >>> allocstall_movable 5867 >>> pgskip_dma 0 >>> pgskip_dma32 0 >>> pgskip_normal 6417890 >>> pgskip_movable 0 >>> pgfree 6309223401 >>> pgactivate 35076483 >>> pgdeactivate 63556974 >>> pgfault 35753842 >>> pgmajfault 69126 >>> pglazyfreed 0 >>> pgrefill 70008598 >>> pgsteal_kswapd 3567289713 >>> pgsteal_direct 5878057 >>> pgscan_kswapd 9059309872 >>> pgscan_direct 4239367903 >>> pgscan_direct_throttle 0 >>> zone_reclaim_failed 0 >>> pginodesteal 102916 >>> slabs_scanned 460790262 >>> kswapd_inodesteal 9130243 >>> kswapd_low_wmark_hit_quickly 10634373 >>> kswapd_high_wmark_hit_quickly 7348173 >>> pageoutrun 18349115 >>> pgrotated 16291322 >>> drop_pagecache 0 >>> drop_slab 0 >>> pgmigrate_success 18912908 >>> pgmigrate_fail 63382146 >>> compact_migrate_scanned 2986269789 >>> compact_free_scanned 190451505123 >>> compact_isolated 109549437 >>> compact_stall 3544 >>> compact_fail 8 >>> compact_success 3536 >>> compact_daemon_wake 1403515 >>> htlb_buddy_alloc_success 0 >>> htlb_buddy_alloc_fail 0 >>> unevictable_pgs_culled 12473 >>> unevictable_pgs_scanned 0 >>> unevictable_pgs_rescued 11979 >>> unevictable_pgs_mlocked 14556 >>> unevictable_pgs_munlocked 14556 >>> unevictable_pgs_cleared 0 >>> unevictable_pgs_stranded 0 >>> thp_fault_alloc 0 >>> thp_fault_fallback 0 >>> thp_collapse_alloc 0 >>> thp_collapse_alloc_failed 0 >>> thp_file_alloc 0 >>> thp_file_mapped 0 >>> thp_split_page 0 >>> thp_split_page_failed 0 >>> thp_deferred_split_page 0 >>> thp_split_pmd 0 >>> thp_zero_page_alloc 0 >>> thp_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: 0kB >>> shmem_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: 0kB >>> anon_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), now >>> anon-rss:0kB, file-rss:0kB, shmem-rss:0kB >>> >>> On Fri, Nov 4, 2016 at 5:00 PM, Vlastimil Babka <vbabka@suse.cz> wrote: >>>> On 11/04/2016 03:13 PM, E V wrote: >>>>> 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. >> ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: [Bug 186671] New: OOM on system with just rsync running 32GB of ram 30GB of pagecache 2016-11-16 13:39 ` E V @ 2016-11-17 21:49 ` Vlastimil Babka 2016-11-18 11:54 ` Tetsuo Handa 2016-11-18 12:13 ` Janos Toth F. 0 siblings, 2 replies; 14+ messages in thread From: Vlastimil Babka @ 2016-11-17 21:49 UTC (permalink / raw) To: E V Cc: Andrew Morton, bugzilla-daemon, linux-mm, Michal Hocko, linux-btrfs, Kirill A. Shutemov On 11/16/2016 02:39 PM, E V wrote: > 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 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 ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: [Bug 186671] New: OOM on system with just rsync running 32GB of ram 30GB of pagecache 2016-11-17 21:49 ` Vlastimil Babka @ 2016-11-18 11:54 ` Tetsuo Handa 2016-11-18 15:02 ` E V 2016-11-18 12:13 ` Janos Toth F. 1 sibling, 1 reply; 14+ messages in thread From: Tetsuo Handa @ 2016-11-18 11:54 UTC (permalink / raw) To: Vlastimil Babka, E V Cc: Andrew Morton, bugzilla-daemon, linux-mm, Michal Hocko, linux-btrfs, Kirill A. Shutemov On 2016/11/18 6:49, Vlastimil Babka wrote: > On 11/16/2016 02:39 PM, E V wrote: >> 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 > > 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) 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. ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: [Bug 186671] New: OOM on system with just rsync running 32GB of ram 30GB of pagecache 2016-11-18 11:54 ` Tetsuo Handa @ 2016-11-18 15:02 ` E V 2016-11-22 13:58 ` E V 0 siblings, 1 reply; 14+ messages in thread From: E V @ 2016-11-18 15:02 UTC (permalink / raw) To: Tetsuo Handa Cc: Vlastimil Babka, Andrew Morton, bugzilla-daemon, linux-mm, Michal Hocko, linux-btrfs, Kirill A. Shutemov 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 On Fri, Nov 18, 2016 at 6:54 AM, Tetsuo Handa <penguin-kernel@i-love.sakura.ne.jp> wrote: > On 2016/11/18 6:49, Vlastimil Babka wrote: >> On 11/16/2016 02:39 PM, E V wrote: >>> 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 >> >> 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) > > 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. > ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: [Bug 186671] New: OOM on system with just rsync running 32GB of ram 30GB of pagecache 2016-11-18 15:02 ` E V @ 2016-11-22 13:58 ` E V 2016-11-22 14:48 ` Vlastimil Babka 0 siblings, 1 reply; 14+ messages in thread From: E V @ 2016-11-22 13:58 UTC (permalink / raw) To: Tetsuo Handa Cc: Vlastimil Babka, Andrew Morton, bugzilla-daemon, linux-mm, Michal Hocko, linux-btrfs, Kirill A. Shutemov 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. On Fri, Nov 18, 2016 at 10:02 AM, E V <eliventer@gmail.com> wrote: > 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 > > On Fri, Nov 18, 2016 at 6:54 AM, Tetsuo Handa > <penguin-kernel@i-love.sakura.ne.jp> wrote: >> On 2016/11/18 6:49, Vlastimil Babka wrote: >>> On 11/16/2016 02:39 PM, E V wrote: >>>> 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 >>> >>> 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) >> >> 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. >> ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: [Bug 186671] New: OOM on system with just rsync running 32GB of ram 30GB of pagecache 2016-11-22 13:58 ` E V @ 2016-11-22 14:48 ` Vlastimil Babka 2016-11-25 14:06 ` E V 0 siblings, 1 reply; 14+ messages in thread From: Vlastimil Babka @ 2016-11-22 14:48 UTC (permalink / raw) To: E V, Tetsuo Handa Cc: Andrew Morton, bugzilla-daemon, linux-mm, Michal Hocko, linux-btrfs, Kirill A. Shutemov, Joonsoo Kim On 11/22/2016 02:58 PM, E V wrote: > 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. 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: > grep GFP_NOFS page_owner_after_af | wc -l 973596 > grep GFP_HIGHUSER_MOVABLE page_owner_after_af | wc -l 158879 > grep GFP_NOFAIL page_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] or add_delayed_tree_ref+0xbf/0x170 [btrfs] or __btrfs_map_block+0x6a8/0x1200 [btrfs] or btrfs_buffer_uptodate+0x48/0x70 [btrfs] or btrfs_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? > On Fri, Nov 18, 2016 at 10:02 AM, E V <eliventer@gmail.com> wrote: >> 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 >> >> On Fri, Nov 18, 2016 at 6:54 AM, Tetsuo Handa >> <penguin-kernel@i-love.sakura.ne.jp> wrote: >>> On 2016/11/18 6:49, Vlastimil Babka wrote: >>>> On 11/16/2016 02:39 PM, E V wrote: >>>>> 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 >>>> >>>> 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) >>> >>> 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. >>> ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: [Bug 186671] New: OOM on system with just rsync running 32GB of ram 30GB of pagecache 2016-11-22 14:48 ` Vlastimil Babka @ 2016-11-25 14:06 ` E V 0 siblings, 0 replies; 14+ messages in thread From: E V @ 2016-11-25 14:06 UTC (permalink / raw) To: Vlastimil Babka Cc: Tetsuo Handa, Andrew Morton, bugzilla-daemon, linux-mm, Michal Hocko, linux-btrfs, Kirill A. Shutemov, Joonsoo Kim 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/ --- fs/btrfs/inode.c 2016-11-13 13:32:32.000000000 -0500 +++ ../linux-4.9-rc6/fs/btrfs/inode.c 2016-11-23 08:31:02.145669550 -0500 @@ -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 On Tue, Nov 22, 2016 at 9:48 AM, Vlastimil Babka <vbabka@suse.cz> wrote: > On 11/22/2016 02:58 PM, E V wrote: >> 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. > > 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: >> grep GFP_NOFS page_owner_after_af | wc -l > 973596 >> grep GFP_HIGHUSER_MOVABLE page_owner_after_af | wc -l > 158879 >> grep GFP_NOFAIL page_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] > or > add_delayed_tree_ref+0xbf/0x170 [btrfs] > or > __btrfs_map_block+0x6a8/0x1200 [btrfs] > or > btrfs_buffer_uptodate+0x48/0x70 [btrfs] > or > btrfs_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? > >> On Fri, Nov 18, 2016 at 10:02 AM, E V <eliventer@gmail.com> wrote: >>> 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 >>> >>> On Fri, Nov 18, 2016 at 6:54 AM, Tetsuo Handa >>> <penguin-kernel@i-love.sakura.ne.jp> wrote: >>>> On 2016/11/18 6:49, Vlastimil Babka wrote: >>>>> On 11/16/2016 02:39 PM, E V wrote: >>>>>> 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 >>>>> >>>>> 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) >>>> >>>> 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. >>>> > ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: [Bug 186671] New: OOM on system with just rsync running 32GB of ram 30GB of pagecache 2016-11-17 21:49 ` Vlastimil Babka 2016-11-18 11:54 ` Tetsuo Handa @ 2016-11-18 12:13 ` Janos Toth F. 1 sibling, 0 replies; 14+ messages in thread From: Janos Toth F. @ 2016-11-18 12:13 UTC (permalink / raw) To: linux-btrfs 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. On Thu, Nov 17, 2016 at 10:49 PM, Vlastimil Babka <vbabka@suse.cz> wrote: > On 11/16/2016 02:39 PM, E V wrote: >> 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 > > 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 > > -- > To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in > the body of a message to majordomo@vger.kernel.org > More majordomo info at http://vger.kernel.org/majordomo-info.html ^ permalink raw reply [flat|nested] 14+ messages in thread
end of thread, other threads:[~2016-11-25 14:06 UTC | newest]
Thread overview: 14+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
[not found] <bug-186671-27@https.bugzilla.kernel.org/>
[not found] ` <20161103115353.de87ff35756a4ca8b21d2c57@linux-foundation.org>
2016-11-03 23:58 ` [Bug 186671] New: OOM on system with just rsync running 32GB of ram 30GB of pagecache Vlastimil Babka
2016-11-04 14:13 ` E V
2016-11-04 21:00 ` Vlastimil Babka
2016-11-14 13:27 ` E V
2016-11-14 17:04 ` Vlastimil Babka
2016-11-14 20:56 ` E V
2016-11-16 13:39 ` E V
2016-11-17 21:49 ` Vlastimil Babka
2016-11-18 11:54 ` Tetsuo Handa
2016-11-18 15:02 ` E V
2016-11-22 13:58 ` E V
2016-11-22 14:48 ` Vlastimil Babka
2016-11-25 14:06 ` E V
2016-11-18 12:13 ` Janos Toth F.
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).