Re: [Qemu-devel] Bug#688964: qemu-kvm: Fedora 17 guest hangs on boot with soft lockup in udevd

[Michael Tokarev <mjt@tls.msk.ru>]

On 27.09.2012 20:25, Nikolai Kondrashov wrote:
> On 09/27/2012 06:23 PM, Michael Tokarev wrote:
>> Please provide full command line which virt-manager uses.  You can find
>> it in virtmanager logs or in ps(1) output.
> 
> Here is the command line:
> 
> LC_ALL=C PATH=/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin HOME=/root USER=root LOGNAME=root QEMU_AUDIO_DRV=none /usr/bin/kvm -S -M pc-1.1 -enable-kvm -m 1024 -smp 1,sockets=1,cores=1,threads=1 -name fedora-hang-test -uuid d155797a-03fb-0181-8e71-8d38181a7158 -nodefconfig -nodefaults -chardev socket,id=charmonitor,path=/var/lib/libvirt/qemu/fedora-hang-test.monitor,server,nowait -mon chardev=charmonitor,id=monitor,mode=control -rtc base=utc -no-shutdown -device piix3-usb-uhci,id=usb,bus=pci.0,addr=0x1.0x2 -drive file=/var/lib/libvirt/images/fedora-hang-test.img,if=none,id=drive-virtio-disk0,format=raw -device virtio-blk-pci,scsi=off,bus=pci.0,addr=0x5,drive=drive-virtio-disk0,id=virtio-disk0,bootindex=1 -drive
> file=/home/nkondras/tmp/Fedora-17-x86_64-Live-Desktop.iso,if=none,id=drive-ide0-1-0,readonly=on,format=raw -device ide-cd,bus=ide.1,unit=0,drive=drive-ide0-1-0,id=ide0-1-0 -netdev tap,fd=20,id=hostnet0,vhost=on,vhostfd=22 -device virtio-net-pci,netdev=hostnet0,id=net0,mac=52:54:00:5e:20:81,bus=pci.0,addr=0x3 -chardev pty,id=charserial0 -device isa-serial,chardev=charserial0,id=serial0 -device usb-tablet,id=input0 -vnc 127.0.0.1:1 -vga cirrus -device intel-hda,id=sound0,bus=pci.0,addr=0x4 -device hda-duplex,id=sound0-codec0,bus=sound0.0,cad=0 -device virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x6
> 
> Simply booting from this Live CD hangs:
>
> http://download.fedoraproject.org/pub/fedora/linux/releases/17/Live/x86_64/Fedora-17-x86_64-Live-Desktop.iso

Ok.  I reproduced this, I _think_, and now I want some confirmation
from you.  This is my command line:

  QEMU_AUDIO_DRV=none qemu-kvm -nodefconfig -nodefaults -enable-kvm \
   -monitor stdio -rtc base=utc \
   -device piix3-usb-uhci,id=usb,bus=pci.0,addr=0x1.0x2 \
   -m 512 -vga cirrus -cdrom Fedora-17-x86_64-Live-Desktop.iso \
   -device intel-hda,id=sound0,bus=pci.0,addr=0x4 \
   -device hda-duplex,id=sound0-codec0,bus=sound0.0,cad=0

leads to this in guest:

...
Starting udev Wait for Complete Device Initialization...
[    4.123978] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0xb100, revision 0
[    4.311473] microcode: AMD CPU family 0x6 not supported
[    4.355429] microcode: AMD CPU family 0x6 not supported
[    7.323032] ALSA sound/pci/hda/hda_intel.c:823 azx_get_response timeout, switching to polling mode: last cmd=0x000f0000
[    8.325018] ALSA sound/pci/hda/hda_intel.c:831 No response from codec, disabling MSI: last cmd=0x000f0000
[   36.055021] BUG: soft lockup - CPU#0 stuck for 22s! [udevd:385]
[   36.055026] Modules linked in: snd_hda_intel(+) snd_hda_codec snd_hwdep i2c_piix4 snd_pcm i2c_core snd_page_alloc snd_timer snd soundcore uinput squashfs
[   36.055026] CPU 0
[   36.055026] Modules linked in: snd_hda_intel(+) snd_hda_codec snd_hwdep i2c_piix4 snd_pcm i2c_core snd_page_alloc snd_timer snd soundcore uinput squashfs
[   36.055026]
[   36.055026]
[   36.055026] Pid: 385, comm: udevd Not tainted 3.3.4-5.fc17.x86_64 #1 Bochs Bochs
[   36.055026] RIP: 0010:[<ffffffff8105dc40>]  [<ffffffff8105dc40>] __do_softirq+0x70/0x1e0
[   36.055026] RSP: 0018:ffff88001f003ef0  EFLAGS: 00000206
[   36.055026] RAX: ffff88001f8a7fd8 RBX: ffffffff81a17240 RCX: 00000001f0542108
[   36.055026] RDX: 0000000000000000 RSI: 000000000000006f RDI: 0000000000000002
[   36.055026] RBP: ffff88001f003f40 R08: 0000000000000000 R09: ffffffff81c64540
[   36.055026] R10: 0000000000000400 R11: 0000000000000020 R12: ffff88001f003e68
[   36.055026] R13: ffffffff815f439e R14: ffff88001f003f40 R15: 0000000000000046
[   36.055026] FS:  00007f14b7509840(0000) GS:ffff88001f000000(0000) knlGS:0000000000000000
[   36.055026] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[   36.055026] CR2: 00007fa5e9e40000 CR3: 000000001f80e000 CR4: 00000000000006f0
[   36.055026] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[   36.055026] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[   36.055026] Process udevd (pid: 385, threadinfo ffff88001f8a6000, task ffff88001b218000)
[   36.055026] Stack:
[   36.055026]  000000008101ac19 ffff88001f8a7fd8 ffff88001f8a7fd8 ffff88000000000a
[   36.055026]  ffff88001f014000 ffff88001f8a7fd8 0000000000000046 0000000000000007
[   36.055026]  0000000000000050 0000000000000001 ffff88001f003f58 ffffffff815f4d9c
[   36.055026] Call Trace:
[   36.055026]  <IRQ>
[   36.055026]  [<ffffffff815f4d9c>] call_softirq+0x1c/0x30
[   36.055026]  [<ffffffff81015465>] do_softirq+0x75/0xb0
[   36.055026]  [<ffffffff8105e055>] irq_exit+0xb5/0xc0
[   36.055026]  [<ffffffff815f56ee>] smp_apic_timer_interrupt+0x6e/0x99
[   36.055026]  [<ffffffff815f439e>] apic_timer_interrupt+0x6e/0x80
[   36.055026]  <EOI>
[   36.055026]  [<ffffffff810e22ac>] ? free_irq+0x5c/0xc0
[   36.055026]  [<ffffffff815eb741>] ? _raw_spin_unlock_irqrestore+0x11/0x20
[   36.055026]  [<ffffffff812dc3c3>] pci_bus_write_config_word+0x83/0xa0
[   36.055026]  [<ffffffff812dfca2>] pci_intx+0x52/0x90
[   36.055026]  [<ffffffff812f6e4d>] pci_intx_for_msi+0x1d/0x30
[   36.055026]  [<ffffffff812f7bed>] pci_msi_shutdown+0x7d/0xf0
[   36.055026]  [<ffffffff812f7c98>] pci_disable_msi+0x38/0x60
[   36.055026]  [<ffffffffa009efbf>] azx_get_response+0x1af/0x280 [snd_hda_intel]
[   36.055026]  [<ffffffffa007a4cf>] codec_exec_verb+0xbf/0x1f0 [snd_hda_codec]
[   36.055026]  [<ffffffffa007a660>] snd_hda_codec_read+0x60/0xa0 [snd_hda_codec]
[   36.055026]  [<ffffffffa007c92a>] snd_hda_codec_new+0x20a/0x690 [snd_hda_codec]
[   36.055026]  [<ffffffff81086b9a>] ? __cond_resched+0x2a/0x40
[   36.055026]  [<ffffffffa009ee9e>] ? azx_get_response+0x8e/0x280 [snd_hda_intel]
[   36.055026]  [<ffffffffa009fd6e>] azx_codec_create+0x1df/0x27c [snd_hda_intel]
[   36.055026]  [<ffffffffa009f1d0>] ? azx_irq_pending_work+0x140/0x140 [snd_hda_intel]
[   36.055026]  [<ffffffffa009ee10>] ? azx_halt+0x40/0x40 [snd_hda_intel]
[   36.055026]  [<ffffffffa009f990>] ? azx_bus_reset+0x90/0x90 [snd_hda_intel]
[   36.055026]  [<ffffffffa009f900>] ? azx_resume+0x170/0x170 [snd_hda_intel]
[   36.055026]  [<ffffffffa009f710>] ? azx_init_chip+0x2b0/0x2b0 [snd_hda_intel]
[   36.055026]  [<ffffffffa00a07b2>] azx_probe+0x9a7/0xb29 [snd_hda_intel]
[   36.055026]  [<ffffffff812e4b2c>] local_pci_probe+0x5c/0xd0
[   36.055026]  [<ffffffff812e4cb1>] pci_device_probe+0x111/0x120
[   36.055026]  [<ffffffff8139e8a6>] driver_probe_device+0x96/0x2f0
[   36.055026]  [<ffffffff8139ebab>] __driver_attach+0xab/0xb0
[   36.055026]  [<ffffffff8139eb00>] ? driver_probe_device+0x2f0/0x2f0
[   36.055026]  [<ffffffff8139cb85>] bus_for_each_dev+0x55/0x90
[   36.055026]  [<ffffffffa00a7000>] ? 0xffffffffa00a6fff
[   36.055026]  [<ffffffff8139e39e>] driver_attach+0x1e/0x20
[   36.055026]  [<ffffffff8139e0a8>] bus_add_driver+0x1a8/0x2a0
[   36.055026]  [<ffffffffa00a7000>] ? 0xffffffffa00a6fff
[   36.055026]  [<ffffffffa00a7000>] ? 0xffffffffa00a6fff
[   36.055026]  [<ffffffff8139f367>] driver_register+0x77/0x150
[   36.055026]  [<ffffffffa00a7000>] ? 0xffffffffa00a6fff
[   36.055026]  [<ffffffff812e3a52>] __pci_register_driver+0x62/0xe0
[   36.055026]  [<ffffffffa00a7000>] ? 0xffffffffa00a6fff
[   36.055026]  [<ffffffffa00a701e>] alsa_card_azx_init+0x1e/0x1000 [snd_hda_intel]
[   36.055026]  [<ffffffff8100212a>] do_one_initcall+0x12a/0x180
[   36.055026]  [<ffffffff810b60a6>] sys_init_module+0x10f6/0x20b0
[   36.055026]  [<ffffffff815f38e9>] system_call_fastpath+0x16/0x1b

