Re: QEMU hangs with smp option on ubuntu 16.04 ... any fix?

So I tried to rebuild kernel with debian kernel source and debian kernel config, except that I added CONFIG_MIPS_MT_SMP, which in turn turns on CONFIG_SMP.

This new kernel boots all the way to user land and I could see CPU1 is brought up. However, it crashes early after it enters userland. It gives some cryptic error messages. See some of them below.

Did I do anything wrongly? Would appreciate any pointers.

Jun

==================

ubuntu@ip-10-1-3-178:~/mipseb$ ./start-mipseb.sh

[ 0.000000] Linux version 4.9.0-7-4kc-malta-rt76 (ubuntu@ip-10-1-3-178) (gcc version 5.4.0 20160609 (Ubuntu 5.4.0-6ubuntu1~16.04.9) ) #9 SMP Sun Oct 7 15:54:10 UTC 2018

[ 0.000000] earlycon: uart8250 at I/O port 0x3f8 (options '38400n8')

[ 0.000000] bootconsole [uart8250] enabled

[ 0.000000] MIPS CPS SMP unable to proceed without a CM

[ 0.000000] CPU0 revision is: 00019500 (MIPS 34Kc)

[ 0.000000] FPU revision is: 00739500

[ 0.000000] MIPS: machine is mti,malta

[ 0.000000] Software DMA cache coherency enabled

[ 0.000000] Determined physical RAM map:

[ 0.000000] memory: 10000000 @ 00000000 (usable)

[ 0.000000] memory: 21fff000 @ 90000000 (usable)

[ 0.000000] Initial ramdisk at: 0x80af0000 (19033219 bytes)

[ 0.000000] Reserving 0MB of memory at 0MB for crashkernel

[ 0.000000] Detected 1 available secondary CPU(s)

[ 0.000000] Primary instruction cache 2kB, VIPT, 2-way, linesize 16 bytes.

[ 0.000000] Primary data cache 2kB, 2-way, VIPT, no aliases, linesize 16 bytes

[ 0.000000] Zone ranges:

[ 0.000000] DMA [mem 0x0000000000000000-0x0000000000ffffff]

[ 0.000000] Normal [mem 0x0000000001000000-0x000000000fffffff]

[ 0.000000] Movable zone start for each node

[ 0.000000] Early memory node ranges

[ 0.000000] node 0: [mem 0x0000000000000000-0x000000000fffffff]

[ 0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x000000000fffffff]

[ 0.000000] percpu: Embedded 15 pages/cpu @81f5d000 s32208 r8192 d21040 u61440

[ 0.000000] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 64960

[ 0.000000] Kernel command line: rd_start=0xffffffff80af0000 rd_size=19033219 root=/dev/sda1 console=ttyS0 nokaslr

[ 0.000000] PID hash table entries: 1024 (order: 0, 4096 bytes)

[ 0.000000] Dentry cache hash table entries: 32768 (order: 5, 131072 bytes)

[ 0.000000] Inode-cache hash table entries: 16384 (order: 4, 65536 bytes)

[ 0.000000] Writing ErrCtl register=00000000

[ 0.000000] Readback ErrCtl register=00000000

[ 0.000000] Memory: 229708K/262144K available (6445K kernel code, 574K rwdata, 1348K rodata, 1480K init, 302K bss, 32436K reserved, 0K cma-reserved)

[ 0.000000] Hierarchical RCU implementation.

[ 0.000000] Build-time adjustment of leaf fanout to 32.

[ 0.000000] NR_IRQS:256

[ 0.000000] CPU frequency 200.00 MHz

[ 0.000000] clocksource: MIPS: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112674795 ns

[ 0.000174] sched_clock: 32 bits at 99MHz, resolution 10ns, wraps every 21474915322ns

[ 0.009984] Console: colour dummy device 80x25

[ 0.011080] Calibrating delay loop... 1142.78 BogoMIPS (lpj=2285568)

[ 0.034914] pid_max: default: 32768 minimum: 301

[ 0.036331] Security Framework initialized

[ 0.036630] Yama: disabled by default; enable with sysctl kernel.yama.*

[ 0.037709] AppArmor: AppArmor disabled by boot time parameter

[ 0.039095] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)

[ 0.039549] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)

[ 0.051724] ftrace: allocating 19328 entries in 38 pages

[ 0.119358] Performance counters: No available PMU.

[ 0.139167] Primary instruction cache 2kB, VIPT, 2-way, linesize 16 bytes.

[ 0.139240] Primary data cache 2kB, 2-way, VIPT, no aliases, linesize 16 bytes

