Bug 14522

Created attachment 4823 [details]
qemu runner log

Intermittent issue; Link to prior discussion from several months ago:
https://lists.openembedded.org/g/openembedded-core/topic/82609331#151329

So, I was looking at this some, and the qemu-ppc is using machine=mac99 which in turn has the ancient m68k-era zilog UART (escc).

With a bit of muddling around, I could get a "kinda-reproducer" - and when it happens, I'd also see 100k+ of IRQ events in /proc/interrupts.

After looking at the old driver, and all of its console warts, I thought - why are we using this thing when nobody else is?   We don't care about being faithful to a y2k era platform - we just want a virtual ppc for validation purposes.   So lets "install" a normal 16550 pci card that uses the driver the rest of the world uses...

        -device pci-serial,chardev=char0 \
        -chardev stdio,mux=on,id=char0 \
        -mon chardev=char0,mode=readline \
        -serial chardev:char0 \
        -serial null \
        -serial chardev:char0 \

I mux the ttyPZ0 and the 16550 so we get both the open firmware/ early boot messages and the linux kernel console/ttyS0 msgs all end up on stdio.

The pci-serial (and 2 and 4 port variants) are built into qemu by default. 

Then rebuild the kernel with 8250 console on, and disable:
CONFIG_SERIAL_PMACZILOG_TTYS and CONFIG_SERIAL_PMACZILOG_CONSOLE -- thinking, I'm done, problem solved, right?  

[    2.021157] Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled
[    2.029666] printk: console [ttyS0] disabled
[    2.032591] 0000:00:11.0: ttyS0 at I/O 0x1100 (irq = 28, base_baud = 115200) is a 16550A
[    2.035149] printk: console [ttyS0] enabled
[    2.035974] printk: bootconsole [udbg0] disabled
              [....]
[    2.486214] 0.00013020:ch-a: ttyPZ0 at MMIO 0x80013020 (irq = 37, base_baud = 230400) is a Z85c30 ESCC - Serial port
[    2.489387] 0.00013000:ch-b: ttyPZ1 at MMIO 0x80013000 (irq = 36, base_baud = 230400) is a Z85c30 ESCC - Serial port
              [....]
[    6.375338] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    6.387968] ehci-pci: EHCI PCI platform driver
[    6.398118] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[    6.408105] ohci-pci: OHCI PCI platform driver
[    6.420002] ohci-pci 0000:00:0d.0: OHCI PCI host controller
[    6.432071] ohci-pci 0000:00:0d.0: new USB bus registered, assigned bus number 1
[    7.038468] irq 28: nobody cared (try booting with the "irqpoll" option)
[    7.051941] CPU: 0 PID: 1 Comm: swapper Not tainted 5.13.9-yocto-standard #1
[    7.064397] Call Trace:
[    7.075573] [e1005f10] [c00b791c] __report_bad_irq+0x50/0x138 (unreliable)

root@qemuppc:~# cat /proc/interrupts
           CPU0
 16:          0   MPIC 1     13 Level     ide0
 18:          0   MPIC 1     14 Level     ide1
 25:        356   MPIC 1     25 Edge      ADB
 27:         11   MPIC 1     27 Level     virtio1
 28:     100545   MPIC 1     28 Level     ohci_hcd:usb1, ttyS0

The fact that I see nearly the same thing with an entirely different linux driver swapped in makes me pretty sure that qemu is doing something kooky with its MPIC emulation that generates a 100k bogus irq storm.  I guess that is good news?  Definitely new news.

The bad news -- Having dabbled in building qemu from source (yay submodules!) for a prior Yocto cgroup/LTP issue, I'm not entirely convinced I want to volunteer to undertake bisecting qemu...

In case it wasn't obvious - I didn't leave the ohci boot messages in by accident - the at boot USB detection (and presumably irq request?) is the last msgs we see before "nobody cared" gets spit out.  That, and seeing the IRQ line is shared by ttyS0 is probably not a coincidence...

I should document a few more things in case anyone wants to chase this further ; at the moment I'm thinking our time would be better spent moving from mac99 to e500 or similar.

That said, and aside for the moment - here is what I learned before I forget.

Reproducer.  I could reliably get the "nobody cared" message to appear by triggering a MPIC IRQ event from the serial console coincidentally with a request_irq for registering an MPIC IRQ handler.

Start by removing console=ttyS1 from the qemu append, and disabling S0 and S1 (getty) from trying to run on serial port(s) at boot - you need to control when userspace reads/writes there, and one console device (ttyS0) is enough to do the job w/o complicating things.

The easiest way to get the sync'd irq events to simply add this:

pr_info(PMACZILOG_NAME"%d takes irq %d\n", uap->port.line, uap->port.irq);

to the bottom of pmz_startup().

