1

I am trying to understand why the OOM killer has reaped a process on a KVM virtual machine running with 1 gigabyte of memory. While I do already know that running Linux machines without swap is not the best idea, I am trying to understand why the process reap has happened.

First of all, here is the kernel log containing all the information I have got from the OOM killer:

Jan  4 10:04:40 <host> kernel: [53542.948247] tor invoked oom-killer: gfp_mask=0x24201ca(GFP_HIGHUSER_MOVABLE|__GFP_COLD), nodemask=0, order=0,     oom_score_adj=0
Jan  4 10:04:40 <host> kernel: [53542.948247] tor cpuset=/ mems_allowed=0
Jan  4 10:04:40 <host> kernel: [53542.948251] CPU: 0 PID: 1439 Comm: tor Not tainted 4.9.0-4-amd64 #1 Debian 4.9.65-3+deb9u1
Jan  4 10:04:40 <host> kernel: [53542.948251] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.10.2-0-g5f4c7b1-prebuilt.qemu-project.org 04/    01/2014
Jan  4 10:04:40 <host> kernel: [53542.948252]  0000000000000000 ffffffffb2129134 ffffc4b4801afc28 ffffa0d89a244100
Jan  4 10:04:40 <host> kernel: [53542.948254]  ffffffffb1ffe340 0000000000000000 0000000000000000 0000000c024213ca
Jan  4 10:04:40 <host> kernel: [53542.948255]  ffffffffb1f84517 000000429a244100 ffffffffc0615695 0000000000000001
Jan  4 10:04:40 <host> kernel: [53542.948257] Call Trace:
Jan  4 10:04:40 <host> kernel: [53542.948261]  [<ffffffffb2129134>] ? dump_stack+0x5c/0x78
Jan  4 10:04:40 <host> kernel: [53542.948263]  [<ffffffffb1ffe340>] ? dump_header+0x78/0x1fd
Jan  4 10:04:40 <host> kernel: [53542.948264]  [<ffffffffb1f84517>] ? get_page_from_freelist+0x3f7/0xb40
Jan  4 10:04:40 <host> kernel: [53542.948268]  [<ffffffffc0615695>] ? virtballoon_oom_notify+0x25/0x70 [virtio_balloon]
Jan  4 10:04:40 <host> kernel: [53542.948269]  [<ffffffffb1f804aa>] ? oom_kill_process+0x21a/0x3e0
Jan  4 10:04:40 <host> kernel: [53542.948271]  [<ffffffffb1f8012d>] ? oom_badness+0xed/0x170
Jan  4 10:04:40 <host> kernel: [53542.948272]  [<ffffffffb1f80941>] ? out_of_memory+0x111/0x470
Jan  4 10:04:40 <host> kernel: [53542.948273]  [<ffffffffb1f85bb7>] ? __alloc_pages_slowpath+0xbb7/0xbf0
Jan  4 10:04:40 <host> kernel: [53542.948274]  [<ffffffffb1f85dee>] ? __alloc_pages_nodemask+0x1fe/0x260
Jan  4 10:04:40 <host> kernel: [53542.948277]  [<ffffffffb1fd6151>] ? alloc_pages_current+0x91/0x140
Jan  4 10:04:40 <host> kernel: [53542.948278]  [<ffffffffb1f7e940>] ? filemap_fault+0x300/0x5a0
Jan  4 10:04:40 <host> kernel: [53542.948290]  [<ffffffffc05677e1>] ? ext4_filemap_fault+0x31/0x50 [ext4]
Jan  4 10:04:40 <host> kernel: [53542.948293]  [<ffffffffb1faef81>] ? __do_fault+0x81/0x170
Jan  4 10:04:40 <host> kernel: [53542.948294]  [<ffffffffb1fb36c0>] ? handle_mm_fault+0xd80/0x12d0
Jan  4 10:04:40 <host> kernel: [53542.948296]  [<ffffffffb2001827>] ? new_sync_read+0xd7/0x120
Jan  4 10:04:40 <host> kernel: [53542.948297]  [<ffffffffb1e5ed9c>] ? __do_page_fault+0x25c/0x500
Jan  4 10:04:40 <host> kernel: [53542.948299]  [<ffffffffb2408a48>] ? async_page_fault+0x28/0x30
Jan  4 10:04:40 <host> kernel: [53542.948299] Mem-Info:
Jan  4 10:04:40 <host> kernel: [53542.948301] active_anon:125187 inactive_anon:2602 isolated_anon:0
Jan  4 10:04:40 <host> kernel: [53542.948301]  active_file:95 inactive_file:1644 isolated_file:0
Jan  4 10:04:40 <host> kernel: [53542.948301]  unevictable:0 dirty:0 writeback:8 unstable:0
Jan  4 10:04:40 <host> kernel: [53542.948301]  slab_reclaimable:4702 slab_unreclaimable:11348
Jan  4 10:04:40 <host> kernel: [53542.948301]  mapped:1458 shmem:2652 pagetables:804 bounce:0
Jan  4 10:04:40 <host> kernel: [53542.948301]  free:12103 free_pcp:89 free_cma:0
Jan  4 10:04:40 <host> kernel: [53542.948303] Node 0 active_anon:500748kB inactive_anon:10408kB active_file:380kB inactive_file:6576kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:5832kB     dirty:0kB writeback:32kB shmem:10608kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 0kB writeback_tmp:0kB unstable:0kB pages_scanned:374512 all_unreclaimable?     yes
Jan  4 10:04:40 <host> kernel: [53542.948303] Node 0 DMA free:4124kB min:716kB low:892kB high:1068kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB     present:15992kB managed:15908kB mlocked:0kB slab_reclaimable:0kB slab_unreclaimable:1096kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB     free_cma:0kB
Jan  4 10:04:40 <host> kernel: [53542.948305] lowmem_reserve[]: 0 959 959 959 959
Jan  4 10:04:40 <host> kernel: [53542.948307] Node 0 DMA32 free:44288kB min:44336kB low:55420kB high:66504kB active_anon:500748kB inactive_anon:10408kB active_file:380kB inactive_file:6576kB unevictable:0kB     writepending:32kB present:1032048kB managed:1004452kB mlocked:0kB slab_reclaimable:18808kB slab_unreclaimable:44296kB kernel_stack:1232kB pagetables:3216kB bounce:0kB free_pcp:356kB local_pcp:356kB     free_cma:0kB
Jan  4 10:04:40 <host> kernel: [53542.948309] lowmem_reserve[]: 0 0 0 0 0
Jan  4 10:04:40 <host> kernel: [53542.948310] Node 0 DMA: 217*4kB (U) 171*8kB (U) 98*16kB (U) 0*32kB 1*64kB (U) 0*128kB 1*256kB (U) 0*512kB 0*1024kB 0*2048kB 0*4096kB =     4124kB
Jan  4 10:04:40 <host> kernel: [53542.948315] Node 0 DMA32: 2150*4kB (UMEH) 2083*8kB (UMEH) 1189*16kB (UMEH) 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB =     44288kB
Jan  4 10:04:40 <host> kernel: [53542.948320] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
Jan  4 10:04:40 <host> kernel: [53542.948321] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Jan  4 10:04:40 <host> kernel: [53542.948321] 4401 total pagecache pages
Jan  4 10:04:40 <host> kernel: [53542.948322] 0 pages in swap cache
Jan  4 10:04:40 <host> kernel: [53542.948323] Swap cache stats: add 0, delete 0, find 0/0
Jan  4 10:04:40 <host> kernel: [53542.948323] Free swap  = 0kB
Jan  4 10:04:40 <host> kernel: [53542.948323] Total swap = 0kB
Jan  4 10:04:40 <host> kernel: [53542.948324] 262010 pages RAM
Jan  4 10:04:40 <host> kernel: [53542.948324] 0 pages HighMem/MovableOnly
Jan  4 10:04:40 <host> kernel: [53542.948324] 6920 pages reserved
Jan  4 10:04:40 <host> kernel: [53542.948324] 0 pages hwpoisoned
Jan  4 10:04:40 <host> kernel: [53542.948325] [ pid ]   uid  tgid total_vm      rss nr_ptes nr_pmds swapents oom_score_adj name
Jan  4 10:04:40 <host> kernel: [53542.948328] [  437]     0   437    14212      372      24       3        0             0     systemd-journal
Jan  4 10:04:40 <host> kernel: [53542.948329] [  467]     0   467    11493      313      24       3        0         -1000 systemd-udevd
Jan  4 10:04:40 <host> kernel: [53542.948330] [  598]     0   598     3005      782      11       3        0             0 haveged
Jan  4 10:04:40 <host> kernel: [53542.948331] [  603]     0   603    37702    11634      80       3        0             0 salt-minion
Jan  4 10:04:40 <host> kernel: [53542.948332] [  605]     0   605    62529      306      27       3        0             0 rsyslogd
Jan  4 10:04:40 <host> kernel: [53542.948333] [  609]     0   609    11618      141      27       3        0             0     systemd-logind
Jan  4 10:04:40 <host> kernel: [53542.948334] [  612]   105   612    11283      117      26       3        0          -900 dbus-daemon
Jan  4 10:04:40 <host> kernel: [53542.948335] [  620]     0   620     7483       62      19       3        0             0 cron
Jan  4 10:04:40 <host> kernel: [53542.948336] [  621]     0   621    17486      189      37       3        0         -1000 sshd
Jan  4 10:04:40 <host> kernel: [53542.948337] [  633]     0   633     3708       34      12       3        0             0 agetty
Jan  4 10:04:40 <host> kernel: [53542.948338] [  716]     0   716   130502    15306     119       4        0             0 salt-minion
Jan  4 10:04:40 <host> kernel: [53542.948339] [  734]   107   734    25516      143      24       3        0             0 ntpd
Jan  4 10:04:40 <host> kernel: [53542.948340] [  738]     0   738    66842    12779      96       3        0             0 salt-minion
Jan  4 10:04:40 <host> kernel: [53542.948341] [ 1439]   109  1439   139276    93739     245       3        0             0 tor
Jan  4 10:04:40 <host> kernel: [53542.948342] Out of memory: Kill process 1439 (tor) score 368 or sacrifice child
Jan  4 10:04:40 <host> kernel: [53542.948364] Killed process 1439 (tor) total-vm:557104kB, anon-rss:374956kB, file-rss:0kB, shmem-rss:0kB
Jan  4 10:04:40 <host> kernel: [53542.966776] oom_reaper: reaped process 1439 (tor), now anon-rss:0kB, file-rss:0kB,     shmem-rss:0kB

