[opensuse-kernel] Memory stalls after upgrading from Kernel 4.4 to 4.12
Hello, not sure if related but since upgrading from Kernel 4.4 to 4.12 based SLES15 kernel i had two times the following traces while the system was nearly unusable: [245513.362669] kvm: page allocation stalls for 194572ms, order:9, mode:0x4740ca(__GFP_HIGHMEM|__GFP_IO|__GFP_FS|__GFP_COMP|__GFP_NOMEMALLOC|__GFP_HARDWALL|__GFP_THISNODE|__GFP_MOVABLE|__GFP_DIRECT_RECLAIM), nodemask=(null) [245513.363983] kvm cpuset=/ mems_allowed=0-1 [245513.364604] CPU: 10 PID: 84752 Comm: kvm Tainted: G W 4.12.0+98-ph <a href="/view.php?id=1" title="[geschlossen] Integration Ramdisk" class="resolved">0000001</a> SLE15 (unreleased) [245513.365258] Hardware name: Supermicro SYS-1029P-WTRT/X11DDW-NT, BIOS 2.0 12/05/2017 [245513.365905] Call Trace: [245513.366535] dump_stack+0x5c/0x84 [245513.367148] warn_alloc+0xe0/0x180 [245513.367769] __alloc_pages_slowpath+0x820/0xc90 [245513.368406] ? __slab_free+0xa9/0x2f0 [245513.369048] ? __slab_free+0xa9/0x2f0 [245513.369671] __alloc_pages_nodemask+0x1cc/0x210 [245513.370300] alloc_pages_vma+0x1e5/0x280 [245513.370921] do_huge_pmd_wp_page+0x83f/0xf00 [245513.371554] ? set_huge_zero_page.isra.52.part.53+0x9b/0xb0 [245513.372184] ? do_huge_pmd_anonymous_page+0x631/0x6d0 [245513.372812] __handle_mm_fault+0x93d/0x1060 [245513.373439] handle_mm_fault+0xc6/0x1b0 [245513.374042] __do_page_fault+0x230/0x430 [245513.374679] ? get_vtime_delta+0x13/0xb0 [245513.375411] do_page_fault+0x2a/0x70 [245513.376145] ? page_fault+0x65/0x80 [245513.376882] page_fault+0x7b/0x80 [245513.377603] RIP: 0033:0x7f3e92cc9055 [245513.378312] RSP: 002b:00007f3e707febf8 EFLAGS: 00010202 [245513.378937] RAX: 00007f370455f000 RBX: 0000000000001000 RCX: 00007f365f937c07 [245513.379554] RDX: 0000000000000f80 RSI: 00007f365f936ca7 RDI: 00007f370455f000 [245513.380184] RBP: 00007f365f933000 R08: 0000000000000000 R09: 00007f370455ffe0 [245513.380811] R10: 0000000000000000 R11: 00007f370455ffe0 R12: 00007f370455f000 [245513.381415] R13: 0000000000000000 R14: 0000000000001000 R15: 00007f3e707fec00 [245513.382056] Mem-Info: [245513.382634] active_anon:126315487 inactive_anon:1612476 isolated_anon:5 active_file:60183 inactive_file:245285 isolated_file:0 unevictable:15657 dirty:286 writeback:1 unstable:0 slab_reclaimable:75543 slab_unreclaimable:2509111 mapped:81814 shmem:31764 pagetables:370616 bounce:0 free:32294031 free_pcp:6233 free_cma:0 [245513.386615] Node 0 active_anon:254680388kB inactive_anon:1112760kB active_file:240648kB inactive_file:981168kB unevictable:13368kB isolated(anon):0kB isolated(file):0kB mapped:280240kB dirty:1144kB writeback:0kB shmem:95832kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 81225728kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no [245513.388650] Node 1 active_anon:250583072kB inactive_anon:5337144kB active_file:84kB inactive_file:0kB unevictable:49260kB isolated(anon):20kB isolated(file):0kB mapped:47016kB dirty:0kB writeback:4kB shmem:31224kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 31897600kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no [245513.391021] Node 0 DMA free:15884kB min:8kB low:20kB high:32kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15968kB managed:15884kB mlocked:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB [245513.393991] lowmem_reserve[]: 0 1618 385589 385589 385589 [245513.394931] Node 0 DMA32 free:1537304kB min:992kB low:2656kB high:4320kB active_anon:129024kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:1733284kB managed:1667716kB mlocked:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB [245513.397582] lowmem_reserve[]: 0 0 383970 383970 383970 [245513.398456] Node 0 Normal free:127154160kB min:234580kB low:627768kB high:1020956kB active_anon:254554892kB inactive_anon:1112760kB active_file:240648kB inactive_file:981168kB unevictable:13368kB writepending:1144kB present:399507456kB managed:393191300kB mlocked:13368kB slab_reclaimable:181408kB slab_unreclaimable:5532200kB kernel_stack:25784kB pagetables:859664kB bounce:0kB free_pcp:12800kB local_pcp:32kB free_cma:0kB [245513.402148] lowmem_reserve[]: 0 0 0 0 0 [245513.403156] Node 1 Normal free:421400kB min:157628kB low:421840kB high:686052kB active_anon:250581056kB inactive_anon:5337144kB active_file:84kB inactive_file:0kB unevictable:49260kB writepending:4kB present:268435456kB managed:264213808kB mlocked:49260kB slab_reclaimable:120764kB slab_unreclaimable:4504748kB kernel_stack:22696kB pagetables:622800kB bounce:0kB free_pcp:15704kB local_pcp:96kB free_cma:0kB [245513.407454] lowmem_reserve[]: 0 0 0 0 0 [245513.408503] Node 0 DMA: 1*4kB (U) 1*8kB (U) 0*16kB 0*32kB 2*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15884kB [245513.410689] Node 0 DMA32: 92*4kB (UM) 91*8kB (UM) 61*16kB (UM) 32*32kB (UM) 30*64kB (UM) 15*128kB (UM) 4*256kB (M) 5*512kB (UM) 1*1024kB (M) 1*2048kB (M) 372*4096kB (M) = 1537304kB [245513.412894] Node 0 Normal: 637442*4kB (UME) 1898055*8kB (UME) 1777889*16kB (ME) 723651*32kB (UME) 258591*64kB (ME) 103397*128kB (UME) 43868*256kB (UME) 17587*512kB (ME) 7570*1024kB (UM) 0*2048kB 0*4096kB = 127108336kB [245513.414888] Node 1 Normal: 20140*4kB (UME) 19290*8kB (UME) 7403*16kB (UME) 1610*32kB (UME) 274*64kB (UM) 1*128kB (U) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 422512kB [245513.417359] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB [245513.418624] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB [245513.419853] Node 1 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB [245513.421298] Node 1 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB [245513.422741] 358967 total pagecache pages [245513.424130] 19042 pages in swap cache [245513.425513] Swap cache stats: add 4930508, delete 4911859, find 1644549/2021457 [245513.426763] Free swap = 5852kB [245513.428016] Total swap = 7813032kB [245513.429263] 167423041 pages RAM [245513.430438] 0 pages HighMem/MovableOnly [245513.431658] 2650864 pages reserved [245513.432839] 0 pages hwpoisoned [245654.463746] INFO: task pvestatd:3175 blocked for more than 120 seconds. [245654.464730] Tainted: G W 4.12.0+98-ph <a href="/view.php?id=1" title="[geschlossen] Integration Ramdisk" class="resolved">0000001</a> [245654.465666] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [245654.466591] pvestatd D 0 3175 1 0x00080000 [245654.467495] Call Trace: [245654.468413] ? __schedule+0x3bc/0x830 [245654.469283] schedule+0x32/0x80 [245654.470108] rwsem_down_read_failed+0x121/0x170 [245654.470918] ? call_rwsem_down_read_failed+0x14/0x30 [245654.471729] ? alloc_pages_current+0x91/0x140 [245654.472530] call_rwsem_down_read_failed+0x14/0x30 [245654.473316] down_read+0x13/0x30 [245654.474064] proc_pid_cmdline_read+0xae/0x3f0 [245654.474802] ? do_filp_open+0x9e/0xf0 [245654.475555] ? cp_new_stat+0x13d/0x160 [245654.476263] ? __vfs_read+0x26/0x130 [245654.476943] __vfs_read+0x26/0x130 [245654.477642] ? SYSC_newfstat+0x29/0x40 [245654.478306] ? set_close_on_exec+0x30/0x60 [245654.478923] vfs_read+0x8a/0x150 [245654.479578] SyS_read+0x42/0x90 [245654.480167] do_syscall_64+0x74/0x150 [245654.480795] entry_SYSCALL_64_after_hwframe+0x3d/0xa2 [245654.481399] RIP: 0033:0x7f1280a9e1f0 [245654.481944] RSP: 002b:00007ffdc9b0bec8 EFLAGS: 00000246 ORIG_RAX: 0000000000000000 [245654.482544] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f1280a9e1f0 [245654.483088] RDX: 0000000000002000 RSI: 0000561feae18030 RDI: 0000000000000008 [245654.483674] RBP: 0000000000002000 R08: 0000561feadcf990 R09: 0000000000002010 [245654.484183] R10: 0000000000000000 R11: 0000000000000246 R12: 0000561feae18030 [245654.484741] R13: 0000561fe639a010 R14: 0000000000000008 R15: 0000561feae5e900 [245654.485537] INFO: task service:86643 blocked for more than 120 seconds. [245654.486015] Tainted: G W 4.12.0+98-ph <a href="/view.php?id=1" title="[geschlossen] Integration Ramdisk" class="resolved">0000001</a> [245654.486502] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [245654.486960] service D 0 86643 1 0x00080000 [245654.487423] Call Trace: [245654.487865] ? __schedule+0x3bc/0x830 [245654.488286] schedule+0x32/0x80 [245654.488763] rwsem_down_read_failed+0x121/0x170 [245654.489200] ? __handle_mm_fault+0xd67/0x1060 [245654.489668] ? call_rwsem_down_read_failed+0x14/0x30 [245654.490088] call_rwsem_down_read_failed+0x14/0x30 [245654.490538] down_read+0x13/0x30 [245654.490964] __do_page_fault+0x32b/0x430 [245654.491389] ? get_vtime_delta+0x13/0xb0 [245654.491835] do_page_fault+0x2a/0x70 [245654.492253] ? page_fault+0x65/0x80 [245654.492703] page_fault+0x7b/0x80 [245654.493120] RIP: 0033:0x7f5ff84364d5 [245654.493548] RSP: 002b:00007f5fdf7f9720 EFLAGS: 00010246 [245654.493968] RAX: 00007f5ff3625200 RBX: 00007f5ff8639000 RCX: 0000000000000000 [245654.494371] RDX: 0000000000000003 RSI: 0000000000000278 RDI: 00000000b2659b52 [245654.494808] RBP: 000000000000001e R08: 00007f5fdf7f9870 R09: 00007f5ff8652428 [245654.495218] R10: 00007f5ff86160a8 R11: 00007f5ff488729c R12: 0000000000000061 [245654.495637] R13: 0000000000000000 R14: 00007f5fe1890280 R15: 0000000000000000 [245654.496050] INFO: task safe_timer:86651 blocked for more than 120 seconds. [245654.496466] Tainted: G W 4.12.0+98-ph <a href="/view.php?id=1" title="[geschlossen] Integration Ramdisk" class="resolved">0000001</a> [245654.496916] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [245654.497336] safe_timer D 0 86651 1 0x00080000 [245654.497790] Call Trace: [245654.498211] ? __schedule+0x3bc/0x830 [245654.498646] schedule+0x32/0x80 [245654.499074] rwsem_down_read_failed+0x121/0x170 [245654.499501] ? call_rwsem_down_read_failed+0x14/0x30 [245654.499959] call_rwsem_down_read_failed+0x14/0x30 [245654.500381] down_read+0x13/0x30 [245654.500851] __do_page_fault+0x32b/0x430 [245654.501285] ? get_vtime_delta+0x13/0xb0 [245654.501722] do_page_fault+0x2a/0x70 [245654.502163] ? page_fault+0x65/0x80 [245654.502600] page_fault+0x7b/0x80 [245654.503051] RIP: 0033:0x7f5ff84364d5 [245654.503468] RSP: 002b:00007f5fd9ff85e0 EFLAGS: 00010202 [245654.503915] RAX: 00007f5ff7309200 RBX: 00007f5ff86414e8 RCX: 0000000000000001 [245654.504342] RDX: 0000000000000003 RSI: 000000000022e038 RDI: 00000000c11a555b [245654.504780] RBP: 0000000000000007 R08: 00007f5fd9ff8730 R09: 00007f5ff8652428 [245654.505219] R10: 00007f5ff86160a8 R11: 0000000000000000 R12: 0000000000000061 [245654.505652] R13: 0000000000000000 R14: 00007f5fe1890280 R15: 0000000000000000 free -m shows: total used free shared buff/cache available Mem: 643641 572505 70477 115 658 67557 Swap: 7629 7629 0 but vm.swappiness is set to 1? vm.swappiness = 1 Is this swap related? Memory fragmentation? Or a bug in the SLES15 kernel? Greets, Stefan -- To unsubscribe, e-mail: opensuse-kernel+unsubscribe@opensuse.org To contact the owner, e-mail: opensuse-kernel+owner@opensuse.org
participants (1)
-
Stefan Priebe - Profihost AG