Then boot up the target, ssh in and "cat /proc/interrupts" ; you should see about 1k interrupts for ttyS0 (from printing bootup messages) and no entry for ttyS1 because it hasn't been opened yet for use (and hence hasn't allocated an IRQ).  Confirm "dmesg" is clean still at this point, with no unexpected messages and none of the "nobody cared" backtrace.

Now, from the same ssh pty, simply run:

cat /dev/ttyS1 &

Then check /proc/interrupts and you should see the 100k IRQ_NONE events that linux allows as detected but unhandled before declaring "nobody cares".  And dmesg will show the characteristic nobody cares backtrace as well.

When you open ttyS1 (or ttyPMZ1 if you've not "cheated" with CONFIG_SERIAL_PMACZILOG_TTYS option) the uart_open will eventually call pmz_setup which does the request_irq (for 36/ttyS1) which causes an IRQ event on 37/ttyS0.

How confident am I that this is the same as the intermittent test instance(s)?  Probably 80-90%.   The variability in the automated tests arises from the randomness of when the getty runs, which opens the port, which causes the pmz driver to alloc the interrupt.  If things are "quiet" and the console isn't being printed to, then the request_irq doesn't happen in parallel with a console UART IRQ event.

How Yocto specific is this?   Seemingly none.  I was able to go back to a v3.10 vanilla mainline kernel - which required an older gcc-4.8 (non yocto) to get there and I also used the Ubuntu qemu powerpc image:

build-qemuppc$qemu-system-ppc --version
QEMU emulator version 2.11.1(Debian 1:2.11+dfsg-1ubuntu7.37)

..which really only left me using the yocto rootfs (which I also had to downgrade to ext2 to avoid unsupported ext4 features).  So it would also appear (assuming my reproducer is valid) that this issue existed for a long time ; perhaps since day one.

Note that all of the above is also generally consistent with the USB subsystem doing a request_irq for when I was testing with the "normal" 16550 UART and not pmz -- as we saw those two even ended up sharing an IRQ.

Not being able to say "this is a regression which started exactly at <something>" was pretty much the point where I figured further time spent on mac99 would be better served spent on updating our qemu-ppc virtual machine.

For tracking purposes, happened again https://autobuilder.yoctoproject.org/typhoon/#/builders/63/builds/3906

(info above is really useful, thanks Paul)

Again, for tracking frequency https://autobuilder.yoctoproject.org/typhoon/#/builders/63/builds/3938/steps/19/logs/stdio

https://autobuilder.yoctoproject.org/typhoon/#/builders/63/builds/3769/steps/18/logs/stdio

https://autobuilder.yoctoproject.org/typhoon/#/builders/63/builds/3983/steps/19/logs/stdio

[   15.888050] irq 36: nobody cared (try booting with the "irqpoll" option)

While looking at cleaning up the old qemu ppc32 BSP dir to make way for e500 or newer, I stumbled across this:

https://git.yoctoproject.org/cgit/cgit.cgi/yocto-kernel-cache/tree/bsp/qemu-ppc32/qemu-powerpc-work-around-for-qemu-powerpc-32-interru.patch?h=yocto-3.10

Given the nature of this issue, and seeing a "qemu interrupt workaround" patch, how can you not be intrigued?

Anyway - while I go down that rabbit hole, I had another thought.

If my description/theory from a couple months ago is correct, we can kick the can down the road a bit so it doesn't savage the AB once a week with sporadic autotest fails.  Maybe with one or two simple changes.

1) ensure the test image doesn't have an inittab entry for getty on ttyS1

2) remove the 2nd serial option from the BSP runqemu template.

