Re: [Qemu-devel] host stalls when qemu-system-aarch64 with kvm and pflash

[Laszlo Ersek]

On 03/29/17 20:56, Christoffer Dall wrote:
> On Tue, Mar 28, 2017 at 01:24:15PM -0700, Radha Mohan wrote:
>> On Tue, Mar 28, 2017 at 1:16 PM, Christoffer Dall <address@hidden> wrote:
>>> Hi Radha,
>>>
>>> On Tue, Mar 28, 2017 at 12:58:24PM -0700, Radha Mohan wrote:
>>>> Hi,
>>>> I am seeing an issue with qemu-system-aarch64 when using pflash
>>>> (booting kernel via UEFI bios).
>>>>
>>>> Host kernel: 4.11.0-rc3-next-20170323
>>>> Qemu version: v2.9.0-rc1
>>>>
>>>> Command used:
>>>> ./aarch64-softmmu/qemu-system-aarch64 -cpu host -enable-kvm -M
>>>> virt,gic_version=3 -nographic -smp 1 -m 2048 -drive
>>>> if=none,id=hd0,file=/root/zesty-server-cloudimg-arm64.img,id=0 -device
>>>> virtio-blk-device,drive=hd0 -pflash /root/flash0.img -pflash
>>>> /root/flash1.img
>>>>
>>>>
>>>> As soon as the guest kernel boots the host starts to stall and prints
>>>> the below messages. And the system never recovers. I can neither
>>>> poweroff the guest nor the host. So I have resort to external power
>>>> reset of the host.
>>>>
>>>> ==================
>>>> [  116.199077] NMI watchdog: BUG: soft lockup - CPU#25 stuck for 23s!
>>>> [kworker/25:1:454]
>>>> [  116.206901] Modules linked in: binfmt_misc nls_iso8859_1 aes_ce_blk
>>>> shpchp crypto_simd gpio_keys cryptd aes_ce_cipher ghash_ce sha2_ce
>>>> sha1_ce uio_pdrv_genirq uio autofs4 btrfs raid10 rai
>>>> d456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor
>>>> raid6_pq libcrc32c raid1 raid0 multipath linear ast i2c_algo_bit ttm
>>>> drm_kms_helper syscopyarea sysfillrect sysimgblt fb_s
>>>> ys_fops drm nicvf ahci nicpf libahci thunder_bgx thunder_xcv
>>>> mdio_thunder mdio_cavium
>>>>
>>>> [  116.206995] CPU: 25 PID: 454 Comm: kworker/25:1 Not tainted
>>>> 4.11.0-rc3-next-20170323 #1
>>>> [  116.206997] Hardware name: www.cavium.com crb-1s/crb-1s, BIOS 0.3 Feb 
>>>> 23 2017
>>>> [  116.207010] Workqueue: events netstamp_clear
>>>> [  116.207015] task: ffff801f906b5400 task.stack: ffff801f901a4000
>>>> [  116.207020] PC is at smp_call_function_many+0x284/0x2e8
>>>> [  116.207023] LR is at smp_call_function_many+0x244/0x2e8
>>>> [  116.207026] pc : [<ffff000008156ecc>] lr : [<ffff000008156e8c>]
>>>> pstate: 80000145
>>>> [  116.207028] sp : ffff801f901a7be0
>>>> [  116.207030] x29: ffff801f901a7be0 x28: ffff000009139000
>>>> [  116.207036] x27: ffff000009139434 x26: 0000000000000080
>>>> [  116.207041] x25: 0000000000000000 x24: ffff0000081565d0
>>>> [  116.207047] x23: 0000000000000001 x22: ffff000008e11e00
>>>> [  116.207052] x21: ffff801f6d5cff00 x20: ffff801f6d5cff08
>>>> [  116.207057] x19: ffff000009138e38 x18: 0000000000000a03
>>>> [  116.207063] x17: 0000ffffb77c9028 x16: ffff0000082e81d8
>>>> [  116.207068] x15: 00003d0d6dd44d08 x14: 0036312196549b4a
>>>> [  116.207073] x13: 0000000058dabe4c x12: 0000000000000018
>>>> [  116.207079] x11: 00000000366e2f04 x10: 00000000000009f0
>>>> [  116.207084] x9 : ffff801f901a7d30 x8 : 0000000000000002
>>>> [  116.207089] x7 : 0000000000000000 x6 : 0000000000000000
>>>> [  116.207095] x5 : ffffffff00000000 x4 : 0000000000000020
>>>> [  116.207100] x3 : 0000000000000020 x2 : 0000000000000000
>>>> [  116.207105] x1 : ffff801f6d682578 x0 : 0000000000000003
>>>>
>>>> [  150.443116] INFO: rcu_sched self-detected stall on CPU
>>>> [  150.448261]  25-...: (14997 ticks this GP)
>>>> idle=47a/140000000000001/0 softirq=349/349 fqs=7495
>>>> [  150.451115] INFO: rcu_sched detected stalls on CPUs/tasks:
>>>> [  150.451123]  25-...: (14997 ticks this GP)
>>>> idle=47a/140000000000001/0 softirq=349/349 fqs=7495
>>>> [  150.451124]  (detected by 13, t=15002 jiffies, g=805, c=804, q=8384)
>>>> [  150.451136] Task dump for CPU 25:
>>>> [  150.451138] kworker/25:1    R  running task        0   454      2 
>>>> 0x00000002
>>>> [  150.451155] Workqueue: events netstamp_clear
>>>> [  150.451158] Call trace:
>>>> [  150.451164] [<ffff000008086188>] __switch_to+0x90/0xa8
>>>> [  150.451172] [<ffff0000081f6240>] static_key_slow_inc+0x128/0x138
>>>> [  150.451175] [<ffff0000081f6284>] static_key_enable+0x34/0x60
>>>> [  150.451178] [<ffff000008843268>] netstamp_clear+0x68/0x80
>>>> [  150.451181] [<ffff0000080e49a0>] process_one_work+0x158/0x478
>>>> [  150.451183] [<ffff0000080e4d10>] worker_thread+0x50/0x4a8
>>>> [  150.451187] [<ffff0000080ebd78>] kthread+0x108/0x138
>>>> [  150.451190] [<ffff0000080836c0>] ret_from_fork+0x10/0x50
>>>> [  150.477451]   (t=15008 jiffies g=805 c=804 q=8384)
>>>> [  150.482242] Task dump for CPU 25:
>>>> [  150.482245] kworker/25:1    R  running task        0   454      2 
>>>> 0x00000002
>>>> [  150.482259] Workqueue: events netstamp_clear
>>>> [  150.482264] Call trace:
>>>> [  150.482271] [<ffff00000808a530>] dump_backtrace+0x0/0x2b0
>>>> [  150.482277] [<ffff00000808a804>] show_stack+0x24/0x30
>>>> [  150.482281] [<ffff0000080fb750>] sched_show_task+0x128/0x178
>>>> [  150.482285] [<ffff0000080fd298>] dump_cpu_task+0x48/0x58
>>>> [  150.482288] [<ffff0000081f81e4>] rcu_dump_cpu_stacks+0xa0/0xe8
>>>> [  150.482297] [<ffff00000813983c>] rcu_check_callbacks+0x774/0x938
>>>> [  150.482305] [<ffff00000813fcb4>] update_process_times+0x34/0x60
>>>> [  150.482314] [<ffff000008151b80>] tick_sched_handle.isra.7+0x38/0x70
>>>> [  150.482319] [<ffff000008151c04>] tick_sched_timer+0x4c/0x98
>>>> [  150.482324] [<ffff000008140510>] __hrtimer_run_queues+0xd8/0x2b8
>>>> [  150.482328] [<ffff000008141180>] hrtimer_interrupt+0xa8/0x228
>>>> [  150.482334] [<ffff0000087f2a2c>] arch_timer_handler_phys+0x3c/0x50
>>>> [  150.482341] [<ffff00000812c194>] handle_percpu_devid_irq+0x8c/0x230
>>>> [  150.482344] [<ffff000008126174>] generic_handle_irq+0x34/0x50
>>>> [  150.482347] [<ffff000008126898>] __handle_domain_irq+0x68/0xc0
>>>> [  150.482351] [<ffff0000080817e4>] gic_handle_irq+0xc4/0x170
>>>> [  150.482356] Exception stack(0xffff801f901a7ab0 to 0xffff801f901a7be0)
>>>> [  150.482360] 7aa0:
>>>> 0000000000000003 ffff801f6d682578
>>>> [  150.482364] 7ac0: 0000000000000000 0000000000000020
>>>> 0000000000000020 ffffffff00000000
>>>> [  150.482367] 7ae0: 0000000000000000 0000000000000000
>>>> 0000000000000002 ffff801f901a7d30
>>>> [  150.482371] 7b00: 00000000000009f0 00000000366e2f04
>>>> 0000000000000018 0000000058dabe4c
>>>> [  150.482375] 7b20: 0036312196549b4a 00003d0d6dd44d08
>>>> ffff0000082e81d8 0000ffffb77c9028
>>>> [  150.482378] 7b40: 0000000000000a03 ffff000009138e38
>>>> ffff801f6d5cff08 ffff801f6d5cff00
>>>> [  150.482382] 7b60: ffff000008e11e00 0000000000000001
>>>> ffff0000081565d0 0000000000000000
>>>> [  150.482386] 7b80: 0000000000000080 ffff000009139434
>>>> ffff000009139000 ffff801f901a7be0
>>>> [  150.482390] 7ba0: ffff000008156e8c ffff801f901a7be0
>>>> ffff000008156ecc 0000000080000145
>>>> [  150.482394] 7bc0: ffff801f901a7be0 ffff000008156e68
>>>> ffffffffffffffff ffff000008156e8c
>>>> [  150.482397] [<ffff000008082ff4>] el1_irq+0xb4/0x140
>>>> [  150.482401] [<ffff000008156ecc>] smp_call_function_many+0x284/0x2e8
>>>> [  150.482405] [<ffff000008157020>] kick_all_cpus_sync+0x30/0x38
>>>> [  150.482409] [<ffff00000897c6cc>] aarch64_insn_patch_text+0xec/0xf8
>>>> [  150.482415] [<ffff000008095978>] arch_jump_label_transform+0x60/0x98
>>>> [  150.482420] [<ffff0000081f593c>] __jump_label_update+0x8c/0xa8
>>>> [  150.482423] [<ffff0000081f6088>] jump_label_update+0x58/0xe8
>>>> [  150.482429] [<ffff0000081f6240>] static_key_slow_inc+0x128/0x138
>>>> [  150.482434] [<ffff0000081f6284>] static_key_enable+0x34/0x60
>>>> [  150.482438] [<ffff000008843268>] netstamp_clear+0x68/0x80
>>>> [  150.482441] [<ffff0000080e49a0>] process_one_work+0x158/0x478
>>>> [  150.482444] [<ffff0000080e4d10>] worker_thread+0x50/0x4a8
>>>> [  150.482448] [<ffff0000080ebd78>] kthread+0x108/0x138
>>>> [  150.482451] [<ffff0000080836c0>] ret_from_fork+0x10/0x50
>>>>
>>>> ====================================
>>>>
>>>> I am observing that this usually happens when the guest tries to
>>>> bringup or use the default virtio-net interface.
>>>> And I am unable to reproduce this when directly booting the guest
>>>> kernel without UEFI BIOS.
>>>> So anyone observed similar issue ?
>>>>
>>>
>>> I haven't seen this myself.
>>>
>>> Have you tried with other versions of QEMU and the host kernel by any
>>> chance using the same setup?
>>
>> The earlier qemu version (atleast 2.5 which is default on ubuntu
>> 16.04) have different issue. The same thing happens when I use
>> vhost=on but without vhost and with virtio-net didn't see the issue.
>> The Armband folks have also reported the vhost issue here
>> https://bugs.launchpad.net/ubuntu/+source/edk2/+bug/1673564
> 
> So I just ran your setup using the flash emulation on the ThunderX in
> packet.net and my host is happily continuing to run hackbench.
> 
>>
>> So I am beginning to think the issue could be related to the flash
>> emulation but wanted to check on ml if anyone else is seeing it. But
>> if it is flash emulation how can it hose the host like this ?
> 
> Why do you think it's related to the flash emulation?
> 
> From what you're telling me it sounds much more like a vhost regression.
> 
> Can you try with v4.10 of the kernel with vhost=on ?

