Created attachment 3987 [details] CreateAutoConf ioctl(KVM_CREATE_VM) failed: 12 Cannot allocate memory failed to initialize KVM: Cannot allocate memory Host: Fedora25.osl.yoctoproject.org bith x86 lsb and x86-64 fail with the same error. I updated the kernel to 4.1.42 so I don't know if this was introduced or is a host system issue at this time.
Just a quick observation: This is a known issue, discussed (for example) here: http://lists.gnu.org/archive/html/qemu-discuss/2015-02/msg00067.html Seems rebooting helps. I would speculate that ioctl(KVM_CREATE_VM) tries to allocate memory via kmalloc (not by vmalloc). This can fail even if there is enough physical memory installed. "kmalloc" needs to allocate physically consecutive memory pages and this may not be possible as the memory becomes fragmented eventually.
Looking at the code, my initial speculation seems to be confirmed: http://elixir.free-electrons.com/linux/v4.1.42/source/virt/kvm/kvm_main.c#L457 we see that "kvm_arch_alloc_vm" can fail with "return ERR_PTR(-ENOMEM);" digging into "kvm_arch_alloc_vm" we see it uses: static inline struct kvm *kvm_arch_alloc_vm(void) { return kzalloc(sizeof(struct kvm), GFP_KERNEL); } This can fail if memory is fragmented (kzalloc calls kmalloc). I also checked the most recent kernel (v4.13), it uses the same code. One way to fix this is to at least retry if the allocation fails: return kzalloc(sizeof(struct kvm), GFP_KERNEL |__GFP_REPEAT); Note the code is not Fedora specific, so it would not come as a big surprise to see this error on other systems as well.
Armin, I don't see the error message in the attached log. Do you still have the log with the actual error? One way to go around this problem (without re-booting) would be to try to re-start qemu, hopefully the memory may get compactified...
(In reply to comment #4) > Armin, I don't see the error message in the attached log. > Do you still have the log with the actual error? > One way to go around this problem (without re-booting) would be to try to > re-start qemu, hopefully the memory may get compactified... Juro, Do you mean the log in the "URL" link above or something else?
(In reply to comment #5) > (In reply to comment #4) > > Armin, I don't see the error message in the attached log. > > Do you still have the log with the actual error? > > One way to go around this problem (without re-booting) would be to try to > > re-start qemu, hopefully the memory may get compactified... > > Juro, > Do you mean the log in the "URL" link above or something else? I found the actual error message in AB log: NOTE: core-image-sato-1.0-r0 do_testimage: Output from runqemu: runqemu - INFO - CONFFILE: /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-deb-non-deb/build/build/tmp/deploy/images/qemux86/core-image-sato-qemux86.qemuboot.conf runqemu - INFO - Continuing with the following parameters: stty: 'standard input': Inappropriate ioctl for device runqemu - INFO - Running /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-deb-non-deb/build/build/tmp/hosttools/ip link... runqemu - INFO - Acquiring lockfile /tmp/qemu-tap-locks/tap0.lock... runqemu - INFO - Acquiring lockfile /tmp/qemu-tap-locks/tap0.lock failed: [Errno 11] Resource temporarily unavailable runqemu - INFO - Acquiring lockfile /tmp/qemu-tap-locks/tap1.lock... runqemu - INFO - Using preconfigured tap device tap1 runqemu - INFO - If this is not intended, touch /tmp/qemu-tap-locks/tap1.skip to make runqemu skip tap1. runqemu - INFO - Network configuration: 192.168.7.4::192.168.7.3:255.255.255.0 runqemu - INFO - Running ldd tmp/work/x86_64-linux/qemu-helper-native/1.0-r1/recipe-sysroot-native/usr/bin//qemu-system-i386... runqemu - INFO - Running tmp/work/x86_64-linux/qemu-helper-native/1.0-r1/recipe-sysroot-native/usr/bin//qemu-system-i386 -device virtio-net-pci,netdev=net0,mac=52:54:00:12:34:04 -netdev tap,id=net0,ifname=tap1,script=no,downscript=no -drive file=/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-deb-non-deb/build/build/tmp/deploy/images/qemux86/core-image-sato-qemux86.ext4,if=virtio,format=raw -vga vmware -show-cursor -usb -usbdevice tablet -device virtio-rng-pci -serial tcp:127.0.0.1:36697 -cpu pentium2 -enable-kvm -m 256 -serial tcp:127.0.0.1:34643 -snapshot -kernel tmp/deploy/images/qemux86/bzImage--4.10.17+git0+ba11a3e8f1_f4ba3db6e5-r0.2-qemux86-20170907223347.bin -append 'root=/dev/vda rw highres=off mem=256M ip=192.168.7.4::192.168.7.3:255.255.255.0 vga=0 uvesafb.mode_option=640x480-32 oprofile.timer=1 uvesafb.task_timeout=-1 console=tty1 console=ttyS0,115200n8 printk.time=1' ioctl(KVM_CREATE_VM) failed: 12 Cannot allocate memory failed to initialize KVM: Cannot allocate memory runqemu - INFO - Releasing lockfile for tap device 'tap1' Traceback (most recent call last): File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-deb-non-deb/build/scripts/runqemu", line 1238, in <module> ret = main() File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-deb-non-deb/build/scripts/runqemu", line 1231, in main config.start_qemu() File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-deb-non-deb/build/scripts/runqemu", line 1142, in start_qemu raise Exception('Failed to run %s' % cmd) So one way to fix this is to modify runqemu to detect this particular error and re-try a few times. Tough part would be to test it, probably should use a container with fragmented memory. (If it still fails after re-tries, don't use -enable-kvm.)
I raised/verified the issue with the Linux KVM mainainer (Paolo Bonzini). I plan on sending in a KVM/Linux patch. This, however, will only fix the issue in future kernels. In order to fix this as of now, we need to implement some kind of re-trying mechanism in runqemu.
The bigger question is why is f25 particularly prone to the issue? Is there some reason its seeing a lot of memory fragmentation?
Observed again: https://autobuilder.yocto.io/builders/nightly-x86-lsb/builds/495/steps/Running%20Sanity%20Tests/logs/stdio ... ERROR: core-image-lsb-1.0-r0 do_testimage: Output from runqemu: runqemu - INFO - Continuing with the following parameters: runqemu - INFO - Acquiring lockfile /tmp/qemu-tap-locks/tap0.lock failed: [Errno 11] Resource temporarily unavailable runqemu - INFO - Using preconfigured tap device tap1 runqemu - INFO - If this is not intended, touch /tmp/qemu-tap-locks/tap1.skip to make runqemu skip tap1. runqemu - INFO - Network configuration: 192.168.7.4::192.168.7.3:255.255.255.0 runqemu - INFO - Running tmp/work/x86_64-linux/qemu-helper-native/1.0-r1/recipe-sysroot-native/usr/bin//qemu-system-i386 -device virtio-net-pci,netdev=net0,mac=52:54:00:12:34:04 -netdev tap,id=net0,ifname=tap1,script=no,downscript=no -drive file=/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-x86-lsb/build/build/tmp/deploy/images/qemux86/core-image-lsb-qemux86.ext4,if=virtio,format=raw -vga vmware -show-cursor -usb -device usb-tablet -device virtio-rng-pci -serial tcp:127.0.0.1:47081 -pidfile pidfile_34383 -cpu pentium2 -enable-kvm -m 256 -serial tcp:127.0.0.1:50407 -snapshot -kernel tmp/deploy/images/qemux86/bzImage--4.9.49+git0+6acae6f720_480ee599fb-r0.2-qemux86-20170920104448.bin -append 'root=/dev/vda rw highres=off mem=256M ip=192.168.7.4::192.168.7.3:255.255.255.0 vga=0 uvesafb.mode_option=640x480-32 oprofile.timer=1 uvesafb.task_timeout=-1 console=tty1 console=ttyS0,115200n8 printk.time=1' runqemu - ERROR - Failed to run qemu: ioctl(KVM_CREATE_VM) failed: 12 Cannot allocate memory qemu-system-i386: failed to initialize KVM: Cannot allocate memory
Created attachment 4016 [details] dmesg output dmesg showing the memory allocation failure
The attached dmesg log clearly shows that: 1. qemu fails to allocate 64 consecutive pages of memory (256k) qemu-system-i38: page allocation failure: order:6, mode:0x140c0c0(GFP_KERNEL|__GFP_COMP|__GFP_ZERO), nodemask=(null) 2. There truly are no chunks of greater than 128k available: [417077.317550] Node 0 Normal: 328626*4kB (UME) 39884*8kB (UME) 11524*16kB (UMEH) 6051*32kB (UMEH) 803*64kB (UMEH) 37*128kB (UMEH) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 2067720kB [417077.317558] Node 1 Normal: 35275*4kB (UMEH) 8322*8kB (UMEH) 3420*16kB (UMEH) 1405*32kB (UMEH) 132*64kB (UMEH) 2*128kB (UE) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 316060kB
So the "fix" would be to detect this particular error, re-try a few times in hope some free pages will concatenate.
*** Bug 12246 has been marked as a duplicate of this bug. ***
FWIW we're seeing the same issue on both clusters but (AFAIK) only with Fedora 25. As Fedora 25 is EOL in Q4 this year one option would be to retire that host OS early on the AB clusters.
I've submitted a patch to have runqemu retry without kvm if the initial qemu run fails: https://patchwork.openembedded.org/patch/145409/
Richard and I discussed this issue earlier and decided the most effective course of action would be to stop using Fedora 25 on the autobuilder clusters. Fedora 25 is EOL at year end so would need replacing in a month or so anyway. Not worth the effort.
Makes sense. Running without kvm would be painful. FWIW I checked some newer kernels, and they all have replaced kmalloc with kvmalloc (except for one small case where they still may try to allocate memory with kmalloc, the printout says 64kB).
*** Bug 12382 has been marked as a duplicate of this bug. ***
Update: We're still seeing this on Fedora 26, and occasionally Suse Tumbleweed. It won't appear after a reboot but after a week of building suddenly a number of builds will fail. From dumping /proc/pagetypeinfo when the failure occurs it does appear that memory is sufficiently utilised/fragmented that KVM cannot allocated 256kb contiguous (order 6 allocation). KVM huge pages (http://fedoraproject.org/wiki/Features/KVM_Huge_Page_Backed_Memory) may help, but shouldn't be required.
Created attachment 4141 [details] kvm kernel allocations
I added some printouts (dumping allocation requests) to 4.15, recompiled, rebooted: 4.15.0-rc1+ #10 SMP Wed Nov 29 14:11:33 PST 2017 x86_64 x86_64 x86_64 GNU/Linux After $ runqemu kvm: runqemu - INFO - Running bitbake -e... runqemu - INFO - Continuing with the following parameters: KERNEL: [/data/master-master/poky/build-12301/tmp/deploy/images/qemux86-64/bzImage--4.12.14+git0+cebe198870_9cc6b0ae1a-r0-qemux86-64-20171122190336.bin] MACHINE: [qemux86-64] FSTYPE: [ext4] ROOTFS: [/data/master-master/poky/build-12301/tmp/deploy/images/qemux86-64/core-image-sato-sdk-qemux86-64-20171128175333.rootfs.ext4] CONFFILE: [/data/master-master/poky/build-12301/tmp/deploy/images/qemux86-64/core-image-sato-sdk-qemux86-64-20171128175333.qemuboot.conf] I observed that the largest kzalloc-ed chunk was 38760 bytes ("kvm_arch_alloc_vm"). Most kmallocs were already converted to kvmalloc. (see the attached dmesg log). Not sure how Fedora manages to request 256k contiguous bytes, I suspect it is via "kvm_arch_alloc_vm". Unfortunately, that one cannot be (easily) converted to kvmalloc, as there are some memory ops associated with it... As for why we only see this on Fedora, I would ** speculate ** that although the machine has 256GB of RAM, it is configured as a file server, caching files and leaving relatively less RAM for apps, so memory can become fragmented quickly. Other machine are probably configured as workstations.
So it happened again (Jan 4/2018), Fedora26: [2333281.291061] qemu-system-i38: page allocation failure: order:6, mode:0x140c0c0(GFP_KERNEL|__GFP_COMP|__GFP_ZERO), nodemask=(null) [2333281.291066] qemu-system-i38 cpuset=/ mems_allowed=0-1 [2333281.291071] CPU: 42 PID: 33256 Comm: qemu-system-i38 Not tainted 4.13.16-202.fc26.x86_64 #1 [2333281.291072] Hardware name: Silicon Mechanics Rackform R346.v5/X10DRI-T, BIOS 2.1 09/13/2016 [2333281.291073] Call Trace: [2333281.291079] dump_stack+0x63/0x8b [2333281.291084] warn_alloc+0x114/0x1c0 [2333281.291086] ? __alloc_pages_direct_compact+0xf4/0x100 [2333281.291088] __alloc_pages_slowpath+0xd96/0xe50 [2333281.291091] ? terminate_walk+0x8b/0xf0 [2333281.291093] __alloc_pages_nodemask+0x283/0x2a0 [2333281.291097] alloc_pages_current+0x6a/0xe0 [2333281.291100] kmalloc_order+0x18/0x40 [2333281.291101] kmalloc_order_trace+0x24/0xb0 [2333281.291126] kvm_dev_ioctl+0xb5/0x6b0 [kvm] [2333281.291129] do_vfs_ioctl+0xa5/0x600 [2333281.291131] SyS_ioctl+0x79/0x90 [2333281.291133] entry_SYSCALL_64_fastpath+0x1a/0xa5 [2333281.291134] RIP: 0033:0x7f6715152377 [2333281.291135] RSP: 002b:00007ffc219a2028 EFLAGS: 00000246 ORIG_RAX: 0000000000000010 [2333281.291137] RAX: ffffffffffffffda RBX: 000056099ef4dae0 RCX: 00007f6715152377 [2333281.291137] RDX: 0000000000000000 RSI: 000000000000ae01 RDI: 000000000000000b [2333281.291138] RBP: 000056099ef34a93 R08: 0000000000000000 R09: 0000000000000000 [2333281.291138] R10: 00007f67151907e0 R11: 0000000000000246 R12: 00007ffc219a21de [2333281.291139] R13: 000056099ef9e870 R14: 0000000000000000 R15: 000056099efb06c0 [2333281.409689] kvm [33004]: vcpu0, guest rIP: 0xc4843250 disabled perfctr wrmsr: 0xc2 data 0xffff The interesting fact is Qemu is calling kvm_dev_ioctl to allocate memory. As Qemu runs in user mode, I fail to see why it would need contiguous memory. There **may** be a reason, otherwise they could simply malloc memory. I'll check Qemu code ...
The only place the error message is issued is in kvm-all.c: do { ret = kvm_ioctl(s, KVM_CREATE_VM, type); } while (ret == -EINTR); if (ret < 0) { fprintf(stderr, "ioctl(KVM_CREATE_VM) failed: %d %s\n", -ret, strerror(-ret)); So the kvm_ioctl(KVM_CREATE_VM,type) fails to allocate the memory.
The only place the error message is issued is in kvm-all.c: do { ret = kvm_ioctl(s, KVM_CREATE_VM, type); } while (ret == -EINTR); if (ret < 0) { fprintf(stderr, "ioctl(KVM_CREATE_VM) failed: %d %s\n", -ret, strerror(-ret)); So the kvm_ioctl(KVM_CREATE_VM,type) fails to allocate the memory. So this is the kvm_dev_ioctl call from the dmesg. Somewhere within KVM_CREATE_VM we tried to allocate 2**6 pages of contiguous memory and failed.
Technically, this is not a bug. We may run into this if the memory is fragmented and KVM cannot allocate enough contiguous memory blocks via kmalloc. The remedy is to drop caches occasionally to free some memory. In addition, KVM developers recognized this as a potential problem and newer Linux kernels replaced most of kmalloc with kvmalloc, which does not require contiguous memory blocks. I am closing this as RESOLVED/NOTABUG, as there is a workaround.