The idea is that if we are hands-off on the 2nd serial port (which we don't really need/use anyway) then we aren't touching the grenade pin.

I chased down an old 3.10 tree with the interrupt patch already applied (and others we carried back then) - enabled the new CONFIG_PPC_QEMU that tree has, and it still fails my printk+cat test detailed above.  So either that isn't related, or the patch had already done a bitrot death march from 2.6.x ---> 3.10 and was ineffective already.

As you rewind back beyond 3.10 and get to v3.8 the virtio is gone.  But you can get around that with replacing virtio-net-pci with pcnet (lance driver is already built in) and replace "-drive .... if=virtio ..." with "-drive .... if=ide ..." and change root=/dev/hda accordingly (in your copy of the runqemu args that you turned into a script when you started).

With careful use of "make oldconfig" as you walk back in time, you can get to v3.2 but then you hit a wall.  The glibc has a minimum kernel version and trying to boot anything older gets "FATAL: kernel too old".

The 3.2 fails with the same one line printk of the irq and opening the device with a simple "cat" as can be seen here:

root@qemuppc:~# cat /proc/interrupts
           CPU0
 16:       2376   MPIC 1    Level     ide0
 18:          0   MPIC 1    Level     ide1
 25:        356   MPIC 1    Edge      ADB
 28:         34   MPIC 1    Level     ohci_hcd:usb1
 30:         96   MPIC 1    Level     eth0
 37:       1477   MPIC 1    Level     SCC
LOC:       8589   Local timer interrupts
SPU:          0   Spurious interrupts
CNT:          0   Performance monitoring interrupts
MCE:          0   Machine check exceptions
root@qemuppc:~# cat /proc/version
Linux version 3.2.0-dirty (paul@sc2600cp) (gcc version 4.8.0 (GCC) ) #1 PREEMPT Fri Oct 15 09:49:12 EDT 2021
root@qemuppc:~# cat /dev/ttyPZ1 &
[1] 617
root@qemuppc:~# cat /proc/interrupts
           CPU0
 16:       2394   MPIC 1    Level     ide0
 18:          0   MPIC 1    Level     ide1
 25:        356   MPIC 1    Edge      ADB
 28:         34   MPIC 1    Level     ohci_hcd:usb1
 30:        221   MPIC 1    Level     eth0
 36:     100001   MPIC 1    Level     SCC
 37:       1477   MPIC 1    Level     SCC
LOC:      15558   Local timer interrupts
SPU:          0   Spurious interrupts
CNT:          0   Performance monitoring interrupts
MCE:          0   Machine check exceptions
root@qemuppc:~#

root@qemuppc:~# dmesg|grep irq
[    0.000000] NR_IRQS:512 nr_irqs:512 16
[    0.991021] ttyPZ0 at MMIO 0x80013020 (irq = 37) is a Z85c30 ESCC - Serial port
[    0.991821] ttyPZ1 at MMIO 0x80013000 (irq = 36) is a Z85c30 ESCC - Serial port
[    2.034993] ide-pmac: Found Apple KeyLargo ATA-3 controller (macio), bus ID 0, irq 16
[    3.026655] ide0 at 0xe1014000-0xe1014070,0xe1014160 on irq 16
[    4.050834] ide-pmac: Found Apple KeyLargo ATA-3 controller (macio), bus ID 1, irq 18
[    5.147544] ide1 at 0xe1016000-0xe1016070,0xe1016160 on irq 18
[    5.282963] ohci_hcd 0000:00:0d.0: irq 28, io mem 0x80080000
[    5.579835] pmz takes irq 37
[    5.791971] pmz takes irq 37
[    5.818933] pmz takes irq 37
[    5.823532] pmz takes irq 37
[    5.826942] pmz takes irq 37
[    5.857459] pmz takes irq 37
[   58.538992] pmz takes irq 36
[   58.937851] irq 36: nobody cared (try booting with the "irqpoll" option)
[   58.939259] [dfff7f20] [c0094f28] __report_bad_irq.isra.5+0x44/0x11c
[   58.939823] [dfff7f70] [c0092cf4] handle_irq_event_percpu+0x140/0x28c
[   58.940102] [dfff7fc0] [c0092ea4] handle_irq_event+0x64/0xa0
[   58.940396] [dfff7fe0] [c00960bc] handle_fasteoi_irq+0x94/0x180
[   58.940709] [dfff7ff0] [c0012268] call_handle_irq+0x18/0x28
root@qemuppc:~#

Yes, I know there is a way to configure glibc for older crap:

OLDEST_KERNEL = "2.6.32"

...and while the docs only suggest it has been tested on x86 - I tried and managed to beat a core-image-full-cmdline build into submission with that but at booting a 3.0 kernel I still got "FATAL: kernel too old".

Anyway, if one was more stubborn than me and was wanting to beat this dead horse back in history beyond v3.2 looking for "when did this work?" --- then it would probably be easier to track down an old prebuilt rootfs.

But I'm thinking I'm done with this "fix mac99" rabbit hole.

We should do the "hands off ttyS1" workaround I detailed above ASAP, since I'm not sure when I can find time to look at moving this to e500 or newer.

I'll see if Paul's suggestions in:
   https://bugzilla.yoctoproject.org/show_bug.cgi?id=14522#c10
help.

https://autobuilder.yoctoproject.org/typhoon/#/builders/63/builds/4210/steps/19/logs/stdio

Reoccurrence in autobuilder 
https://autobuilder.yoctoproject.org/typhoon/#/builders/63/builds/4904

Sakib, we need to talk with Paul about this one.

Occurred on the dunfell 3.1.20 build:

 https://autobuilder.yoctoproject.org/typhoon/#/builders/63/builds/5930/steps/19/logs/stdio

https://autobuilder.yoctoproject.org/typhoon/#/builders/63/builds/6069/steps/19/logs/stdio

qemuppc opensuse154-ty-3

irq handler in qemuppc is not ideal. With lower load it's unlikley to happen again.

Happened again :(

https://autobuilder.yoctoproject.org/typhoon/#/builders/63/builds/6610/steps/19/logs/stdio

qemuppc on opensuse154-ty-3

looking closer, it looks like 14401