| Summary: | 6.6.23 and 6.12.x qemux86 boot hang [qemu without kvm, not kernel] | ||
|---|---|---|---|
| Product: | [Build System, Metadata & Runtime] OE-Core | Reporter: | Richard Purdie <richard.purdie> |
| Component: | kernel | Assignee: | Bruce Ashfield <bruce.ashfield> |
| Status: | RESOLVED WORKSFORME | QA Contact: | |
| Severity: | normal | ||
| Priority: | Medium+ | CC: | alexandre.belloni, ccasciato, paulg, randy.macleod, tim.orling, yoann.congal |
| Version: | 0.0.0 | ||
| Target Milestone: | 6.0 M1 | ||
| Hardware: | x86 | ||
| OS: | Multiple | ||
| Whiteboard: | AB-INT | ||
| OS type for building Yocto: | --- | Type of Regression: | --- |
| Verified: | Documentation change: | No (bug/feature does not impact docs) | |
| Attachments: | |||
|
Description
Richard Purdie
2024-04-01 09:00:11 UTC
This was on rocky9-ty-1 and I suspect it is the non-kvm case Second occurrence: https://autobuilder.yoctoproject.org/typhoon/#/builders/145/builds/1521/steps/12/logs/stdio fedora38-ty-4 non-kvm qemux86 https://autobuilder.yoctoproject.org/typhoon/#/builders/148/builds/1530/steps/12/logs/stdio qemux86-64-tc fedora38-ty-3 https://autobuilder.yoctoproject.org/typhoon/#/builders/145/builds/1519/steps/13/logs/stdio qemux86-tc alma8-ty-1 https://autobuilder.yoctoproject.org/typhoon/#/builders/145/builds/1521/steps/12/logs/stdio qemux86-tc fedora38-ty-4 https://autobuilder.yoctoproject.org/typhoon/#/builders/148/builds/1446/steps/12/logs/stdio qemux86-64-tc debian12-ty-1 https://autobuilder.yoctoproject.org/typhoon/#/builders/145/builds/1524/steps/12/logs/stdio qemux86-tc fedora38-ty-4 Created attachment 5039 [details]
diff between the dmesg of a failed boot vs. a good boot.
So I stripped off the kernel time stamps so I could diff the failed boot with the passed boot (attached and annotated). It revealed a few clues.
Executive summary is that I would thought the two boots would largely be consistent but no. Early e820 is different and and by the time you get to PCI (where it consistently hangs) there are a whole bunch of differences which someone needs to explain!! Same kernel config, same toolchain, and same qemu binary, and I would expect a *lot* more consistency.
The other thing that was odd - one was booting with /dev/nfs and the other booting with /dev/vda -- if runqemu script was used, wouldn't these be consistent?
I couldn't use any of the other fails in a diff over the e820 stuff because they are truncated to a paltry 25 lines. :-( Could we not at least make it 100 lines? It isn't 1985 where we are on a BBS anymore.
Those logs are from the same kernel binary and the same qemu binaries (so built with the same toolchain). The difference in command line is a difference in how runqemu is being called for the two test contexts. One test is using NFS, the other isn't. We probably need to find a successful run of this on the autobuilder and see if the logs vary between the two. The differences do seem rather suspicious though. I'd take a patch changing the 25 lines to 100 lines. I wish we had an easier way to save failure log files to make this easier. OK, so I managed to reproduce the same d8000 vs. de000 locally just by switching from /dev/vda to /dev/nfs locally. Similarly there were also some changes in the PCI register dump. So it isn't anything specific to the AB. I then ran the default ubu-20.04 qemu-i386 which is v6.2 (our sysroot one 8-something) and saw the same. I haven't yet compared the PCI dumps line by line between the two qemu versions - just wanted to confirm somehow nfs vs. vda changed it. I also reopened all six failure cases linked here, and they are *all* NFS root. That is a new data point we didn't have before AFAIK. So I've got the old test harness from previous "fun" hard-to-reproduce bugs. Of course it didn't support NFS because it was truly stand-alone and had no idea about user-nfs or pseudo, or ... So I did a complete bodge job on it and it is now running within the "oe-init-build-env" itself and booting nfsroot. Anyway, the point is that I'm doing what we did before - trying to see if I can reproduce it within < 250 boots locally (give or take) I'm about 100 boots in and haven't seen it yet. Here is the problem. As seen in the v6.6.7 kernel: 239bff0171a8 x86/tdx: Allow 32-bit emulation by default 22ca647c8f88 x86/entry: Do not allow external 0x80 interrupts 4591766ff655 x86/entry: Convert INT 0x80 emulation to IDTENTRY 34c686e5be2f x86/coco: Disable 32-bit emulation by default on TDX and SEV f259af26ee04 x86: Introduce ia32_enabled() ia32_enabled commit is just a dependency for the above. It can largely be ignored as runtime impact is pretty much zero. commit f35e46631b28a63ca3887d7afef1a65a5544da52 Merge: 55b224d90d44 f4116bfc4462 Author: Linus Torvalds <torvalds@linux-foundation.org> Date: Thu Dec 7 11:56:34 2023 -0800 Merge tag 'x86-int80-20231207' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip Pull x86 int80 fixes from Dave Hansen: "Avoid VMM misuse of 'int 0x80' handling in TDX and SEV guests. It also has the very nice side effect of getting rid of a bunch of assembly entry code" * tag 'x86-int80-20231207' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip: x86/tdx: Allow 32-bit emulation by default x86/entry: Do not allow external 0x80 interrupts x86/entry: Convert INT 0x80 emulation to IDTENTRY x86/coco: Disable 32-bit emulation by default on TDX and SEV Last commit also doesn't impact the 32bit qemu use case impacting Yocto either, as we don't even compile it. Trying to bisect into there didn't make any sense to me, at least in a linux-stable context - it is pretty clearly a package deal and not a group of independent fixes. Testing details: The v6.6.7 froze in the PCI code in less than 30 runs. The v6.6.6 ran for over 300 runs until I got bored and declared it "good". The v6.6.7 with the above "fix" of 5 commits reverted has gone 125 runs and counting. I'd say we've found the problem. Tested on the v6.6.23+ with the 5 reverts for 150-odd iterations, and it seems fine as well. Sent the reverts with commit logs. https://lists.yoctoproject.org/g/linux-yocto/message/13837 I also built mainline f35e46631b2 (the merge mentioned above where the content originally appeared) and fed that to the test harness -- knew that if I waited any, I'd forget what manual steps I was doing. After 300+ iterations, I didn't see the "PCI hang" -- so I have to assume they have some implicit dependency which is satisfied in mainline, but not so in the case of the stable backports. I guess that is good news? So the above comment (saying mainline at the merge is OK) is false. I just didn't wait long enough. Ran it for another bunch of hours and it did the PCI-freeze. I also tested the v6.6.27 that has the Branch History Injection (BHI) fixes that conflict with the reverts -- thinking that if it conflicts that bad at the source level, then we can't assume the runtime still has the same issue. Unfortunately it still does. Just takes longer to show. Got two PCI-freeze in 800+ runs overnight. :-( Which is why I went back and re-tested mainline. Full disclosure -- when testing the merge point (v6.7-rc4-16-gf35e46631b28) I would cherry pick back the NOP rewrite fix (v6.7-rc5-3-g2dc419613805) as otherwise I'd keep "re-finding" that other qemu issue we've since got fixed. So the obvious next question anyone would ask is "Is it still an issue on the latest mainline?" Yes. An overnight run of v6.9-rc5 showed three PCI boot hangs in 700 boot cycles. Given it isn't specific to the stable backports, it would seem it is time to loop in the folks associated with the three identified commits and see if they can shed some light on why it silently just hits a wall in the PCI code. Created attachment 5040 [details]
Kernel config for mainline v6.9-rc5
Adding the config from v6.9-rc5 (basically our v6.6.x config fed through "make oldconfig") and the full qemu arg list so (in theory) others can replicate it outside of Yocto/OE.
Created attachment 5041 [details]
full qemu args used by the Yocto "runqemu" wrapper.
For those not following the lkml thread, I did more extensive testing on the trunk, just under the five INT80 related changes, and was also able to reproduce the PCI hang there by waiting long enough. Which means the INT80 changes (at least on mainline) are not responsible. I'm not quite sure what to make of my v6.6-stable data above, as it seemed pretty conclusive that v6.6.6 was OK and v6.6.7 was broken. I'm letting v6.6.6 run some more in order to have more confidence in it really being good (vs. just being lucky). Lost access to the larger server I was using, but maybe that was a good thing. Made me re-think a strategy. You really don't need a fast machine to *run* the qemu tests - and with sstate, even slow machines can be set up to run the qemu boot tests. So with a six-pack of "old COTS junkers" I can get more "boot tests per hour" than I got with the server hardware. Just a lot more hands on having six kids to feed instead of just one... So, I 1st checked I could reproduce the issue. Yep, the current v6.6.29 would hang in the PCI code just like before, even on an old COTS PC. The question we left off with, was whether v6.6.6 was really good or 500+ tests simply wasn't enough. It wasn't enough. Same for v6.6.5 and v6.6.4 and v6.6.3 and v6.6.2. I'm sensing a pattern here. I skip v6.6.1 and prove to myself that v6.6 (i.e. mainline, and *zero* stable backports) does the PCI hang. Well, that sucks. I was treating/assuming this was a regression that happened *after* we'd moved to the v6.6 baseline. And I still believe there are changes that happened in the v6.6.7 area that somehow made it more probable to happen. Since the "kids" were all spun up, and looking for something to do, and since I'm thinking I've been chasing ghosts, I decided to test a hunch. I checked out vanilla v6.1.90 stable - the current baseline for our previous release; ran "make oldconfig" using our current v6.6.x config as the input (a tried and true process) and let the kids chew on that. Guess what? PCI hangs. Four instances in 1178 boot tests on v6.1.90 - whee! So that leaves one with basically two options: 1) Assume that the issue is still kernel, and was present in the prior release, and the AB just didn't find it somehow, or.... 2) As per the LKML thread, assume "TCG code generator" (i.e. non-KVM) has caused people to "have seen some weird bugs with it in the past." I'm leaning towards #2, and as such, I'm pretty much done trying to figure this one out any further. It would be interesting to get access to the QEMU console in one of the "hung" cases and poke at it like suggested on LKML, but I'm not sure I know how to pull that off - and this has already eaten waaaay too much time. Some technical details re: testing: ------------------------------------ I determined that toolchain used to build the kernel didn't matter. So I had a mix of building with our current gcc in a "bitbake -c devshell linux-yocto" and also with ubuntu-18.04 and 20.04 default gcc versions. I also compiled each test point on each test box (vs. sharing one bzImage six times) to introduce more variability. There was no obvious pattern in which test box found more or less PCI hangs. They all seemed to find a couple at one point or another. Created attachment 5044 [details]
Kernel dmesg for PCI hang on v6.1.90 (spring 2023 release) kernel
Cleaning up after the prior fun testing, and look what I found... paul@o990:~/poky/build/q$ dmesg|grep qemu qemu-system-i38[758683]: segfault at 7f7378b02 ip 0000557a5051cec4 sp 00007f7383dfe0e0 error 4 in qemu-system-i386[557a5019e000+5b0000] qemu-system-i38[776442]: segfault at 118 ip 0000562f56c86673 sp 00007f45d67fb110 error 4 in qemu-system-i386[562f56906000+5b0000] qemu-system-i38[965554]: segfault at 7f5f6d428 ip 000055f1557e1673 sp 00007f5fd4f36110 error 4 in qemu-system-i386[55f155461000+5b0000] qemu-system-i38[1071145]: segfault at 7f5e882e0 ip 0000562f827faec4 sp 00007f5ef486a0e0 error 4 in qemu-system-i386[562f8247c000+5b0000] paul@o990:~/poky/build/q$ How many tests did this poor guy run? paul@o990:~/poky/build/q$ ls -1 v6*/qemu_boot_log.202405* | wc -l 4458 And how many PCI hangs did he encounter? paul@o990:~/poky/build/q$ tail -n1 v6*/qemu_boot_log.202405* | grep -i pci pci 0000:00:1f.2: [8086:2922] type 00 class 0x010601 pci 0000:00:1d.1: [8086:2935] type 00 class 0x0c0300 pci 0000:00:1f.2: [8086:2922] type 00 class 0x010601 pci 0000:00:03.0: reg 0x20: [mem 0xfe004000-0xfe007fff 64bit pref] paul@o990:~/poky/build/q$ Four times QEMU got SIGSEGV and four instances of PCI hang. Coincidence? Nope. Checked a couple of the other "kids" and saw the same thing. So this is 100% a QEMU issue and has *nothing* to do with the kernel. (No surprise after my v6.1.90 testing). I'm kind of surprised that the AB doesn't snapshot the test host dmesg and compare it before and after a test completes. If they aren't the same, the test should fail as a whole. We really should have that. I'm sure I've seen it somewhere before, LTP or some custom test. It will catch OOM and crap like this that cost me a lot of time. We probably should file an enhancement request against the AB to do the before and after dmesg check. Otherwise it will fall through the cracks, and we'll be wasting days on cases like this one, simply because we are missing all of the normal/obvious information. I know we discussed it on IRC, and there was a hesitation because some distros have "turned off" regular access to dmesg for "security" (a joke), but on my ubu-20.04 installs it works, and I never had to go tweak it to make that happen. So the check could simply 1st check if dmesg is available, and bypass it if not. The other thing - since the work I did proved it was a qemu issue, and since we recently upgraded to qemu-v9.0, we probably should "reset" our AB intermittent boot fail counter and see if by luck the qemu uprev fixed things. Recently updated to qemu 9, we'll wait a while to the AB to test or for Paul to do so! https://autobuilder.yoctoproject.org/typhoon/#/builders/145/builds/1880 https://autobuilder.yocto.io/pub/failed-builds-data/qemux86-tc-hang2/ interestingly rocky9-ty-1 despite being non kvm https://autobuilder.yocto.io/pub/failed-builds-data/qemux86-tc-hang2/qemu_boot_log.20240701005524 looks to hang in roughly the same place. This was a newer kernel version and new qemu Keeping for a few more months. Does not seem to be happening on the new autobuilder. qemux86-tc alma8-vk-2 abelloni/master-next completed at 2025-01-11T21:04:51Z https://valkyrie.yoctoproject.org/#/builders/28/builds/770/steps/13/logs/stdio Can anyone confirm the host still shows the qemu binary segfaults in dmesg - the key finding from the work I did in the past here? Or is the whole nonsense of "we aren't allowed to look at dmesg because that is what the other kids do" still an unresolved issue with the AB deployment? Assuming the segfault is still reported in the host running the qemu binary, and now after probably several qemu uprevs since the initial reporting, I think the prudent thing to do is open a ticket with the qemu project and then move on. At least let the qemu folks be aware of it, if they aren't already. Yes, qemu is a key component to the validation the AB does, but at the same time, it isn't within scope for YP to fix every issue we trip over in qemu - any more than it would be for any other key component - be it python, gcc or even the kernel. Nothing related in dmesg now (1) The system was rebooted as part of maintenance. I don't have sudo so someone else will have to take a look. 1) [rmacleod@alma8-vk-2 ~]$ uptime 19:38:32 up 22:33, 2 users, load average: 1.35, 1.31, 1.23 [rmacleod@alma8-vk-2 ~]$ dmesg | grep segfault [51152.175715] rustc[2590219]: segfault at 7efd9f7ffe70 ip 00007efda9ab395a sp 00007efd9f7ffe40 error 6 in librustc_driver-655b55d4e10e5907.so[7efda5046000+5105000] [51152.240077] rustc[2589380]: segfault at 7f9d55796eb0 ip 00007f9d5b448591 sp 00007f9d55796ea0 error 6 in librustc_driver-655b55d4e10e5907.so[7f9d56f07000+5105000] [51152.416656] rustc[2589691]: segfault at 7f0c58f5cf90 ip 00007f0c5ec0e591 sp 00007f0c58f5cf80 error 6 in librustc_driver-655b55d4e10e5907.so[7f0c5a6cd000+5105000] [51154.269223] rustc[2589208]: segfault at 7fd55b354ee8 ip 00007fd560e6cf2a sp 00007fd55b354ee0 error 6 in librustc_driver-655b55d4e10e5907.so[7fd55cac5000+5105000] [rmacleod@alma8-vk-2 ~]$ less /var/log/messages /var/log/messages: Permission denied I have an email out about the rust segfault and we'll create a bug once we know more about when it happens. FYI, it does happen on our build system as well. qemux86-tc debian12-vk-3 master-next completed at 2025-02-10T10:43:45Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/28/builds/955/steps/12/logs/stdio qemux86-tc ubuntu2204-vk-2 master-next completed at 2025-02-12T02:29:31Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/28/builds/968/steps/12/logs/stdio qemux86-tc ubuntu2404-vk-1 mathieu/master-next completed at 2024-12-19T09:26:56Z https://valkyrie.yoctoproject.org/#/builders/28/builds/661/steps/12/logs/stdio qemux86-tc fedora40-vk-2 master completed at 2025-02-28T03:27:30Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/28/builds/1069/steps/12/logs/stdio qemux86-tc ubuntu2004-vk-3 master-next completed at 2025-03-26T00:47:03Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/28/builds/1232/steps/13/logs/stdio qemuarm-tc debian11-vk-1 mathieu/master-next completed at 2025-04-17T10:17:48Z So, this one is on ARM, but still kinda similar... https://autobuilder.yoctoproject.org/valkyrie/#/builders/42/builds/1384/steps/12/logs/stdio Found this old one in untriaged entries. qemux86-64-tc ubuntu2404-vk-3 mathieu/master-next completed at 2024-11-29T18:26:43Z https://valkyrie.yoctoproject.org/#/builders/66/builds/550/steps/12/logs/stdio qemux86-tc fedora40-vk-3 master-next completed at 2025-04-26T01:23:26Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/28/builds/1422/steps/12/logs/stdio qemux86-tc fedora39-vk-2 mathieu/master-next completed at 2025-05-03T15:47:25Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/28/builds/1467/steps/12/logs/stdio qemux86-tc ubuntu2404-vk-1 master-next completed at 2025-05-11T01:04:27Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/28/builds/1517/steps/12/logs/stdio qemux86-tc stream9-vk-1 master-next completed at 2025-05-16T10:32:16Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/28/builds/1552/steps/12/logs/stdio qemux86-64-tc fedora39-vk-1 mathieu/master-next completed at 2025-05-26T14:52:14Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/66/builds/1622/steps/12/logs/stdio oe-selftest-armhost ubuntu2004-vk-arm1 master-next completed at 2025-06-05T19:55:21Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/23/builds/1855/steps/15/logs/stdio qemux86-64-tc ubuntu2404-vk-2 agodard/master-next completed at 2025-06-17 13:06:29+00:00 https://autobuilder.yoctoproject.org/valkyrie/#/builders/66/builds/1780/steps/12/logs/stdio qemux86-tc rocky8-vk-1 master completed at 2025-06-25 03:07:39+00:00 https://autobuilder.yoctoproject.org/valkyrie/#/builders/28/builds/1813/steps/13/logs/stdio qemux86-64-tc debian11-vk-3 agodard/master-next completed at 2025-06-25 11:12:30+00:00 https://autobuilder.yoctoproject.org/valkyrie/#/builders/66/builds/1828/steps/12/logs/stdio qemux86-64-ptest ubuntu2204-vk-3 agodard/master-next completed at 2025-07-02 12:47:10+00:00 https://autobuilder.yoctoproject.org/valkyrie/#/builders/73/builds/1821/steps/12/logs/stdio qemux86-tc fedora39-vk-2 master-next completed at 2025-07-08 00:41:58+00:00 https://autobuilder.yoctoproject.org/valkyrie/#/builders/28/builds/1898/steps/12/logs/stdio qemux86-64-tc fedora40-vk-1 mathieu/master-next completed at 2025-07-15 08:00:43+00:00 https://autobuilder.yoctoproject.org/valkyrie#/builders/66/builds/1950/steps/12/logs/stdio qemux86-tc alma9-vk-2 master completed at 2025-08-05 04:32:04+00:00 https://autobuilder.yoctoproject.org/valkyrie/#/builders/28/builds/2066/steps/12/logs/stdio qemux86-tc alma8-vk-1 mathieu/master-next completed at 2025-08-11 07:12:05+00:00 https://autobuilder.yoctoproject.org/valkyrie/#/builders/28/builds/2100/steps/13/logs/stdio Likely a qemu bug that has been fixed since it hasn't been seen in many months. Back, now with 6.18 kernel? :( qemux86-64-tc alma8-vk-1 mathieu/master-next completed at 2026-02-19 20:58:15+00:00 https://valkyrie.yocto.io/pub/non-release/20260219-111/testresults/qemux86-64-tc/ https://autobuilder.yoctoproject.org/valkyrie/#/builders/66/builds/3239/steps/14/logs/stdio |