The TL;DR is that the Yocto folks encountered a regression in their
automated QA tests (after a move from v6.4 --> v6.5) where non-KVM
enabled boot tests on 32 bit x86 would (with ~2% frequency) splat with:
[0.326235] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
[0.326556] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256
[0.326965] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format.
[0.331789] __common_interrupt: 0.167 No irq handler for vector
[0.331789] __common_interrupt: 0.112 No irq handler for vector
[0.331789] iret exception: 0000 [#1] PREEMPT SMP
[0.331789] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 6.5.7-yocto-standard #1
[0.331789] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.16.2-0-gea1b7a073390-prebuilt.qemu.org 04/01/2014
[0.331789] EIP: 0x60
[0.331789] Code: Unable to access opcode bytes at 0x36.
..or similar - common theme being FPU init and __common_interrupt.
The 2% reproducibility was a problem, so the Yocto folks asked me to
take a look, and keeping with the TL;DR I managed to bisect it to the
tip merge of alternates, and then in turn to the commit within:
6c480f222128 x86/alternative: Rewrite optimize_nops() some
That failed six times in 381 qemu boots. I've run the commit below it,
14e4ec9c3e91 close to 1500 times (still going) without a fail - since as
we all know at 2%, that bad is bad but good is only statistically proven.
I'm not quite sure where to go next. Has been nearly 20 years since
I've had to juggle NOP counts for some IMHO broken MIPS pipeline. So I
figured I best report it at this point.
I've put a bunch of details in the bugzilla of the Yocto folks here:
https://bugzilla.yoctoproject.org/show_bug.cgi?id=15230
Skip ahead to comment 11 and you'll avoid me chasing FPU changes like
tglx's FPU init relocation commits, only to go nowhere.
I've kept kernel build dirs, boot logs, etc for all the commits I've
touched down into for testing, so I can revisit and re-test easily.
Paul.
On Sun, Oct 29, 2023 at 02:41:46PM -0400, Paul Gortmaker wrote:
> The TL;DR is that the Yocto folks encountered a regression in their
> automated QA tests (after a move from v6.4 --> v6.5) where non-KVM
> enabled boot tests on 32 bit x86 would (with ~2% frequency) splat with:
You're sure you're not running into this here:
https://lkml.kernel.org/r/[email protected]
?
On Mon, 2023-10-30 at 09:26 +0100, Peter Zijlstra wrote:
> On Sun, Oct 29, 2023 at 02:41:46PM -0400, Paul Gortmaker wrote:
> > The TL;DR is that the Yocto folks encountered a regression in their
> > automated QA tests (after a move from v6.4 --> v6.5) where non-KVM
> > enabled boot tests on 32 bit x86 would (with ~2% frequency) splat with:
>
> You're sure you're not running into this here:
>
> https://lkml.kernel.org/r/[email protected]
>
> ?
We're using qemu 8.1.0. Whilst I will get us updated to 8.1.2 and see
if that helps, I think those commits are in 8.1.0:
$ git show cb62bd15e14e304617d250158b77d0deb032f03
commit cb62bd15e14e304617d250158b77d0deb032f032
Author: Richard Henderson <[email protected]>
Date: Thu Jul 6 08:45:13 2023 +0100
accel/tcg: Split out cpu_exec_longjmp_cleanup
[...]
$ git tag --contains cb62bd15e14e304617d250158b77d0deb032f03
v8.1.0
v8.1.0-rc0
v8.1.0-rc1
v8.1.0-rc2
v8.1.0-rc3
v8.1.0-rc4
v8.1.1
v8.1.2
Similarly for:
commit deba78709ae8ce103e2248413857747f804cd1ef
Author: Richard Henderson <[email protected]>
Date: Thu Jul 6 17:55:48 2023 +0100
accel/tcg: Always lock pages before translation
and
commit ad17868eb162a5466d8ad43e5ccb428776403308
Author: Richard Henderson <[email protected]>
Date: Wed Jul 26 12:58:08 2023 -0700
accel/tcg: Clear tcg_ctx->gen_tb on buffer overflow
[...]
Fixes: deba78709ae8 ("accel/tcg: Always lock pages before translation")
Both of which are also in 8.1.0.
Is there any other patch related to those we might be missing?
Cheers,
Richard
On Mon, Oct 30, 2023 at 10:55:26AM +0000, Richard Purdie wrote:
> On Mon, 2023-10-30 at 09:26 +0100, Peter Zijlstra wrote:
> > On Sun, Oct 29, 2023 at 02:41:46PM -0400, Paul Gortmaker wrote:
> > > The TL;DR is that the Yocto folks encountered a regression in their
> > > automated QA tests (after a move from v6.4 --> v6.5) where non-KVM
> > > enabled boot tests on 32 bit x86 would (with ~2% frequency) splat with:
> >
> > You're sure you're not running into this here:
> >
> > https://lkml.kernel.org/r/[email protected]
> >
> > ?
>
> We're using qemu 8.1.0. Whilst I will get us updated to 8.1.2 and see
> if that helps, I think those commits are in 8.1.0:
>
> $ git show cb62bd15e14e304617d250158b77d0deb032f03
> commit cb62bd15e14e304617d250158b77d0deb032f032
> Author: Richard Henderson <[email protected]>
> Date: Thu Jul 6 08:45:13 2023 +0100
>
> accel/tcg: Split out cpu_exec_longjmp_cleanup
> [...]
> $ git tag --contains cb62bd15e14e304617d250158b77d0deb032f03
> v8.1.0
> v8.1.0-rc0
> v8.1.0-rc1
> v8.1.0-rc2
> v8.1.0-rc3
> v8.1.0-rc4
> v8.1.1
> v8.1.2
>
> Similarly for:
>
> commit deba78709ae8ce103e2248413857747f804cd1ef
> Author: Richard Henderson <[email protected]>
> Date: Thu Jul 6 17:55:48 2023 +0100
>
> accel/tcg: Always lock pages before translation
>
> and
>
> commit ad17868eb162a5466d8ad43e5ccb428776403308
> Author: Richard Henderson <[email protected]>
> Date: Wed Jul 26 12:58:08 2023 -0700
>
> accel/tcg: Clear tcg_ctx->gen_tb on buffer overflow
> [...]
> Fixes: deba78709ae8 ("accel/tcg: Always lock pages before translation")
>
> Both of which are also in 8.1.0.
>
> Is there any other patch related to those we might be missing?
Not sure -- afaik that was it.
Thomas was looking at this and wondered if something like the below
would help?
---
arch/x86/kernel/alternative.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/arch/x86/kernel/alternative.c b/arch/x86/kernel/alternative.c
index 73be3931e4f0..fd44739828f7 100644
--- a/arch/x86/kernel/alternative.c
+++ b/arch/x86/kernel/alternative.c
@@ -1685,8 +1685,8 @@ void __init_or_module text_poke_early(void *addr, const void *opcode,
} else {
local_irq_save(flags);
memcpy(addr, opcode, len);
- local_irq_restore(flags);
sync_core();
+ local_irq_restore(flags);
/*
* Could also do a CLFLUSH here to speed up CPU recovery; but
[Re: 32 bit qemu regression from v6.5 tip pull [6c480f222128 x86/alternative: Rewrite optimize_nops() some]] On 30/10/2023 (Mon 12:44) Peter Zijlstra wrote:
> Thomas was looking at this and wondered if something like the below
> would help?
I tested this on a vanilla v6.5.7 baseline, for lack of a better choice
and got six failures in 136 boots - everything else unchanged - even the
shell instance that builds the kernel.
Paul.
--
>
> ---
> arch/x86/kernel/alternative.c | 2 +-
> 1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/arch/x86/kernel/alternative.c b/arch/x86/kernel/alternative.c
> index 73be3931e4f0..fd44739828f7 100644
> --- a/arch/x86/kernel/alternative.c
> +++ b/arch/x86/kernel/alternative.c
> @@ -1685,8 +1685,8 @@ void __init_or_module text_poke_early(void *addr, const void *opcode,
> } else {
> local_irq_save(flags);
> memcpy(addr, opcode, len);
> - local_irq_restore(flags);
> sync_core();
> + local_irq_restore(flags);
>
> /*
> * Could also do a CLFLUSH here to speed up CPU recovery; but
rp-qemu32-v6.5.7-tglx$while [ 1 ] ; do date ; ls -l1 qemurunner_log* | wc -l ; grep -l _common qemu_boot_log.2023* ; sleep 5m ; done
Mon 30 Oct 2023 10:29:57 AM EDT
22
Mon 30 Oct 2023 10:34:57 AM EDT
32
qemu_boot_log.20231030103001
Mon 30 Oct 2023 10:39:57 AM EDT
46
qemu_boot_log.20231030103001
Mon 30 Oct 2023 10:44:57 AM EDT
60
qemu_boot_log.20231030103001
Mon 30 Oct 2023 10:49:57 AM EDT
70
qemu_boot_log.20231030103001
qemu_boot_log.20231030104722
Mon 30 Oct 2023 10:54:57 AM EDT
80
qemu_boot_log.20231030103001
qemu_boot_log.20231030104722
qemu_boot_log.20231030105036
Mon 30 Oct 2023 10:59:57 AM EDT
89
qemu_boot_log.20231030103001
qemu_boot_log.20231030104722
qemu_boot_log.20231030105036
qemu_boot_log.20231030105809
Mon 30 Oct 2023 11:04:57 AM EDT
99
qemu_boot_log.20231030103001
qemu_boot_log.20231030104722
qemu_boot_log.20231030105036
qemu_boot_log.20231030105809
qemu_boot_log.20231030110019
Mon 30 Oct 2023 11:09:57 AM EDT
109
qemu_boot_log.20231030103001
qemu_boot_log.20231030104722
qemu_boot_log.20231030105036
qemu_boot_log.20231030105809
qemu_boot_log.20231030110019
qemu_boot_log.20231030110615
Mon 30 Oct 2023 11:14:57 AM EDT
123
qemu_boot_log.20231030103001
qemu_boot_log.20231030104722
qemu_boot_log.20231030105036
qemu_boot_log.20231030105809
qemu_boot_log.20231030110019
qemu_boot_log.20231030110615
Mon 30 Oct 2023 11:19:57 AM EDT
136
qemu_boot_log.20231030103001
qemu_boot_log.20231030104722
qemu_boot_log.20231030105036
qemu_boot_log.20231030105809
qemu_boot_log.20231030110019
qemu_boot_log.20231030110615
^C
On Mon, Oct 30 2023 at 11:28, Paul Gortmaker wrote:
> [Re: 32 bit qemu regression from v6.5 tip pull [6c480f222128 x86/alternative: Rewrite optimize_nops() some]] On 30/10/2023 (Mon 12:44) Peter Zijlstra wrote:
>
>> Thomas was looking at this and wondered if something like the below
>> would help?
>
> I tested this on a vanilla v6.5.7 baseline, for lack of a better choice
> and got six failures in 136 boots - everything else unchanged - even the
> shell instance that builds the kernel.
While the sync_core() invocation is definitely at the wrong place, I did
not really expect that this cures it.
Can you add "debug-alternative" to the kernel command line and log both
a working and the non-working kernel output. It's noisy :)
Also do you have a .config and the qemu command line handy?
Thanks,
tglx
On Mon, Oct 30 2023 at 19:24, Thomas Gleixner wrote:
> On Mon, Oct 30 2023 at 11:28, Paul Gortmaker wrote:
>> [Re: 32 bit qemu regression from v6.5 tip pull [6c480f222128 x86/alternative: Rewrite optimize_nops() some]] On 30/10/2023 (Mon 12:44) Peter Zijlstra wrote:
>>
>>> Thomas was looking at this and wondered if something like the below
>>> would help?
>>
>> I tested this on a vanilla v6.5.7 baseline, for lack of a better choice
>> and got six failures in 136 boots - everything else unchanged - even the
>> shell instance that builds the kernel.
>
> While the sync_core() invocation is definitely at the wrong place, I did
> not really expect that this cures it.
>
> Can you add "debug-alternative" to the kernel command line and log both
> a working and the non-working kernel output. It's noisy :)
>
> Also do you have a .config and the qemu command line handy?
Forgot to ask: Does the probkem persist with 6.6 ?
Thanks,
tglx
[Re: 32 bit qemu regression from v6.5 tip pull [6c480f222128 x86/alternative: Rewrite optimize_nops() some]] On 30/10/2023 (Mon 20:30) Thomas Gleixner wrote:
> On Mon, Oct 30 2023 at 19:24, Thomas Gleixner wrote:
> > Can you add "debug-alternative" to the kernel command line and log both
> > a working and the non-working kernel output. It's noisy :)
> >
> > Also do you have a .config and the qemu command line handy?
>
> Forgot to ask: Does the probkem persist with 6.6 ?
My bad, should have mentioned v6.6 and linux-next is impacted. Always a
conflict between burying the lead and boring people with details.
The "debug-alternative" is definitely "chatty" -- the "works" case is
easy to capture -- working on getting a snapshot of the "fails" case.
I will attach a .config to the yocto bugzilla case, for lack of a better
place to put it.
The giant sh*tshow of qemu args used by QA are as follows:
Running
paul/poky/build-qemu-x86_32/tmp/work/x86_64-linux/qemu-helper-native/1.0/recipe-sysroot-native/usr/bin/qemu-system-i386
-device virtio-net-pci,netdev=net0,mac=52:54:00:12:34:02 -netdev
tap,id=net0,ifname=tap0,script=no,downscript=no -object
rng-random,filename=/dev/urandom,id=r
ng0 -device virtio-rng-pci,rng=rng0 -drive
file=./core-image-minimal-qemux86.rootfs.ext4.2545136,if=virtio,format=raw
-usb -device usb-tablet -usb -device usb
-kbd -cpu IvyBridge -machine q35,i8042=off -smp 4 -m 256 -serial
tcp:127.0.0.1:45019 -serial tcp:127.0.0.1:49567 -pidfile
/folk/pgortmak/tglx/pidfile_25451
32 -S -qmp unix:./.ut8nuyx1,server,wait -qmp
unix:./.7mu5pxk1,server,nowait -nographic -kernel
/yow-lpggp32/paul/poky/build-qemu-x86_32/tmp/deploy/images/qemux86/bzImage -append 'root=/dev/vda rw
ip=192.168.7.2::192.168.7.1:255.255.255.0::eth0:off:8.8.8.8
net.ifnames=0 console=ttyS0 console=ttyS1 oprofile.timer=
1 tsc=reliable no_timer_check rcupdate.rcu_expedited=1 swiotlb=0
debug-alternative printk.time=1'
It pains me that it fills a screen. But there it is.
On Sat, 2023-11-11 at 12:51 +0100, Linux regression tracking (Thorsten
Leemhuis) wrote:
> [CCing the regression list, as it should be in the loop for regressions:
> https://docs.kernel.org/admin-guide/reporting-regressions.html]
>
> > [Re: 32 bit qemu regression from v6.5 tip pull [6c480f222128 x86/alternative: Rewrite optimize_nops() some]] On 30/10/2023 (Mon 20:30) Thomas Gleixner wrote:
> >
> > > On Mon, Oct 30 2023 at 19:24, Thomas Gleixner wrote:
> >
> > > > Can you add "debug-alternative" to the kernel command line and log both
> > > > a working and the non-working kernel output. It's noisy :)
> > > >
> > > > Also do you have a .config and the qemu command line handy?
> > >
> > > Forgot to ask: Does the probkem persist with 6.6 ?
> >
> > My bad, should have mentioned v6.6 and linux-next is impacted. Always a
> > conflict between burying the lead and boring people with details.
>
> Paul, was this regression ever solved? I wonder as I could not find
> anything with a "Fixes: 6c480f222128 [...]" tag on lore and this thread
> looks stalled.
I didn't see a reply to this. I can confirm the issue is still present
and we're not aware of any fix yet.
Cheers,
Richard
On Sat, Nov 11 2023 at 12:51, Linux regression tracking wrote:
> [CCing the regression list, as it should be in the loop for regressions:
> https://docs.kernel.org/admin-guide/reporting-regressions.html]
>
>> [Re: 32 bit qemu regression from v6.5 tip pull [6c480f222128 x86/alternative: Rewrite optimize_nops() some]] On 30/10/2023 (Mon 20:30) Thomas Gleixner wrote:
>>
>>> On Mon, Oct 30 2023 at 19:24, Thomas Gleixner wrote:
>>
>>> > Can you add "debug-alternative" to the kernel command line and log both
>>> > a working and the non-working kernel output. It's noisy :)
>>> >
>>> > Also do you have a .config and the qemu command line handy?
>>>
>>> Forgot to ask: Does the probkem persist with 6.6 ?
>>
>> My bad, should have mentioned v6.6 and linux-next is impacted. Always a
>> conflict between burying the lead and boring people with details.
>
> Paul, was this regression ever solved? I wonder as I could not find
> anything with a "Fixes: 6c480f222128 [...]" tag on lore and this thread
> looks stalled.
Hmm. I was waiting for the .config file to materialize and for an
eventual analysis of the alternatives debug output....
[Re: 32 bit qemu regression from v6.5 tip pull [6c480f222128 x86/alternative: Rewrite optimize_nops() some]] On 29/11/2023 (Wed 09:57) Thomas Gleixner wrote:
[...]
> > Paul, was this regression ever solved? I wonder as I could not find
> > anything with a "Fixes: 6c480f222128 [...]" tag on lore and this thread
> > looks stalled.
>
> Hmm. I was waiting for the .config file to materialize and for an
> eventual analysis of the alternatives debug output....
Sorry - was off for a week vacation, and was playing catch-up on my
return and 32 bit non-KVM qemu wasn't top on my priority list.
Then I did a batch of runs to get a fail, but without also booting with
"ignore-loglevel" - since the lines are debug and don't show on the
crashed console by default - start over! :(
The config file and both "good" and "bad" files are there now:
https://bugzilla.yoctoproject.org/show_bug.cgi?id=15230
There are a lot more debug lines in the good/working output!
$ grep alternatives: dmesg-debug-alt-good.txt | wc -l
4868
$ grep alternatives: dmesg-debug-alt.txt | wc -l
19
Paul
--
On Wed, Dec 06 2023 at 10:46, Paul Gortmaker wrote:
> The config file and both "good" and "bad" files are there now:
>
> https://bugzilla.yoctoproject.org/show_bug.cgi?id=15230
>
> There are a lot more debug lines in the good/working output!
>
> $ grep alternatives: dmesg-debug-alt-good.txt | wc -l
> 4868
> $ grep alternatives: dmesg-debug-alt.txt | wc -l
> 19
Unsurprisingly so. The failing one dies right at the start of
alternative patching....
[Re: 32 bit qemu regression from v6.5 tip pull [6c480f222128 x86/alternative: Rewrite optimize_nops() some]] On 07/12/2023 (Thu 17:34) Thomas Gleixner wrote:
> On Wed, Dec 06 2023 at 10:46, Paul Gortmaker wrote:
> > The config file and both "good" and "bad" files are there now:
> >
> > https://bugzilla.yoctoproject.org/show_bug.cgi?id=15230
> >
> > There are a lot more debug lines in the good/working output!
> >
> > $ grep alternatives: dmesg-debug-alt-good.txt | wc -l
> > 4868
> > $ grep alternatives: dmesg-debug-alt.txt | wc -l
> > 19
>
> Unsurprisingly so. The failing one dies right at the start of
> alternative patching....
I'm still set up to where I can pick a version of your choice, add a
debug patch or whatever, and let it run the 200 odd boots it takes
before it fails once. And I'll try and be more prompt this time!