[ 0.142776] CPU1 revision is: 00019500 (MIPS 34Kc)

[ 0.142795] FPU revision is: 00739500

[ 3.388816] Synchronize counters for CPU 1:

[ 3.388834] done.

[ 3.391435] Brought up 2 CPUs

[ 3.441632] devtmpfs: initialized

[ 3.484928] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns

[ 3.485834] futex hash table entries: 512 (order: 3, 32768 bytes)

[ 3.539332] NET: Registered protocol family 16

[ 3.557040] pm-cps: no CM, non-coherent states unavailable

[ 4.943802] vgaarb: loaded

[ 4.945261] SCSI subsystem initialized

[ 4.947839] PCI host bridge to bus 0000:00

[ 4.948526] pci_bus 0000:00: root bus resource [mem 0x10000000-0x17ffffff]

[ 4.948991] pci_bus 0000:00: root bus resource [io 0x1000-0x1fffff]

[ 4.949558] pci_bus 0000:00: root bus resource [??? 0x00000000 flags 0x0]

[ 4.950012] pci_bus 0000:00: No busn resource found for root bus, will use [bus 00-ff]

[ 4.951733] pci 0000:00:00.0: [Firmware Bug]: reg 0x14: invalid BAR (can't size)

[ 4.952198] pci 0000:00:00.0: [Firmware Bug]: reg 0x18: invalid BAR (can't size)

[ 4.952636] pci 0000:00:00.0: [Firmware Bug]: reg 0x1c: invalid BAR (can't size)

[ 4.953074] pci 0000:00:00.0: [Firmware Bug]: reg 0x20: invalid BAR (can't size)

[ 4.953530] pci 0000:00:00.0: [Firmware Bug]: reg 0x24: invalid BAR (can't size)

[ 4.956039] pci 0000:00:0a.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7]

[ 4.956495] pci 0000:00:0a.1: legacy IDE quirk: reg 0x14: [io 0x03f6]

[ 4.956903] pci 0000:00:0a.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177]

[ 4.957337] pci 0000:00:0a.1: legacy IDE quirk: reg 0x1c: [io 0x0376]

[ 4.959035] pci 0000:00:0a.3: quirk: [io 0x1000-0x103f] claimed by PIIX4 ACPI

[ 4.959507] pci 0000:00:0a.3: quirk: [io 0x1100-0x110f] claimed by PIIX4 SMB

[ 4.961180] vgaarb: device added: PCI:0000:00:12.0,decodes=io+mem,owns=none,locks=none

[ 4.962671] pci 0000:00:12.0: BAR 0: assigned [mem 0x10000000-0x11ffffff pref]

[ 4.963235] pci 0000:00:0b.0: BAR 6: assigned [mem 0x12000000-0x1203ffff pref]

[ 4.963693] pci 0000:00:12.0: BAR 6: assigned [mem 0x12040000-0x1204ffff pref]

[ 4.964147] pci 0000:00:12.0: BAR 1: assigned [mem 0x12050000-0x12050fff]

[ 4.964587] pci 0000:00:0a.2: BAR 4: assigned [io 0x1040-0x105f]

[ 4.964964] pci 0000:00:0b.0: BAR 0: assigned [io 0x1060-0x107f]

[ 4.965335] pci 0000:00:0b.0: BAR 1: assigned [mem 0x12051000-0x1205101f]

[ 4.965743] pci 0000:00:0a.1: BAR 4: assigned [io 0x1080-0x108f]

[ 16.002004] clocksource: Switched to clocksource MIPS

[ 17.511363] VFS: Disk quotas dquot_6.6.0

[ 18.010327] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)

[ 18.020783] random: fast init done

[ 20.044699] NET: Registered protocol family 2

[ 21.544726] TCP established hash table entries: 2048 (order: 1, 8192 bytes)

[ 21.545391] TCP bind hash table entries: 2048 (order: 2, 16384 bytes)

[ 21.545894] TCP: Hash tables configured (established 2048 bind 2048)

[ 21.546944] UDP hash table entries: 256 (order: 1, 8192 bytes)

[ 21.547382] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes)

[ 22.043069] NET: Registered protocol family 1

[ 22.044032] PCI: Enabling device 0000:00:0a.2 (0000 -> 0001)

[ 22.049627] Unpacking initramfs...

[ 23.318000] Freeing initrd memory: 18584K

[ 24.820672] audit: initializing netlink subsys (disabled)

[ 24.821840] audit: type=2000 audit(1538945938.020:1): initialized

[ 24.826730] workingset: timestamp_bits=14 max_order=16 bucket_order=2

[ 24.828367] zbud: loaded

[ 26.426847] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 251)

