mm:ksm02 from ubuntu_ltp failed on L/M P10 VM (OOM, ssh session killed)

[Po-Hsu Lin]

This issue was found on Power10 VM with just L/M.

On Lunar this issue seems began with 6.2.0-34 (test passed with -32)

A manual test shows when this happens it will trigger OOM and cause connectivity lost. The system is still alive, you can SSH back into it without any problem. Eventually this test interruption will lead to the sut-test failure as the whole test did not complete as expected.

Test log:
<<<test_start>>>
tag=ksm02 stime=1703651197
cmdline="ksm02"
contacts=""
analysis=exit
<<<test_output>>>
incrementing stop
tst_kconfig.c:87: TINFO: Parsing kernel config '/lib/modules/6.2.0-39-generic/build/.config'
tst_test.c:1690: TINFO: LTP version: 20230929-185-g19ef6521d
tst_test.c:1574: TINFO: Timeout per run is 0h 01m 02s
mem.c:615: TINFO: get node2.
mem.c:422: TINFO: wait for all children to stop.
mem.c:388: TINFO: child 0 stops.
mem.c:388: TINFO: child 1 stops.
mem.c:388: TINFO: child 2 stops.
mem.c:495: TINFO: KSM merging...
mem.c:434: TINFO: resume all children.
mem.c:422: TINFO: wait for all children to stop.
mem.c:344: TINFO: child 1 continues...
mem.c:344: TINFO: child 0 continues...
mem.c:347: TINFO: child 0 allocates 128 MB filled with 'c'
mem.c:344: TINFO: child 2 continues...
mem.c:347: TINFO: child 2 allocates 128 MB filled with 'a'
mem.c:347: TINFO: child 1 allocates 128 MB filled with 'a'
mem.c:400: TINFO: child 2 stops.
mem.c:400: TINFO: child 1 stops.
mem.c:400: TINFO: child 0 stops.
ksm_helper.c:36: TINFO: ksm daemon takes 1s to run two full scans
mem.c:264: TINFO: check!
mem.c:255: TPASS: run is 1.
mem.c:255: TPASS: pages_shared is 2.
mem.c:255: TPASS: pages_sharing is 6142.
mem.c:255: TPASS: pages_volatile is 0.
mem.c:255: TPASS: pages_unshared is 0.
mem.c:255: TPASS: sleep_millisecs is 0.
mem.c:255: TPASS: pages_to_scan is 6144.
mem.c:434: TINFO: resume all children.
mem.c:422: TINFO: wait for all children to stop.
mem.c:313: TINFO: child 0 verifies memory content.
mem.c:313: TINFO: child 2 verifies memory content.
mem.c:313: TINFO: child 1 verifies memory content.
mem.c:344: TINFO: child 2 continues...
mem.c:347: TINFO: child 2 allocates 128 MB filled with 'a'
mem.c:344: TINFO: child 1 continues...
mem.c:344: TINFO: child 0 continues...
mem.c:347: TINFO: child 1 allocates 128 MB filled with 'b'
mem.c:347: TINFO: child 0 allocates 128 MB filled with 'c'
mem.c:400: TINFO: child 2 stops.
mem.c:400: TINFO: child 1 stops.
mem.c:400: TINFO: child 0 stops.
ksm_helper.c:36: TINFO: ksm daemon takes 1s to run two full scans
mem.c:264: TINFO: check!
mem.c:255: TPASS: run is 1.
mem.c:255: TPASS: pages_shared is 3.
mem.c:255: TPASS: pages_sharing is 6141.
mem.c:255: TPASS: pages_volatile is 0.
mem.c:255: TPASS: pages_unshared is 0.
mem.c:255: TPASS: sleep_millisecs is 0.
mem.c:255: TPASS: pages_to_scan is 6144.
mem.c:434: TINFO: resume all children.
mem.c:422: TINFO: wait for all children to stop.
mem.c:313: TINFO: child 2 verifies memory content.
mem.c:313: TINFO: child 1 verifies memory content.
mem.c:313: TINFO: child 0 verifies memory content.
mem.c:344: TINFO: child 2 continues...
mem.c:347: TINFO: child 2 allocates 128 MB filled with 'd'
mem.c:344: TINFO: child 1 continues...
mem.c:347: TINFO: child 1 allocates 128 MB filled with 'd'
mem.c:344: TINFO: child 0 continues...
mem.c:347: TINFO: child 0 allocates 128 MB filled with 'd'
mem.c:400: TINFO: child 2 stops.
mem.c:400: TINFO: child 1 stops.
mem.c:400: TINFO: child 0 stops.
ksm_helper.c:36: TINFO: ksm daemon takes 1s to run two full scans
mem.c:264: TINFO: check!
mem.c:255: TPASS: run is 1.
mem.c:255: TPASS: pages_shared is 1.
mem.c:255: TPASS: pages_sharing is 6143.
mem.c:255: TPASS: pages_volatile is 0.
mem.c:255: TPASS: pages_unshared is 0.
mem.c:255: TPASS: sleep_millisecs is 0.
mem.c:255: TPASS: pages_to_scan is 6144.
mem.c:434: TINFO: resume all children.
mem.c:422: TINFO: wait for all children to stop.
mem.c:313: TINFO: child 1 verifies memory content.
mem.c:313: TINFO: child 2 verifies memory content.
mem.c:313: TINFO: child 0 verifies memory content.
mem.c:344: TINFO: child 1 continues...
mem.c:351: TINFO: child 1 allocates 128 MB filled with 'd' except one page with 'e'
mem.c:344: TINFO: child 2 continues...
mem.c:347: TINFO: child 2 allocates 128 MB filled with 'd'
mem.c:344: TINFO: child 0 continues...
mem.c:347: TINFO: child 0 allocates 128 MB filled with 'd'
mem.c:400: TINFO: child 1 stops.
mem.c:400: TINFO: child 2 stops.
mem.c:400: TINFO: child 0 stops.
ksm_helper.c:36: TINFO: ksm daemon takes 1s to run two full scans
mem.c:264: TINFO: check!
mem.c:255: TPASS: run is 1.
mem.c:255: TPASS: pages_shared is 1.
mem.c:255: TPASS: pages_sharing is 6142.
mem.c:255: TPASS: pages_volatile is 0.
mem.c:255: TPASS: pages_unshared is 1.
mem.c:255: TPASS: sleep_millisecs is 0.
mem.c:255: TPASS: pages_to_scan is 6144.
mem.c:521: TINFO: KSM unmerging...
mem.c:434: TINFO: resume all children.
mem.c:264: TINFO: check!
mem.c:313: TINFO: child 1 verifies memory content.
mem.c:313: TINFO: child 0 verifies memory content.
mem.c:313: TINFO: child 1 verifies memory content.
mem.c:313: TINFO: child 2 verifies memory content.
mem.c:255: TPASS: run is 2.
mem.c:255: TPASS: pages_shared is 0.
mem.c:255: TPASS: pages_sharing is 0.
mem.c:255: TPASS: pages_volatile is 0.
mem.c:255: TPASS: pages_unshared is 0.
mem.c:255: TPASS: sleep_millisecs is 0.
mem.c:255: TPASS: pages_to_scan is 6144.
mem.c:527: TINFO: stop KSM.
mem.c:264: TINFO: check!
mem.c:255: TPASS: run is 0.
mem.c:255: TPASS: pages_shared is 0.
mem.c:255: TPASS: pages_sharing is 0.
mem.c:255: TPASS: pages_volatile is 0.
mem.c:255: TPASS: pages_unshared is 0.
mem.c:255: TPASS: sleep_millisecs is 0.
mem.c:255: TPASS: pages_to_scan is 6144.
mem.c:415: TINFO: child 1 finished.
mem.c:415: TINFO: child 2 finished.
mem.c:415: TINFO: child 0 finished.
mem.c:422: TINFO: wait for all children to stop.
mem.c:388: TINFO: child 0 stops.
mem.c:388: TINFO: child 1 stops.
mem.c:388: TINFO: child 2 stops.
mem.c:495: TINFO: KSM merging...
mem.c:434: TINFO: resume all children.
mem.c:422: TINFO: wait for all children to stop.
mem.c:344: TINFO: child 0 continues...
mem.c:344: TINFO: child 1 continues...
mem.c:347: TINFO: child 0 allocates 128 MB filled with 'c'
mem.c:347: TINFO: child 1 allocates 128 MB filled with 'a'
mem.c:344: TINFO: child 2 continues...
mem.c:347: TINFO: child 2 allocates 128 MB filled with 'a'
mem.c:400: TINFO: child 2 stops.
mem.c:400: TINFO: child 1 stops.
mem.c:400: TINFO: child 0 stops.
ksm_helper.c:36: TINFO: ksm daemon takes 1s to run two full scans
mem.c:264: TINFO: check!
mem.c:255: TPASS: run is 1.
mem.c:255: TPASS: pages_shared is 2.
mem.c:255: TPASS: pages_sharing is 6142.
mem.c:255: TPASS: pages_volatile is 0.
mem.c:255: TPASS: pages_unshared is 0.
mem.c:255: TPASS: sleep_millisecs is 0.
mem.c:255: TPASS: pages_to_scan is 6144.
mem.c:434: TINFO: resume all children.
mem.c:422: TINFO: wait for all children to stop.
mem.c:313: TINFO: child 0 verifies memory content.
mem.c:313: TINFO: child 2 verifies memory content.
mem.c:313: TINFO: child 1 verifies memory content.
mem.c:344: TINFO: child 2 continues...
mem.c:347: TINFO: child 2 allocates 128 MB filled with 'a'
mem.c:344: TINFO: child 0 continues...
mem.c:347: TINFO: child 0 allocates 128 MB filled with 'c'
mem.c:344: TINFO: child 1 continues...
mem.c:347: TINFO: child 1 allocates 128 MB filled with 'b'
mem.c:400: TINFO: child 2 stops.
mem.c:400: TINFO: child 0 stops.
mem.c:400: TINFO: child 1 stops.
ksm_helper.c:36: TINFO: ksm daemon takes 1s to run two full scans
mem.c:264: TINFO: check!
mem.c:255: TPASS: run is 1.
mem.c:255: TPASS: pages_shared is 3.
mem.c:255: TPASS: pages_sharing is 6141.
mem.c:255: TPASS: pages_volatile is 0.
mem.c:255: TPASS: pages_unshared is 0.
mem.c:255: TPASS: sleep_millisecs is 0.
mem.c:255: TPASS: pages_to_scan is 6144.
mem.c:434: TINFO: resume all children.
mem.c:422: TINFO: wait for all children to stop.
mem.c:313: TINFO: child 2 verifies memory content.
mem.c:313: TINFO: child 0 verifies memory content.
mem.c:313: TINFO: child 1 verifies memory content.
mem.c:344: TINFO: child 2 continues...
mem.c:347: TINFO: child 2 allocates 128 MB filled with 'd'
mem.c:344: TINFO: child 0 continues...
mem.c:347: TINFO: child 0 allocates 128 MB filled with 'd'
mem.c:344: TINFO: child 1 continues...
mem.c:347: TINFO: child 1 allocates 128 MB filled with 'd'
mem.c:400: TINFO: child 2 stops.
mem.c:400: TINFO: child 0 stops.
mem.c:400: TINFO: child 1 stops.
ksm_helper.c:36: TINFO: ksm daemon takes 1s to run two full scans
mem.c:264: TINFO: check!
mem.c:255: TPASS: run is 1.
mem.c:255: TPASS: pages_shared is 1.
mem.c:255: TPASS: pages_sharing is 6143.
mem.c:255: TPASS: pages_volatile is 0.
mem.c:255: TPASS: pages_unshared is 0.
mem.c:255: TPASS: sleep_millisecs is 0.
mem.c:255: TPASS: pages_to_scan is 6144.
mem.c:434: TINFO: resume all children.
mem.c:422: TINFO: wait for all children to stop.
mem.c:313: TINFO: child 1 verifies memory content.
mem.c:313: TINFO: child 0 verifies memory content.
mem.c:313: TINFO: child 2 verifies memory content.
mem.c:344: TINFO: child 2 continues...
mem.c:344: TINFO: child 0 continues...
mem.c:347: TINFO: child 0 allocates 128 MB filled with 'd'
mem.c:347: TINFO: child 2 allocates 128 MB filled with 'd'
mem.c:344: TINFO: child 1 continues...
mem.c:351: TINFO: child 1 allocates 128 MB filled with 'd' except one page with 'e'
mem.c:400: TINFO: child 2 stops.
mem.c:400: TINFO: child 0 stops.
mem.c:400: TINFO: child 1 stops.
ksm_helper.c:36: TINFO: ksm daemon takes 1s to run two full scans
mem.c:264: TINFO: check!
mem.c:255: TPASS: run is 1.
mem.c:255: TPASS: pages_shared is 1.
mem.c:255: TPASS: pages_sharing is 6142.
mem.c:255: TPASS: pages_volatile is 0.
mem.c:255: TPASS: pages_unshared is 1.
mem.c:255: TPASS: sleep_millisecs is 0.
mem.c:255: TPASS: pages_to_scan is 6144.
mem.c:521: TINFO: KSM unmerging...
mem.c:434: TINFO: resume all children.
mem.c:264: TINFO: check!
mem.c:313: TINFO: child 1 verifies memory content.
mem.c:313: TINFO: child 0 verifies memory content.
mem.c:313: TINFO: child 2 verifies memory content.
mem.c:313: TINFO: child 1 verifies memory content.
mem.c:255: TPASS: run is 2.
mem.c:255: TPASS: pages_shared is 0.
mem.c:255: TPASS: pages_sharing is 0.
mem.c:255: TPASS: pages_volatile is 0.
mem.c:255: TPASS: pages_unshared is 0.
mem.c:255: TPASS: sleep_millisecs is 0.
mem.c:255: TPASS: pages_to_scan is 6144.
mem.c:527: TINFO: stop KSM.
mem.c:264: TINFO: check!
mem.c:255: TPASS: run is 0.
mem.c:255: TPASS: pages_shared is 0.
mem.c:255: TPASS: pages_sharing is 0.
mem.c:255: TPASS: pages_volatile is 0.
mem.c:255: TPASS: pages_unshared is 0.
mem.c:255: TPASS: sleep_millisecs is 0.
mem.c:255: TPASS: pages_to_scan is 6144.
mem.c:415: TINFO: child 0 finished.
mem.c:415: TINFO: child 2 finished.
mem.c:415: TINFO: child 1 finished.
Connection to 10.245.68.210 closed by remote host.
Connection to 10.245.68.210 closed.