I have now tried to find the culprit by converting the amount of pages to the usage of memory in MiB (x 4 / 1024) for all the different memory statistics:

MemInfo Name            Pages   Memory in MiB
active_anon             125187  489.0117188
inactive_anon           2602    10.1640625
active_file             95      0.37109375
inactive_file           1644    6.421875
writeback               8       0.03125
slam_reclaimable        4702    18.3671875
slab_unreclaimable      11348   44.328125
mapped                  1458    5.6953125
shmem                   2652    10.359375
pagetables              804     3.140625
pagecache               4401    17.19140625

But even if I add all those numbers together I will only end up with a usage of around 600 MiB. When just using the sum of all "rss" values of the process table printed by the OOM killer, I even end up with only 135917 pages (~530 MiB).

Now if we subtract that calculated number from the total amount of memory (e.g. 996MiB - 600MiB in the worst case based on the numbers from above), we still end up with more than 300MiB of theoretically usable memory, however within the kernel log "free:44288kB" states that only ~44MiB of memory are left.

Why is there a difference and what did I miss? Are there any other memory allocations that have to be taken into account which are using up that space?

EDIT 1: I want to mention that the hypervisor itself has 32GB of memory and only runs that single VM at the moment. There are over 20GB of memory available according to meminfo/free/top and the other few GBs are used for caching.

