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(a)opensuse.org
To contact the owner, e-mail: opensuse-kernel+owner(a)opensuse.org