demsg:
[ 3593.548830] LTP: starting ksm02
[ 3603.460865] ksm02 invoked oom-killer: gfp_mask=0x140cca(GFP_HIGHUSER_MOVABLE|__GFP_COMP), order=0, oom_score_adj=0
[ 3603.460877] CPU: 3 PID: 46401 Comm: ksm02 Not tainted 6.2.0-39-generic #40-Ubuntu
[ 3603.460880] Hardware name: IBM,9080-HEX POWER10 (raw) 0x800200 0xf000006 of:IBM,FW1030.00 (NH1030_017) hv:phyp pSeries
[ 3603.460882] Call Trace:
[ 3603.460883] [c000000038313680] [c000000001573f9c] dump_stack_lvl+0x70/0xb4 (unreliable)
[ 3603.460892] [c0000000383136b0] [c0000000004fd888] dump_header+0x64/0x2c4
[ 3603.460896] [c000000038313730] [c0000000004fc894] oom_kill_process+0x364/0x370
[ 3603.460900] [c000000038313770] [c0000000004fd3a4] out_of_memory+0x124/0x460
[ 3603.460904] [c000000038313800] [c0000000005b81a4] __alloc_pages_may_oom+0x174/0x270
[ 3603.460908] [c0000000383138a0] [c0000000005b8dec] __alloc_pages_slowpath.constprop.0+0x76c/0xc00
[ 3603.460912] [c0000000383139d0] [c0000000005b94b0] __alloc_pages+0x230/0x340
[ 3603.460915] [c000000038313a60] [c0000000005ba0b4] __folio_alloc+0x34/0xb0
[ 3603.460919] [c000000038313a90] [c0000000005faa78] vma_alloc_folio+0xd8/0x5b0
[ 3603.460922] [c000000038313b60] [c00000000056e88c] wp_page_copy+0xcc/0xae0
[ 3603.460926] [c000000038313c20] [c0000000005799f8] __handle_mm_fault+0x448/0x6b0
[ 3603.460928] [c000000038313d30] [c000000000579dd0] handle_mm_fault+0x170/0x360
[ 3603.460930] [c000000038313d80] [c00000000009aa90] ___do_page_fault+0x2e0/0x6f0
[ 3603.460934] [c000000038313e20] [c00000000009b250] do_page_fault+0x60/0x160
[ 3603.460937] [c000000038313e50] [c000000000008918] data_access_common_virt+0x198/0x1f0
[ 3603.460940] --- interrupt: 300 at 0x184a3dc8fc
[ 3603.460943] NIP: 000000184a3dc8fc LR: 000000184a3dec44 CTR: 800000000280f033
[ 3603.460945] REGS: c000000038313e80 TRAP: 0300 Not tainted (6.2.0-39-generic)
[ 3603.460947] MSR: 800000000280f033 <SF,VEC,VSX,EE,PR,FP,ME,IR,DR,RI,LE> CR: 24002408 XER: 00000025
[ 3603.460955] CFAR: 000000184a3dec40 DAR: 000000184a4304d0 DSISR: 0a000000 IRQMASK: 0
               GPR00: 000000184a3dec44 00007fffe00c7070 000000184a437f00 0000000000000000
               GPR04: 000000000000000a 0000000000000000 0000000000000001 0000000000000001
               GPR08: 0000000000000001 000000184a430020 000000184a3dd530 0000000000000000
               GPR12: 0000000000000000 00007b43c532ace0 0000000000000000 0000000000000000
               GPR16: 0000000000000000 0000000000000000 0000000000000003 000000184a430148
               GPR20: 000000184a42e830 00007fffe00c7160 0000000000000001 0000000000000000
               GPR24: 000000184a4304c0 0000000000000001 0000000000000000 0000000000000000
               GPR28: 0000000000000000 0000000000000000 000000184a445880 000000184a405670
