Re: [Qemu-devel] [PATCH 0/6] virtio: refactor host notifiers

[Cornelia Huck]

On Tue, 29 Mar 2016 17:14:21 +0800
tu bo <address@hidden> wrote:

> Hi Paolo:
> 
> On 03/29/2016 02:11 AM, Paolo Bonzini wrote:
> > On 28/03/2016 05:55, TU BO wrote:
> >> Hi Cornelia:
> >>
> >> I got two crash with qemu master + "[PATCH 0/6] virtio: refactor host
> >> notifiers",
> >
> > Hi Tu Bo,
> >
> > please always include the assertion patch at
> > https://lists.gnu.org/archive/html/qemu-block/2016-03/msg00546.html in
> > your tests.  Can you include the backtrace from all threads with that patch?
> >
> thanks for your reminder about the assertion patch. Here is the 
> backtrace with qemu master + assertion patch + "[PATCH 0/6] virtio: 
> refactor host notifiers",

FWIW, I've been running this in a reboot loop for the last 2 1/2 hours.
Could you perhaps share your command line?

> 
> I got two crashes,
> 
> 1. For 1st crash,
> (gdb) thread apply all bt

This one looks a lot like the crashes before the rework, which I don't
understand...

> 
> Thread 8 (Thread 0x3ff8daf1910 (LWP 52859)):
> #0  0x000003ff9718ec62 in do_futex_timed_wait () from /lib64/libpthread.so.0
> #1  0x000003ff9718ed76 in sem_timedwait () from /lib64/libpthread.so.0
> #2  0x000002aa2d755868 in qemu_sem_timedwait (sem=0x3ff88000fa8, 
> ms=<optimized out>) at util/qemu-thread-posix.c:245
> #3  0x000002aa2d6803e4 in worker_thread (opaque=0x3ff88000f40) at 
> thread-pool.c:92
> #4  0x000003ff971884c6 in start_thread () from /lib64/libpthread.so.0
> #5  0x000003ff96802ec2 in thread_start () from /lib64/libc.so.6
> 
> Thread 7 (Thread 0x3ff8e679910 (LWP 52856)):
> #0  0x000003ff9718ec62 in do_futex_timed_wait () from /lib64/libpthread.so.0
> #1  0x000003ff9718ed76 in sem_timedwait () from /lib64/libpthread.so.0
> #2  0x000002aa2d755868 in qemu_sem_timedwait (sem=0x2aa2e1fbfa8, 
> ms=<optimized out>) at util/qemu-thread-posix.c:245
> #3  0x000002aa2d6803e4 in worker_thread (opaque=0x2aa2e1fbf40) at 
> thread-pool.c:92
> #4  0x000003ff971884c6 in start_thread () from /lib64/libpthread.so.0
> #5  0x000003ff96802ec2 in thread_start () from /lib64/libc.so.6
> 
> Thread 6 (Thread 0x3ff9497f910 (LWP 52850)):
> #0  0x000003ff9718c50e in pthread_cond_wait@@GLIBC_2.3.2 () from 
> /lib64/libpthread.so.0
> #1  0x000003ff96d19792 in g_cond_wait () from /lib64/libglib-2.0.so.0
> #2  0x000002aa2d7165d2 in wait_for_trace_records_available () at 
> trace/simple.c:147
> ---Type <return> to continue, or q <return> to quit---
> #3  writeout_thread (opaque=<optimized out>) at trace/simple.c:165
> #4  0x000003ff96cfa44c in g_thread_proxy () from /lib64/libglib-2.0.so.0
> #5  0x000003ff971884c6 in start_thread () from /lib64/libpthread.so.0
> #6  0x000003ff96802ec2 in thread_start () from /lib64/libc.so.6
> 
> Thread 5 (Thread 0x3ff8efff910 (LWP 52855)):
> #0  0x000003ff967f819a in ioctl () from /lib64/libc.so.6
> #1  0x000002aa2d546f3e in kvm_vcpu_ioctl (address@hidden, 
> address@hidden)
>      at /usr/src/debug/qemu-2.5.50/kvm-all.c:1984
> #2  0x000002aa2d54701e in kvm_cpu_exec (cpu=0x2aa2e239030) at 
> /usr/src/debug/qemu-2.5.50/kvm-all.c:1834
> #3  0x000002aa2d533cd6 in qemu_kvm_cpu_thread_fn (arg=<optimized out>) 
> at /usr/src/debug/qemu-2.5.50/cpus.c:1056
> #4  0x000003ff971884c6 in start_thread () from /lib64/libpthread.so.0
> #5  0x000003ff96802ec2 in thread_start () from /lib64/libc.so.6
> 
> Thread 4 (Thread 0x3ff951ff910 (LWP 52849)):
> #0  0x000003ff967fcf56 in syscall () from /lib64/libc.so.6
> #1  0x000002aa2d755a36 in futex_wait (val=<optimized out>, ev=<optimized 
> out>) at util/qemu-thread-posix.c:292
> #2  qemu_event_wait (ev=0x2aa2ddb5914 <rcu_call_ready_event>) at 
> util/qemu-thread-posix.c:399
> #3  0x000002aa2d765002 in call_rcu_thread (opaque=<optimized out>) at 
> util/rcu.c:250
> #4  0x000003ff971884c6 in start_thread () from /lib64/libpthread.so.0
> #5  0x000003ff96802ec2 in thread_start () from /lib64/libc.so.6
> ---Type <return> to continue, or q <return> to quit---
> 
> Thread 3 (Thread 0x3ff978e0bf0 (LWP 52845)):
> #0  0x000003ff967f66e6 in ppoll () from /lib64/libc.so.6
> #1  0x000002aa2d68928e 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=-1) 
> at qemu-timer.c:313
> #3  0x000002aa2d688b02 in os_host_main_loop_wait (timeout=-1) at 
> main-loop.c:251
> #4  main_loop_wait (nonblocking=<optimized out>) at main-loop.c:505
> #5  0x000002aa2d4faade in main_loop () at vl.c:1933
> #6  main (argc=<optimized out>, argv=<optimized out>, envp=<optimized 
> out>) at vl.c:4646
> 
> Thread 2 (Thread 0x3ff8ffff910 (LWP 52851)):
> #0  0x000003ff967f66e6 in ppoll () from /lib64/libc.so.6
> #1  0x000002aa2d68928e 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=-1) 
> at qemu-timer.c:313
> #3  0x000002aa2d68a788 in aio_poll (ctx=0x2aa2de77e00, 
> blocking=<optimized out>) at aio-posix.c:453
> #4  0x000002aa2d5b909c in iothread_run (opaque=0x2aa2de77220) at 
> iothread.c:46
> #5  0x000003ff971884c6 in start_thread () from /lib64/libpthread.so.0
> #6  0x000003ff96802ec2 in thread_start () from /lib64/libc.so.6
> 
> Thread 1 (Thread 0x3ff8f7ff910 (LWP 52854)):
> #0  0x000003ff9673b650 in raise () from /lib64/libc.so.6
> ---Type <return> to continue, or q <return> to quit---
> #1  0x000003ff9673ced8 in abort () from /lib64/libc.so.6
> #2  0x000003ff96733666 in __assert_fail_base () from /lib64/libc.so.6
> #3  0x000003ff967336f4 in __assert_fail () from /lib64/libc.so.6
> #4  0x000002aa2d562608 in virtio_blk_handle_output (vdev=<optimized 
> out>, vq=<optimized out>)
>      at /usr/src/debug/qemu-2.5.50/hw/block/virtio-blk.c:595