Does this QEMU pull req help by any chance?

  [Qemu-devel] [PULL 0/2] vhost, pc: fixes
  http://lists.nongnu.org/archive/html/qemu-devel/2017-03/msg06103.html

It says "Region caching is still causing issues around reset". (Region
caching was a recent, very intrusive, virtio change in QEMU that sort of
blew up everything and developers have been dealing with the fallout
ever since. <-- my personal account anyway)

In another (separate, downstream) discussion, I explained that the
VirtioNetDxe driver in OVMF and ArmVirtQemu does a virtio reset on the
virtio network device in an ExitBootServices() callback; that is, when
the kernel's UEFI stub takes control of the system. Resetting the virtio
device is supposed to cause the host to de-configure the device and to
forget all about it. If that doesn't occur correctly, the guest kernel
can definitely end up in a crappy state (the host might still consider
memory areas belong to the virtio device that were originally allocated
by the firmware, but are now overwritten by the guest kernel).

In addition, I found some relevant-looking, recent vhost commits in the
kernel:

275bf960ac69 vhost: better detection of available buffers
0ed005ce02fa vhost_net: tx batching
635b8c8ecdd2 tap: Renaming tap related APIs, data structures, macros
9a393b5d5988 tap: tap as an independent module
e3b56cdd4351 vhost: try avoiding avail index access when getting
             descriptor
f88949138058 vhost: introduce O(1) vq metadata cache

I think the symptoms could be a strange interplay between recent QEMU
and kernel changes that are tickled by the firmware's virtio-net driver
the wrong way.

Thanks
Laszlo

> 
> Thanks,
> -Christoffer
> _______________________________________________
> kvmarm mailing list
> address@hidden
> https://lists.cs.columbia.edu/mailman/listinfo/kvmarm
>