[ 26.428457] io scheduler noop registered

[ 26.428881] io scheduler deadline registered

[ 27.425910] io scheduler cfq registered (default)

[ 27.427252] PCI: Enabling device 0000:00:12.0 (0000 -> 0002)

[ 27.429071] cirrusfb 0000:00:12.0: Cirrus Logic chipset on PCI bus, RAM (4096 kB) at 0x10000000

[ 27.666740] Console: switching to colour frame buffer device 80x30

[ 27.688486] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled

[ 27.695375] console [ttyS0] disabled

[ 27.720304] serial8250.0: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A

[ 27.721708] console [ttyS0] enabled

[ 27.722687] bootconsole [uart8250] disabled

[ 27.747064] serial8250.0: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A

[ 27.751639] mousedev: PS/2 mouse device common for all mice

[ 27.754282] rtc_cmos 70.rtc: rtc core: registered rtc_cmos as rtc0

[ 27.755165] rtc_cmos 70.rtc: alarms up to one day, 242 bytes nvram

[ 27.756946] ledtrig-cpu: registered to indicate activity on CPUs

[ 29.497742] NET: Registered protocol family 10

[ 30.497515] mip6: Mobile IPv6

[ 30.497841] NET: Registered protocol family 17

[ 30.498219] mpls_gso: MPLS GSO support

[ 30.500361] registered taskstats version 1

[ 30.501270] zswap: loaded using pool lzo/zbud

[ 30.503611] ima: No TPM chip found, activating TPM-bypass!

[ 30.504203] ima: Allocated hash algorithm: sha256

[ 30.996619] rtc_cmos 70.rtc: setting system clock to 2018-10-07 20:59:23 UTC (1538945963)

[ 31.022045] Freeing unused kernel memory: 1480K

[ 31.022366] This architecture does not have kernel memory protection.

Loading, please wait...

[ 3.889843] INFO: rcu_sched self-detected stall on CPU

[ 3.890535] 0-...: (2 ticks this GP) idle=385/2/0 softirq=0/0 fqs=0

[ 3.891233] (t=5353 jiffies g=-299 c=-300 q=2017)

[ 3.891755] rcu_sched kthread starved for 5353 jiffies! g4294966997 c4294966996 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1

[ 3.892941] rcu_sched S 0 7 2 0x00100000

[ 3.893553] Stack : 81f642c0 8fca8280 8fcfc900 8fcfd1c0 8fcfc900 807562b4 80741f44 81f642c0

[ 3.894325] 81f642f8 8099d2c0 808b1220 808b0000 81f642f8 00040900 8fcfc900 8fcffdf4

[ 3.895234] 81f5f680 808b0000 81f5f680 808b0000 00000000 ffffffff 00000000 80741f44

[ 3.895989] 8fcffdf4 809a0000 808b0000 fffee4ed fffee4ed 807454f8 8fcffe98 808b0000

[ 3.896724] 808c2650 801921c4 00000001 81f5f680 00000001 00000000 81f5f930 fffee4ed

[ 3.897360] ...

[ 3.897850] Call Trace:

[ 3.898314] [<80741a78>] __schedule+0x62c/0xaa8

[ 3.898835] [<80741f44>] schedule+0x50/0xf0

[ 3.899135] [<807454f8>] schedule_timeout+0x1ec/0x484

[ 3.899493] [<801c1580>] rcu_gp_kthread+0x5bc/0xa90

[ 3.899840] [<80161a74>] kthread+0xfc/0x114

[ 3.900139] [<80106a58>] ret_from_kernel_thread+0x14/0x1c

[ 3.900774] Task dump for CPU 0:

[ 3.901018] swapper/0 R running task 0 0 0 0x00100004

[ 3.901530] Stack : 80aa9410 00000000 80ab0000 801ac6b8 00000000 00000000 80ab0000 801ac6b8

[ 3.902139] 0000001d 00000006 00000006 00000000 00000000 00000000 0000000a 00000000

[ 3.902790] 00000000 80aa9412 0000001d 80aa9878 808b0000 808c24c0 808b0000 808b0808

[ 3.903508] 00000140 808b0000 00000000 00000000 00000000 00000000 00000000 00000000

[ 3.904194] 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000

[ 3.904857] ...

[ 3.905052] Call Trace:

[ 3.905251] [<8010d8d0>] show_stack+0xa0/0xc4

[ 3.905595] [<8027c2e4>] rcu_dump_cpu_stacks+0xe8/0x128

