| Message ID | 1487361200-29966-13-git-send-email-mst@redhat.com |
|---|---|
| State | New |
| Headers | show |
On Fr, 2017-02-17 at 21:54 +0200, Michael S. Tsirkin wrote: > From: Paolo Bonzini <pbonzini@redhat.com> > > The virtio-net change is necessary because it uses virtqueue_fill > and virtqueue_flush instead of the more convenient virtqueue_push. > > Reviewed-by: Stefan Hajnoczi <stefanha@redhat.com> > Signed-off-by: Paolo Bonzini <pbonzini@redhat.com> > Reviewed-by: Michael S. Tsirkin <mst@redhat.com> > Signed-off-by: Michael S. Tsirkin <mst@redhat.com> This change breaks ovmf for me, although it isn't obvious to me why. Bisect landed here, and reverting indeed makes things going again. Using q35 machine type, pcie virtio devices, with the rhel ovmf build (OVMF-20160608b-1.git988715a.el7.noarch). First thing I've tried is swapping virtio-net for another nic, suspecting this change might trigger a bug in the ovmf virtio-net driver, but that didn't change things. Effect is that qemu just exits, without logging some error, looks like a normal guest shutdown. Firmware log doesn't give a clue either, it just stops at some point, again without any error message. Here are the last lines of the log: SataControllerStart START SataControllerStart error return status = Already started SetPciIntLine: [00:1C.0] PciRoot(0x0)/Pci(0x1C,0x0) -> 0x0A SetPciIntLine: [01:00.0] PciRoot(0x0)/Pci(0x1C,0x0)/Pci(0x0,0x0) -> 0x0A SetPciIntLine: [00:1C.1] PciRoot(0x0)/Pci(0x1C,0x1) -> 0x0A SetPciIntLine: [02:00.0] PciRoot(0x0)/Pci(0x1C,0x1)/Pci(0x0,0x0) -> 0x0A SetPciIntLine: [00:1C.2] PciRoot(0x0)/Pci(0x1C,0x2) -> 0x0A SetPciIntLine: [00:1C.3] PciRoot(0x0)/Pci(0x1C,0x3) -> 0x0A SetPciIntLine: [00:1C.4] PciRoot(0x0)/Pci(0x1C,0x4) -> 0x0A SetPciIntLine: [05:00.0] PciRoot(0x0)/Pci(0x1C,0x4)/Pci(0x0,0x0) -> 0x0A SetPciIntLine: [05:00.1] PciRoot(0x0)/Pci(0x1C,0x4)/Pci(0x0,0x1) -> 0x0A SetPciIntLine: [05:00.2] PciRoot(0x0)/Pci(0x1C,0x4)/Pci(0x0,0x2) -> 0x0A SetPciIntLine: [00:1C.5] PciRoot(0x0)/Pci(0x1C,0x5) -> 0x0A SetPciIntLine: [06:00.0] PciRoot(0x0)/Pci(0x1C,0x5)/Pci(0x0,0x0) -> 0x0A SetPciIntLine: [00:1C.6] PciRoot(0x0)/Pci(0x1C,0x6) -> 0x0A SetPciIntLine: [00:1C.7] PciRoot(0x0)/Pci(0x1C,0x7) -> 0x0A SetPciIntLine: [00:1F.2] PciRoot(0x0)/Pci(0x1F,0x2) -> 0x0A SetPciIntLine: [00:1F.3] PciRoot(0x0)/Pci(0x1F,0x3) -> 0x0A Select Item: 0x8 Select Item: 0x17 qemu -kernel was not used. cheers, Gerd
On 02/21/17 13:57, Gerd Hoffmann wrote: > On Fr, 2017-02-17 at 21:54 +0200, Michael S. Tsirkin wrote: >> From: Paolo Bonzini <pbonzini@redhat.com> >> >> The virtio-net change is necessary because it uses virtqueue_fill >> and virtqueue_flush instead of the more convenient virtqueue_push. >> >> Reviewed-by: Stefan Hajnoczi <stefanha@redhat.com> >> Signed-off-by: Paolo Bonzini <pbonzini@redhat.com> >> Reviewed-by: Michael S. Tsirkin <mst@redhat.com> >> Signed-off-by: Michael S. Tsirkin <mst@redhat.com> > > This change breaks ovmf for me, although it isn't obvious to me why. > Bisect landed here, and reverting indeed makes things going again. I looked at the patch (on the list) and I don't have the slightest idea what's going on. I read the word "cache" in it, so I guess it introduces (or exposes) some cache coherency issue. > Using q35 machine type, pcie virtio devices, with the rhel ovmf build > (OVMF-20160608b-1.git988715a.el7.noarch). > > First thing I've tried is swapping virtio-net for another nic, > suspecting this change might trigger a bug in the ovmf virtio-net > driver, but that didn't change things. > > Effect is that qemu just exits, without logging some error, looks like a > normal guest shutdown. That's very strange (especially given the OVMF log below). > Firmware log doesn't give a clue either, it just > stops at some point, again without any error message. Here are the last > lines of the log: > > SataControllerStart START > SataControllerStart error return status = Already started > SetPciIntLine: [00:1C.0] PciRoot(0x0)/Pci(0x1C,0x0) -> 0x0A > SetPciIntLine: [01:00.0] PciRoot(0x0)/Pci(0x1C,0x0)/Pci(0x0,0x0) -> 0x0A > SetPciIntLine: [00:1C.1] PciRoot(0x0)/Pci(0x1C,0x1) -> 0x0A > SetPciIntLine: [02:00.0] PciRoot(0x0)/Pci(0x1C,0x1)/Pci(0x0,0x0) -> 0x0A > SetPciIntLine: [00:1C.2] PciRoot(0x0)/Pci(0x1C,0x2) -> 0x0A > SetPciIntLine: [00:1C.3] PciRoot(0x0)/Pci(0x1C,0x3) -> 0x0A > SetPciIntLine: [00:1C.4] PciRoot(0x0)/Pci(0x1C,0x4) -> 0x0A > SetPciIntLine: [05:00.0] PciRoot(0x0)/Pci(0x1C,0x4)/Pci(0x0,0x0) -> 0x0A > SetPciIntLine: [05:00.1] PciRoot(0x0)/Pci(0x1C,0x4)/Pci(0x0,0x1) -> 0x0A > SetPciIntLine: [05:00.2] PciRoot(0x0)/Pci(0x1C,0x4)/Pci(0x0,0x2) -> 0x0A > SetPciIntLine: [00:1C.5] PciRoot(0x0)/Pci(0x1C,0x5) -> 0x0A > SetPciIntLine: [06:00.0] PciRoot(0x0)/Pci(0x1C,0x5)/Pci(0x0,0x0) -> 0x0A > SetPciIntLine: [00:1C.6] PciRoot(0x0)/Pci(0x1C,0x6) -> 0x0A > SetPciIntLine: [00:1C.7] PciRoot(0x0)/Pci(0x1C,0x7) -> 0x0A > SetPciIntLine: [00:1F.2] PciRoot(0x0)/Pci(0x1F,0x2) -> 0x0A > SetPciIntLine: [00:1F.3] PciRoot(0x0)/Pci(0x1F,0x3) -> 0x0A > Select Item: 0x8 > Select Item: 0x17 > qemu -kernel was not used. The next action would be the EfiBootManagerRefreshAllBootOption() function call in PlatformBootManagerAfterConsole(), in file "OvmfPkg/Library/PlatformBootManagerLib/BdsPlatform.c". That function (from "MdeModulePkg/Library/UefiBootManagerLib/BmBoot.c") "enumerates all boot options, creates them and registers them in the BootOrder variable". While doing that, it definitely looks (indirectly) at any UEFI-bootable virtio-scsi or virtio-blk device. The direct symptom you are seeing ("qemu just exits / shuts down") is inexplicable. If there were a virtio-de-sync between guest and host, I'd expect OVMF to hang, and/or emit error messages. Thanks Laszlo
On 02/21/17 17:25, Laszlo Ersek wrote: > On 02/21/17 13:57, Gerd Hoffmann wrote: >> On Fr, 2017-02-17 at 21:54 +0200, Michael S. Tsirkin wrote: >>> From: Paolo Bonzini <pbonzini@redhat.com> >>> >>> The virtio-net change is necessary because it uses virtqueue_fill >>> and virtqueue_flush instead of the more convenient virtqueue_push. >>> >>> Reviewed-by: Stefan Hajnoczi <stefanha@redhat.com> >>> Signed-off-by: Paolo Bonzini <pbonzini@redhat.com> >>> Reviewed-by: Michael S. Tsirkin <mst@redhat.com> >>> Signed-off-by: Michael S. Tsirkin <mst@redhat.com> >> >> This change breaks ovmf for me, although it isn't obvious to me why. >> Bisect landed here, and reverting indeed makes things going again. > > I looked at the patch (on the list) and I don't have the slightest idea > what's going on. I read the word "cache" in it, so I guess it introduces > (or exposes) some cache coherency issue. > >> Using q35 machine type, pcie virtio devices, with the rhel ovmf build >> (OVMF-20160608b-1.git988715a.el7.noarch). >> >> First thing I've tried is swapping virtio-net for another nic, >> suspecting this change might trigger a bug in the ovmf virtio-net >> driver, but that didn't change things. >> >> Effect is that qemu just exits, without logging some error, looks like a >> normal guest shutdown. > > That's very strange (especially given the OVMF log below). > >> Firmware log doesn't give a clue either, it just >> stops at some point, again without any error message. Here are the last >> lines of the log: >> >> SataControllerStart START >> SataControllerStart error return status = Already started >> SetPciIntLine: [00:1C.0] PciRoot(0x0)/Pci(0x1C,0x0) -> 0x0A >> SetPciIntLine: [01:00.0] PciRoot(0x0)/Pci(0x1C,0x0)/Pci(0x0,0x0) -> 0x0A >> SetPciIntLine: [00:1C.1] PciRoot(0x0)/Pci(0x1C,0x1) -> 0x0A >> SetPciIntLine: [02:00.0] PciRoot(0x0)/Pci(0x1C,0x1)/Pci(0x0,0x0) -> 0x0A >> SetPciIntLine: [00:1C.2] PciRoot(0x0)/Pci(0x1C,0x2) -> 0x0A >> SetPciIntLine: [00:1C.3] PciRoot(0x0)/Pci(0x1C,0x3) -> 0x0A >> SetPciIntLine: [00:1C.4] PciRoot(0x0)/Pci(0x1C,0x4) -> 0x0A >> SetPciIntLine: [05:00.0] PciRoot(0x0)/Pci(0x1C,0x4)/Pci(0x0,0x0) -> 0x0A >> SetPciIntLine: [05:00.1] PciRoot(0x0)/Pci(0x1C,0x4)/Pci(0x0,0x1) -> 0x0A >> SetPciIntLine: [05:00.2] PciRoot(0x0)/Pci(0x1C,0x4)/Pci(0x0,0x2) -> 0x0A >> SetPciIntLine: [00:1C.5] PciRoot(0x0)/Pci(0x1C,0x5) -> 0x0A >> SetPciIntLine: [06:00.0] PciRoot(0x0)/Pci(0x1C,0x5)/Pci(0x0,0x0) -> 0x0A >> SetPciIntLine: [00:1C.6] PciRoot(0x0)/Pci(0x1C,0x6) -> 0x0A >> SetPciIntLine: [00:1C.7] PciRoot(0x0)/Pci(0x1C,0x7) -> 0x0A >> SetPciIntLine: [00:1F.2] PciRoot(0x0)/Pci(0x1F,0x2) -> 0x0A >> SetPciIntLine: [00:1F.3] PciRoot(0x0)/Pci(0x1F,0x3) -> 0x0A >> Select Item: 0x8 >> Select Item: 0x17 >> qemu -kernel was not used. > > The next action would be the EfiBootManagerRefreshAllBootOption() > function call in PlatformBootManagerAfterConsole(), in file > "OvmfPkg/Library/PlatformBootManagerLib/BdsPlatform.c". > > That function (from "MdeModulePkg/Library/UefiBootManagerLib/BmBoot.c") > "enumerates all boot options, creates them and registers them in the > BootOrder variable". While doing that, it definitely looks (indirectly) > at any UEFI-bootable virtio-scsi or virtio-blk device. > > The direct symptom you are seeing ("qemu just exits / shuts down") is > inexplicable. If there were a virtio-de-sync between guest and host, I'd > expect OVMF to hang, and/or emit error messages. Actually, QEMU segfaults. From the dmesg: [Tue Feb 21 18:47:28 2017] CPU 0/KVM[8298]: segfault at 48 ip 00007fcb5dd02105 sp 00007fcb49efc270 error 4 in qemu-system-x86_64[7fcb5dae3000+905000] Complete backtrace below. (Thread 11 seems to be the one segfaulting.) Thanks Laszlo > Program received signal SIGSEGV, Segmentation fault. > [Switching to Thread 0x7f651dcbb700 (LWP 8553)] > 0x00007f6531ac0105 in address_space_translate_cached (cache=0x38, addr=2, xlat=0x7f651dcba2d0, plen=0x7f651dcba2d8, > is_write=false) at .../exec.c:3181 > 3181 assert(addr < cache->len && *plen <= cache->len - addr); > (gdb) thread apply all bt full > > Thread 13 (Thread 0x7f651f5d8700 (LWP 8549)): > #0 0x00007f6528937bdd in nanosleep () from /lib64/libpthread.so.0 > No symbol table info available. > #1 0x00007f6526f316f8 in g_usleep () from /lib64/libglib-2.0.so.0 > No symbol table info available. > #2 0x00007f6531f8791e in call_rcu_thread (opaque=0x0) at .../util/rcu.c:244 > tries = 1 > n = 1 > node = 0x7f65180053b0 > #3 0x00007f6528930dc5 in start_thread () from /lib64/libpthread.so.0 > No symbol table info available. > #4 0x00007f6525bad73d in clone () from /lib64/libc.so.6 > No symbol table info available. > > Thread 12 (Thread 0x7f651ebc4700 (LWP 8551)): > #0 0x00007f65289369b1 in do_futex_wait () from /lib64/libpthread.so.0 > No symbol table info available. > #1 0x00007f6528936a77 in __new_sem_wait_slow () from /lib64/libpthread.so.0 > No symbol table info available. > #2 0x00007f6528936b15 in sem_timedwait () from /lib64/libpthread.so.0 > No symbol table info available. > #3 0x00007f6531f7249a in qemu_sem_timedwait (sem=0x7f6532c1f488, ms=10000) at .../util/qemu-thread-posix.c:255 > rc = 0 > ts = {tv_sec = 1487699392, tv_nsec = 569220000} > __func__ = "qemu_sem_timedwait" > #4 0x00007f6531f6c7a4 in worker_thread (opaque=0x7f6532c1f420) at .../util/thread-pool.c:92 > req = 0x7f65184f1a20 > ret = 0 > pool = 0x7f6532c1f420 > #5 0x00007f6528930dc5 in start_thread () from /lib64/libpthread.so.0 > No symbol table info available. > #6 0x00007f6525bad73d in clone () from /lib64/libc.so.6 > No symbol table info available. > > Thread 11 (Thread 0x7f651dcbb700 (LWP 8553)): > #0 0x00007f6531ac0105 in address_space_translate_cached (cache=0x38, addr=2, xlat=0x7f651dcba2d0, plen=0x7f651dcba2d8, is_write=false) at .../exec.c:3181 > __PRETTY_FUNCTION__ = "address_space_translate_cached" > #1 0x00007f6531ac07aa in address_space_lduw_internal_cached (cache=0x38, addr=2, attrs=..., result=0x0, endian=DEVICE_LITTLE_ENDIAN) at .../memory_ldst.inc.c:264 > ptr = 0x7f6476c73802 "H\004" > val = 1096 > mr = 0x7f6532d91260 > l = 2 > addr1 = 3202824194 > r = 0 > release_lock = false > #2 0x00007f6531ac0917 in address_space_lduw_le_cached (cache=0x38, addr=2, attrs=..., result=0x0) at .../memory_ldst.inc.c:315 > No locals. > #3 0x00007f6531ac09c3 in lduw_le_phys_cached (cache=0x38, addr=2) at .../memory_ldst.inc.c:334 > No locals. > #4 0x00007f6531b737b1 in virtio_lduw_phys_cached (vdev=0x7f65343fa4e0, cache=0x38, pa=2) at .../include/hw/virtio/virtio-access.h:166 > No locals. > #5 0x00007f6531b73d40 in vring_avail_idx (vq=0x7f651c09c090) at .../hw/virtio/virtio.c:201 > caches = 0x0 > pa = 2 > #6 0x00007f6531b7421f in virtio_queue_empty (vq=0x7f651c09c090) at .../hw/virtio/virtio.c:332 > empty = true > #7 0x00007f6531b78b82 in virtio_queue_host_notifier_aio_poll (opaque=0x7f651c09c0f8) at .../hw/virtio/virtio.c:2294 > n = 0x7f651c09c0f8 > vq = 0x7f651c09c090 > progress = false > #8 0x00007f6531f6fe2c in run_poll_handlers_once (ctx=0x7f6532bcd940) at .../util/aio-posix.c:490 > progress = false > node = 0x7f6518478650 > #9 0x00007f6531f7002d in try_poll_mode (ctx=0x7f6532bcd940, blocking=true) at .../util/aio-posix.c:566 > No locals. > #10 0x00007f6531f700c1 in aio_poll (ctx=0x7f6532bcd940, blocking=true) at .../util/aio-posix.c:595 > node = 0x7f6531ed48fc <aio_context_in_iothread+17> > i = 32613 > ret = 0 > progress = false > timeout = 140072268314064 > start = 0 > __PRETTY_FUNCTION__ = "aio_poll" > #11 0x00007f6531ed6157 in blk_prw (blk=0x7f6532bf7ee0, offset=16896, buf=0x7f650d404200 " ", bytes=512, co_entry=0x7f6531ed5fe3 <blk_write_entry>, flags=0) at .../block/block-backend.c:905 > waited_ = false > bs_ = 0x7f6532c07980 > ctx_ = 0x7f6532bcd940 > co = 0x7f6518184010 > qiov = {iov = 0x7f651dcba600, niov = 1, nalloc = -1, size = 512} > iov = {iov_base = 0x7f650d404200, iov_len = 512} > rwco = {blk = 0x7f6532bf7ee0, offset = 16896, qiov = 0x7f651dcba610, ret = 2147483647, flags = 0} > __PRETTY_FUNCTION__ = "blk_prw" > #12 0x00007f6531ed67c3 in blk_pwrite (blk=0x7f6532bf7ee0, offset=16896, buf=0x7f650d404200, count=512, flags=0) at .../block/block-backend.c:1064 > ret = 0 > #13 0x00007f6531cad498 in pflash_update (pfl=0x7f6532e5fbb0, offset=16896, size=1) at .../hw/block/pflash_cfi01.c:420 > offset_end = 17408 > #14 0x00007f6531cad8e8 in pflash_write (pfl=0x7f6532e5fbb0, offset=17378, value=62, width=1, be=0) at .../hw/block/pflash_cfi01.c:545 > p = 0x7f651dcba760 "°§Ë\035e\177" > cmd = 62 '>' > __func__ = "pflash_write" > #15 0x00007f6531caddbd in pflash_mem_write_with_attrs (opaque=0x7f6532e5fbb0, addr=17378, value=62, len=1, attrs=...) at .../hw/block/pflash_cfi01.c:691 > pfl = 0x7f6532e5fbb0 > be = false > #16 0x00007f6531b10524 in memory_region_write_with_attrs_accessor (mr=0x7f6532e5ff50, addr=17378, value=0x7f651dcba838, size=1, shift=0, mask=255, attrs=...) at .../memory.c:552 > tmp = 62 > #17 0x00007f6531b10643 in access_with_adjusted_size (addr=17378, value=0x7f651dcba838, size=1, access_size_min=1, access_size_max=4, access=0x7f6531b1043f <memory_region_write_with_attrs_accessor>, mr=0x7f6532e5ff50, attrs=...) at .../memory.c:592 > access_mask = 255 > access_size = 1 > i = 0 > r = 0 > #18 0x00007f6531b12ca3 in memory_region_dispatch_write (mr=0x7f6532e5ff50, addr=17378, data=62, size=1, attrs=...) at .../memory.c:1329 > No locals. > #19 0x00007f6531abdbff in address_space_write_continue (as=0x7f65325ddd80 <address_space_memory>, addr=4292887522, attrs=..., buf=0x7f6531894028 ">\020", len=1, addr1=17378, l=1, mr=0x7f6532e5ff50) at .../exec.c:2647 > ptr = 0x0 > val = 62 > result = 0 > release_lock = true > #20 0x00007f6531abdd4e in address_space_write (as=0x7f65325ddd80 <address_space_memory>, addr=4292887522, attrs=..., buf=0x7f6531894028 ">\020", len=1) at .../exec.c:2692 > l = 1 > addr1 = 17378 > mr = 0x7f6532e5ff50 > result = 0 > #21 0x00007f6531abe078 in address_space_rw (as=0x7f65325ddd80 <address_space_memory>, addr=4292887522, attrs=..., buf=0x7f6531894028 ">\020", len=1, is_write=true) at .../exec.c:2794 > No locals. > #22 0x00007f6531b0d039 in kvm_cpu_exec (cpu=0x7f6532c4f9b0) at .../kvm-all.c:1968 > attrs = {unspecified = 0, secure = 0, user = 0, requester_id = 0} > run = 0x7f6531894000 > ret = 0 > run_ret = 0 > #23 0x00007f6531af4f0a in qemu_kvm_cpu_thread_fn (arg=0x7f6532c4f9b0) at .../cpus.c:1000 > cpu = 0x7f6532c4f9b0 > r = 0 > #24 0x00007f6528930dc5 in start_thread () from /lib64/libpthread.so.0 > No symbol table info available. > #25 0x00007f6525bad73d in clone () from /lib64/libc.so.6 > No symbol table info available. > > Thread 10 (Thread 0x7f651d4ba700 (LWP 8554)): > #0 0x00007f6525ba4507 in ioctl () from /lib64/libc.so.6 > No symbol table info available. > #1 0x00007f6531b0d526 in kvm_vcpu_ioctl (cpu=0x7f6532cb2810, type=44672) at .../kvm-all.c:2080 > ret = 32613 > arg = 0x0 > ap = {{gp_offset = 24, fp_offset = 48, overflow_arg_area = 0x7f651d4b99b0, reg_save_area = 0x7f651d4b98f0}} > #2 0x00007f6531b0cede in kvm_cpu_exec (cpu=0x7f6532cb2810) at .../kvm-all.c:1929 > attrs = {unspecified = 0, secure = 0, user = 0, requester_id = 29500} > run = 0x7f6531891000 > ret = 32613 > run_ret = 32613 > #3 0x00007f6531af4f0a in qemu_kvm_cpu_thread_fn (arg=0x7f6532cb2810) at .../cpus.c:1000 > cpu = 0x7f6532cb2810 > r = 65536 > #4 0x00007f6528930dc5 in start_thread () from /lib64/libpthread.so.0 > No symbol table info available. > #5 0x00007f6525bad73d in clone () from /lib64/libc.so.6 > No symbol table info available. > > Thread 9 (Thread 0x7f651ccb9700 (LWP 8555)): > #0 0x00007f6525ba4507 in ioctl () from /lib64/libc.so.6 > No symbol table info available. > #1 0x00007f6531b0d526 in kvm_vcpu_ioctl (cpu=0x7f6532cd2310, type=44672) at .../kvm-all.c:2080 > ret = 32613 > arg = 0x0 > ap = {{gp_offset = 24, fp_offset = 48, overflow_arg_area = 0x7f651ccb89b0, reg_save_area = 0x7f651ccb88f0}} > #2 0x00007f6531b0cede in kvm_cpu_exec (cpu=0x7f6532cd2310) at .../kvm-all.c:1929 > attrs = {unspecified = 0, secure = 0, user = 0, requester_id = 28988} > run = 0x7f653188e000 > ret = 32613 > run_ret = 32613 > #3 0x00007f6531af4f0a in qemu_kvm_cpu_thread_fn (arg=0x7f6532cd2310) at .../cpus.c:1000 > cpu = 0x7f6532cd2310 > r = 65536 > #4 0x00007f6528930dc5 in start_thread () from /lib64/libpthread.so.0 > No symbol table info available. > #5 0x00007f6525bad73d in clone () from /lib64/libc.so.6 > No symbol table info available. > > Thread 8 (Thread 0x7f650ffff700 (LWP 8556)): > #0 0x00007f6525ba4507 in ioctl () from /lib64/libc.so.6 > No symbol table info available. > #1 0x00007f6531b0d526 in kvm_vcpu_ioctl (cpu=0x7f6532cf1e40, type=44672) at .../kvm-all.c:2080 > ret = 32613 > arg = 0x0 > ap = {{gp_offset = 24, fp_offset = 48, overflow_arg_area = 0x7f650fffe9b0, reg_save_area = 0x7f650fffe8f0}} > #2 0x00007f6531b0cede in kvm_cpu_exec (cpu=0x7f6532cf1e40) at .../kvm-all.c:1929 > attrs = {unspecified = 0, secure = 0, user = 0, requester_id = 64828} > run = 0x7f653188b000 > ret = 32613 > run_ret = 32613 > #3 0x00007f6531af4f0a in qemu_kvm_cpu_thread_fn (arg=0x7f6532cf1e40) at .../cpus.c:1000 > cpu = 0x7f6532cf1e40 > r = 65536 > #4 0x00007f6528930dc5 in start_thread () from /lib64/libpthread.so.0 > No symbol table info available. > #5 0x00007f6525bad73d in clone () from /lib64/libc.so.6 > No symbol table info available. > > Thread 7 (Thread 0x7f650f7fe700 (LWP 8557)): > #0 0x00007f6525ba4507 in ioctl () from /lib64/libc.so.6 > No symbol table info available. > #1 0x00007f6531b0d526 in kvm_vcpu_ioctl (cpu=0x7f6532d11750, type=44672) at .../kvm-all.c:2080 > ret = 32613 > arg = 0x0 > ap = {{gp_offset = 24, fp_offset = 48, overflow_arg_area = 0x7f650f7fd9b0, reg_save_area = 0x7f650f7fd8f0}} > #2 0x00007f6531b0cede in kvm_cpu_exec (cpu=0x7f6532d11750) at .../kvm-all.c:1929 > attrs = {unspecified = 0, secure = 0, user = 0, requester_id = 64316} > run = 0x7f6531888000 > ret = 32613 > run_ret = 32613 > #3 0x00007f6531af4f0a in qemu_kvm_cpu_thread_fn (arg=0x7f6532d11750) at .../cpus.c:1000 > cpu = 0x7f6532d11750 > r = 65536 > #4 0x00007f6528930dc5 in start_thread () from /lib64/libpthread.so.0 > No symbol table info available. > #5 0x00007f6525bad73d in clone () from /lib64/libc.so.6 > No symbol table info available. > > Thread 6 (Thread 0x7f650effd700 (LWP 8558)): > #0 0x00007f6525ba4507 in ioctl () from /lib64/libc.so.6 > No symbol table info available. > #1 0x00007f6531b0d526 in kvm_vcpu_ioctl (cpu=0x7f6532d31060, type=44672) at .../kvm-all.c:2080 > ret = 32613 > arg = 0x0 > ap = {{gp_offset = 24, fp_offset = 48, overflow_arg_area = 0x7f650effc9b0, reg_save_area = 0x7f650effc8f0}} > #2 0x00007f6531b0cede in kvm_cpu_exec (cpu=0x7f6532d31060) at .../kvm-all.c:1929 > attrs = {unspecified = 0, secure = 0, user = 0, requester_id = 63804} > run = 0x7f6531885000 > ret = 32613 > run_ret = 32613 > #3 0x00007f6531af4f0a in qemu_kvm_cpu_thread_fn (arg=0x7f6532d31060) at .../cpus.c:1000 > cpu = 0x7f6532d31060 > r = 65536 > #4 0x00007f6528930dc5 in start_thread () from /lib64/libpthread.so.0 > No symbol table info available. > #5 0x00007f6525bad73d in clone () from /lib64/libc.so.6 > No symbol table info available. > > Thread 5 (Thread 0x7f650e7fc700 (LWP 8559)): > #0 0x00007f6525ba4507 in ioctl () from /lib64/libc.so.6 > No symbol table info available. > #1 0x00007f6531b0d526 in kvm_vcpu_ioctl (cpu=0x7f6532d51190, type=44672) at .../kvm-all.c:2080 > ret = 32613 > arg = 0x0 > ap = {{gp_offset = 24, fp_offset = 48, overflow_arg_area = 0x7f650e7fb9b0, reg_save_area = 0x7f650e7fb8f0}} > #2 0x00007f6531b0cede in kvm_cpu_exec (cpu=0x7f6532d51190) at .../kvm-all.c:1929 > attrs = {unspecified = 0, secure = 0, user = 0, requester_id = 63292} > run = 0x7f6531882000 > ret = 32613 > run_ret = 32613 > #3 0x00007f6531af4f0a in qemu_kvm_cpu_thread_fn (arg=0x7f6532d51190) at .../cpus.c:1000 > cpu = 0x7f6532d51190 > r = 65536 > #4 0x00007f6528930dc5 in start_thread () from /lib64/libpthread.so.0 > No symbol table info available. > #5 0x00007f6525bad73d in clone () from /lib64/libc.so.6 > No symbol table info available. > > Thread 4 (Thread 0x7f650dffb700 (LWP 8560)): > #0 0x00007f6525ba4507 in ioctl () from /lib64/libc.so.6 > No symbol table info available. > #1 0x00007f6531b0d526 in kvm_vcpu_ioctl (cpu=0x7f6532d70a90, type=44672) at .../kvm-all.c:2080 > ret = 32613 > arg = 0x0 > ap = {{gp_offset = 24, fp_offset = 48, overflow_arg_area = 0x7f650dffa9b0, reg_save_area = 0x7f650dffa8f0}} > #2 0x00007f6531b0cede in kvm_cpu_exec (cpu=0x7f6532d70a90) at .../kvm-all.c:1929 > attrs = {unspecified = 0, secure = 0, user = 0, requester_id = 62780} > run = 0x7f653187f000 > ret = 32613 > run_ret = 32613 > #3 0x00007f6531af4f0a in qemu_kvm_cpu_thread_fn (arg=0x7f6532d70a90) at .../cpus.c:1000 > cpu = 0x7f6532d70a90 > r = 65536 > #4 0x00007f6528930dc5 in start_thread () from /lib64/libpthread.so.0 > No symbol table info available. > #5 0x00007f6525bad73d in clone () from /lib64/libc.so.6 > No symbol table info available. > > Thread 3 (Thread 0x7f63af22c700 (LWP 8562)): > #0 0x00007f6525ba2dfd in poll () from /lib64/libc.so.6 > No symbol table info available. > #1 0x00007f652744a327 in red_worker_main () from /lib64/libspice-server.so.1 > No symbol table info available. > #2 0x00007f6528930dc5 in start_thread () from /lib64/libpthread.so.0 > No symbol table info available. > #3 0x00007f6525bad73d in clone () from /lib64/libc.so.6 > No symbol table info available. > > Thread 2 (Thread 0x7f63ae9ff700 (LWP 8563)): > #0 0x00007f65289346d5 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 > No symbol table info available. > #1 0x00007f6531f72293 in qemu_cond_wait (cond=0x7f653443c710, mutex=0x7f653443c740) at .../util/qemu-thread-posix.c:133 > err = 32613 > __func__ = "qemu_cond_wait" > #2 0x00007f6531e7fd47 in vnc_worker_thread_loop (queue=0x7f653443c710) at .../ui/vnc-jobs.c:205 > job = 0x7f6534ca4700 > entry = 0x0 > tmp = 0x0 > vs = {sioc = 0x0, ioc = 0x0, ioc_tag = 0, disconnecting = 0, > dirty = {{0, 0, 0} <repeats 2048 times>}, lossy_rect = 0x0, vd = 0x0, > need_update = 0, force_update = 0, has_dirty = 0, features = 0, absolute > = 0, last_x = 0, last_y = 0, last_bmask = 0, client_width = 0, > client_height = 0, share_mode = 0, vnc_encoding = 0, major = 0, minor = > 0, auth = 0, subauth = 0, challenge = '\000' <repeats 15 times>, tls = > 0x0, sasl = {conn = 0x0, wantSSF = false, runSSF = false, waitWriteSSF = > 0, encoded = 0x0, encodedLength = 0, encodedOffset = 0, username = 0x0, > mechlist = 0x0}, encode_ws = false, websocket = false, info = 0x0, > output = {name = 0x0, capacity = 0, offset = 0, avg_size = 0, buffer = > 0x0}, input = {name = 0x0, capacity = 0, offset = 0, avg_size = 0, > buffer = 0x0}, write_pixels = 0x0, client_pf = {bits_per_pixel = 0 > '\000', bytes_per_pixel = 0 '\000', depth = 0 '\000', rmask = 0, gmask = > 0, bmask = 0, amask = 0, rshift = 0 '\000', gshift = 0 '\000', bshift = > 0 '\000', ashift = 0 '\000', rmax = 0 '\000', gmax = 0 '\000', bmax = 0 > '\000', amax = 0 '\000', rbits = 0 '\000', gbits = 0 '\000', bbits = 0 > '\000', abits = 0 '\000'}, client_format = 0, client_be = false, > audio_cap = 0x0, as = {freq = 0, nchannels = 0, fmt = AUD_FMT_U8, > endianness = 0}, read_handler = 0x0, read_handler_expect = 0, > modifiers_state = '\000' <repeats 255 times>, abort = false, > output_mutex = {lock = {__data = {__lock = 0, __count = 0, __owner = 0, > __nusers = 0, __kind = 0, __spins = 0, __list = {__prev = 0x0, __next = > 0x0}}, __size = '\000' <repeats 39 times>, __align = 0}}, bh = 0x0, > jobs_buffer = {name = 0x0, capacity = 0, offset = 0, avg_size = 0, > buffer = 0x0}, tight = {type = 0, quality = 0 '\000', compression = 0 > '\000', pixel24 = 0 '\000', tight = {name = 0x0, capacity = 0, offset = > 0, avg_size = 0, buffer = 0x0}, tmp = {name = 0x0, capacity = 0, offset > = 0, avg_size = 0, buffer = 0x0}, zlib = {name = 0x0, capacity = 0, > offset = 0, avg_size = 0, buffer = 0x0}, gradient = {name = 0x0, > capacity = 0, offset = 0, avg_size = 0, buffer = 0x0}, jpeg = {name = > 0x0, capacity = 0, offset = 0, avg_size = 0, buffer = 0x0}, png = {name > = 0x0, capacity = 0, offset = 0, avg_size = 0, buffer = 0x0}, levels = > {0, 0, 0, 0}, stream = {{next_in = 0x0, avail_in = 0, total_in = 0, > next_out = 0x0, avail_out = 0, total_out = 0, msg = 0x0, state = 0x0, > zalloc = 0x0, zfree = 0x0, opaque = 0x0, data_type = 0, adler = 0, > reserved = 0}, {next_in = 0x0, avail_in = 0, total_in = 0, next_out = > 0x0, avail_out = 0, total_out = 0, msg = 0x0, state = 0x0, zalloc = 0x0, > zfree = 0x0, opaque = 0x0, data_type = 0, adler = 0, reserved = 0}, > {next_in = 0x0, avail_in = 0, total_in = 0, next_out = 0x0, avail_out = > 0, total_out = 0, msg = 0x0, state = 0x0, zalloc = 0x0, zfree = 0x0, > opaque = 0x0, data_type = 0, adler = 0, reserved = 0}, {next_in = 0x0, > avail_in = 0, total_in = 0, next_out = 0x0, avail_out = 0, total_out = > 0, msg = 0x0, state = 0x0, zalloc = 0x0, zfree = 0x0, opaque = 0x0, > data_type = 0, adler = 0, reserved = 0}}}, zlib = {zlib = {name = 0x0, > capacity = 0, offset = 0, avg_size = 0, buffer = 0x0}, tmp = {name = > 0x0, capacity = 0, offset = 0, avg_size = 0, buffer = 0x0}, stream = > {next_in = 0x0, avail_in = 0, total_in = 0, next_out = 0x0, avail_out = > 0, total_out = 0, msg = 0x0, state = 0x0, zalloc = 0x0, zfree = 0x0, > opaque = 0x0, data_type = 0, adler = 0, reserved = 0}, level = 0}, > hextile = {send_tile = 0x0}, zrle = {type = 0, fb = {name = 0x0, > capacity = 0, offset = 0, avg_size = 0, buffer = 0x0}, zrle = {name = > 0x0, capacity = 0, offset = 0, avg_size = 0, buffer = 0x0}, tmp = {name > = 0x0, capacity = 0, offset = 0, avg_size = 0, buffer = 0x0}, zlib = > {name = 0x0, capacity = 0, offset = 0, avg_size = 0, buffer = 0x0}, > stream = {next_in = 0x0, avail_in = 0, total_in = 0, next_out = 0x0, > avail_out = 0, total_out = 0, msg = 0x0, state = 0x0, zalloc = 0x0, > zfree = 0x0, opaque = 0x0, data_type = 0, adler = 0, reserved = 0}, > palette = {pool = {{idx = 0, color = 0, next = {le_next = 0x0, le_prev = > 0x0}} <repeats 256 times>}, size = 0, max = 0, bpp = 0, table = > {{lh_first = 0x0} <repeats 256 times>}}}, zywrle = {buf = {0 <repeats > 4096 times>}}, mouse_mode_notifier = {notify = 0x0, node = {le_next = > 0x0, le_prev = 0x0}}, next = {tqe_next = 0x0, tqe_prev = 0x0}} > n_rectangles = 4 > saved_offset = 2 > #3 0x00007f6531e801cb in vnc_worker_thread (arg=0x7f653443c710) at .../ui/vnc-jobs.c:312 > queue = 0x7f653443c710 > #4 0x00007f6528930dc5 in start_thread () from /lib64/libpthread.so.0 > No symbol table info available. > #5 0x00007f6525bad73d in clone () from /lib64/libc.so.6 > No symbol table info available. > > Thread 1 (Thread 0x7f6531835c40 (LWP 8527)): > #0 0x00007f65289371bd in __lll_lock_wait () from /lib64/libpthread.so.0 > No symbol table info available. > #1 0x00007f6528932d02 in _L_lock_791 () from /lib64/libpthread.so.0 > No symbol table info available. > #2 0x00007f6528932c08 in pthread_mutex_lock () from /lib64/libpthread.so.0 > No symbol table info available. > #3 0x00007f6531f720cd in qemu_mutex_lock (mutex=0x7f6532606940 <qemu_global_mutex>) at .../util/qemu-thread-posix.c:60 > err = 0 > __func__ = "qemu_mutex_lock" > #4 0x00007f6531af5830 in qemu_mutex_lock_iothread () at .../cpus.c:1351 > No locals. > #5 0x00007f6531f6e8af in os_host_main_loop_wait (timeout=902507) at .../util/main-loop.c:257 > ret = 1 > spin_counter = 0 > #6 0x00007f6531f6e955 in main_loop_wait (nonblocking=0) at .../util/main-loop.c:508 > ret = 0 > timeout = 4294967295 > timeout_ns = 902507 > #7 0x00007f6531c2bd89 in main_loop () at .../vl.c:1877 > nonblocking = false > last_io = 0 > #8 0x00007f6531c335e0 in main (argc=88, argv=0x7ffd256a2918, envp=0x7ffd256a2be0) at .../vl.c:4628 > i = 32613 > snapshot = 0 > linux_boot = 0 > initrd_filename = 0x0 > kernel_filename = 0x0 > kernel_cmdline = 0x7f6531fc713e "" > boot_order = 0x7f6531faf741 "cad" > boot_once = 0x0 > ds = 0x7f6534ca4120 > cyls = 0 > heads = 0 > secs = 0 > translation = 0 > hda_opts = 0x0 > opts = 0x7f6532b6ec50 > machine_opts = 0x7f6532b6d840 > icount_opts = 0x0 > olist = 0x7f65324903a0 <qemu_machine_opts> > optind = 88 > optarg = 0x7ffd256a4f54 "timestamp=on" > loadvm = 0x0 > machine_class = 0x7f6532b96800 > cpu_model = 0x7ffd256a464a "Haswell-noTSX,+vmx" > vga_model = 0x0 > qtest_chrdev = 0x0 > qtest_log = 0x0 > pid_file = 0x0 > incoming = 0x0 > defconfig = true > userconfig = false > nographic = false > display_type = DT_DEFAULT > display_remote = 1 > log_mask = 0x0 > log_file = 0x0 > trace_file = 0x0 > maxram_size = 5368709120 > ram_slots = 0 > vmstate_dump_file = 0x0 > main_loop_err = 0x0 > err = 0x0 > list_data_dirs = false > __func__ = "main" > __FUNCTION__ = "main"
On 21/02/2017 13:57, Gerd Hoffmann wrote: > This change breaks ovmf for me, although it isn't obvious to me why. > Bisect landed here, and reverting indeed makes things going again. > > Using q35 machine type, pcie virtio devices, with the rhel ovmf build > (OVMF-20160608b-1.git988715a.el7.noarch). > > First thing I've tried is swapping virtio-net for another nic, > suspecting this change might trigger a bug in the ovmf virtio-net > driver, but that didn't change things. > > Effect is that qemu just exits, without logging some error, looks like a > normal guest shutdown. Firmware log doesn't give a clue either, it just > stops at some point, again without any error message. Here are the last > lines of the log: > > SataControllerStart START > SataControllerStart error return status = Already started > SetPciIntLine: [00:1C.0] PciRoot(0x0)/Pci(0x1C,0x0) -> 0x0A > SetPciIntLine: [01:00.0] PciRoot(0x0)/Pci(0x1C,0x0)/Pci(0x0,0x0) -> 0x0A > SetPciIntLine: [00:1C.1] PciRoot(0x0)/Pci(0x1C,0x1) -> 0x0A > SetPciIntLine: [02:00.0] PciRoot(0x0)/Pci(0x1C,0x1)/Pci(0x0,0x0) -> 0x0A > SetPciIntLine: [00:1C.2] PciRoot(0x0)/Pci(0x1C,0x2) -> 0x0A > SetPciIntLine: [00:1C.3] PciRoot(0x0)/Pci(0x1C,0x3) -> 0x0A > SetPciIntLine: [00:1C.4] PciRoot(0x0)/Pci(0x1C,0x4) -> 0x0A > SetPciIntLine: [05:00.0] PciRoot(0x0)/Pci(0x1C,0x4)/Pci(0x0,0x0) -> 0x0A > SetPciIntLine: [05:00.1] PciRoot(0x0)/Pci(0x1C,0x4)/Pci(0x0,0x1) -> 0x0A > SetPciIntLine: [05:00.2] PciRoot(0x0)/Pci(0x1C,0x4)/Pci(0x0,0x2) -> 0x0A > SetPciIntLine: [00:1C.5] PciRoot(0x0)/Pci(0x1C,0x5) -> 0x0A > SetPciIntLine: [06:00.0] PciRoot(0x0)/Pci(0x1C,0x5)/Pci(0x0,0x0) -> 0x0A > SetPciIntLine: [00:1C.6] PciRoot(0x0)/Pci(0x1C,0x6) -> 0x0A > SetPciIntLine: [00:1C.7] PciRoot(0x0)/Pci(0x1C,0x7) -> 0x0A > SetPciIntLine: [00:1F.2] PciRoot(0x0)/Pci(0x1F,0x2) -> 0x0A > SetPciIntLine: [00:1F.3] PciRoot(0x0)/Pci(0x1F,0x3) -> 0x0A > Select Item: 0x8 > Select Item: 0x17 > qemu -kernel was not used. Command line? I tried with x86_64-softmmu/qemu-system-x86_64 \ -pflash /usr/share/edk2/ovmf/OVMF_CODE.fd \ -pflash /usr/share/edk2/ovmf/OVMF_VARS.fd \ --enable-kvm -M q35 -debugcon stdio \ -global isa-debugcon.iobase=0x402 \ -net nic,model=virtio \ -net bridge,helper=/usr/libexec/qemu-bridge-helper,br=virbr0 \ -snapshot foo.raw and after the above lines I get: Select Item: 0x19 [Bds]OsIndication: 0000000000000000 [Bds]=============Begin Load Options Dumping ...============= Driver Options: SysPrep Options: Boot Options: Boot0000: UiApp 0x0109 Boot0001: UEFI QEMU DVD-ROM QM00005 0x0001 Boot0002: UEFI QEMU HARDDISK QM00001 0x0001 Boot0003: EFI Internal Shell 0x0001 PlatformRecovery Options: PlatformRecovery0000: Default PlatformRecovery 0x0001 (but I'm using a different OVMF build, edk2-ovmf-20161105git3b25ca8-2.fc25.noarch; dinner time now). Thanks, Paolo
On 02/21/17 19:08, Paolo Bonzini wrote: > > > On 21/02/2017 13:57, Gerd Hoffmann wrote: >> This change breaks ovmf for me, although it isn't obvious to me why. >> Bisect landed here, and reverting indeed makes things going again. >> >> Using q35 machine type, pcie virtio devices, with the rhel ovmf build >> (OVMF-20160608b-1.git988715a.el7.noarch). >> >> First thing I've tried is swapping virtio-net for another nic, >> suspecting this change might trigger a bug in the ovmf virtio-net >> driver, but that didn't change things. >> >> Effect is that qemu just exits, without logging some error, looks like a >> normal guest shutdown. Firmware log doesn't give a clue either, it just >> stops at some point, again without any error message. Here are the last >> lines of the log: >> >> SataControllerStart START >> SataControllerStart error return status = Already started >> SetPciIntLine: [00:1C.0] PciRoot(0x0)/Pci(0x1C,0x0) -> 0x0A >> SetPciIntLine: [01:00.0] PciRoot(0x0)/Pci(0x1C,0x0)/Pci(0x0,0x0) -> 0x0A >> SetPciIntLine: [00:1C.1] PciRoot(0x0)/Pci(0x1C,0x1) -> 0x0A >> SetPciIntLine: [02:00.0] PciRoot(0x0)/Pci(0x1C,0x1)/Pci(0x0,0x0) -> 0x0A >> SetPciIntLine: [00:1C.2] PciRoot(0x0)/Pci(0x1C,0x2) -> 0x0A >> SetPciIntLine: [00:1C.3] PciRoot(0x0)/Pci(0x1C,0x3) -> 0x0A >> SetPciIntLine: [00:1C.4] PciRoot(0x0)/Pci(0x1C,0x4) -> 0x0A >> SetPciIntLine: [05:00.0] PciRoot(0x0)/Pci(0x1C,0x4)/Pci(0x0,0x0) -> 0x0A >> SetPciIntLine: [05:00.1] PciRoot(0x0)/Pci(0x1C,0x4)/Pci(0x0,0x1) -> 0x0A >> SetPciIntLine: [05:00.2] PciRoot(0x0)/Pci(0x1C,0x4)/Pci(0x0,0x2) -> 0x0A >> SetPciIntLine: [00:1C.5] PciRoot(0x0)/Pci(0x1C,0x5) -> 0x0A >> SetPciIntLine: [06:00.0] PciRoot(0x0)/Pci(0x1C,0x5)/Pci(0x0,0x0) -> 0x0A >> SetPciIntLine: [00:1C.6] PciRoot(0x0)/Pci(0x1C,0x6) -> 0x0A >> SetPciIntLine: [00:1C.7] PciRoot(0x0)/Pci(0x1C,0x7) -> 0x0A >> SetPciIntLine: [00:1F.2] PciRoot(0x0)/Pci(0x1F,0x2) -> 0x0A >> SetPciIntLine: [00:1F.3] PciRoot(0x0)/Pci(0x1F,0x3) -> 0x0A >> Select Item: 0x8 >> Select Item: 0x17 >> qemu -kernel was not used. > > Command line? I tried with > > x86_64-softmmu/qemu-system-x86_64 \ > -pflash /usr/share/edk2/ovmf/OVMF_CODE.fd \ > -pflash /usr/share/edk2/ovmf/OVMF_VARS.fd \ > --enable-kvm -M q35 -debugcon stdio \ > -global isa-debugcon.iobase=0x402 \ > -net nic,model=virtio \ > -net bridge,helper=/usr/libexec/qemu-bridge-helper,br=virbr0 \ > -snapshot foo.raw > > and after the above lines I get: > > Select Item: 0x19 > [Bds]OsIndication: 0000000000000000 > [Bds]=============Begin Load Options Dumping ...============= > Driver Options: > SysPrep Options: > Boot Options: > Boot0000: UiApp 0x0109 > Boot0001: UEFI QEMU DVD-ROM QM00005 0x0001 > Boot0002: UEFI QEMU HARDDISK QM00001 0x0001 > Boot0003: EFI Internal Shell 0x0001 > PlatformRecovery Options: > PlatformRecovery0000: Default PlatformRecovery 0x0001 > > (but I'm using a different OVMF build, > edk2-ovmf-20161105git3b25ca8-2.fc25.noarch; dinner time now). The bug reproduces for me with current upstream OVMF. I sent a full QEMU backtrace (SIGSEGV) in another message. I use libvirt (and I assume Gerd does that too, because otherwise the shell would report the SIGSEGV immediately). Interestingly, in that call stack, I see pflash_update -> blk_pwrite -> blk_prw -> aio_poll -> ... -> virtio_queue_host_notifier_aio_poll. Therefore the direct trigger seems to be a UEFI variable update, but I don't understand how that lands in virtio code in QEMU. Thanks Laszlo
Hi, > The bug reproduces for me with current upstream OVMF. I sent a full QEMU > backtrace (SIGSEGV) in another message. I use libvirt (and I assume Gerd > does that too, because otherwise the shell would report the SIGSEGV > immediately). libvirt indeed, config attached. cheers, Gerd
diff --git a/hw/net/virtio-net.c b/hw/net/virtio-net.c index 354a19e..c321680 100644 --- a/hw/net/virtio-net.c +++ b/hw/net/virtio-net.c @@ -1130,7 +1130,8 @@ static int receive_filter(VirtIONet *n, const uint8_t *buf, int size) return 0; } -static ssize_t virtio_net_receive(NetClientState *nc, const uint8_t *buf, size_t size) +static ssize_t virtio_net_receive_rcu(NetClientState *nc, const uint8_t *buf, + size_t size) { VirtIONet *n = qemu_get_nic_opaque(nc); VirtIONetQueue *q = virtio_net_get_subqueue(nc); @@ -1233,6 +1234,17 @@ static ssize_t virtio_net_receive(NetClientState *nc, const uint8_t *buf, size_t return size; } +static ssize_t virtio_net_receive(NetClientState *nc, const uint8_t *buf, + size_t size) +{ + ssize_t r; + + rcu_read_lock(); + r = virtio_net_receive_rcu(nc, buf, size); + rcu_read_unlock(); + return r; +} + static int32_t virtio_net_flush_tx(VirtIONetQueue *q); static void virtio_net_tx_complete(NetClientState *nc, ssize_t len) diff --git a/hw/virtio/virtio.c b/hw/virtio/virtio.c index cdafcec..c08e50f 100644 --- a/hw/virtio/virtio.c +++ b/hw/virtio/virtio.c @@ -173,6 +173,7 @@ void virtio_queue_update_rings(VirtIODevice *vdev, int n) virtio_init_region_cache(vdev, n); } +/* Called within rcu_read_lock(). */ static void vring_desc_read(VirtIODevice *vdev, VRingDesc *desc, MemoryRegionCache *cache, int i) { @@ -184,88 +185,110 @@ static void vring_desc_read(VirtIODevice *vdev, VRingDesc *desc, virtio_tswap16s(vdev, &desc->next); } +/* Called within rcu_read_lock(). */ static inline uint16_t vring_avail_flags(VirtQueue *vq) { - hwaddr pa; - pa = vq->vring.avail + offsetof(VRingAvail, flags); - return virtio_lduw_phys(vq->vdev, pa); + VRingMemoryRegionCaches *caches = atomic_rcu_read(&vq->vring.caches); + hwaddr pa = offsetof(VRingAvail, flags); + return virtio_lduw_phys_cached(vq->vdev, &caches->avail, pa); } +/* Called within rcu_read_lock(). */ static inline uint16_t vring_avail_idx(VirtQueue *vq) { - hwaddr pa; - pa = vq->vring.avail + offsetof(VRingAvail, idx); - vq->shadow_avail_idx = virtio_lduw_phys(vq->vdev, pa); + VRingMemoryRegionCaches *caches = atomic_rcu_read(&vq->vring.caches); + hwaddr pa = offsetof(VRingAvail, idx); + vq->shadow_avail_idx = virtio_lduw_phys_cached(vq->vdev, &caches->avail, pa); return vq->shadow_avail_idx; } +/* Called within rcu_read_lock(). */ static inline uint16_t vring_avail_ring(VirtQueue *vq, int i) { - hwaddr pa; - pa = vq->vring.avail + offsetof(VRingAvail, ring[i]); - return virtio_lduw_phys(vq->vdev, pa); + VRingMemoryRegionCaches *caches = atomic_rcu_read(&vq->vring.caches); + hwaddr pa = offsetof(VRingAvail, ring[i]); + return virtio_lduw_phys_cached(vq->vdev, &caches->avail, pa); } +/* Called within rcu_read_lock(). */ static inline uint16_t vring_get_used_event(VirtQueue *vq) { return vring_avail_ring(vq, vq->vring.num); } +/* Called within rcu_read_lock(). */ static inline void vring_used_write(VirtQueue *vq, VRingUsedElem *uelem, int i) { - hwaddr pa; + VRingMemoryRegionCaches *caches = atomic_rcu_read(&vq->vring.caches); + hwaddr pa = offsetof(VRingUsed, ring[i]); virtio_tswap32s(vq->vdev, &uelem->id); virtio_tswap32s(vq->vdev, &uelem->len); - pa = vq->vring.used + offsetof(VRingUsed, ring[i]); - address_space_write(vq->vdev->dma_as, pa, MEMTXATTRS_UNSPECIFIED, - (void *)uelem, sizeof(VRingUsedElem)); + address_space_write_cached(&caches->used, pa, uelem, sizeof(VRingUsedElem)); + address_space_cache_invalidate(&caches->used, pa, sizeof(VRingUsedElem)); } +/* Called within rcu_read_lock(). */ static uint16_t vring_used_idx(VirtQueue *vq) { - hwaddr pa; - pa = vq->vring.used + offsetof(VRingUsed, idx); - return virtio_lduw_phys(vq->vdev, pa); + VRingMemoryRegionCaches *caches = atomic_rcu_read(&vq->vring.caches); + hwaddr pa = offsetof(VRingUsed, idx); + return virtio_lduw_phys_cached(vq->vdev, &caches->used, pa); } +/* Called within rcu_read_lock(). */ static inline void vring_used_idx_set(VirtQueue *vq, uint16_t val) { - hwaddr pa; - pa = vq->vring.used + offsetof(VRingUsed, idx); - virtio_stw_phys(vq->vdev, pa, val); + VRingMemoryRegionCaches *caches = atomic_rcu_read(&vq->vring.caches); + hwaddr pa = offsetof(VRingUsed, idx); + virtio_stw_phys_cached(vq->vdev, &caches->used, pa, val); + address_space_cache_invalidate(&caches->used, pa, sizeof(val)); vq->used_idx = val; } +/* Called within rcu_read_lock(). */ static inline void vring_used_flags_set_bit(VirtQueue *vq, int mask) { + VRingMemoryRegionCaches *caches = atomic_rcu_read(&vq->vring.caches); VirtIODevice *vdev = vq->vdev; - hwaddr pa; - pa = vq->vring.used + offsetof(VRingUsed, flags); - virtio_stw_phys(vdev, pa, virtio_lduw_phys(vdev, pa) | mask); + hwaddr pa = offsetof(VRingUsed, flags); + uint16_t flags = virtio_lduw_phys_cached(vq->vdev, &caches->used, pa); + + virtio_stw_phys_cached(vdev, &caches->used, pa, flags | mask); + address_space_cache_invalidate(&caches->used, pa, sizeof(flags)); } +/* Called within rcu_read_lock(). */ static inline void vring_used_flags_unset_bit(VirtQueue *vq, int mask) { + VRingMemoryRegionCaches *caches = atomic_rcu_read(&vq->vring.caches); VirtIODevice *vdev = vq->vdev; - hwaddr pa; - pa = vq->vring.used + offsetof(VRingUsed, flags); - virtio_stw_phys(vdev, pa, virtio_lduw_phys(vdev, pa) & ~mask); + hwaddr pa = offsetof(VRingUsed, flags); + uint16_t flags = virtio_lduw_phys_cached(vq->vdev, &caches->used, pa); + + virtio_stw_phys_cached(vdev, &caches->used, pa, flags & ~mask); + address_space_cache_invalidate(&caches->used, pa, sizeof(flags)); } +/* Called within rcu_read_lock(). */ static inline void vring_set_avail_event(VirtQueue *vq, uint16_t val) { + VRingMemoryRegionCaches *caches; hwaddr pa; if (!vq->notification) { return; } - pa = vq->vring.used + offsetof(VRingUsed, ring[vq->vring.num]); - virtio_stw_phys(vq->vdev, pa, val); + + caches = atomic_rcu_read(&vq->vring.caches); + pa = offsetof(VRingUsed, ring[vq->vring.num]); + virtio_stw_phys_cached(vq->vdev, &caches->used, pa, val); } void virtio_queue_set_notification(VirtQueue *vq, int enable) { vq->notification = enable; + + rcu_read_lock(); if (virtio_vdev_has_feature(vq->vdev, VIRTIO_RING_F_EVENT_IDX)) { vring_set_avail_event(vq, vring_avail_idx(vq)); } else if (enable) { @@ -277,6 +300,7 @@ void virtio_queue_set_notification(VirtQueue *vq, int enable) /* Expose avail event/used flags before caller checks the avail idx. */ smp_mb(); } + rcu_read_unlock(); } int virtio_queue_ready(VirtQueue *vq) @@ -285,8 +309,9 @@ int virtio_queue_ready(VirtQueue *vq) } /* Fetch avail_idx from VQ memory only when we really need to know if - * guest has added some buffers. */ -int virtio_queue_empty(VirtQueue *vq) + * guest has added some buffers. + * Called within rcu_read_lock(). */ +static int virtio_queue_empty_rcu(VirtQueue *vq) { if (vq->shadow_avail_idx != vq->last_avail_idx) { return 0; @@ -295,6 +320,20 @@ int virtio_queue_empty(VirtQueue *vq) return vring_avail_idx(vq) == vq->last_avail_idx; } +int virtio_queue_empty(VirtQueue *vq) +{ + bool empty; + + if (vq->shadow_avail_idx != vq->last_avail_idx) { + return 0; + } + + rcu_read_lock(); + empty = vring_avail_idx(vq) == vq->last_avail_idx; + rcu_read_unlock(); + return empty; +} + static void virtqueue_unmap_sg(VirtQueue *vq, const VirtQueueElement *elem, unsigned int len) { @@ -373,6 +412,7 @@ bool virtqueue_rewind(VirtQueue *vq, unsigned int num) return true; } +/* Called within rcu_read_lock(). */ void virtqueue_fill(VirtQueue *vq, const VirtQueueElement *elem, unsigned int len, unsigned int idx) { @@ -393,6 +433,7 @@ void virtqueue_fill(VirtQueue *vq, const VirtQueueElement *elem, vring_used_write(vq, &uelem, idx); } +/* Called within rcu_read_lock(). */ void virtqueue_flush(VirtQueue *vq, unsigned int count) { uint16_t old, new; @@ -416,10 +457,13 @@ void virtqueue_flush(VirtQueue *vq, unsigned int count) void virtqueue_push(VirtQueue *vq, const VirtQueueElement *elem, unsigned int len) { + rcu_read_lock(); virtqueue_fill(vq, elem, len, 0); virtqueue_flush(vq, 1); + rcu_read_unlock(); } +/* Called within rcu_read_lock(). */ static int virtqueue_num_heads(VirtQueue *vq, unsigned int idx) { uint16_t num_heads = vring_avail_idx(vq) - idx; @@ -439,6 +483,7 @@ static int virtqueue_num_heads(VirtQueue *vq, unsigned int idx) return num_heads; } +/* Called within rcu_read_lock(). */ static bool virtqueue_get_head(VirtQueue *vq, unsigned int idx, unsigned int *head) { @@ -740,8 +785,9 @@ void *virtqueue_pop(VirtQueue *vq, size_t sz) if (unlikely(vdev->broken)) { return NULL; } - if (virtio_queue_empty(vq)) { - return NULL; + rcu_read_lock(); + if (virtio_queue_empty_rcu(vq)) { + goto done; } /* Needed after virtio_queue_empty(), see comment in * virtqueue_num_heads(). */ @@ -754,11 +800,11 @@ void *virtqueue_pop(VirtQueue *vq, size_t sz) if (vq->inuse >= vq->vring.num) { virtio_error(vdev, "Virtqueue size exceeded"); - return NULL; + goto done; } if (!virtqueue_get_head(vq, vq->last_avail_idx++, &head)) { - return NULL; + goto done; } if (virtio_vdev_has_feature(vdev, VIRTIO_RING_F_EVENT_IDX)) { @@ -767,7 +813,6 @@ void *virtqueue_pop(VirtQueue *vq, size_t sz) i = head; - rcu_read_lock(); caches = atomic_rcu_read(&vq->vring.caches); if (caches->desc.len < max * sizeof(VRingDesc)) { virtio_error(vdev, "Cannot map descriptor ring"); @@ -1483,6 +1528,7 @@ static void virtio_set_isr(VirtIODevice *vdev, int value) } } +/* Called within rcu_read_lock(). */ static bool virtio_should_notify(VirtIODevice *vdev, VirtQueue *vq) { uint16_t old, new; @@ -1508,7 +1554,12 @@ static bool virtio_should_notify(VirtIODevice *vdev, VirtQueue *vq) void virtio_notify_irqfd(VirtIODevice *vdev, VirtQueue *vq) { - if (!virtio_should_notify(vdev, vq)) { + bool should_notify; + rcu_read_lock(); + should_notify = virtio_should_notify(vdev, vq); + rcu_read_unlock(); + + if (!should_notify) { return; } @@ -1535,7 +1586,12 @@ void virtio_notify_irqfd(VirtIODevice *vdev, VirtQueue *vq) void virtio_notify(VirtIODevice *vdev, VirtQueue *vq) { - if (!virtio_should_notify(vdev, vq)) { + bool should_notify; + rcu_read_lock(); + should_notify = virtio_should_notify(vdev, vq); + rcu_read_unlock(); + + if (!should_notify) { return; } @@ -1996,6 +2052,7 @@ int virtio_load(VirtIODevice *vdev, QEMUFile *f, int version_id) } } + rcu_read_lock(); for (i = 0; i < num; i++) { if (vdev->vq[i].vring.desc) { uint16_t nheads; @@ -2030,6 +2087,7 @@ int virtio_load(VirtIODevice *vdev, QEMUFile *f, int version_id) } } } + rcu_read_unlock(); return 0; } @@ -2156,9 +2214,11 @@ void virtio_queue_set_last_avail_idx(VirtIODevice *vdev, int n, uint16_t idx) void virtio_queue_update_used_idx(VirtIODevice *vdev, int n) { + rcu_read_lock(); if (vdev->vq[n].vring.desc) { vdev->vq[n].used_idx = vring_used_idx(&vdev->vq[n]); } + rcu_read_unlock(); } void virtio_queue_invalidate_signalled_used(VirtIODevice *vdev, int n)