EDIT 2: As per request, I will hereby list the kernel modules active on the hypervisor system which is running Proxmox with ZFS storage:

acpi_pad, aes_x86_64, aesni_intel, ahci, ast, autofs4, binfmt_misc, coretemp, crc32_pclmul, crct10dif_pclmul, cryptd, crypto_simd, dca, drm, drm_kms_helper, e1000e, fb_sys_fops, ghash_clmulni_intel, glue_helper, gre, hid, hid_generic, i2c_algo_bit, i2c_i801, ib_cm, ib_core, ib_iser, icp, ie31200_edac, igb, inet_diag, input_leds, intel_cstate, intel_pch_thermal, intel_powerclamp, intel_rapl, intel_rapl_perf, ip6_tables, ip6table_filter, ip_gre, ip_set, ip_tables, ip_tunnel, ipmi_devintf, ipmi_msghandler, ipmi_si, ipmi_ssif, iptable_filter, irqbypass, iscsi_tcp, iw_cm, joydev, kvm, kvm_intel, libahci, libcrc32c, libiscsi, libiscsi_tcp, lpc_ich, mac_hid, mei, mei_me, nf_conntrack, nf_conntrack_ipv4, nf_conntrack_ipv6, nf_conntrack_proto_gre, nf_defrag_ipv4, nf_defrag_ipv6, nf_nat, nf_nat_ipv4, nf_nat_ipv6, nfnetlink, nfnetlink_log, nls_iso8859_1, openvswitch, pcbc, pcspkr, pps_core, ptp, rdma_cm, scsi_transport_iscsi, shpchp, softdog, spl, sunrpc, syscopyarea, sysfillrect, sysimgblt, tap, tcp_diag, ttm, usbhid, usbkbd, usbmouse, vhost, vhost_net, video, x86_pkg_temp_thermal, x_tables, zavl, zcommon, zfs, znvpair, zunicode

Also, these are the kernel modules loaded within the affected VM:

ablk_helper, aes_x86_64, aesni_intel, ata_generic, ata_piix, autofs4, binfmt_misc, bochs_drm, button, cdrom, crc16, crc32_pclmul, crc32c_generic, crc32c_intel, crct10dif_pclmul, cryptd, drm, drm_kms_helper, ecb, ehci_hcd, evdev, ext4, floppy, fscrypto, gf128mul, ghash_clmulni_intel, glue_helper, hid, hid_generic, i2c_piix4, ip6_tables, ip6t_REJECT, ip6table_filter, ip_set, ip_set_hash_net, ip_set_list_set, ip_tables, ipmi_msghandler, ipmi_watchdog, ipt_REJECT, iptable_filter, jbd2, joydev, libata, lrw, mbcache, nf_conntrack, nf_conntrack_ipv4, nf_conntrack_ipv6, nf_defrag_ipv4, nf_defrag_ipv6, nf_log_common, nf_log_ipv4, nf_log_ipv6, nf_reject_ipv4, nf_reject_ipv6, nfnetlink, parport, parport_pc, pcspkr, ppdev, psmouse, scsi_mod, sd_mod, serio_raw, sg, shpchp, sr_mod, ttm, uhci_hcd, usb_common, usbcore, usbhid, virtio, virtio_balloon, virtio_net, virtio_pci, virtio_ring, virtio_scsi, x_tables, xt_addrtype, xt_comment, xt_conntrack, xt_limit, xt_LOG, xt_multiport, xt_recent, xt_tcpudp

Last but not least, the command line which is being used for launching the virtual machine:

/usr/bin/kvm -id 100 -chardev socket,id=qmp,path=/var/run/qemu-server/100.qmp,server,nowait -mon chardev=qmp,mode=control -pidfile /var/run/qemu-server/100.pid -daemonize -smbios type=1,uuid=<censored> -name <censored> -smp 1,sockets=1,cores=1,maxcpus=1 -nodefaults -boot menu=on,strict=on,reboot-timeout=1000,splash=/usr/share/qemu-server/bootsplash.jpg -vga std -vnc unix:/var/run/qemu-server/100.vnc,x509,password -cpu host,+kvm_pv_unhalt,+kvm_pv_eoi -m 1024 -k en-us -device pci-bridge,id=pci.2,chassis_nr=2,bus=pci.0,addr=0x1f -device pci-bridge,id=pci.1,chassis_nr=1,bus=pci.0,addr=0x1e -device piix3-usb-uhci,id=uhci,bus=pci.0,addr=0x1.0x2 -device usb-tablet,id=tablet,bus=uhci.0,port=1 -device virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x3 -iscsi initiator-name=iqn.1993-08.org.debian:01:f4b280ed945d -drive if=none,id=drive-ide2,media=cdrom,aio=threads -device ide-cd,bus=ide.1,unit=0,drive=drive-ide2,id=ide2,bootindex=200 -device virtio-scsi-pci,id=scsihw0,bus=pci.0,addr=0x5 -drive file=/dev/zvol/rpool/srv/vmdata/vm-100-disk-1,if=none,id=drive-scsi0,discard=on,format=raw,cache=none,aio=native,detect-zeroes=unmap -device scsi-hd,bus=scsihw0.0,channel=0,scsi-id=0,lun=0,drive=drive-scsi0,id=scsi0,bootindex=100 -netdev type=tap,id=net0,ifname=tap100i0,script=/var/lib/qemu-server/pve-bridge,downscript=/var/lib/qemu-server/pve-bridgedown,vhost=on -device virtio-net-pci,mac=<censored>,netdev=net0,bus=pci.0,addr=0x12,id=net0,bootindex=300
  • Looks at first glance like the KVM host has overcommitted RAM and is running out. – Michael Hampton Jan 4 '18 at 22:29
  • @Michael Hampton Thanks for your comment. I have updated the question to clarify that the host has more than enough RAM available. – ppmathis Jan 4 '18 at 23:22
  • Can you provide a list of kernel modules that are active too? – Matthew Ife Jan 5 '18 at 20:23
  • Also, a description of the VM hardware (if using libvirt the xml for that is fine) or the qemu command line you invoked. – Matthew Ife Jan 5 '18 at 20:41
  • @matthew-ife I have added a list of kernel modules active on both hypervisor and guest. Additionally, I have provided the command line which is being generated by Proxmox for spawning the virtual machine. – ppmathis Jan 6 '18 at 16:43
0

I still cannot comment so I'll try to create something like an answer. First, take a look at these sources:

The memory zone which triggered the OOM killer was DMA32:

Node 0 DMA32 free:44288kB min:44336kB low:55420kB high:66504kB

As I understand this and your log shows it's possible, your server's memory is fragmented:

Node 0 DMA32: 2150*4kB (UMEH) 2083*8kB (UMEH) 1189*16kB (UMEH) 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB =     44288kB

The largest available page is 16kB.

You may take a look at your current memory fragmentation:

cat /proc/buddyinfo
cat /proc/pagetypeinfo

Here is an explanation of both files and their content.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.