Created attachment 4116 [details]
Logs of the good/bad boots

Jsut to be clear, many of these tests were made with the kernel modified to set "CONFIG_FTRACE is not set" to rule out that piece. I've not yet seen a hang when all the kernel commandline options mentioned are set together.

Also noticed this:

$ grep BIOS * -R | grep bug
1/bad/qemu_boot_log.20171106114453:[    0.000000] BIOS bug: APIC version is 0 for CPU 0/0x0, fixing up to 0x10
1/bad/qemu_boot_log.20171106114453:[    0.000000] BIOS bug: APIC version mismatch, boot CPU: 0, CPU 0: version 10
1/bad/qemu_boot_log.20171106141805:[    0.000000] BIOS bug: APIC version is 0 for CPU 0/0x0, fixing up to 0x10
1/bad/qemu_boot_log.20171106141805:[    0.000000] BIOS bug: APIC version mismatch, boot CPU: 0, CPU 0: version 10
1/qemu_boot_log.20171106131447:[    0.000000] BIOS bug: APIC version mismatch, boot CPU: 0, CPU 0: version 14
2/bad/qemu_boot_log.20171106130421:[    0.000000] BIOS bug: APIC version is 0 for CPU 0/0x0, fixing up to 0x10
2/bad/qemu_boot_log.20171106130421:[    0.000000] BIOS bug: APIC version mismatch, boot CPU: 0, CPU 0: version 10
2/bad/qemu_boot_log.20171106140453:[    0.000000] BIOS bug: APIC version is 0 for CPU 0/0x0, fixing up to 0x10
2/bad/qemu_boot_log.20171106140453:[    0.000000] BIOS bug: APIC version mismatch, boot CPU: 0, CPU 0: version 10
2/bad/qemu_boot_log.20171106131447:[    0.000000] BIOS bug: APIC version mismatch, boot CPU: 0, CPU 0: version 14
2/bad/qemu_boot_log.20171106112930:[    0.000000] BIOS bug: APIC version is 0 for CPU 0/0x0, fixing up to 0x10
2/bad/qemu_boot_log.20171106112930:[    0.000000] BIOS bug: APIC version mismatch, boot CPU: 0, CPU 0: version 10
2/qemu_boot_log.20171106130943:[    0.000000] BIOS bug: APIC version mismatch, boot CPU: 0, CPU 0: version 14
2/qemu_boot_log.20171106133135:[    0.000000] BIOS bug: APIC version mismatch, boot CPU: 0, CPU 0: version 14
3/bad/qemu_boot_log.20171106112930:[    0.000000] BIOS bug: APIC version is 0 for CPU 0/0x0, fixing up to 0x10
3/bad/qemu_boot_log.20171106112930:[    0.000000] BIOS bug: APIC version mismatch, boot CPU: 0, CPU 0: version 10

The bad runs have the "version is 0" message, some of the good and bad have the version mismatch.