[ 3603.460981] NIP [000000184a3dc8fc] 0x184a3dc8fc
[ 3603.460982] LR [000000184a3dec44] 0x184a3dec44
[ 3603.460984] --- interrupt: 300
[ 3603.460986] Mem-Info:
[ 3603.460987] active_anon:186 inactive_anon:2491 isolated_anon:0
                active_file:47255 inactive_file:51251 isolated_file:0
                unevictable:547 dirty:4 writeback:0
                slab_reclaimable:3775 slab_unreclaimable:4477
                mapped:1290 shmem:194 pagetables:118
                sec_pagetables:0 bounce:0
                kernel_misc_reclaimable:0
                free:139714 free_pcp:0 free_cma:0
[ 3603.460992] Node 0 Normal free:0kB boost:0kB min:0kB low:0kB high:0kB reserved_highatomic:0KB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:262144kB managed:0kB mlocked:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[ 3603.460996] lowmem_reserve[]: 0 0 0
[ 3603.460998] Node 0 Normal: 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB 0*8192kB 0*16384kB = 0kB
[ 3603.461008] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
[ 3603.461010] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
[ 3603.461011] 98893 total pagecache pages
[ 3603.461012] 0 pages in swap cache
[ 3603.461013] Free swap = 4194240kB
[ 3603.461013] Total swap = 4194240kB
[ 3603.461014] 262144 pages RAM
[ 3603.461015] 0 pages HighMem/MovableOnly
[ 3603.461016] 10121 pages reserved
[ 3603.461016] 0 pages cma reserved
[ 3603.461017] 0 pages hwpoisoned
[ 3603.461018] Tasks state (memory values in pages):
[ 3603.461019] [ pid ] uid tgid total_vm rss pgtables_bytes swapents oom_score_adj name
[ 3603.461022] [ 399] 0 399 898 320 34048 0 -250 systemd-journal
[ 3603.461025] [ 434] 0 434 4639 482 30720 0 -1000 multipathd
[ 3603.461027] [ 446] 0 446 494 96 28416 0 -1000 systemd-udevd
[ 3603.461030] [ 656] 996 656 461 256 29440 0 0 systemd-resolve
[ 3603.461032] [ 975] 998 975 406 192 33024 0 0 systemd-network
[ 3603.461034] [ 1064] 100 1064 232 96 31488 0 -900 dbus-daemon
[ 3603.461036] [ 1070] 0 1070 1336 0 26112 0 0 iprdump
[ 3603.461038] [ 1071] 0 1071 1369 96 27392 0 0 irqbalance
[ 3603.461040] [ 1080] 0 1080 36826 684 69120 0 -900 snapd
[ 3603.461042] [ 1084] 0 1084 393 128 28672 0 0 systemd-logind
[ 3603.461044] [ 1093] 0 1093 60 0 26112 0 0 iprinit
[ 3603.461047] [ 1094] 0 1094 60 0 30208 0 0 iprupdate
[ 3603.461048] [ 1118] 0 1118 123 32 26368 0 0 rtas_errd
[ 3603.461050] [ 1119] 0 1119 1921 451 31744 0 0 unattended-upgr
[ 3603.461052] [ 1126] 101 1126 3562 143 28672 0 0 rsyslogd
[ 3603.461054] [ 1710] 0 1710 156 32 30720 0 0 cron
[ 3603.461055] [ 1721] 0 1721 124 32 30464 0 0 agetty
[ 3603.461057] [ 1731] 0 1731 113 32 34816 0 0 agetty
[ 3603.461059] [ 1802] 997 1802 1528 188 28672 0 0 systemd-timesyn
[ 3603.461061] [ 1845] 0 1845 359 128 28416 0 -1000 sshd
[ 3603.461062] [ 1846] 0 1846 454 224 29440 0 0 sshd
[ 3603.461064] [ 1849] 1000 1849 427 192 33280 0 100 systemd
[ 3603.461066] [ 1850] 1000 1850 2836 136 30208 0 100 (sd-pam)
[ 3603.461068] [ 1938] 1000 1938 487 222 29696 0 0 sshd
[ 3603.461070] [ 1973] 1000 1973 186 64 30720 0 0 bash
[ 3603.461072] [ 3345] 0 3345 4923 128 33792 0 0 polkitd
[ 3603.461074] [ 46174] 0 46174 454 224 29440 0 0 sshd
[ 3603.461076] [ 46230] 1000 46230 457 192 29440 0 0 sshd
[ 3603.461078] [ 46232] 1000 46232 183 64 30976 0 0 bash
[ 3603.461079] [ 46257] 1000 46257 266 128 31488 0 0 sudo
[ 3603.461081] [ 46258] 1000 46258 266 32 31232 0 0 sudo
[ 3603.461083] [ 46259] 0 46259 131 32 26624 0 0 dmesg
[ 3603.461085] [ 46260] 1000 46260 266 128 31744 0 0 sudo
[ 3603.461086] [ 46261] 1000 46261 266 32 31488 0 0 sudo
[ 3603.461088] [ 46262] 0 46262 64 32 26112 0 0 runltp
[ 3603.461090] [ 46399] 0 46399 59 32 30464 0 0 ltp-pan
[ 3603.461091] [ 46400] 0 46400 68 32 26368 0 -1000 ksm02
[ 3603.461093] [ 46401] 0 46401 68 0 26368 0 0 ksm02
[ 3603.461095] oom-kill:constraint=CONSTRAINT_MEMORY_POLICY,nodemask=0,cpuset=drain,mems_allowed=0,2,global_oom,task_memcg=/user.slice/user-1000.slice/[e-mail]/init.scope,task=systemd,pid=1849,uid=1000
[ 3603.461114] Out of memory: Killed process 1849 (systemd) total-vm:27328kB, anon-rss:4096kB, file-rss:8192kB, shmem-rss:0kB, UID:1000 pgtables:32kB oom_score_adj:100