Is it the issue you're seeing?

Removing hda-duplex device lets it to work.  Removing piix3-usb-uhci
allows it to boot too.  Even removing the explicit bus address from
piix3-usb-uhci allow it to boot.

I tried to bisect between qemu-kvm 1.1.0 and qemu-kvm-1.1.1, and the
bisection points to this commit:

commit 0ec39075710ae15acc2a5825cd21e0c229fa04af
(8e729e3b521d9fcd87fc2e40b6322e684f58bb2e upstream)
Author: Jan Kiszka <jan.kiszka@siemens.com>
Date:   Fri May 11 11:42:35 2012 -0300

    intel-hda: Fix reset of MSI function

    Call msi_reset on device reset as still required by the core.

    CC: Gerd Hoffmann <kraxel@redhat.com>
    CC: qemu-stable@nongnu.org
    Signed-off-by: Jan Kiszka <jan.kiszka@siemens.com>
    Signed-off-by: Michael S. Tsirkin <mst@redhat.com>
    (cherry picked from commit 8e729e3b521d9fcd87fc2e40b6322e684f58bb2e)

--- a/hw/intel-hda.c
+++ b/hw/intel-hda.c
@@ -1107,6 +1107,9 @@ static void intel_hda_reset(DeviceState *dev)
     DeviceState *qdev;
     HDACodecDevice *cdev;

+    if (d->msi) {
+        msi_reset(&d->pci);
+    }
     intel_hda_regs_reset(d);
     d->wall_base_ns = qemu_get_clock_ns(vm_clock);

which is exactly about this hda thing.  I'm CC'ing relevant
people here.

Now I'm not sure what goes on here.  Is libvirt not right somehow?
Note: it is qemu-kvm 1.1.2, problem exists in 1.1.1 already, after
the above commit.

Nikolai, please verify if this is the issue you're seeing, and
please try without sound device.  If this is the case, let's
downgrade this bug from important to normal, since emulated sound
devices aren't really of high priority in this context, and there
should be easy workaround (to disable sound).

Thank you!

/mjt