(In reply to comment #3) 
> The bad runs have the "version is 0" message, some of the good and bad have
> the version mismatch.

Note that not all bad runs have this message.

Another observation, several "bad" (7/9) logs have the last message:

[    0.022539] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1

After this, the code goes on and fiddles with APIC bits...
/arch/x86/kernel/apic/io_apic.c line 2082 ...

I will try to reproduce the problem (need to install tumbleweed first), optionally add few messages following the line 2082...

FWIW I tried to reproduce this on Ubuntu 17.04 and can't

I also did about 60 boot sequences on my builder and haven't seen it. I tried with and without KVM.

Will continue trying here.

I upgraded to Ubuntu 1710 which has a 4.13.0 kernel and this still works fine. I also copied the qemu-native binaries from the tumbleweed builder and those also work fine (once the interpreter paths are tweaked).

This leads to me suspect its the tumbleweed 4.13.10 kernel (which is preempt) compared to the Ubuntu 4.10.0 which isn't preempt.

Further update - we changed the kernel on tumbleweed.yocto.io from the default to the vanilla one which means the suse patchset was removed. The hang has then disappeared. Its looking very likely that something in the suse patchset is therefore breaking the timers in qemu when using kvm.

*** Bug 12124 has been marked as a duplicate of this bug. ***

We've just seen two failures which look very like this on fedora26. https://autobuilder.yocto.io/builders/nightly-x86-64-lsb/builds/575 has the failures however the SIGTERM is misleading. The actual logs are attached.

I've added a separate patch which addresses the logging issue this raises (http://git.yoctoproject.org/cgit.cgi/poky/commit/?id=702f4692a25c670d7d14da106f545b86e55473ce)

Fedora 26 has a 4.13.10 kernel like tumbleweed so I suspect we're looking for a broken patch that both Fedora and SUSE apply to 4.13.10.

Created attachment 4118 [details]
fedora26 qemu boot log

Created attachment 4119 [details]
fedora26 qemu boot log #2

Created attachment 4120 [details]
testimage task log

Tumbleweed kernel patches:
https://github.com/openSUSE/kernel-source/tree/db36cf83181a996bfdb86b3c32dc376d7b6922f0

Fedora 26 kernel patches:
https://src.fedoraproject.org/rpms/kernel/tree/f26

Created attachment 4121 [details]
testiamge task log #2

Also just to note that rng is running on fedora26 so I suspect this issue is not entropy related.

Since affecting more than one worker, up priority.

(In reply to comment #16)
> Tumbleweed kernel patches:
> https://github.com/openSUSE/kernel-source/tree/
> db36cf83181a996bfdb86b3c32dc376d7b6922f0
> 
> Fedora 26 kernel patches:
> https://src.fedoraproject.org/rpms/kernel/tree/f26

Actually, that's the 4.3.12 kernel. For 4.3.10 we want: 

https://src.fedoraproject.org/rpms/kernel/tree/0b2f4649840f7fb349bcfe10378a85bfc9e448a2

Also, https://autobuilder.yocto.io/builders/nightly-oe-selftest/builds/614

which looks like the same kernel issue and on tumbleweed but with the vanilla kernel:

rpurdie@tumbleweed:~> cat /proc/version 
Linux version 4.13.10-1-vanilla (geeko@buildhost) (gcc version 7.2.1 20171020 [gcc-7-branch revision 253932] (SUSE Linux)) #1 SMP PREEMPT Fri Oct 27 09:03:09 UTC 2017 (db36cf8)

So this could be a 4.13 general issue.

I installed tumbleweed.
Then I could reproduce the bug by simply:

$ MACHINE=qemux86-64 bitbake core-image-minimal
$ runqemu kvm

The QEMU boot stopped at the TIMER mesage, this happened about 3x out of 5 attempts.
Then I installed some other packages (can't remember which, remember, this was a brand new install so some of my favorite utilities were not present). So I think something else was updated as a by product.

After that I could not reproduce the problem in about 50 attempts.
The current kernel is:
4-13-10-1-default #1 SMP PREEMPT Fri Oct 27 09:03:09 UTC 2017 (db36cf8)

I tried to boot a previous snapshot, but it only boots read-only, so I could not get the TAP working.

Anyway, I will try Fedora 26, as it is more reproducible environment (Tumbleweed has rolling updates, so occasional "instabilities" are to be expected)

Since the problem seems to be related to kernel 4.13.10, I installed and booted upstreamed 4.13.10 with Ubuntu 17.04. (I built/tested with and without CONFIG_PREEMPT), presently I have:
4.13.10 #11 SMP PREEMPT Sat Nov 11 22:20:26 PST 2017 x86_64 x86_64 x86_64 GNU/Linux

I repeatedly ran (with and without KVM, does not seem to matter) over the weekend:

$ bitbake core-image-minimal core-image-full-cmdline core-image-sato-sdk -c testimage

Although I did not reproduce the problem, I saw frequent anomalies:
Normally, I would expect:

tsc: Fast TSC calibration using PIT

But sometimes (frequently) the boot massage says:

[    0.000000] tsc: Fast TSC calibration failed
[    0.000000] tsc: Unable to calibrate against PIT
[    0.000000] tsc: No reference (HPET/PMTIMER) available
...
[    0.946000] APIC calibration not consistent with PM-Timer: 103ms instead of 100ms
[    0.946000] APIC delta adjusted to PM-Timer: 6249951 (6440338)


I also saw these messages in some log files::

[    0.000000] tsc: Unable to calibrate against PIT
[    0.000000] tsc: No reference (HPET/PMTIMER) available
...
[    0.003000] tsc: Fast TSC calibration failed
[    0.008000] tsc: Unable to calibrate against PIT
[    0.008000] tsc: using HPET reference calibration
..
[    0.803000] APIC calibration not consistent with PM-Timer: 103ms instead of 100ms
[    0.803000] APIC delta adjusted to PM-Timer: 6249972 (6499899)

I would expect the dmesg log to be always identical (with possible timestamps differences), but it seems sometimes we detect HPET/PTIMER and sometimes we don't.

BTW, I don't know if this is 4.13.10 issue only, I will check if we had these kind of inconsistent boot messages before. Since the boot/tests succeed  in both cases (with or without HPET/PTIMER detected), we may have not noticed these before.

I installed Fedora26.
I ran repeatedly:

$ bitbake core-image-minimal core-image-full-cmdline core-image-sato-sdk -c testimage

Could not reproduce the problem. But I found out my Fedora is not 4.13.10:

Linux localhost.localdomain 4.13.11-200.fc26.x86_64 #1 SMP Thu Nov 2 18:28:35 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

It does not seem to be possible to "downgrade" the kernel to 4.13.10,
as the kernel is not listed in:

$ yum list --showduplicates kernel
...
Available Packages
kernel.x86_64                                 4.11.8-300.fc26                                   @anaconda
kernel.x86_64                                 4.11.8-300.fc26                                   fedora   
kernel.x86_64                                 4.13.11-200.fc26                                  @updates 
kernel.x86_64                                 4.13.11-200.fc26                                  updates

Observed again on:
Linux version 4.13.12-1-vanilla (geeko@buildhost) (gcc version 7.2.1 20171020 [gcc-7-branch revision 253932] (SUSE Linux)) #1 SMP PREEMPT Wed Nov 8 11:21:09 UTC 2017 (9151c66)

| DEBUG: Target didn't reached login boot in 1500 seconds
| DEBUG: Last 25 lines of text:
| [    0.000000] Memory: 239224K/261608K available (9366K kernel code, 1201K rwdata, 2872K rodata, 1440K init, 480K bss, 22384K reserved, 0K cma-reserved)
| [    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
| [    0.000000] ftrace: allocating 37138 entries in 146 pages
| [    0.001000] Preemptible hierarchical RCU implementation.
| [    0.001000] 	RCU restricting CPUs from NR_CPUS=64 to nr_cpu_ids=1.
| [    0.001000] RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1
| [    0.001000] NR_IRQS:4352 nr_irqs:256 16
| [    0.001000] Console: colour VGA+ 80x25
| [    0.001000] console [tty1] enabled
| [    0.001000] console [ttyS0] enabled
| [    0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns
| [    0.001000] tsc: Detected 2599.996 MHz processor
| [    0.001000] Calibrating delay loop (skipped) preset value.. 5199.99 BogoMIPS (lpj=2599996)
| [    0.001000] pid_max: default: 32768 minimum: 301
| [    0.001000] ACPI: Core revision 20170303
| [    0.001000] ACPI: 1 ACPI AML tables successfully acquired and loaded
| [    0.001000] Security Framework initialized
| [    0.001000] Mount-cache hash table entries: 512 (order: 0, 4096 bytes)
| [    0.001000] Mountpoint-cache hash table entries: 512 (order: 0, 4096 bytes)
| [    0.001000] mce: CPU supports 10 MCE banks
| [    0.001000] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0
| [    0.001000] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0
| [    0.001000] Freeing SMP alternatives memory: 36K
| [    0.001000] smpboot: Max logical packages: 1
| [    0.001000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1

To add some extra data to this bug report, we're seeing the issue on both fedora26 and tumbleweed autobuilders. We've seen it with 4.13.10 and 4.13.12 kernels and with the vanialla tumbleweed kernel.

When the bug occurs, the dmesg usually contains:

BIOS bug: APIC version is 0 for CPU 0/0x0, fixing up to 0x10
BIOS bug: APIC version mismatch, boot CPU: 0, CPU 0: version 10

it should have a version field of 0x14. I've checked the qemu code and that puts the 0x14 version in all the right places. I've instrumented a guest kernel and reads of the version register through mmio always reads 0.

When it sees version 0x0, it basically means the APIC is missing and the kernel then later hangs at some future point, often the ..TIMER line but sometimes elsewhere, basically as it never gets timer interrupts.

For some reason our x86-64 kernel does not enable x2apic mode. If we enable x2apic mode, the guest will switch to accessing the APIC through MSR and will then start working.

Also, if we disable KVM (or likely just irqchip), we don't see this issue.

The issue is therefore likely somewhere in the APIC virutalisation code and the mmio page memory (rather than the MSR).

I have tried taking the tumbleweed kernel+kernel modules and qemu binary (but not dependencies), copying them to my local ubuntu system and booting/using them. I was unable to reproduce the hangs locally.

I am able to reproduce the hangs on the tumbleweed autobuilder at will using my brute force script which I used for the qemuppc bug. In this case you can just test of the BIOS BUG message to know if there was a problem.

From /proc/cpuinfo, flags in common:
fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc cpuid aperfmperf pni pclmulqdq dtes64 monitor ds_cpl vmx smx est tm2 ssse3 sdbg fma cx16 xtpr pdcm pcid dca sse4_1 sse4_2 movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm abm cpuid_fault epb intel_ppin tpr_shadow vnmi flexpriority ept vpid fsgsbase tsc_adjust bmi1 avx2 smep bmi2 erms invpcid cqm xsaveopt cqm_llc cqm_occup_llc dtherm ida arat pln pts 

Tubleweed autobuilder only:
x2apic

My local system only:
3dnowprefetch  intel_pt cat_l3 cdp_l3 hle rtm rdt_a rdseed adx smap cqm_mbm_total cqm_mbm_local

I was testing my local system booting with nox2apic, I also tried is intel_pstate disabled.

The code in linus kernel apic.c says:

	if (version == 0x0) {
		pr_warning("BIOS bug: APIC version is 0 for CPU %d/0x%x, fixing up to 0x10\n",
			   cpu, apicid);
		version = 0x10;
	}

	if (version != boot_cpu_apic_version) {
		pr_warning("BIOS bug: APIC version mismatch, boot CPU: %x, CPU %d: version %x\n",
			boot_cpu_apic_version, cpu, version);
	}

But it only **says** it is fixing the version. I don't actually see the version being changed. It says 0x0 (or whatever the passed "version" was), so the message is a bit misleading.

(In reply to comment #27)
> From /proc/cpuinfo, flags in common:
> fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36
> clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm
> constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc cpuid
> aperfmperf pni pclmulqdq dtes64 monitor ds_cpl vmx smx est tm2 ssse3 sdbg
> fma cx16 xtpr pdcm pcid dca sse4_1 sse4_2 movbe popcnt tsc_deadline_timer
> aes xsave avx f16c rdrand lahf_lm abm cpuid_fault epb intel_ppin tpr_shadow
> vnmi flexpriority ept vpid fsgsbase tsc_adjust bmi1 avx2 smep bmi2 erms
> invpcid cqm xsaveopt cqm_llc cqm_occup_llc dtherm ida arat pln pts 
> 
> Tubleweed autobuilder only:
> x2apic
> 
> My local system only:
> 3dnowprefetch  intel_pt cat_l3 cdp_l3 hle rtm rdt_a rdseed adx smap
> cqm_mbm_total cqm_mbm_local
> 
> I was testing my local system booting with nox2apic, I also tried is
> intel_pstate disabled.

Speaking of x2apic, QEMU only enables (emulates) it with KVM, you can verify this with (runqemu with and without KVM):

# grep x2apic /proc/cpuinfo

So if we don't see problems without KVM, it could be pointing at problems with x2apic emulation.

(In reply to comment #26)
> To add some extra data to this bug report, we're seeing the issue on both
> fedora26 and tumbleweed autobuilders. We've seen it with 4.13.10 and 4.13.12
> kernels and with the vanialla tumbleweed kernel.
> 
> When the bug occurs, the dmesg usually contains:
> 
> BIOS bug: APIC version is 0 for CPU 0/0x0, fixing up to 0x10
> BIOS bug: APIC version mismatch, boot CPU: 0, CPU 0: version 10
> 
> it should have a version field of 0x14. I've checked the qemu code and that
> puts the 0x14 version in all the right places. I've instrumented a guest
> kernel and reads of the version register through mmio always reads 0.
> 
> When it sees version 0x0, it basically means the APIC is missing and the
> kernel then later hangs at some future point, often the ..TIMER line but
> sometimes elsewhere, basically as it never gets timer interrupts.
> 
> For some reason our x86-64 kernel does not enable x2apic mode. If we enable
> x2apic mode, the guest will switch to accessing the APIC through MSR and
> will then start working.
> 
> Also, if we disable KVM (or likely just irqchip), we don't see this issue.
> 
> The issue is therefore likely somewhere in the APIC virutalisation code and
> the mmio page memory (rather than the MSR).
> 
> I have tried taking the tumbleweed kernel+kernel modules and qemu binary
> (but not dependencies), copying them to my local ubuntu system and
> booting/using them. I was unable to reproduce the hangs locally.
> 
> I am able to reproduce the hangs on the tumbleweed autobuilder at will using
> my brute force script which I used for the qemuppc bug. In this case you can
> just test of the BIOS BUG message to know if there was a problem.

Just to clarify: are there no problems when used together -enable-kvm -no-kvm-irqchip ?

(In reply to comment #30)
> Just to clarify: are there no problems when used together -enable-kvm
> -no-kvm-irqchip ?

I think there may be two bugs. With "-enable-kvm -no-kvm-irqchip", I do not see the BIOS bug message and I do not see it hang at ..TIMER but I do see it hang later in the boot around udevd or ssh key generation, in a similar way to the qemuppc lack of timer interrupts bug.

So there are two issues here and removing the emulated APIC only seems to partly solve the issue. Whether they're related, unsure.

Robert reported that upgrading qemu to 2.11-rc2 resolved issues for him. I tried that and it does resolve the hangs I saw with -no-kvm-irqchip however the issues I saw without that remain.

Also, passing in the kernel options "noapic nolapic hpet=disable clocksource=kvm-clock noioapic" does not avoid the hang.

After some comments from Robert I rebooted tumbleweed and was no longer able to reproduce the issue.

This is therefore starting to look like some kind of bad kernel kvm state. The question is therefore becomming, how do you wedge the kernel in that state?

(In reply to comment #34)
> After some comments from Robert I rebooted tumbleweed and was no longer able
> to reproduce the issue.
> 
> This is therefore starting to look like some kind of bad kernel kvm state.
> The question is therefore becomming, how do you wedge the kernel in that
> state?

Is there a possibility the rebooted tumbleweed was not the same as before?
I believe they tend to upgrade various components rapidly, you may not necessarily notice that.

(In reply to comment #34)
> After some comments from Robert I rebooted tumbleweed and was no longer able
> to reproduce the issue.
> 
> This is therefore starting to look like some kind of bad kernel kvm state.
> The question is therefore becomming, how do you wedge the kernel in that
> state?

Please see my comment 22, same thing: I rebooted tumbleweed and could not reproduce the problem anymore

Next up is to mix up qemux86 and qemux86-64 runs. Its possible bad state from 32 bit runs which could explain why qemux86 keeps working...

(In reply to comment #37)
> Next up is to mix up qemux86 and qemux86-64 runs. Its possible bad state
> from 32 bit runs which could explain why qemux86 keeps working...

No luck booting all qemux86 first, then qemux86-64, or all qemux86-64, then qemux86, then qemux86-64 or intermixing qemux86 and qemx86-64 on my local autobuilder with the tumbleweed kernel+modules. With qemu 2.10, not 2.11.

The tumbleweed builder is also no longer reproducing now its been rebooted.

It's so strange, I can't reproduce it any more with 2.10 or 2.11 after reboot it again. I got got hang everytime with 2.10 yesterday.

New data point. The build failed on tumbleweed with the hanging boot. I then could reproduce hangs with runqemu-parallel.py. I tried unloading and reloading the kvm + kvm_intel + irqbypass modules which made no difference.

After a "echo 1 > /proc/sys/vm/drop_caches" it all started working perfectly.

So it appears that its a memory fragmentation related bug.

From the builder's dmesg:

[85637.442463] dropcache (1187): drop_caches: 1
[163691.861365] bash (39598): drop_caches: 1

so it was able to fragment memory in around 24 hours. The rough log of builds on that machine from reboot is:

Dec 10 12:42 nightly-ppc
Dec 10 12:42 nightly-mips-lsb 	#624 	Build successful (master)
Dec 10 12:42 nightly-x86-64-lsb 	#644 	Failed running sanity tests (master)
Dec 10 02:09 nightly-oe-selftest 	#677 	Failed running oe-selftest (morty)
Dec 10 01:53 nightly-mips-lsb 	#623 	Build successful (morty)
Dec 10 02:11 build-appliance 	#629 	Build successful (morty)
Dec 10 02:09 poky-tiny 	#620 	Build successful (morty)
Dec 10 02:07 buildtools 	#621 	Build successful (morty)
Dec 10 01:53 nightly-deb-non-deb 	#635 	Build successful (morty)
Dec 10 02:05 nightly-refkit 	#339 	Build successful (morty)
Dec 10 01:59 nightly-musl 	#644 	Build successful (morty)
Dec 10 01:54 eclipse-plugin-oxygen 	#136 	Build successful (master)
Dec  9 15:01 nightly-x86 (master)
Dec  9 14:59 nightly-mips64 (master)
Dec  9 14:53 eclipse-plugin-neon (master)
Dec  9 14:53 nightly-wic (master)
Dec  9 14:53 nightly-non-gpl3 (master)
Dec  9 11:26 nightly-mips (morty)
Dec  9 11:24 nightly-world-lsb (morty)
Dec  9 06:27 nightly-arm64 (rocko)
Dec  9 04:53 nightly-x86-64 (rocko)
Dec  8 18:25 nightly-qa-extras (morty)
Dec  8 18:15 nightly-uclibc (morty)
Dec  8 18:15 nightly-musl-x86-64 (morty)
<reboot>

(In reply to comment #40)
> New data point. The build failed on tumbleweed with the hanging boot. I then
> could reproduce hangs with runqemu-parallel.py. I tried unloading and
> reloading the kvm + kvm_intel + irqbypass modules which made no difference.
> 
> After a "echo 1 > /proc/sys/vm/drop_caches" it all started working perfectly.
> 
> So it appears that its a memory fragmentation related bug.

Interesting, I assume after you drop the caches you need to wait until the memory becomes fragmented before you can reproduce the problem again. Is it possible to get the dmesg log after the problem occurs? Any memory failures should be logged in there, they may contain hints.

(In reply to comment #42)
> (In reply to comment #40)
> > New data point. The build failed on tumbleweed with the hanging boot. I then
> > could reproduce hangs with runqemu-parallel.py. I tried unloading and
> > reloading the kvm + kvm_intel + irqbypass modules which made no difference.
> > 
> > After a "echo 1 > /proc/sys/vm/drop_caches" it all started working perfectly.
> > 
> > So it appears that its a memory fragmentation related bug.
> 
> Interesting, I assume after you drop the caches you need to wait until the
> memory becomes fragmented before you can reproduce the problem again.

I would assume so, yes.

> Is it
> possible to get the dmesg log after the problem occurs? Any memory failures
> should be logged in there, they may contain hints.

There is nothing in the logs that appears related...

I'm finding:

https://elixir.free-electrons.com/linux/latest/source/arch/x86/kvm/lapic.c#L177

an interesting piece of code.

Its a kvzalloc() call so would use kalloc, falling back to vmalloc so it may or may not be contiguous. If it fails, as far as I can tell the system is in trouble...

(In reply to comment #44)
> I'm finding:
> 
> https://elixir.free-electrons.com/linux/latest/source/arch/x86/kvm/lapic.
> c#L177
> 
> an interesting piece of code.
> 
> Its a kvzalloc() call so would use kalloc, falling back to vmalloc so it may
> or may not be contiguous. If it fails, as far as I can tell the system is in
> trouble...

This is by (relatively new) design, so you can work in fragmented memory. Basically, most of kmallocs were converted to kvmallocs. I am pretty sure I tried replacing kvmallocs with vmallocs at some point to see if something breaks. There was only one allocation (kvm_arch_init) that actually complained (BUG_ON triggerd). Having said that, maybe there were allocations that I somehow did not test.

I did some further digging on tumbleweed as I was once again able to reproduce the hangs.

I ran: 

$ trace-cmd record -b 20000 -T -e kmem

whilst reproducing the hang. This generated a 19GB log.

$ trace-cmd report | grep kmalloc.*ptr=[^0]

the listed six kmalloc failures. Since this is on a 56 core system the logs were unreadable to associate the right stack trace with the right kmalloc. I therefore took the cpu number and did:

$ trace-cmd report --cpu 27 | grep kmalloc.*ptr=[^0] 

which shows the key piece:

           <...>-8213  [027] 248759.935967: kmalloc_node:         (kvmalloc_node+0x3e) call_site=ffffffffad1ce5ae ptr=(nil) bytes_req=522240 bytes_alloc=524288 gfp_flags=GFP_KERNEL|__GFP_NOWARN|__GFP_NORETRY|__GFP_ZERO node=-1
           <...>-8213  [027] 248759.935968: kernel_stack:         <stack trace>
=> kvm_arch_create_memslot (ffffffffc0d43a45)
=> __kvm_set_memory_region (ffffffffc0d29065)
=> kvm_set_memory_region (ffffffffc0d29356)
=> kvm_vm_ioctl (ffffffffc0d297e0)
=> do_vfs_ioctl (ffffffffad253cbd)
=> SyS_ioctl (ffffffffad254274)
=> entry_SYSCALL_64_fastpath (ffffffffad78ac3b)

so the call is coming from kvm_arch_create_memslot() which calls kvzalloc():

https://elixir.free-electrons.com/linux/latest/source/arch/x86/kvm/x86.c#L8286

I therefore suspect than when this call site falls back to vmalloc, the apic breaks.

(In reply to comment #45)
> (In reply to comment #44)
> > I'm finding:
> > 
> > https://elixir.free-electrons.com/linux/latest/source/arch/x86/kvm/lapic.
> > c#L177
> > 
> > an interesting piece of code.
> > 
> > Its a kvzalloc() call so would use kalloc, falling back to vmalloc so it may
> > or may not be contiguous. If it fails, as far as I can tell the system is in
> > trouble...
> 
> This is by (relatively new) design, so you can work in fragmented memory.
> Basically, most of kmallocs were converted to kvmallocs. I am pretty sure I
> tried replacing kvmallocs with vmallocs at some point to see if something
> breaks. There was only one allocation (kvm_arch_init) that actually
> complained (BUG_ON triggerd). Having said that, maybe there were allocations
> that I somehow did not test.

A straight replacement with vmalloc might not work as it might allocate contigous memory that happens to work. You'd have to call a vmalloc which deliberately reordered the pages...

(In reply to comment #47)
> (In reply to comment #45)
> > (In reply to comment #44)
> > > I'm finding:
> > > 
> > > https://elixir.free-electrons.com/linux/latest/source/arch/x86/kvm/lapic.
> > > c#L177
> > > 
> > > an interesting piece of code.
> > > 
> > > Its a kvzalloc() call so would use kalloc, falling back to vmalloc so it may
> > > or may not be contiguous. If it fails, as far as I can tell the system is in
> > > trouble...
> > 
> > This is by (relatively new) design, so you can work in fragmented memory.
> > Basically, most of kmallocs were converted to kvmallocs. I am pretty sure I
> > tried replacing kvmallocs with vmallocs at some point to see if something
> > breaks. There was only one allocation (kvm_arch_init) that actually
> > complained (BUG_ON triggerd). Having said that, maybe there were allocations
> > that I somehow did not test.
> 
> A straight replacement with vmalloc might not work as it might allocate
> contigous memory that happens to work. You'd have to call a vmalloc which
> deliberately reordered the pages...

Good point. At some point I asked the KVM maintainers if there is a need for contiguous memory, the answer was not really.  But, this can be easily verified by 
a. Replacing kvmallocs with kmallocs. We could get memory allocatione errors but not crashes. 
b. Adding printouts to kvmalloc when "switching" to to vmalloc.

My main problem is I cannot reproduce the problem.

Juro, Have you tried manually filling up the page cache:
  https://serverfault.com/questions/534770/how-to-fill-up-linux-cache

That may not be sufficient.
In my previous job, I had a somewhat similar problem and I found a useful tool to fragment all memory so that there was only page-sized fragments available and all larger alocations would fail. It's a kernel module so that we didn't have to wait days to be able to reproduce the problem. The code is still online but it's for 2.4 only! Perhaps the idea is useful and the code may be a good starting point:
  http://opensource.sys-con.com/node/284266
  https://oss.oracle.com/projects/codefragments/src/trunk/fragment-slab/README

I tried a bunch of simple core-image-minimal boots of qemu on Fedora 27  and they all worked. I am trying to get the testimage to build now... in my spare time.

(In reply to comment #49)
> Juro, Have you tried manually filling up the page cache:
>   https://serverfault.com/questions/534770/how-to-fill-up-linux-cache
> 
> That may not be sufficient.
> In my previous job, I had a somewhat similar problem and I found a useful
> tool to fragment all memory so that there was only page-sized fragments
> available and all larger alocations would fail. It's a kernel module so that
> we didn't have to wait days to be able to reproduce the problem. The code is
> still online but it's for 2.4 only! Perhaps the idea is useful and the code
> may be a good starting point:
>   http://opensource.sys-con.com/node/284266
>  
> https://oss.oracle.com/projects/codefragments/src/trunk/fragment-slab/README
> 
> I tried a bunch of simple core-image-minimal boots of qemu on Fedora 27  and
> they all worked. I am trying to get the testimage to build now... in my
> spare time.

A kernel module that fragments memory quickly would be ** very ** useful.
I'll check the links you provided.

Some further details:

I was able to clean up that fragmentation module and get it building with 4.13-4.15 kernels.

With the module I was able to reproduce qemu hangs on my local machine. The BIOS bug shows up some of the time but not always.

I tried a number of tweaks with my 4.13.12 kernel including:
* only using kzalloc (no vzalloc in kvm)
* forcing different sections of memory to different NUMA nodes
* forcing use of vzalloc within kvm

Only fragmentation appears to cause the problem.

I was able to reproduce the problem with 4.14.0 and 4.14.5.

I was not able to reproduce the problem with 4.15-rc3.

I'm therefore bisecting between 4.14.0 and 4.15-rc3 to see if I can find out which kernel change fixes this.

I believe we have a winning commit: https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=b1394e745b9453dcb5b0671c205b770e87dedb87

Found by inspection before I reached it with bisect. Confirmed that applying it to 4.14.0 fixes the hangs which otherwise occurred.

Now the question is how to fix the fedora and tumbleweed builders...

As a quick fix for the autobuilders I'm going to propose we enable x2apic in qemux86-64 which will mean it accesses the apic via msrs and avoids the issue...

For anyone reading along, Richard has added some debugging notes, including a link to a minimally working memory-fragmenting kernel module, here:
https://wiki.yoctoproject.org/wiki/TipsAndTricks/DebuggingHardQemuFailures

Resolved on x86_64 with: http://git.yoctoproject.org/cgit.cgi/poky/commit/?id=7fbb9a4bb65b4a1cf0b4eb34b30c5567f1c1c1ad
and for 32 bit:
http://git.yoctoproject.org/cgit.cgi/poky/commit/?id=d18003726f561bab2ab07acf16baee074da37cdc