qemux86 shutdown timeout on ubuntu1804-ty-3 rcu stall logs


Richard Purdie
 

qemux86 didn't shutdown 120s on ubuntu1804-ty-3

https://autobuilder.yoctoproject.org/typhoon/#/builders/59/builds/4421

showed an rcu stall in the kernel logs

cat pokybuild@ubuntu1804-ty-3:~/yocto-worker/qemux86/build/build-st-48375/tmp/work/qemux86-poky-linux/core-image-minimal/1.0-r0/testimage/qemu_boot_log.20211205013910

c[?7l[2J[0mSeaBIOS (version rel-1.14.0-0-g155821a1990b-prebuilt.qemu.org)


iPXE (http://ipxe.org) 00:02.0 CA00 PCI2.10 PnP PMM+0FF86E80+0FEE6E80 CA00
Press Ctrl-B to configure iPXE (PCI 00:02.0)...^M


Booting from ROM...
c[?7l[2J[ 0.000000] Linux version 5.14.18-yocto-standard (oe-user@oe-host) (i686-poky-linux-gcc (GCC) 11.2.0, GNU ld (GNU Binutils) 2.37.20210721) #1 SMP PREEMPT Tue Nov 16 03:53:43 UTC 2021
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
[ 0.000000] x86/fpu: Enabled xstate features 0x3, context size is 576 bytes, using 'standard' format.
[ 0.000000] signal: max sigframe size: 1504
[ 0.000000] BIOS-provided physical RAM map:
[ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
[ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
[ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
[ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000000ffd7fff] usable
[ 0.000000] BIOS-e820: [mem 0x000000000ffd8000-0x000000000fffffff] reserved
[ 0.000000] BIOS-e820: [mem 0x00000000b0000000-0x00000000bfffffff] reserved
[ 0.000000] BIOS-e820: [mem 0x00000000fed1c000-0x00000000fed1ffff] reserved
[ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
[ 0.000000] Notice: NX (Execute Disable) protection cannot be enabled: non-PAE kernel!
[ 0.000000] user-defined physical RAM map:
[ 0.000000] user: [mem 0x0000000000000000-0x000000000009fbff] usable
[....]
[ 2.491515] scsi 2:0:0:0: CD-ROM QEMU QEMU DVD-ROM 2.5+ PQ: 0 ANSI: 5
[ 2.517660] sr 2:0:0:0: [sr0] scsi3-mmc drive: 4x/4x cd/rw xa/form2 tray
[ 2.518434] cdrom: Uniform CD-ROM driver Revision: 3.20
[ 2.569165] input: QEMU QEMU USB Tablet as /devices/pci0000:00/0000:00:1d.7/usb1/1-1/1-1:1.0/0003:0627:0001.0001/input/input4
[ 2.571240] hid-generic 0003:0627:0001.0001: input: USB HID v0.01 Mouse [QEMU QEMU USB Tablet] on usb-0000:00:1d.7-1/input0
[ 2.638291] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input3
[ 2.714786] IP-Config: Complete:
[ 2.715049] device=eth0, hwaddr=52:54:00:12:34:02, ipaddr=192.168.7.2, mask=255.255.255.0, gw=192.168.7.1
[ 2.715846] host=192.168.7.2, domain=, nis-domain=(none)
[ 2.716053] bootserver=255.255.255.255, rootserver=255.255.255.255, rootpath=
[ 2.725860] md: Waiting for all devices to be available before autodetect
[ 2.726464] md: If you don't use raid, use raid=noautodetect
[ 2.726757] md: Autodetecting RAID arrays.
[ 2.726959] md: autorun ...
[ 2.727195] md: ... autorun DONE.
[ 2.842432] EXT4-fs (vda): mounted filesystem with ordered data mode. Opts: (null). Quota mode: disabled.
[ 2.843771] VFS: Mounted root (ext4 filesystem) on device 253:0.
[ 2.846695] devtmpfs: mounted
[ 2.936371] Freeing unused kernel image (initmem) memory: 884K
[ 2.937830] Write protecting kernel text and read-only data: 15120k
[ 2.938432] Run /sbin/init as init process
^MINIT: version 3.00 booting
Starting udev
[ 4.824244] udevd[156]: starting version 3.2.10
[ 4.949028] udevd[157]: starting eudev-3.2.10
[ 6.976057] EXT4-fs (vda): re-mounted. Opts: (null). Quota mode: disabled.
[ 32.954837] hrtimer: interrupt took 5666197 ns
^MINIT: Entering runlevel: 5
Configuring network interfaces... ip: RTNETLINK answers: File exists
Starting syslogd/klogd: done

Poky (Yocto Project Reference Distro) 3.4+snapshot-22ba018eb357be2575ae346f69c7591a0bc80dde qemux86 /dev/ttyS0

^Mqemux86 login: ^MINIT: Switching to runlevel: 0
Stopping syslogd/klogd: stopped syslogd (pid 311)
stopped klogd (pid 314)
done
Deconfiguring network interfaces... ifdown: interface lo not configured
done.
Sending all processes the TERM signal...
Sending all processes the KILL signal...
Unmounting remote filesystems...
[ 141.107314] rcu: INFO: rcu_preempt self-detected stall on CPU
[ 141.108515] rcu: 0-...0: (1 GPs behind) idle=76a/1/0x40000000 softirq=1893/1894 fqs=20
[ 141.109282] (t=66396 jiffies g=3577 q=2)
[ 141.110253] NMI backtrace for cpu 0
[ 141.111179] CPU: 0 PID: 348 Comm: S38urandom Not tainted 5.14.18-yocto-standard #1
[ 141.111875] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.14.0-0-g155821a1990b-prebuilt.qemu.org 04/01/2014
[ 141.113333] Call Trace:
[ 141.114141] dump_stack_lvl+0x34/0x44
[ 141.114808] dump_stack+0xd/0x10
[ 141.115161] nmi_cpu_backtrace.cold+0x16/0x5b
[ 141.115442] ? lapic_can_unplug_cpu+0x70/0x70
[ 141.115591] nmi_trigger_cpumask_backtrace+0x97/0xc0
[ 141.115751] arch_trigger_cpumask_backtrace+0x15/0x20
[ 141.115906] rcu_dump_cpu_stacks+0x9c/0xc8
[ 141.116059] rcu_sched_clock_irq.cold+0xa9/0x3cc
[ 141.116306] ? cpuacct_account_field+0x59/0x70
[ 141.116459] ? account_user_time+0xa8/0xb0
[ 141.116598] ? account_process_tick+0xab/0x170
[ 141.116747] update_process_times+0x77/0xb0
[ 141.116915] tick_sched_timer+0xcb/0x100
[ 141.117055] __hrtimer_run_queues+0x14a/0x2c0
[ 141.117261] ? get_cpu_iowait_time_us+0x150/0x150
[ 141.117407] hrtimer_interrupt+0x113/0x2e0
[ 141.117539] ? syscall_exit_to_user_mode+0x1b/0x40
[ 141.117692] ? sysvec_call_function_single+0x30/0x30
[ 141.117846] __sysvec_apic_timer_interrupt+0x59/0x100
[ 141.117998] sysvec_apic_timer_interrupt+0x1a/0x30
[ 141.118169] handle_exception+0x133/0x133
[ 141.118462] EIP: 0x4ccf15
[ 141.118965] Code: 83 f2 01 09 d0 88 46 01 8b 45 a8 85 c0 0f 85 88 f1 ff ff c6 07 88 0f b6 1e 83 c7 01 80 fb 02 0f 85 ba f0 ff ff e9 a8 f0 ff ff <0f> b7 06 66 25 00 fb 66 0d 01 04 66 89 06 8b 46 04 85 c0 74 c9 eb
[ 141.119615] EAX: 00000004 EBX: 00000000 ECX: 004ccf15 EDX: 00000004
[ 141.119833] ESI: bfefab50 EDI: 0052f3ac EBP: bfefab88 ESP: bfefab10
[ 141.120039] DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 007b EFLAGS: 00000203
[ 141.120407] ? sysvec_call_function_single+0x30/0x30
Deactivating swap...
Unmounting local filesystems...