| Message ID | 56EAC706.2040006@redhat.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
On 03/17/2016 04:02 PM, Paolo Bonzini wrote: > > > On 17/03/2016 13:39, Christian Borntraeger wrote: >> As an interesting side note, I updated my system from F20 to F23 some days ago >> (after the initial report). While To Bo is still on a F20 system. I was not able >> to reproduce the original crash on f23. but going back to F20 made this >> problem re-appear. >> >> Stack trace of thread 26429: >> #0 0x00000000802008aa tracked_request_begin (qemu-system-s390x) >> #1 0x0000000080203f3c bdrv_co_do_preadv (qemu-system-s390x) >> #2 0x000000008020567c bdrv_co_do_readv (qemu-system-s390x) >> #3 0x000000008025d0f4 coroutine_trampoline (qemu-system-s390x) >> #4 0x000003ff943d150a __makecontext_ret (libc.so.6) >> >> this is with patch 2-4 plus the removal of virtio_queue_host_notifier_read. >> >> Without removing virtio_queue_host_notifier_read, I get the same mutex lockup (as expected). >> >> Maybe we have two independent issues here and this is some old bug in glibc or >> whatever? > > I'm happy to try and reproduce on x86 if you give me some instruction > (RHEL7 should be close enough to Fedora 20). Tu Bo has a standard guest that he starting multiple times. I can trigger some issues by starting 20 guests that only have a kernel (with virtio-blk and bus driver compiled in) and a busybox ramdisk that simply calls reboot. Sooner or later a qemu crashes. This guest has several virtio devices attached as well (partition detection will do minimal reads) ala <qemu:commandline> <qemu:arg value='-drive'/> <qemu:arg value='driver=null-co,id=null1,if=none,size=100G'/> <qemu:arg value='-device'/> <qemu:arg value='virtio-blk-ccw,scsi=off,drive=null1,serial=null1,iothread=iothread1'/> <qemu:arg value='-drive'/> <qemu:arg value='driver=null-co,id=null2,if=none,size=100G'/> <qemu:arg value='-device'/> <qemu:arg value='virtio-blk-ccw,scsi=off,drive=null2,serial=null2,iothread=iothread1'/> <qemu:arg value='-drive'/> <qemu:arg value='driver=null-co,id=null3,if=none,size=100G'/> <qemu:arg value='-device'/> <qemu:arg value='virtio-blk-ccw,scsi=off,drive=null3,serial=null3,iothread=iothread1'/> <qemu:arg value='-drive'/> <qemu:arg value='driver=null-co,id=null4,if=none,size=100G'/> <qemu:arg value='-device'/> <qemu:arg value='virtio-blk-ccw,scsi=off,drive=null4,serial=null4,iothread=iothread1'/> <qemu:arg value='-drive'/> <qemu:arg value='driver=null-co,id=null5,if=none,size=100G'/> <qemu:arg value='-device'/> <qemu:arg value='virtio-blk-ccw,scsi=off,drive=null5,serial=null5,iothread=iothread1'/> <qemu:arg value='-drive'/> <qemu:arg value='driver=null-co,id=null6,if=none,size=100G'/> <qemu:arg value='-device'/> <qemu:arg value='virtio-blk-ccw,scsi=off,drive=null6,serial=null6,iothread=iothread1'/> <qemu:arg value='-drive'/> <qemu:arg value='driver=null-co,id=null7,if=none,size=100G'/> <qemu:arg value='-device'/> <qemu:arg value='virtio-blk-ccw,scsi=off,drive=null7,serial=null7,iothread=iothread1'/> <qemu:arg value='-drive'/> <qemu:arg value='driver=null-co,id=null8,if=none,size=100G'/> <qemu:arg value='-device'/> <qemu:arg value='virtio-blk-ccw,scsi=off,drive=null8,serial=null8,iothread=iothread1'/> </qemu:commandline> > > Can you add an assert in virtio_blk_handle_output to catch reentrancy, like Will do. > > diff --git a/hw/block/virtio-blk.c b/hw/block/virtio-blk.c > index a7ec572..96ea896 100644 > --- a/hw/block/virtio-blk.c > +++ b/hw/block/virtio-blk.c > @@ -591,6 +591,8 @@ static void virtio_blk_handle_output(VirtIODevice > *vdev, VirtQueue *vq) > return; > } > > + int x = atomic_fetch_inc(&s->test); > + assert(x == 0); > blk_io_plug(s->blk); > > while ((req = virtio_blk_get_request(s))) { > @@ -602,6 +604,7 @@ static void virtio_blk_handle_output(VirtIODevice > *vdev, VirtQueue *vq) > } > > blk_io_unplug(s->blk); > + atomic_dec(&s->test); > } > > static void virtio_blk_dma_restart_bh(void *opaque) > diff --git a/include/hw/virtio/virtio-blk.h b/include/hw/virtio/virtio-blk.h > index ae84d92..6472503 100644 > --- a/include/hw/virtio/virtio-blk.h > +++ b/include/hw/virtio/virtio-blk.h > @@ -48,6 +48,7 @@ typedef struct VirtIOBlock { > BlockBackend *blk; > VirtQueue *vq; > void *rq; > + int test; > QEMUBH *bh; > VirtIOBlkConf conf; > unsigned short sector_mask; > > ? > > Paolo >
On 03/17/2016 04:02 PM, Paolo Bonzini wrote: > > > On 17/03/2016 13:39, Christian Borntraeger wrote: >> As an interesting side note, I updated my system from F20 to F23 some days ago >> (after the initial report). While To Bo is still on a F20 system. I was not able >> to reproduce the original crash on f23. but going back to F20 made this >> problem re-appear. >> >> Stack trace of thread 26429: >> #0 0x00000000802008aa tracked_request_begin (qemu-system-s390x) >> #1 0x0000000080203f3c bdrv_co_do_preadv (qemu-system-s390x) >> #2 0x000000008020567c bdrv_co_do_readv (qemu-system-s390x) >> #3 0x000000008025d0f4 coroutine_trampoline (qemu-system-s390x) >> #4 0x000003ff943d150a __makecontext_ret (libc.so.6) >> >> this is with patch 2-4 plus the removal of virtio_queue_host_notifier_read. >> >> Without removing virtio_queue_host_notifier_read, I get the same mutex lockup (as expected). >> >> Maybe we have two independent issues here and this is some old bug in glibc or >> whatever? > > I'm happy to try and reproduce on x86 if you give me some instruction > (RHEL7 should be close enough to Fedora 20). > > Can you add an assert in virtio_blk_handle_output to catch reentrancy, like that was quick (let me know if I should recompile with debugging) (gdb) thread apply all bt Thread 5 (Thread 0x3ff7b8ff910 (LWP 236419)): #0 0x000003ff7cdfcf56 in syscall () from /lib64/libc.so.6 #1 0x000000001022452e in futex_wait (val=<optimized out>, ev=<optimized out>) at /home/cborntra/REPOS/qemu/util/qemu-thread-posix.c:292 #2 qemu_event_wait (ev=ev@entry=0x1082b5c4 <rcu_call_ready_event>) at /home/cborntra/REPOS/qemu/util/qemu-thread-posix.c:399 #3 0x000000001023353a in call_rcu_thread (opaque=<optimized out>) at /home/cborntra/REPOS/qemu/util/rcu.c:250 #4 0x000003ff7cf084c6 in start_thread () from /lib64/libpthread.so.0 #5 0x000003ff7ce02ec2 in thread_start () from /lib64/libc.so.6 Thread 4 (Thread 0x3ff78eca910 (LWP 236426)): #0 0x000003ff7cdf819a in ioctl () from /lib64/libc.so.6 #1 0x000000001005ddf8 in kvm_vcpu_ioctl (cpu=cpu@entry=0x10c27d40, type=type@entry=44672) at /home/cborntra/REPOS/qemu/kvm-all.c:1984 #2 0x000000001005df1c in kvm_cpu_exec (cpu=cpu@entry=0x10c27d40) at /home/cborntra/REPOS/qemu/kvm-all.c:1834 #3 0x000000001004b1be in qemu_kvm_cpu_thread_fn (arg=0x10c27d40) at /home/cborntra/REPOS/qemu/cpus.c:1050 #4 0x000003ff7cf084c6 in start_thread () from /lib64/libpthread.so.0 #5 0x000003ff7ce02ec2 in thread_start () from /lib64/libc.so.6 Thread 3 (Thread 0x3ff7e8dcbb0 (LWP 236395)): #0 0x000003ff7cdf66e6 in ppoll () from /lib64/libc.so.6 #1 0x00000000101a5e08 in ppoll (__ss=0x0, __timeout=0x3ffd6afe8a0, __nfds=<optimized out>, __fds=<optimized out>) at /usr/include/bits/poll2.h:77 #2 qemu_poll_ns (fds=<optimized out>, nfds=<optimized out>, timeout=timeout@entry=1034000000) at /home/cborntra/REPOS/qemu/qemu-timer.c:325 #3 0x00000000101a56f2 in os_host_main_loop_wait (timeout=1034000000) at /home/cborntra/REPOS/qemu/main-loop.c:251 #4 main_loop_wait (nonblocking=<optimized out>) at /home/cborntra/REPOS/qemu/main-loop.c:505 #5 0x00000000100136d6 in main_loop () at /home/cborntra/REPOS/qemu/vl.c:1933 #6 main (argc=<optimized out>, argv=<optimized out>, envp=<optimized out>) at /home/cborntra/REPOS/qemu/vl.c:4656 Thread 2 (Thread 0x3ff7b0ff910 (LWP 236421)): #0 0x000003ff7cdf66e6 in ppoll () from /lib64/libc.so.6 #1 0x00000000101a5e28 in ppoll (__ss=0x0, __timeout=0x0, __nfds=<optimized out>, __fds=<optimized out>) at /usr/include/bits/poll2.h:77 #2 qemu_poll_ns (fds=<optimized out>, nfds=<optimized out>, timeout=timeout@entry=-1) at /home/cborntra/REPOS/qemu/qemu-timer.c:313 #3 0x00000000101a727c in aio_poll (ctx=0x10880560, blocking=<optimized out>) at /home/cborntra/REPOS/qemu/aio-posix.c:453 #4 0x00000000100d39f0 in iothread_run (opaque=0x10880020) at /home/cborntra/REPOS/qemu/iothread.c:46 #5 0x000003ff7cf084c6 in start_thread () from /lib64/libpthread.so.0 #6 0x000003ff7ce02ec2 in thread_start () from /lib64/libc.so.6 Thread 1 (Thread 0x3ff57fff910 (LWP 236427)): #0 0x000003ff7cd3b650 in raise () from /lib64/libc.so.6 #1 0x000003ff7cd3ced8 in abort () from /lib64/libc.so.6 #2 0x000003ff7cd33666 in __assert_fail_base () from /lib64/libc.so.6 #3 0x000003ff7cd336f4 in __assert_fail () from /lib64/libc.so.6 #4 0x000000001007a3c4 in virtio_blk_handle_output (vdev=<optimized out>, vq=<optimized out>) at /home/cborntra/REPOS/qemu/hw/block/virtio-blk.c:595 #5 0x000000001009390e in virtio_queue_notify_vq (vq=0x10d77c70) at /home/cborntra/REPOS/qemu/hw/virtio/virtio.c:1095 #6 0x0000000010095894 in virtio_queue_notify_vq (vq=<optimized out>) at /home/cborntra/REPOS/qemu/hw/virtio/virtio.c:1091 #7 virtio_queue_notify (vdev=<optimized out>, n=n@entry=0) at /home/cborntra/REPOS/qemu/hw/virtio/virtio.c:1101 #8 0x00000000100a17c8 in virtio_ccw_hcall_notify (args=<optimized out>) at /home/cborntra/REPOS/qemu/hw/s390x/s390-virtio-ccw.c:66 #9 0x000000001009c210 in s390_virtio_hypercall (env=env@entry=0x10c75aa0) at /home/cborntra/REPOS/qemu/hw/s390x/s390-virtio-hcall.c:35 #10 0x00000000100cb4e8 in handle_hypercall (run=<optimized out>, cpu=0x10c6d7d0) at /home/cborntra/REPOS/qemu/target-s390x/kvm.c:1283 #11 handle_diag (ipb=<optimized out>, run=0x3ff78680000, cpu=0x10c6d7d0) at /home/cborntra/REPOS/qemu/target-s390x/kvm.c:1352 #12 handle_instruction (run=0x3ff78680000, cpu=0x10c6d7d0) at /home/cborntra/REPOS/qemu/target-s390x/kvm.c:1799 #13 handle_intercept (cpu=0x10c6d7d0) at /home/cborntra/REPOS/qemu/target-s390x/kvm.c:1842 #14 kvm_arch_handle_exit (cs=cs@entry=0x10c6d7d0, run=run@entry=0x3ff78680000) at /home/cborntra/REPOS/qemu/target-s390x/kvm.c:2028 #15 0x000000001005df70 in kvm_cpu_exec (cpu=cpu@entry=0x10c6d7d0) at /home/cborntra/REPOS/qemu/kvm-all.c:1921 #16 0x000000001004b1be in qemu_kvm_cpu_thread_fn (arg=0x10c6d7d0) at /home/cborntra/REPOS/qemu/cpus.c:1050 #17 0x000003ff7cf084c6 in start_thread () from /lib64/libpthread.so.0 #18 0x000003ff7ce02ec2 in thread_start () from /lib64/libc.so.6
On 03/17/2016 04:15 PM, Christian Borntraeger wrote: > On 03/17/2016 04:02 PM, Paolo Bonzini wrote: >> >> >> On 17/03/2016 13:39, Christian Borntraeger wrote: >>> As an interesting side note, I updated my system from F20 to F23 some days ago >>> (after the initial report). While To Bo is still on a F20 system. I was not able >>> to reproduce the original crash on f23. but going back to F20 made this >>> problem re-appear. >>> >>> Stack trace of thread 26429: >>> #0 0x00000000802008aa tracked_request_begin (qemu-system-s390x) >>> #1 0x0000000080203f3c bdrv_co_do_preadv (qemu-system-s390x) >>> #2 0x000000008020567c bdrv_co_do_readv (qemu-system-s390x) >>> #3 0x000000008025d0f4 coroutine_trampoline (qemu-system-s390x) >>> #4 0x000003ff943d150a __makecontext_ret (libc.so.6) >>> >>> this is with patch 2-4 plus the removal of virtio_queue_host_notifier_read. >>> >>> Without removing virtio_queue_host_notifier_read, I get the same mutex lockup (as expected). >>> >>> Maybe we have two independent issues here and this is some old bug in glibc or >>> whatever? >> >> I'm happy to try and reproduce on x86 if you give me some instruction >> (RHEL7 should be close enough to Fedora 20). >> >> Can you add an assert in virtio_blk_handle_output to catch reentrancy, like > > that was quick (let me know if I should recompile with debugging) > > (gdb) thread apply all bt > > Thread 5 (Thread 0x3ff7b8ff910 (LWP 236419)): > #0 0x000003ff7cdfcf56 in syscall () from /lib64/libc.so.6 > #1 0x000000001022452e in futex_wait (val=<optimized out>, ev=<optimized out>) at /home/cborntra/REPOS/qemu/util/qemu-thread-posix.c:292 > #2 qemu_event_wait (ev=ev@entry=0x1082b5c4 <rcu_call_ready_event>) at /home/cborntra/REPOS/qemu/util/qemu-thread-posix.c:399 > #3 0x000000001023353a in call_rcu_thread (opaque=<optimized out>) at /home/cborntra/REPOS/qemu/util/rcu.c:250 > #4 0x000003ff7cf084c6 in start_thread () from /lib64/libpthread.so.0 > #5 0x000003ff7ce02ec2 in thread_start () from /lib64/libc.so.6 > > Thread 4 (Thread 0x3ff78eca910 (LWP 236426)): > #0 0x000003ff7cdf819a in ioctl () from /lib64/libc.so.6 > #1 0x000000001005ddf8 in kvm_vcpu_ioctl (cpu=cpu@entry=0x10c27d40, type=type@entry=44672) at /home/cborntra/REPOS/qemu/kvm-all.c:1984 > #2 0x000000001005df1c in kvm_cpu_exec (cpu=cpu@entry=0x10c27d40) at /home/cborntra/REPOS/qemu/kvm-all.c:1834 > #3 0x000000001004b1be in qemu_kvm_cpu_thread_fn (arg=0x10c27d40) at /home/cborntra/REPOS/qemu/cpus.c:1050 > #4 0x000003ff7cf084c6 in start_thread () from /lib64/libpthread.so.0 > #5 0x000003ff7ce02ec2 in thread_start () from /lib64/libc.so.6 > > Thread 3 (Thread 0x3ff7e8dcbb0 (LWP 236395)): > #0 0x000003ff7cdf66e6 in ppoll () from /lib64/libc.so.6 > #1 0x00000000101a5e08 in ppoll (__ss=0x0, __timeout=0x3ffd6afe8a0, __nfds=<optimized out>, __fds=<optimized out>) at /usr/include/bits/poll2.h:77 > #2 qemu_poll_ns (fds=<optimized out>, nfds=<optimized out>, timeout=timeout@entry=1034000000) at /home/cborntra/REPOS/qemu/qemu-timer.c:325 > #3 0x00000000101a56f2 in os_host_main_loop_wait (timeout=1034000000) at /home/cborntra/REPOS/qemu/main-loop.c:251 > #4 main_loop_wait (nonblocking=<optimized out>) at /home/cborntra/REPOS/qemu/main-loop.c:505 > #5 0x00000000100136d6 in main_loop () at /home/cborntra/REPOS/qemu/vl.c:1933 > #6 main (argc=<optimized out>, argv=<optimized out>, envp=<optimized out>) at /home/cborntra/REPOS/qemu/vl.c:4656 > > Thread 2 (Thread 0x3ff7b0ff910 (LWP 236421)): > #0 0x000003ff7cdf66e6 in ppoll () from /lib64/libc.so.6 > #1 0x00000000101a5e28 in ppoll (__ss=0x0, __timeout=0x0, __nfds=<optimized out>, __fds=<optimized out>) at /usr/include/bits/poll2.h:77 > #2 qemu_poll_ns (fds=<optimized out>, nfds=<optimized out>, timeout=timeout@entry=-1) at /home/cborntra/REPOS/qemu/qemu-timer.c:313 > #3 0x00000000101a727c in aio_poll (ctx=0x10880560, blocking=<optimized out>) at /home/cborntra/REPOS/qemu/aio-posix.c:453 > #4 0x00000000100d39f0 in iothread_run (opaque=0x10880020) at /home/cborntra/REPOS/qemu/iothread.c:46 > #5 0x000003ff7cf084c6 in start_thread () from /lib64/libpthread.so.0 > #6 0x000003ff7ce02ec2 in thread_start () from /lib64/libc.so.6 > > Thread 1 (Thread 0x3ff57fff910 (LWP 236427)): > #0 0x000003ff7cd3b650 in raise () from /lib64/libc.so.6 > #1 0x000003ff7cd3ced8 in abort () from /lib64/libc.so.6 > #2 0x000003ff7cd33666 in __assert_fail_base () from /lib64/libc.so.6 > #3 0x000003ff7cd336f4 in __assert_fail () from /lib64/libc.so.6 > #4 0x000000001007a3c4 in virtio_blk_handle_output (vdev=<optimized out>, vq=<optimized out>) at /home/cborntra/REPOS/qemu/hw/block/virtio-blk.c:595 > #5 0x000000001009390e in virtio_queue_notify_vq (vq=0x10d77c70) at /home/cborntra/REPOS/qemu/hw/virtio/virtio.c:1095 > #6 0x0000000010095894 in virtio_queue_notify_vq (vq=<optimized out>) at /home/cborntra/REPOS/qemu/hw/virtio/virtio.c:1091 > #7 virtio_queue_notify (vdev=<optimized out>, n=n@entry=0) at /home/cborntra/REPOS/qemu/hw/virtio/virtio.c:1101 > #8 0x00000000100a17c8 in virtio_ccw_hcall_notify (args=<optimized out>) at /home/cborntra/REPOS/qemu/hw/s390x/s390-virtio-ccw.c:66 > #9 0x000000001009c210 in s390_virtio_hypercall (env=env@entry=0x10c75aa0) at /home/cborntra/REPOS/qemu/hw/s390x/s390-virtio-hcall.c:35 > #10 0x00000000100cb4e8 in handle_hypercall (run=<optimized out>, cpu=0x10c6d7d0) at /home/cborntra/REPOS/qemu/target-s390x/kvm.c:1283 > #11 handle_diag (ipb=<optimized out>, run=0x3ff78680000, cpu=0x10c6d7d0) at /home/cborntra/REPOS/qemu/target-s390x/kvm.c:1352 FWIW, this looks like that we still have a case, without eventfd during reboot or startup > #12 handle_instruction (run=0x3ff78680000, cpu=0x10c6d7d0) at /home/cborntra/REPOS/qemu/target-s390x/kvm.c:1799 > #13 handle_intercept (cpu=0x10c6d7d0) at /home/cborntra/REPOS/qemu/target-s390x/kvm.c:1842 > #14 kvm_arch_handle_exit (cs=cs@entry=0x10c6d7d0, run=run@entry=0x3ff78680000) at /home/cborntra/REPOS/qemu/target-s390x/kvm.c:2028 > #15 0x000000001005df70 in kvm_cpu_exec (cpu=cpu@entry=0x10c6d7d0) at /home/cborntra/REPOS/qemu/kvm-all.c:1921 > #16 0x000000001004b1be in qemu_kvm_cpu_thread_fn (arg=0x10c6d7d0) at /home/cborntra/REPOS/qemu/cpus.c:1050 > #17 0x000003ff7cf084c6 in start_thread () from /lib64/libpthread.so.0 > #18 0x000003ff7ce02ec2 in thread_start () from /lib64/libc.so.6 >
Good (or bad?) news is the assert also triggers on F23, it just seems to take longer. trace 1 (compiled on F20) Thread 5 (Thread 0x3ff84b7f910 (LWP 33030)): #0 0x000003ff86a817b8 in ppoll () at /lib64/libc.so.6 #1 0x00000000102c712e in qemu_poll_ns (fds=0x3ff80001e70, nfds=3, timeout=-1) at /home/cborntra/REPOS/qemu/qemu-timer.c:313 #2 0x00000000102c96d6 in aio_poll (ctx=0x10a7b050, blocking=true) at /home/cborntra/REPOS/qemu/aio-posix.c:453 #3 0x000000001014fb1e in iothread_run (opaque=0x10a7ab10) at /home/cborntra/REPOS/qemu/iothread.c:46 #4 0x000003ff86b87c2c in start_thread () at /lib64/libpthread.so.0 #5 0x000003ff86a8ec9a in thread_start () at /lib64/libc.so.6 Thread 4 (Thread 0x3ff8537f910 (LWP 33029)): #0 0x000003ff86a8841e in syscall () at /lib64/libc.so.6 #1 0x000000001039cbe8 in futex_wait (ev=0x10a140ec <rcu_call_ready_event>, val=4294967295) at /home/cborntra/REPOS/qemu/util/qemu-thread-posix.c:292 #2 0x000000001039ce1e in qemu_event_wait (ev=0x10a140ec <rcu_call_ready_event>) at /home/cborntra/REPOS/qemu/util/qemu-thread-posix.c:399 #3 0x00000000103b9678 in call_rcu_thread (opaque=0x0) at /home/cborntra/REPOS/qemu/util/rcu.c:250 #4 0x000003ff86b87c2c in start_thread () at /lib64/libpthread.so.0 #5 0x000003ff86a8ec9a in thread_start () at /lib64/libc.so.6 Thread 3 (Thread 0x3ff66428910 (LWP 33041)): #0 0x000003ff86a8334a in ioctl () at /lib64/libc.so.6 #1 0x000000001007b97a in kvm_vcpu_ioctl (cpu=0x10b15970, type=44672) at /home/cborntra/REPOS/qemu/kvm-all.c:1984 #2 0x000000001007b2f0 in kvm_cpu_exec (cpu=0x10b15970) at /home/cborntra/REPOS/qemu/kvm-all.c:1834 #3 0x000000001005bd92 in qemu_kvm_cpu_thread_fn (arg=0x10b15970) at /home/cborntra/REPOS/qemu/cpus.c:1050 #4 0x000003ff86b87c2c in start_thread () at /lib64/libpthread.so.0 #5 0x000003ff86a8ec9a in thread_start () at /lib64/libc.so.6 Thread 2 (Thread 0x3ff885dbb90 (LWP 32970)): #0 0x000003ff86a817b8 in ppoll () at /lib64/libc.so.6 #1 0x00000000102c7244 in qemu_poll_ns (fds=0x10a77a90, nfds=5, timeout=965000000) at /home/cborntra/REPOS/qemu/qemu-timer.c:325 #2 0x00000000102c5ef2 in os_host_main_loop_wait (timeout=965000000) at /home/cborntra/REPOS/qemu/main-loop.c:251 #3 0x00000000102c6006 in main_loop_wait (nonblocking=0) at /home/cborntra/REPOS/qemu/main-loop.c:505 #4 0x00000000101667e4 in main_loop () at /home/cborntra/REPOS/qemu/vl.c:1933 #5 0x000000001016e8ea in main (argc=72, argv=0x3ffe977e978, envp=0x3ffe977ebc0) at /home/cborntra/REPOS/qemu/vl.c:4656 Thread 1 (Thread 0x3ff66c28910 (LWP 33033)): #0 0x000003ff869be2c0 in raise () at /lib64/libc.so.6 #1 0x000003ff869bfc26 in abort () at /lib64/libc.so.6 #2 0x000003ff869b5bce in __assert_fail_base () at /lib64/libc.so.6 #3 0x000003ff869b5c5c in () at /lib64/libc.so.6 #4 0x00000000100ab8f2 in virtio_blk_handle_output (vdev=0x10ad57e8, vq=0x10eec270) at /home/cborntra/REPOS/qemu/hw/block/virtio-blk.c:595 #5 0x00000000100e18a4 in virtio_queue_notify_vq (vq=0x10eec270) at /home/cborntra/REPOS/qemu/hw/virtio/virtio.c:1095 #6 0x00000000100e1906 in virtio_queue_notify (vdev=0x10ad57e8, n=0) at /home/cborntra/REPOS/qemu/hw/virtio/virtio.c:1101 #7 0x00000000100f921c in virtio_ccw_hcall_notify (args=0x10e2aad0) at /home/cborntra/REPOS/qemu/hw/s390x/s390-virtio-ccw.c:66 #8 0x00000000100ee518 in s390_virtio_hypercall (env=0x10e2aac0) at /home/cborntra/REPOS/qemu/hw/s390x/s390-virtio-hcall.c:35 #9 0x000000001014192e in handle_hypercall (cpu=0x10e227f0, run=0x3ff84280000) at /home/cborntra/REPOS/qemu/target-s390x/kvm.c:1283 #10 0x0000000010141c36 in handle_diag (cpu=0x10e227f0, run=0x3ff84280000, ipb=83886080) at /home/cborntra/REPOS/qemu/target-s390x/kvm.c:1352 #11 0x00000000101431b6 in handle_instruction (cpu=0x10e227f0, run=0x3ff84280000) at /home/cborntra/REPOS/qemu/target-s390x/kvm.c:1799 #12 0x00000000101433ee in handle_intercept (cpu=0x10e227f0) at /home/cborntra/REPOS/qemu/target-s390x/kvm.c:1842 #13 0x0000000010143c22 in kvm_arch_handle_exit (cs=0x10e227f0, run=0x3ff84280000) at /home/cborntra/REPOS/qemu/target-s390x/kvm.c:2028 #14 0x000000001007b5aa in kvm_cpu_exec (cpu=0x10e227f0) at /home/cborntra/REPOS/qemu/kvm-all.c:1921 #15 0x000000001005bd92 in qemu_kvm_cpu_thread_fn (arg=0x10e227f0) at /home/cborntra/REPOS/qemu/cpus.c:1050 #16 0x000003ff86b87c2c in start_thread () at /lib64/libpthread.so.0 #17 0x000003ff86a8ec9a in thread_start () at /lib64/libc.so.6 trace 2 (compiled on F23) Thread 5 (Thread 0x3ffb897f910 (LWP 37895)): #0 0x000003ffba00841e in syscall () at /lib64/libc.so.6 #1 0x00000000803d5306 in futex_wait (ev=0x80a4a104 <rcu_call_ready_event>, val=4294967295) at /home/cborntra/REPOS/qemu/util/qemu-thread-posix.c:292 #2 0x00000000803d5596 in qemu_event_wait (ev=0x80a4a104 <rcu_call_ready_event>) at /home/cborntra/REPOS/qemu/util/qemu-thread-posix.c:399 #3 0x00000000803f2c3c in call_rcu_thread (opaque=0x0) at /home/cborntra/REPOS/qemu/util/rcu.c:250 #4 0x000003ffba107c2c in start_thread () at /lib64/libpthread.so.0 #5 0x000003ffba00ec9a in thread_start () at /lib64/libc.so.6 Thread 4 (Thread 0x3ffb574a910 (LWP 37907)): #0 0x000003ffba00334a in ioctl () at /lib64/libc.so.6 #1 0x0000000080081a44 in kvm_vcpu_ioctl (cpu=0x80b4b970, type=44672) at /home/cborntra/REPOS/qemu/kvm-all.c:1984 #2 0x000000008008130c in kvm_cpu_exec (cpu=0x80b4b970) at /home/cborntra/REPOS/qemu/kvm-all.c:1834 #3 0x000000008006074c in qemu_kvm_cpu_thread_fn (arg=0x80b4b970) at /home/cborntra/REPOS/qemu/cpus.c:1050 #4 0x000003ffba107c2c in start_thread () at /lib64/libpthread.so.0 #5 0x000003ffba00ec9a in thread_start () at /lib64/libc.so.6 Thread 3 (Thread 0x3ffb5f4a910 (LWP 37906)): #0 0x000003ffb9f3f5b2 in sigtimedwait () at /lib64/libc.so.6 #1 0x000000008005fcda in qemu_kvm_eat_signals (cpu=0x80e587f0) at /home/cborntra/REPOS/qemu/cpus.c:804 #2 0x00000000800605fc in qemu_kvm_wait_io_event (cpu=0x80e587f0) at /home/cborntra/REPOS/qemu/cpus.c:1019 #3 0x000000008006077a in qemu_kvm_cpu_thread_fn (arg=0x80e587f0) at /home/cborntra/REPOS/qemu/cpus.c:1055 #4 0x000003ffba107c2c in start_thread () at /lib64/libpthread.so.0 #5 0x000003ffba00ec9a in thread_start () at /lib64/libc.so.6 Thread 2 (Thread 0x3ffbbbdbb90 (LWP 37839)): #0 0x000003ffba110cd4 in __lll_lock_wait () at /lib64/libpthread.so.0 #1 0x000003ffba113ed4 in __lll_lock_elision () at /lib64/libpthread.so.0 #2 0x00000000803d49d6 in qemu_mutex_lock (mutex=0x8061f260 <qemu_global_mutex>) at /home/cborntra/REPOS/qemu/util/qemu-thread-posix.c:64 #3 0x0000000080060ef4 in qemu_mutex_lock_iothread () at /home/cborntra/REPOS/qemu/cpus.c:1226 #4 0x00000000802eeae4 in os_host_main_loop_wait (timeout=1291000000) at /home/cborntra/REPOS/qemu/main-loop.c:254 #5 0x00000000802eebf6 in main_loop_wait (nonblocking=0) at /home/cborntra/REPOS/qemu/main-loop.c:505 #6 0x000000008017b4bc in main_loop () at /home/cborntra/REPOS/qemu/vl.c:1933 #7 0x00000000801839aa in main (argc=72, argv=0x3ffda07e4b8, envp=0x3ffda07e700) at /home/cborntra/REPOS/qemu/vl.c:4656 Thread 1 (Thread 0x3ffb817f910 (LWP 37897)): #0 0x000003ffb9f3e2c0 in raise () at /lib64/libc.so.6 #1 0x000003ffb9f3fc26 in abort () at /lib64/libc.so.6 #2 0x000003ffb9f35bce in __assert_fail_base () at /lib64/libc.so.6 #3 0x000003ffb9f35c5c in () at /lib64/libc.so.6 #4 0x00000000800b4ee2 in virtio_blk_handle_output (vdev=0x80e51468, vq=0x80f3e280) at /home/cborntra/REPOS/qemu/hw/block/virtio-blk.c:595 #5 0x00000000800ef434 in virtio_queue_notify_vq (vq=0x80f3e280) at /home/cborntra/REPOS/qemu/hw/virtio/virtio.c:1095 #6 0x00000000800f1cf4 in virtio_queue_host_notifier_read (n=0x80f3e2d8) at /home/cborntra/REPOS/qemu/hw/virtio/virtio.c:1785 #7 0x00000000802f1cdc in aio_dispatch (ctx=0x80ab1050) at /home/cborntra/REPOS/qemu/aio-posix.c:327 #8 0x00000000802f2662 in aio_poll (ctx=0x80ab1050, blocking=false) at /home/cborntra/REPOS/qemu/aio-posix.c:475 #9 0x0000000080163942 in iothread_run (opaque=0x80ab0b10) at /home/cborntra/REPOS/qemu/iothread.c:46 #10 0x000003ffba107c2c in start_thread () at /lib64/libpthread.so.0 #11 0x000003ffba00ec9a in thread_start () at /lib64/libc.so.6 (gdb)
On 17/03/2016 17:08, Christian Borntraeger wrote: > Good (or bad?) news is the assert also triggers on F23, it just seems > to take longer. I guess good news, because we can rule out the kernel (not that I believed it was a kernel problem, but the thought is always there in the background...). The interaction between ioeventfd and dataplane is too complicated. I think if we get rid of the start/stop ioeventfd calls (just set up the ioeventfd as soon as possible and then only set/clear the handlers) things would be much simpler. I'll see if I can produce something based on Conny's patches, which are already a start. Today I had a short day so I couldn't play with the bug; out of curiosity, does the bug reproduce with her work + patch 4 from this series + the reentrancy assertion? Paolo
On Fri, 03/18 16:03, Paolo Bonzini wrote: > > > On 17/03/2016 17:08, Christian Borntraeger wrote: > > Good (or bad?) news is the assert also triggers on F23, it just seems > > to take longer. > > I guess good news, because we can rule out the kernel (not that I > believed it was a kernel problem, but the thought is always there in > the background...). > > The interaction between ioeventfd and dataplane is too complicated. I > think if we get rid of the start/stop ioeventfd calls (just set up the > ioeventfd as soon as possible and then only set/clear the handlers) > things would be much simpler. > > I'll see if I can produce something based on Conny's patches, which are > already a start. Today I had a short day so I couldn't play with the > bug; out of curiosity, does the bug reproduce with her work + patch 4 > from this series + the reentrancy assertion? The other half of the race condition is from ioport write in the vcpu thread. I hit this by adding an extra assert(is_in_iothread()) in virtio_blk_handle_request(), at the same place with Paolo's atomic read of variable "test". I haven't tried to find where this ioport write is from, but that is indeed an issue in virtio-pci. (gdb) thread apply all bt <...> Thread 3 (Thread 0x7f9e8928b700 (LWP 30671)): #0 0x00007f9e8bac65d7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56 #1 0x00007f9e8bac7cc8 in __GI_abort () at abort.c:90 #2 0x00007f9e8babf546 in __assert_fail_base (fmt=0x7f9e8bc0f128 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x7f9e8e04e9d1 "is_in_iothread()", file=file@entry=0x7f9e8e04e8e0 "/home/fam/work/qemu/hw/block/virtio-blk.c", line=line@entry=597, function=function@entry=0x7f9e8e04ec30 <__PRETTY_FUNCTION__.37148> "virtio_blk_handle_output") at assert.c:92 #3 0x00007f9e8babf5f2 in __GI___assert_fail (assertion=0x7f9e8e04e9d1 "is_in_iothread()", file=0x7f9e8e04e8e0 "/home/fam/work/qemu/hw/block/virtio-blk.c", line=597, function=0x7f9e8e04ec30 <__PRETTY_FUNCTION__.37148> "virtio_blk_handle_output") at assert.c:101 #4 0x00007f9e8dc9f414 in virtio_blk_handle_output (vdev=0x7f9e929d7b68, vq=0x7f9e92a762f0) at /home/fam/work/qemu/hw/block/virtio-blk.c:597 #5 0x00007f9e8dcd6f53 in virtio_queue_notify_vq (vq=0x7f9e92a762f0) at /home/fam/work/qemu/hw/virtio/virtio.c:1095 #6 0x00007f9e8dcd6f91 in virtio_queue_notify (vdev=0x7f9e929d7b68, n=0) at /home/fam/work/qemu/hw/virtio/virtio.c:1101 #7 0x00007f9e8df03d2f in virtio_ioport_write (opaque=0x7f9e929cf840, addr=16, val=0) at /home/fam/work/qemu/hw/virtio/virtio-pci.c:419 #8 0x00007f9e8df041be in virtio_pci_config_write (opaque=0x7f9e929cf840, addr=16, val=0, size=2) at /home/fam/work/qemu/hw/virtio/virtio-pci.c:552 #9 0x00007f9e8dc7c8c9 in memory_region_write_accessor (mr=0x7f9e929d00c0, addr=16, value=0x7f9e8928a988, size=2, shift=0, mask=65535, attrs=...) at /home/fam/work/qemu/memory.c:524 #10 0x00007f9e8dc7cad4 in access_with_adjusted_size (addr=16, value=0x7f9e8928a988, size=2, access_size_min=1, access_size_max=4, access= 0x7f9e8dc7c7e8 <memory_region_write_accessor>, mr=0x7f9e929d00c0, attrs=...) at /home/fam/work/qemu/memory.c:590 #11 0x00007f9e8dc7f71b in memory_region_dispatch_write (mr=0x7f9e929d00c0, addr=16, data=0, size=2, attrs=...) at /home/fam/work/qemu/memory.c:1272 #12 0x00007f9e8dc32815 in address_space_write_continue (as=0x7f9e8e5834a0 <address_space_io>, addr=49232, attrs=..., buf=0x7f9e8daa9000 <Address 0x7f9e8daa9000 out of bounds>, len=2, addr1=16, l=2, mr=0x7f9e929d00c0) at /home/fam/work/qemu/exec.c:2607 #13 0x00007f9e8dc329c1 in address_space_write (as=0x7f9e8e5834a0 <address_space_io>, addr=49232, attrs=..., buf=0x7f9e8daa9000 <Address 0x7f9e8daa9000 out of bounds>, len=2) at /home/fam/work/qemu/exec.c:2659 #14 0x00007f9e8dc32d78 in address_space_rw (as=0x7f9e8e5834a0 <address_space_io>, addr=49232, attrs=..., buf=0x7f9e8daa9000 <Address 0x7f9e8daa9000 out of bounds>, len=2, is_write=true) at /home/fam/work/qemu/exec.c:2762 #15 0x00007f9e8dc79358 in kvm_handle_io (port=49232, attrs=..., data=0x7f9e8daa9000, direction=1, size=2, count=1) at /home/fam/work/qemu/kvm-all.c:1699 #16 0x00007f9e8dc79858 in kvm_cpu_exec (cpu=0x7f9e905a5250) at /home/fam/work/qemu/kvm-all.c:1863 #17 0x00007f9e8dc619a3 in qemu_kvm_cpu_thread_fn (arg=0x7f9e905a5250) at /home/fam/work/qemu/cpus.c:1056 #18 0x00007f9e8be59df5 in start_thread (arg=0x7f9e8928b700) at pthread_create.c:308 #19 0x00007f9e8bb871ad in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113 <...> Thread 1 (Thread 0x7f9e8b28f700 (LWP 30667)): #0 0x00007f9e8bac65d7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56 #1 0x00007f9e8bac7cc8 in __GI_abort () at abort.c:90 #2 0x00007f9e8babf546 in __assert_fail_base (fmt=0x7f9e8bc0f128 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x7f9e8e04e9e2 "x == 0", file=file@entry=0x7f9e8e04e8e0 "/home/fam/work/qemu/hw/block/virtio-blk.c", line=line@entry=598, function=function@entry=0x7f9e8e04ec30 <__PRETTY_FUNCTION__.37148> "virtio_blk_handle_output") at assert.c:92 #3 0x00007f9e8babf5f2 in __GI___assert_fail (assertion=0x7f9e8e04e9e2 "x == 0", file=0x7f9e8e04e8e0 "/home/fam/work/qemu/hw/block/virtio-blk.c", line=598, function=0x7f9e8e04ec30 <__PRETTY_FUNCTION__.37148> "virtio_blk_handle_output") at assert.c:101 #4 0x00007f9e8dc9f43c in virtio_blk_handle_output (vdev=0x7f9e929d7b68, vq=0x7f9e92a762f0) at /home/fam/work/qemu/hw/block/virtio-blk.c:598 #5 0x00007f9e8dcd6f53 in virtio_queue_notify_vq (vq=0x7f9e92a762f0) at /home/fam/work/qemu/hw/virtio/virtio.c:1095 #6 0x00007f9e8dcd8dfd in virtio_queue_host_notifier_read (n=0x7f9e92a76348) at /home/fam/work/qemu/hw/virtio/virtio.c:1785 #7 0x00007f9e8df76b40 in aio_dispatch (ctx=0x7f9e90540a50) at /home/fam/work/qemu/aio-posix.c:327 #8 0x00007f9e8df770f8 in aio_poll (ctx=0x7f9e90540a50, blocking=true) at /home/fam/work/qemu/aio-posix.c:475 #9 0x00007f9e8dd7b5c4 in iothread_run (opaque=0x7f9e905404d0) at /home/fam/work/qemu/iothread.c:55 #10 0x00007f9e8be59df5 in start_thread (arg=0x7f9e8b28f700) at pthread_create.c:308 #11 0x00007f9e8bb871ad in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113
On 03/21/2016 10:42 AM, Fam Zheng wrote: > On Fri, 03/18 16:03, Paolo Bonzini wrote: >> >> >> On 17/03/2016 17:08, Christian Borntraeger wrote: >>> Good (or bad?) news is the assert also triggers on F23, it just seems >>> to take longer. >> >> I guess good news, because we can rule out the kernel (not that I >> believed it was a kernel problem, but the thought is always there in >> the background...). >> >> The interaction between ioeventfd and dataplane is too complicated. I >> think if we get rid of the start/stop ioeventfd calls (just set up the >> ioeventfd as soon as possible and then only set/clear the handlers) >> things would be much simpler. >> >> I'll see if I can produce something based on Conny's patches, which are >> already a start. Today I had a short day so I couldn't play with the >> bug; out of curiosity, does the bug reproduce with her work + patch 4 >> from this series + the reentrancy assertion? > > The other half of the race condition is from ioport write in the vcpu thread. I > hit this by adding an extra assert(is_in_iothread()) in > virtio_blk_handle_request(), at the same place with Paolo's atomic read of > variable "test". Thats good, that you can reproduce on x86. the ioport write in the vcpu thread, is the equivalent of s390_virtio_hypercall on s390 - a virtio kick that is usually handled by eventfd but here we have a case where we go the slow path. So the good thing is that this is not s390 specific, which might help to find the issue more quickly. > > I haven't tried to find where this ioport write is from, but that is indeed an > issue in virtio-pci. > > (gdb) thread apply all bt > > <...> > > Thread 3 (Thread 0x7f9e8928b700 (LWP 30671)): > #0 0x00007f9e8bac65d7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56 > #1 0x00007f9e8bac7cc8 in __GI_abort () at abort.c:90 > #2 0x00007f9e8babf546 in __assert_fail_base (fmt=0x7f9e8bc0f128 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x7f9e8e04e9d1 "is_in_iothread()", > file=file@entry=0x7f9e8e04e8e0 "/home/fam/work/qemu/hw/block/virtio-blk.c", line=line@entry=597, > function=function@entry=0x7f9e8e04ec30 <__PRETTY_FUNCTION__.37148> "virtio_blk_handle_output") at assert.c:92 > #3 0x00007f9e8babf5f2 in __GI___assert_fail (assertion=0x7f9e8e04e9d1 "is_in_iothread()", file=0x7f9e8e04e8e0 "/home/fam/work/qemu/hw/block/virtio-blk.c", line=597, > function=0x7f9e8e04ec30 <__PRETTY_FUNCTION__.37148> "virtio_blk_handle_output") at assert.c:101 > #4 0x00007f9e8dc9f414 in virtio_blk_handle_output (vdev=0x7f9e929d7b68, vq=0x7f9e92a762f0) at /home/fam/work/qemu/hw/block/virtio-blk.c:597 > #5 0x00007f9e8dcd6f53 in virtio_queue_notify_vq (vq=0x7f9e92a762f0) at /home/fam/work/qemu/hw/virtio/virtio.c:1095 > #6 0x00007f9e8dcd6f91 in virtio_queue_notify (vdev=0x7f9e929d7b68, n=0) at /home/fam/work/qemu/hw/virtio/virtio.c:1101 > #7 0x00007f9e8df03d2f in virtio_ioport_write (opaque=0x7f9e929cf840, addr=16, val=0) at /home/fam/work/qemu/hw/virtio/virtio-pci.c:419 > #8 0x00007f9e8df041be in virtio_pci_config_write (opaque=0x7f9e929cf840, addr=16, val=0, size=2) at /home/fam/work/qemu/hw/virtio/virtio-pci.c:552 > #9 0x00007f9e8dc7c8c9 in memory_region_write_accessor (mr=0x7f9e929d00c0, addr=16, value=0x7f9e8928a988, size=2, shift=0, mask=65535, attrs=...) > at /home/fam/work/qemu/memory.c:524 > #10 0x00007f9e8dc7cad4 in access_with_adjusted_size (addr=16, value=0x7f9e8928a988, size=2, access_size_min=1, access_size_max=4, access= > 0x7f9e8dc7c7e8 <memory_region_write_accessor>, mr=0x7f9e929d00c0, attrs=...) at /home/fam/work/qemu/memory.c:590 > #11 0x00007f9e8dc7f71b in memory_region_dispatch_write (mr=0x7f9e929d00c0, addr=16, data=0, size=2, attrs=...) at /home/fam/work/qemu/memory.c:1272 > #12 0x00007f9e8dc32815 in address_space_write_continue (as=0x7f9e8e5834a0 <address_space_io>, addr=49232, attrs=..., buf=0x7f9e8daa9000 <Address 0x7f9e8daa9000 out of bounds>, > len=2, addr1=16, l=2, mr=0x7f9e929d00c0) at /home/fam/work/qemu/exec.c:2607 > #13 0x00007f9e8dc329c1 in address_space_write (as=0x7f9e8e5834a0 <address_space_io>, addr=49232, attrs=..., buf=0x7f9e8daa9000 <Address 0x7f9e8daa9000 out of bounds>, len=2) > at /home/fam/work/qemu/exec.c:2659 > #14 0x00007f9e8dc32d78 in address_space_rw (as=0x7f9e8e5834a0 <address_space_io>, addr=49232, attrs=..., buf=0x7f9e8daa9000 <Address 0x7f9e8daa9000 out of bounds>, len=2, > is_write=true) at /home/fam/work/qemu/exec.c:2762 > #15 0x00007f9e8dc79358 in kvm_handle_io (port=49232, attrs=..., data=0x7f9e8daa9000, direction=1, size=2, count=1) at /home/fam/work/qemu/kvm-all.c:1699 > #16 0x00007f9e8dc79858 in kvm_cpu_exec (cpu=0x7f9e905a5250) at /home/fam/work/qemu/kvm-all.c:1863 > #17 0x00007f9e8dc619a3 in qemu_kvm_cpu_thread_fn (arg=0x7f9e905a5250) at /home/fam/work/qemu/cpus.c:1056 > #18 0x00007f9e8be59df5 in start_thread (arg=0x7f9e8928b700) at pthread_create.c:308 > #19 0x00007f9e8bb871ad in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113 > > <...> > > Thread 1 (Thread 0x7f9e8b28f700 (LWP 30667)): > #0 0x00007f9e8bac65d7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56 > #1 0x00007f9e8bac7cc8 in __GI_abort () at abort.c:90 > #2 0x00007f9e8babf546 in __assert_fail_base (fmt=0x7f9e8bc0f128 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x7f9e8e04e9e2 "x == 0", > file=file@entry=0x7f9e8e04e8e0 "/home/fam/work/qemu/hw/block/virtio-blk.c", line=line@entry=598, > function=function@entry=0x7f9e8e04ec30 <__PRETTY_FUNCTION__.37148> "virtio_blk_handle_output") at assert.c:92 > #3 0x00007f9e8babf5f2 in __GI___assert_fail (assertion=0x7f9e8e04e9e2 "x == 0", file=0x7f9e8e04e8e0 "/home/fam/work/qemu/hw/block/virtio-blk.c", line=598, > function=0x7f9e8e04ec30 <__PRETTY_FUNCTION__.37148> "virtio_blk_handle_output") at assert.c:101 > #4 0x00007f9e8dc9f43c in virtio_blk_handle_output (vdev=0x7f9e929d7b68, vq=0x7f9e92a762f0) at /home/fam/work/qemu/hw/block/virtio-blk.c:598 > #5 0x00007f9e8dcd6f53 in virtio_queue_notify_vq (vq=0x7f9e92a762f0) at /home/fam/work/qemu/hw/virtio/virtio.c:1095 > #6 0x00007f9e8dcd8dfd in virtio_queue_host_notifier_read (n=0x7f9e92a76348) at /home/fam/work/qemu/hw/virtio/virtio.c:1785 > #7 0x00007f9e8df76b40 in aio_dispatch (ctx=0x7f9e90540a50) at /home/fam/work/qemu/aio-posix.c:327 > #8 0x00007f9e8df770f8 in aio_poll (ctx=0x7f9e90540a50, blocking=true) at /home/fam/work/qemu/aio-posix.c:475 > #9 0x00007f9e8dd7b5c4 in iothread_run (opaque=0x7f9e905404d0) at /home/fam/work/qemu/iothread.c:55 > #10 0x00007f9e8be59df5 in start_thread (arg=0x7f9e8b28f700) at pthread_create.c:308 > #11 0x00007f9e8bb871ad in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113 >
On Mon, 21 Mar 2016 17:42:06 +0800 Fam Zheng <famz@redhat.com> wrote: > On Fri, 03/18 16:03, Paolo Bonzini wrote: > > > > > > On 17/03/2016 17:08, Christian Borntraeger wrote: > > > Good (or bad?) news is the assert also triggers on F23, it just seems > > > to take longer. > > > > I guess good news, because we can rule out the kernel (not that I > > believed it was a kernel problem, but the thought is always there in > > the background...). > > > > The interaction between ioeventfd and dataplane is too complicated. I > > think if we get rid of the start/stop ioeventfd calls (just set up the > > ioeventfd as soon as possible and then only set/clear the handlers) > > things would be much simpler. > > > > I'll see if I can produce something based on Conny's patches, which are > > already a start. Today I had a short day so I couldn't play with the > > bug; out of curiosity, does the bug reproduce with her work + patch 4 > > from this series + the reentrancy assertion? > > The other half of the race condition is from ioport write in the vcpu thread. I > hit this by adding an extra assert(is_in_iothread()) in > virtio_blk_handle_request(), at the same place with Paolo's atomic read of > variable "test". > > I haven't tried to find where this ioport write is from, but that is indeed an > issue in virtio-pci. Might this be a slow-path notification from before the ioeventfd got registered on the io bus (IOW before qemu got control)? We have the first notification that triggers dataplane setup (including registering the ioeventfd). The second notification was already making its way to qemu, and gets only handled when ->started had already been set. Now I'm totally disregarding any possible locking between threads etc. (perhaps somebody on cc: knows better?), but would the following logic in handle_output make sense? if (dataplane) { if (!started) { dataplane_start(); } if (!disabled) { return; } } /* slow path processing */
On 16/3/18 ??11:03, Paolo Bonzini wrote: > > On 17/03/2016 17:08, Christian Borntraeger wrote: >> Good (or bad?) news is the assert also triggers on F23, it just seems >> to take longer. > I guess good news, because we can rule out the kernel (not that I > believed it was a kernel problem, but the thought is always there in > the background...). > > The interaction between ioeventfd and dataplane is too complicated. I > think if we get rid of the start/stop ioeventfd calls (just set up the > ioeventfd as soon as possible and then only set/clear the handlers) > things would be much simpler. > > I'll see if I can produce something based on Conny's patches, which are > already a start. Today I had a short day so I couldn't play with the > bug; out of curiosity, does the bug reproduce with her work + patch 4 > from this series + the reentrancy assertion? I did NOT see crash with qemu master + "[PATCH RFC 0/6] virtio: refactor host notifiers" from Conny + patch 4 + assertion. thx > > Paolo >
On 21/03/2016 14:47, TU BO wrote: >> I'll see if I can produce something based on Conny's patches, which are >> already a start. Today I had a short day so I couldn't play with the >> bug; out of curiosity, does the bug reproduce with her work + patch 4 >> from this series + the reentrancy assertion? > I did NOT see crash with qemu master + "[PATCH RFC 0/6] virtio: refactor > host notifiers" from Conny + patch 4 + assertion. thx That's unexpected, but I guess it only says that I didn't review her patches well enough. :) Paolo
On Mon, 21 Mar 2016 14:54:04 +0100 Paolo Bonzini <pbonzini@redhat.com> wrote: > On 21/03/2016 14:47, TU BO wrote: > >> I'll see if I can produce something based on Conny's patches, which are > >> already a start. Today I had a short day so I couldn't play with the > >> bug; out of curiosity, does the bug reproduce with her work + patch 4 > >> from this series + the reentrancy assertion? > > I did NOT see crash with qemu master + "[PATCH RFC 0/6] virtio: refactor > > host notifiers" from Conny + patch 4 + assertion. thx > > That's unexpected, but I guess it only says that I didn't review her > patches well enough. :) I'm also a bit surprised, the only thing that should really be different is passing the 'assign' argument in stop_ioeventfd(). Any other fixes are purely accidental :) Would be interesting to see how this setup fares with virtio-pci.
On Mon, 03/21 15:19, Cornelia Huck wrote: > On Mon, 21 Mar 2016 14:54:04 +0100 > Paolo Bonzini <pbonzini@redhat.com> wrote: > > > On 21/03/2016 14:47, TU BO wrote: > > >> I'll see if I can produce something based on Conny's patches, which are > > >> already a start. Today I had a short day so I couldn't play with the > > >> bug; out of curiosity, does the bug reproduce with her work + patch 4 > > >> from this series + the reentrancy assertion? > > > I did NOT see crash with qemu master + "[PATCH RFC 0/6] virtio: refactor > > > host notifiers" from Conny + patch 4 + assertion. thx > > > > That's unexpected, but I guess it only says that I didn't review her > > patches well enough. :) > > I'm also a bit surprised, the only thing that should really be > different is passing the 'assign' argument in stop_ioeventfd(). Any > other fixes are purely accidental :) > > Would be interesting to see how this setup fares with virtio-pci. > Seems to fix the assertion I'm hitting too. Fam
diff --git a/hw/block/virtio-blk.c b/hw/block/virtio-blk.c index a7ec572..96ea896 100644 --- a/hw/block/virtio-blk.c +++ b/hw/block/virtio-blk.c @@ -591,6 +591,8 @@ static void virtio_blk_handle_output(VirtIODevice *vdev, VirtQueue *vq) return; } + int x = atomic_fetch_inc(&s->test); + assert(x == 0); blk_io_plug(s->blk); while ((req = virtio_blk_get_request(s))) { @@ -602,6 +604,7 @@ static void virtio_blk_handle_output(VirtIODevice *vdev, VirtQueue *vq) } blk_io_unplug(s->blk); + atomic_dec(&s->test); } static void virtio_blk_dma_restart_bh(void *opaque) diff --git a/include/hw/virtio/virtio-blk.h b/include/hw/virtio/virtio-blk.h index ae84d92..6472503 100644 --- a/include/hw/virtio/virtio-blk.h +++ b/include/hw/virtio/virtio-blk.h @@ -48,6 +48,7 @@ typedef struct VirtIOBlock { BlockBackend *blk; VirtQueue *vq; void *rq; + int test; QEMUBH *bh; VirtIOBlkConf conf; unsigned short sector_mask;