Hit this strange issue recently.
I'm on latest kernel version and I've seen multiple times this error occurs when I start a new KVM guest.
At the time I have plenty of available memory.
Workaround is to drop the cache.
I'm on latest kernel version and I've seen multiple times this error occurs when I start a new KVM guest.
May 22 23:12:24 REDACTED kernel: [1252986.887939] kvm: page allocation failure: order:6, mode:0x140c0c0(GFP_KERNEL|__GFP_COMP|__GFP_ZERO), nodemask=(null)
May 22 23:12:24 REDACTED kernel: [1252986.887941] kvm cpuset=/ mems_allowed=0
May 22 23:12:24 REDACTED kernel: [1252986.887945] CPU: 4 PID: 13632 Comm: kvm Tainted: G O 4.15.18-13-pve #1
May 22 23:12:24 REDACTED kernel: [1252986.887946] Hardware name: Supermicro X9SCL/X9SCM/X9SCL/X9SCM, BIOS 2.3 06/12/2018
May 22 23:12:24 REDACTED kernel: [1252986.887954] Call Trace:
May 22 23:12:24 REDACTED kernel: [1252986.887959] dump_stack+0x63/0x8b
May 22 23:12:24 REDACTED kernel: [1252986.887961] warn_alloc+0xfc/0x190
May 22 23:12:24 REDACTED kernel: [1252986.887963] ? __alloc_pages_direct_compact+0x51/0x100
May 22 23:12:24 REDACTED kernel: [1252986.887964] __alloc_pages_slowpath+0xed2/0xee0
May 22 23:12:24 REDACTED kernel: [1252986.887966] ? mntput+0x24/0x40
May 22 23:12:24 REDACTED kernel: [1252986.887967] ? terminate_walk+0x91/0xf0
May 22 23:12:24 REDACTED kernel: [1252986.887969] __alloc_pages_nodemask+0x25b/0x280
May 22 23:12:24 REDACTED kernel: [1252986.887971] alloc_pages_current+0x6a/0xe0
May 22 23:12:24 REDACTED kernel: [1252986.887972] kmalloc_order+0x18/0x40
May 22 23:12:24 REDACTED kernel: [1252986.887973] kmalloc_order_trace+0x24/0xa0
May 22 23:12:24 REDACTED kernel: [1252986.887992] ? kvm_vm_ioctl_check_extension+0xb0/0x140 [kvm]
May 22 23:12:24 REDACTED kernel: [1252986.888000] kvm_dev_ioctl+0xb5/0x6b0 [kvm]
May 22 23:12:24 REDACTED kernel: [1252986.888001] do_vfs_ioctl+0xa6/0x620
May 22 23:12:24 REDACTED kernel: [1252986.888002] ? putname+0x54/0x60
May 22 23:12:24 REDACTED kernel: [1252986.888004] ? do_sys_open+0x1bc/0x280
May 22 23:12:24 REDACTED kernel: [1252986.888006] SyS_ioctl+0x79/0x90
May 22 23:12:24 REDACTED kernel: [1252986.888008] do_syscall_64+0x73/0x130
May 22 23:12:24 REDACTED kernel: [1252986.888010] entry_SYSCALL_64_after_hwframe+0x3d/0xa2
May 22 23:12:24 REDACTED kernel: [1252986.888011] RIP: 0033:0x7f6a965c1777
May 22 23:12:24 REDACTED kernel: [1252986.888012] RSP: 002b:00007fff7ca763a8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
May 22 23:12:24 REDACTED kernel: [1252986.888013] RAX: ffffffffffffffda RBX: 000000000000ae01 RCX: 00007f6a965c1777
May 22 23:12:24 REDACTED kernel: [1252986.888014] RDX: 0000000000000000 RSI: 000000000000ae01 RDI: 000000000000000d
May 22 23:12:24 REDACTED kernel: [1252986.888015] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
May 22 23:12:24 REDACTED kernel: [1252986.888015] R10: 0000000000000000 R11: 0000000000000246 R12: 00007f6a891c9000
May 22 23:12:24 REDACTED kernel: [1252986.888016] R13: 00007f6a890e3300 R14: 0000000000000000 R15: 00007f6a891c9000
May 22 23:12:24 REDACTED kernel: [1252986.888017] Mem-Info:
May 22 23:12:24 REDACTED kernel: [1252986.888020] active_anon:1079437 inactive_anon:214368 isolated_anon:0
May 22 23:12:24 REDACTED kernel: [1252986.888020] active_file:1037691 inactive_file:1521785 isolated_file:0
May 22 23:12:24 REDACTED kernel: [1252986.888020] unevictable:0 dirty:14 writeback:0 unstable:0
May 22 23:12:24 REDACTED kernel: [1252986.888020] slab_reclaimable:104400 slab_unreclaimable:53305
May 22 23:12:24 REDACTED kernel: [1252986.888020] mapped:24691 shmem:14171 pagetables:6604 bounce:0
May 22 23:12:24 REDACTED kernel: [1252986.888020] free:43338 free_pcp:0 free_cma:0
May 22 23:12:24 REDACTED kernel: [1252986.888023] Node 0 active_anon:4317748kB inactive_anon:857472kB active_file:4150764kB inactive_file:6087140kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:98764kB dirty:56kB writeback:0kB shmem:56684kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 3383296kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
May 22 23:12:24 REDACTED kernel: [1252986.888023] Node 0 DMA free:15876kB min:64kB low:80kB high:96kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15992kB managed:15876kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
May 22 23:12:24 REDACTED kernel: [1252986.888026] lowmem_reserve[]: 0 3186 15957 15957 15957
May 22 23:12:24 REDACTED kernel: [1252986.888028] Node 0 DMA32 free:85008kB min:13480kB low:16848kB high:20216kB active_anon:327820kB inactive_anon:242088kB active_file:966784kB inactive_file:1525156kB unevictable:0kB writepending:8kB present:3363728kB managed:3297256kB mlocked:0kB kernel_stack:224kB pagetables:4100kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
May 22 23:12:24 REDACTED kernel: [1252986.888031] lowmem_reserve[]: 0 0 12770 12770 12770
May 22 23:12:24 REDACTED kernel: [1252986.888032] Node 0 Normal free:72468kB min:54032kB low:67540kB high:81048kB active_anon:3990028kB inactive_anon:615384kB active_file:3184148kB inactive_file:4561992kB unevictable:0kB writepending:48kB present:13369344kB managed:13083380kB mlocked:0kB kernel_stack:4144kB pagetables:22316kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
May 22 23:12:24 REDACTED kernel: [1252986.888035] lowmem_reserve[]: 0 0 0 0 0
May 22 23:12:24 REDACTED kernel: [1252986.888037] Node 0 DMA: 1*4kB (U) 2*8kB (U) 1*16kB (U) 1*32kB (U) 3*64kB (U) 2*128kB (U) 0*256kB 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15876kB
May 22 23:12:24 REDACTED kernel: [1252986.888044] Node 0 DMA32: 2529*4kB (UMEH) 3694*8kB (UMEH) 2754*16kB (UMEH) 32*32kB (UEH) 10*64kB (EH) 2*128kB (H) 2*256kB (H) 0*512kB 0*1024kB 0*2048kB 0*4096kB = 86164kB
May 22 23:12:24 REDACTED kernel: [1252986.888051] Node 0 Normal: 1197*4kB (UMEH) 2841*8kB (UMEH) 1813*16kB (UMEH) 343*32kB (UMEH) 91*64kB (MEH) 2*128kB (H) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 73580kB
May 22 23:12:24 REDACTED kernel: [1252986.888058] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
May 22 23:12:24 REDACTED kernel: [1252986.888059] 2598912 total pagecache pages
May 22 23:12:24 REDACTED kernel: [1252986.888061] 25390 pages in swap cache
May 22 23:12:24 REDACTED kernel: [1252986.888062] Swap cache stats: add 747021, delete 721453, find 11183777/11439418
May 22 23:12:24 REDACTED kernel: [1252986.888062] Free swap = 7860184kB
May 22 23:12:24 REDACTED kernel: [1252986.888062] Total swap = 8388592kB
May 22 23:12:24 REDACTED kernel: [1252986.888063] 4187266 pages RAM
May 22 23:12:24 REDACTED kernel: [1252986.888063] 0 pages HighMem/MovableOnly
May 22 23:12:24 REDACTED kernel: [1252986.888063] 88138 pages reserved
May 22 23:12:24 REDACTED kernel: [1252986.888064] 0 pages cma reserved
May 22 23:12:24 REDACTED kernel: [1252986.888064] 0 pages hwpoisoned
May 22 23:12:24 REDACTED pvedaemon[5049]: <root@pam> end task UPID:REDACTED:0000352D:0777F4EC:5CE60F96:qmstart:110:root@pam: start failed: command '/usr/bin/kvm -id 110 -name REDACTED -chardev 'socket,id=qmp,path=/var/run/qemu-server/110.qmp,server,nowait' -mon 'chardev=qmp,mode=control' -chardev 'socket,id=qmp-event,path=/var/run/qmeventd.sock,reconnect=5' -mon 'chardev=qmp-event,mode=control' -pidfile /var/run/qemu-server/110.pid -daemonize -smbios 'type=1,uuid=e0c7459f-f62f-4527-a080-7da5690410de' -smp '1,sockets=1,cores=1,maxcpus=1' -nodefaults -boot 'menu=on,strict=on,reboot-timeout=1000,splash=/usr/share/qemu-server/bootsplash.jpg' -vnc unix:/var/run/qemu-server/110.vnc,x509,password -cpu host,+kvm_pv_unhalt,+kvm_pv_eoi -m 1024 -device 'vmgenid,guid=f228a35c-549a-4a26-a728-27ccb2ced638' -readconfig /usr/share/qemu-server/pve-q35.cfg -device 'usb-tablet,id=tablet,bus=ehci.0,port=1' -device 'VGA,id=vga,bus=pcie.0,addr=0x1' -device 'virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x3' -drive 'file=/var/lib/vz/template/iso/x.iso,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/vg0/vm-110-disk-0,if=none,id=drive-scsi0,cache=writeback,format=raw,aio=threads,detect-zeroes=on' -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=tap110i0,script=/var/lib/qemu-server/pve-bridge,downscript=/var/lib/qemu-server/pve-bridgedown,vhost=on' -device 'virtio-net-pci,mac=1E:28:65:ED:1F:4F,netdev=net0,bus=pci.0,addr=0x12,id=net0,bootindex=300' -machine 'type=q35'' failed: exit code 1
At the time I have plenty of available memory.
Code:
# free -m
total used free shared buff/cache available
Mem: 16012 5372 226 52 10413 10258
Swap: 8191 516 7675
Workaround is to drop the cache.
Code:
# echo 3 > /proc/sys/vm/drop_caches