I don't see how we could get here from the cpu thread anymore... Did
you see any failure messages for setting host notifiers, btw.?
Otherwise, it might be worthwile adding some instrumentation for
setting up the host notifiers, so we can trace when the handler switch
is actually done.

> #5  0x000002aa2d587464 in virtio_ccw_hcall_notify (args=<optimized out>) 
> at /usr/src/debug/qemu-2.5.50/hw/s390x/s390-virtio-ccw.c:64
> #6  0x000002aa2d58236c in s390_virtio_hypercall (env=0x2aa2e205660) at 
> /usr/src/debug/qemu-2.5.50/hw/s390x/s390-virtio-hcall.c:35
> #7  0x000002aa2d5b0920 in handle_hypercall (run=<optimized out>, 
> cpu=0x2aa2e1fd390) at /usr/src/debug/qemu-2.5.50/target-s390x/kvm.c:1258
> #8  handle_diag (ipb=<optimized out>, run=0x3ff94080000, 
> cpu=0x2aa2e1fd390) at /usr/src/debug/qemu-2.5.50/target-s390x/kvm.c:1327
> #9  handle_instruction (run=0x3ff94080000, cpu=0x2aa2e1fd390) at 
> /usr/src/debug/qemu-2.5.50/target-s390x/kvm.c:1774
> #10 handle_intercept (cpu=0x2aa2e1fd390) at 
> /usr/src/debug/qemu-2.5.50/target-s390x/kvm.c:1817
> #11 kvm_arch_handle_exit (cs=<optimized out>, run=<optimized out>) at 
> /usr/src/debug/qemu-2.5.50/target-s390x/kvm.c:2003
> #12 0x000002aa2d547072 in kvm_cpu_exec (cpu=0x2aa2e1fd390) at 
> /usr/src/debug/qemu-2.5.50/kvm-all.c:1921
> #13 0x000002aa2d533cd6 in qemu_kvm_cpu_thread_fn (arg=<optimized out>) 
> at /usr/src/debug/qemu-2.5.50/cpus.c:1056
> #14 0x000003ff971884c6 in start_thread () from /lib64/libpthread.so.0
> #15 0x000003ff96802ec2 in thread_start () from /lib64/libc.so.6
> 
> 
> 
> 2. For 2nd crash,
> (gdb) thread apply all bt
> 
> Thread 10 (Thread 0x3ffacdff910 (LWP 52818)):
> #0  0x000003ffafcf819a in ioctl () from /lib64/libc.so.6
> #1  0x000002aa090c6f3e in kvm_vcpu_ioctl (address@hidden, 
> address@hidden) at /usr/src/debug/qemu-2.5.50/kvm-all.c:1984
> #2  0x000002aa090c701e in kvm_cpu_exec (cpu=0x2aa09d7d390) at 
> /usr/src/debug/qemu-2.5.50/kvm-all.c:1834
> #3  0x000002aa090b3cd6 in qemu_kvm_cpu_thread_fn (arg=0x2aa09d7d390) at 
> /usr/src/debug/qemu-2.5.50/cpus.c:1056
> #4  0x000003ffb06884c6 in start_thread () from /lib64/libpthread.so.0
> #5  0x000003ffafd02ec2 in thread_start () from /lib64/libc.so.6
> 
> Thread 9 (Thread 0x3ff5feff910 (LWP 52819)):
> #0  0x000003ffafcf819a in ioctl () from /lib64/libc.so.6
> #1  0x000002aa090c6f3e in kvm_vcpu_ioctl (address@hidden, 
> address@hidden) at /usr/src/debug/qemu-2.5.50/kvm-all.c:1984
> #2  0x000002aa090c701e in kvm_cpu_exec (cpu=0x2aa09db91d0) at 
> /usr/src/debug/qemu-2.5.50/kvm-all.c:1834
> #3  0x000002aa090b3cd6 in qemu_kvm_cpu_thread_fn (arg=0x2aa09db91d0) at 
> /usr/src/debug/qemu-2.5.50/cpus.c:1056
> #4  0x000003ffb06884c6 in start_thread () from /lib64/libpthread.so.0
> #5  0x000003ffafd02ec2 in thread_start () from /lib64/libc.so.6
> 
> Thread 8 (Thread 0x3ff5e6ff910 (LWP 52822)):
> #0  0x000003ffb068ec62 in do_futex_timed_wait () from /lib64/libpthread.so.0
> #1  0x000003ffb068ed76 in sem_timedwait () from /lib64/libpthread.so.0
> #2  0x000002aa092d5868 in qemu_sem_timedwait (sem=0x2aa09dfc288, 
> ms=<optimized out>) at util/qemu-thread-posix.c:245
> #3  0x000002aa092003e4 in worker_thread (opaque=0x2aa09dfc220) at 
> thread-pool.c:92
> #4  0x000003ffb06884c6 in start_thread () from /lib64/libpthread.so.0
> #5  0x000003ffafd02ec2 in thread_start () from /lib64/libc.so.6
> 
> Thread 7 (Thread 0x3ffade7f910 (LWP 52814)):
> #0  0x000003ffb068c50e in pthread_cond_wait@@GLIBC_2.3.2 () from 
> /lib64/libpthread.so.0
> #1  0x000003ffb0219792 in g_cond_wait () from /lib64/libglib-2.0.so.0
> #2  0x000002aa092965d2 in wait_for_trace_records_available () at 
> trace/simple.c:147
> #3  writeout_thread (opaque=<optimized out>) at trace/simple.c:165
> #4  0x000003ffb01fa44c in g_thread_proxy () from /lib64/libglib-2.0.so.0
> #5  0x000003ffb06884c6 in start_thread () from /lib64/libpthread.so.0
> #6  0x000003ffafd02ec2 in thread_start () from /lib64/libc.so.6
> 
> Thread 6 (Thread 0x3ff5dcfd910 (LWP 52824)):
> #0  0x000003ffb068ec62 in do_futex_timed_wait () from /lib64/libpthread.so.0
> #1  0x000003ffb068ed76 in sem_timedwait () from /lib64/libpthread.so.0
> #2  0x000002aa092d5868 in qemu_sem_timedwait (sem=0x3ffa0000fa8, 
> ms=<optimized out>) at util/qemu-thread-posix.c:245
> #3  0x000002aa092003e4 in worker_thread (opaque=0x3ffa0000f40) at 
> thread-pool.c:92
> #4  0x000003ffb06884c6 in start_thread () from /lib64/libpthread.so.0
> #5  0x000003ffafd02ec2 in thread_start () from /lib64/libc.so.6
> 
> Thread 5 (Thread 0x3ffae6ff910 (LWP 52813)):
> #0  0x000003ffafcfcf56 in syscall () from /lib64/libc.so.6
> #1  0x000002aa092d5a36 in futex_wait (val=<optimized out>, ev=<optimized 
> out>) at util/qemu-thread-posix.c:292
> #2  qemu_event_wait (ev=0x2aa09935914 <rcu_call_ready_event>) at 
> util/qemu-thread-posix.c:399
> #3  0x000002aa092e5002 in call_rcu_thread (opaque=<optimized out>) at 
> util/rcu.c:250
> #4  0x000003ffb06884c6 in start_thread () from /lib64/libpthread.so.0
> #5  0x000003ffafd02ec2 in thread_start () from /lib64/libc.so.6
> 
> Thread 4 (Thread 0x3ff5f6ff910 (LWP 52820)):
> #0  0x000003ffafcf819a in ioctl () from /lib64/libc.so.6
> #1  0x000002aa090c6f3e in kvm_vcpu_ioctl (address@hidden, 
> address@hidden) at /usr/src/debug/qemu-2.5.50/kvm-all.c:1984
> #2  0x000002aa090c701e in kvm_cpu_exec (cpu=0x2aa09dcb490) at 
> /usr/src/debug/qemu-2.5.50/kvm-all.c:1834
> #3  0x000002aa090b3cd6 in qemu_kvm_cpu_thread_fn (arg=0x2aa09dcb490) at 
> /usr/src/debug/qemu-2.5.50/cpus.c:1056
> #4  0x000003ffb06884c6 in start_thread () from /lib64/libpthread.so.0
> #5  0x000003ffafd02ec2 in thread_start () from /lib64/libc.so.6
> ---Type <return> to continue, or q <return> to quit---
> 
> Thread 3 (Thread 0x3ffb0de0bf0 (LWP 52773)):
> #0  0x000003ffafcf66e6 in ppoll () from /lib64/libc.so.6
> #1  0x000002aa0920928e 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=-1) 
> at qemu-timer.c:313
> #3  0x000002aa09208b02 in os_host_main_loop_wait (timeout=-1) at 
> main-loop.c:251
> #4  main_loop_wait (nonblocking=<optimized out>) at main-loop.c:505
> #5  0x000002aa0907aade in main_loop () at vl.c:1933
> #6  main (argc=<optimized out>, argv=<optimized out>, envp=<optimized 
> out>) at vl.c:4646
> 
> Thread 2 (Thread 0x3ff5eeff910 (LWP 52821)):
> #0  0x000003ffafcf819a in ioctl () from /lib64/libc.so.6
> #1  0x000002aa090c6f3e in kvm_vcpu_ioctl (address@hidden, 
> address@hidden) at /usr/src/debug/qemu-2.5.50/kvm-all.c:1984
> #2  0x000002aa090c701e in kvm_cpu_exec (cpu=0x2aa09ddd750) at 
> /usr/src/debug/qemu-2.5.50/kvm-all.c:1834
> #3  0x000002aa090b3cd6 in qemu_kvm_cpu_thread_fn (arg=0x2aa09ddd750) at 
> /usr/src/debug/qemu-2.5.50/cpus.c:1056
> #4  0x000003ffb06884c6 in start_thread () from /lib64/libpthread.so.0
> #5  0x000003ffafd02ec2 in thread_start () from /lib64/libc.so.6
> 
> Thread 1 (Thread 0x3ffad67f910 (LWP 52815)):
> #0  blk_aio_read_entry (opaque=0x0) at block/block-backend.c:922
> #1  0x000002aa092e5f6e in coroutine_trampoline (i0=<optimized out>, 
> i1=1342188224) at util/coroutine-ucontext.c:78
> #2  0x000003ffafc5150a in __makecontext_ret () from /lib64/libc.so.6

I don't see the crash in here?