[ 3.905971] [<801c274c>] rcu_check_callbacks+0x854/0xa20

[ 3.906344] [<801ca378>] update_process_times+0x4c/0x80

[ 3.906946] [<801e1928>] tick_sched_handle.isra.4+0x34/0x94

[ 3.907390] [<801e19f8>] tick_sched_timer+0x70/0xdc

[ 3.907782] [<801cb9b4>] __hrtimer_run_queues+0x144/0x3d8

[ 3.908173] [<801cc6cc>] hrtimer_interrupt+0x118/0x338

[ 3.908543] [<80112580>] c0_compare_interrupt+0x8c/0xe4

[ 3.908920] [<801aee0c>] __handle_irq_event_percpu+0x8c/0x2a0

[ 3.909330] [<801af078>] handle_irq_event_percpu+0x58/0xbc

[ 3.909723] [<801b4820>] handle_percpu_irq+0x98/0xc8

[ 3.910083] [<801ae100>] generic_handle_irq+0x50/0x6c

[ 3.910459] [<80747e48>] do_IRQ+0x28/0x34

[ 3.910771] [<804a3800>] plat_irq_dispatch+0x64/0xb8

[ 3.911133] [<80106f68>] except_vec_vi_end+0xb8/0xc4

[ 3.911531] Task dump for CPU 1:

[ 3.911761] init R running task 0 68 1 0x08100020

[ 3.912254] Stack : 808e0000 8082745c 8ca86300 80367030 00002017 802b8e60 80aa0000 802f79a4

[ 3.912898] 8fd51022 00000000 8ca86302 2f62696e 2f736800 00000000 00000010 8cb05e80

[ 3.913537] 808b0000 00000000 00000000 00040900 00000e51 00000000 7ffffe51 564ac4ac

[ 3.914176] 8ca86300 00000000 8cad8180 00040900 8cb02600 808b0000 00000044 00000044

[ 3.914904] 564ac4e4 8fd51000 8ca86300 00000000 8ca86300 80400a7c 564ac4ac 803005a0

[ 3.915595] ...

[ 3.915786] Call Trace:

[ 3.915980] [<80741a78>] __schedule+0x62c/0xaa8

starting version 232

[ 46.611678] random: systemd-udevd: uninitialized urandom read (16 bytes read)

[ 46.618684] random: systemd-udevd: uninitialized urandom read (16 bytes read)

[ 46.701579] random: udevadm: uninitialized urandom read (16 bytes read)

Begin: Loading essential drivers ... done.

Begin: Running /scripts/init-premount ... done.

Begin: Mounting root file system ... Begin: Running /scripts/local-top ... done.

Begin: Running /scripts/local-premount ... Begin: Waiting for suspend/resume device ... [ 9.552903] INFO: rcu_sched self-detected stall on CPU

[ 9.553683] 1-...: (3 ticks this GP) idle=391/140000000000001/0 softirq=0/0 fqs=0

[ 9.554157] (t=10615 jiffies g=-290 c=-291 q=2422)

[ 9.554600] rcu_sched kthread starved for 10615 jiffies! g4294967006 c4294967005 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1

[ 9.561916] rcu_sched S 0 7 2 0x00100000

[ 9.562364] Stack : 81f642c0 8fca8280 8fcfc900 8fcfd1c0 8fcfc900 8fcffdf4 808b0000 8fcffdf4

[ 9.563023] 808b0000 8ca24400 81f6e680 808b0000 8fcffdf4 801c6ef8 8fcfc900 8fcffdf4

[ 9.563344] 81f6e680 808b0000 81f6e680 808b0000 00000000 ffffffff 00000001 80741f44

[ 9.563627] 8fcffdf4 809a0000 808b0000 fffeffd9 fffeffd9 807454f8 8fcffe98 808b0000

[ 9.563956] 808c2650 801921c4 00000001 81f6e680 00000001 00000000 81f6e748 fffeffd9

[ 9.564258] ...

[ 9.564426] Call Trace:

[ 9.564997] [<80741a78>] __schedule+0x62c/0xaa8

[ 9.565428] [<80741f44>] schedule+0x50/0xf0

[ 9.565558] [<807454f8>] schedule_timeout+0x1ec/0x484

[ 9.565741] [<801c1580>] rcu_gp_kthread+0x5bc/0xa90

[ 9.565900] [<80161a74>] kthread+0xfc/0x114

[ 9.566035] [<80106a58>] ret_from_kernel_thread+0x14/0x1c

[ 9.566478] Task dump for CPU 0:

[ 9.566603] swapper/0 R running task 0 0 0 0x00100000

[ 9.566828] Stack : 00000008 801e1874 808c21e4 81f5f618 808c2734 00000000 00000000 00000000

[ 9.567327] 00000002 ffffffe3 81f5d200 00000000 00000008 081b3200 00000008 c71dc863

[ 9.567862] 7fffffff ffffffff 80812ae8 00040900 808b0804 00000001 808b0000 80920000

[ 9.568331] 80812ae8 80920000 00000001 00000000 00000000 801e1c58 808b0804 00000001

[ 9.568751] 808b0000 80920000 808b0804 80192c4c 808b0000 80742390 00000000 00000000

[ 9.569239] ...

[ 9.569351] Call Trace:

[ 9.569509] [<80741a78>] __schedule+0x62c/0xaa8

[ 9.569758] Task dump for CPU 1:

[ 9.575233] cat R running task 0 93 88 0x08110004

[ 9.575695] Stack : 80aa9410 00000000 80ab0000 801ac6b8 00000000 00000000 80ab0000 801ac6b8

[ 9.576222] 0000001d 00000006 00000006 8fcfc900 00000000 00000000 0000000a 00000000

[ 9.576822] 00000000 80aa9412 0000001d 80aa9878 808b0000 808c24c0 808b0000 808b0808

[ 9.577385] 00000140 808b0000 00000000 00000000 00000000 00000000 00000000 00000000

[ 9.577911] 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000

[ 9.578434] ...

[ 9.578574] Call Trace:

[ 9.578734] [<8010d8d0>] show_stack+0xa0/0xc4

[ 9.579025] [<8027c2e4>] rcu_dump_cpu_stacks+0xe8/0x128

[ 9.579491] [<801c274c>] rcu_check_callbacks+0x854/0xa20

[ 9.579936] [<801ca378>] update_process_times+0x4c/0x80

[ 9.580254] [<801e1928>] tick_sched_handle.isra.4+0x34/0x94

[ 9.580587] [<801e19f8>] tick_sched_timer+0x70/0xdc

[ 9.580944] [<801cb9b4>] __hrtimer_run_queues+0x144/0x3d8

[ 9.581275] [<801cc6cc>] hrtimer_interrupt+0x118/0x338

[ 9.581582] [<80112580>] c0_compare_interrupt+0x8c/0xe4

[ 9.582524] [<801aee0c>] __handle_irq_event_percpu+0x8c/0x2a0

[ 9.582939] [<801af078>] handle_irq_event_percpu+0x58/0xbc

[ 9.583705] [<801b4820>] handle_percpu_irq+0x98/0xc8

[ 9.584026] [<801ae100>] generic_handle_irq+0x50/0x6c

[ 9.584392] [<80747e48>] do_IRQ+0x28/0x34

[ 9.585228] [<804a3800>] plat_irq_dispatch+0x64/0xb8

[ 9.585544] [<80106f68>] except_vec_vi_end+0xb8/0xc4

[ 9.586059] [<80306d7c>] path_init+0xe4/0x3b8

[ 9.587379] [<8030ac24>] path_openat+0x94/0x111c

[ 9.587725] [<8030d114>] do_filp_open+0xf4/0x138

[ 9.588053] [<802f6fc8>] do_sys_open+0x1c0/0x27c

[ 9.589432] [<80117f98>] syscall_common+0x34/0x58

[ 52.550795] INFO: rcu_sched self-detected stall on CPU

[ 52.552049] 1-...: (7 ticks this GP) idle=391/140000000000002/0 softirq=0/0 fqs=0

[ 52.552508] (t=32101 jiffies g=-290 c=-291 q=2422)

[ 10.105092] rcu_sched kthread starved for 32101 jiffies! g4294967006 c4294967005 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x0

[ 12.124160] INFO: rcu_sched detected stalls on CPUs/tasks:

[ 13.123363] 1-...: (7 ticks this GP) idle=391/140000000000002/0 softirq=0/0 fqs=0

[ 15.121749] (detected by 0, t=32101 jiffies, g=-290, c=-291, q=2422)

[ 16.120913] Task dump for CPU 1:

[ 17.130901] cat R running task [ 19.129399] rcu_sched R

[ 20.128479] running task 0 7 2 0x00100000

Stack :

[ 23.126117] 81f642c0 8fca8280 8fcfc900 8fcfd1c0 8fcfc900 8fcffdf4 808b0000 8fcffdf4qemu-system-mips: terminating on signal 15 from pid 3927

ubuntu@ip-10-1-3-178:~/mipseb$