migration-test hung again during 'make check'.
Process tree:
ubuntu 42067 0.0 0.0 5460 3156 ? S 13:55 0:00
\_ bash -o pipefail -c echo
'MALLOC_PERTURB_=${MALLOC_PERTURB_:-$(( ${RANDOM:-0} % 255 + 1))}
QTEST_QEMU_IMG=./qemu-img
G_TEST_DBUS_DAEMON=/home/ubuntu/qemu/tests/dbus-vmstate-daemon.sh
QTEST_QEMU_BINARY=./qemu-system-aarch64
QTEST_QEMU_STORAGE_DAEMON_BINARY=./storage-daemon/qemu-storage-daemon
tests/qtest/migration-test --tap -k' &&
MALLOC_PERTURB_=${MALLOC_PERTURB_:-$(( ${RANDOM:-0} % 255 + 1))}
QTEST_QEMU_IMG=./qemu-img
G_TEST_DBUS_DAEMON=/home/ubuntu/qemu/tests/dbus-vmstate-daemon.sh
QTEST_QEMU_BINARY=./qemu-system-aarch64
QTEST_QEMU_STORAGE_DAEMON_BINARY=./storage-daemon/qemu-storage-daemon
tests/qtest/migration-test --tap -k -m quick < /dev/null |
./scripts/tap-driver.pl --test-name="qtest-aarch64/migration-test"
ubuntu 42070 0.0 0.0 78844 3184 ? Sl 13:55 0:01
\_ tests/qtest/migration-test --tap -k -m quick
ubuntu 43248 0.0 4.1 1401368 160852 ? Sl 13:55 0:03
| \_ ./qemu-system-aarch64 -qtest
unix:/tmp/qtest-42070.sock -qtest-log /dev/null -chardev
socket,path=/tmp/qtest-42070.qmp,id=char0 -mon
chardev=char0,mode=control -display none -accel kvm -accel tcg
-machine virt,gic-version=max -name source,debug-threads=on -m 150M
-serial file:/tmp/migration-test-SL7EkN/src_serial -cpu max -kernel
/tmp/migration-test-SL7EkN/bootsect -accel qtest
ubuntu 43256 0.0 1.4 1394208 57648 ? Sl 13:55 0:00
| \_ ./qemu-system-aarch64 -qtest
unix:/tmp/qtest-42070.sock -qtest-log /dev/null -chardev
socket,path=/tmp/qtest-42070.qmp,id=char0 -mon
chardev=char0,mode=control -display none -accel kvm -accel tcg
-machine virt,gic-version=max -name target,debug-threads=on -m 150M
-serial file:/tmp/migration-test-SL7EkN/dest_serial -incoming
unix:/tmp/migration-test-SL7EkN/migsocket -cpu max -kernel
/tmp/migration-test-SL7EkN/bootsect -accel qtest
ubuntu 42071 0.0 0.2 14116 11372 ? S 13:55 0:00
\_ perl ./scripts/tap-driver.pl
--test-name=qtest-aarch64/migration-test
Backtrace, migration-test process:
Thread 2 (Thread 0x3ff8ff7f910 (LWP 42075)):
#0 syscall () at ../sysdeps/unix/sysv/linux/s390/s390-64/syscall.S:53
#1 0x000002aa1d0d1c1c in qemu_futex_wait (val=<optimized out>,
f=<optimized out>) at /home/ubuntu/qemu/include/qemu/futex.h:29
#2 qemu_event_wait (ev=ev@entry=0x2aa1d0fda58 <rcu_call_ready_event>)
at ../../util/qemu-thread-posix.c:480
#3 0x000002aa1d0d0884 in call_rcu_thread (opaque=opaque@entry=0x0) at
../../util/rcu.c:258
#4 0x000002aa1d0d0c32 in qemu_thread_start (args=<optimized out>) at
../../util/qemu-thread-posix.c:541
#5 0x000003ff90207aa8 in start_thread (arg=0x3ff8ff7f910) at
pthread_create.c:463
#6 0x000003ff900fa11e in thread_start () at
../sysdeps/unix/sysv/linux/s390/s390-64/clone.S:65
Thread 1 (Thread 0x3ff905f7c00 (LWP 42070)):
#0 0x000003ff90212978 in __waitpid (pid=<optimized out>,
stat_loc=stat_loc@entry=0x2aa1d5e06bc, options=options@entry=0)
at ../sysdeps/unix/sysv/linux/waitpid.c:30
#1 0x000002aa1d0a2176 in qtest_kill_qemu (s=0x2aa1d5e06b0) at
../../tests/qtest/libqtest.c:144
#2 0x000003ff903c0de6 in g_hook_list_invoke () from
/usr/lib/s390x-linux-gnu/libglib-2.0.so.0
#3 <signal handler called>
#4 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#5 0x000003ff9003f3ca in __GI_abort () at abort.c:79
#6 0x000003ff903fcbb2 in g_assertion_message () from
/usr/lib/s390x-linux-gnu/libglib-2.0.so.0
#7 0x000003ff903fd2b4 in g_assertion_message_cmpstr () from
/usr/lib/s390x-linux-gnu/libglib-2.0.so.0
#8 0x000002aa1d0a10f6 in check_migration_status
(ungoals=0x3ffffdfe198, goal=0x2aa1d0d75c0 "postcopy-paused",
who=0x2aa1d5dee90)
at ../../tests/qtest/migration-helpers.c:146
#9 wait_for_migration_status (who=0x2aa1d5dee90, goal=<optimized
out>, ungoals=0x3ffffdfe198)
at ../../tests/qtest/migration-helpers.c:156
#10 0x000002aa1d09f610 in test_postcopy_recovery () at
../../tests/qtest/migration-test.c:773
#11 0x000003ff903fc70c in ?? () from /usr/lib/s390x-linux-gnu/libglib-2.0.so.0
#12 0x000003ff903fc648 in ?? () from /usr/lib/s390x-linux-gnu/libglib-2.0.so.0
#13 0x000003ff903fc648 in ?? () from /usr/lib/s390x-linux-gnu/libglib-2.0.so.0
#14 0x000003ff903fc648 in ?? () from /usr/lib/s390x-linux-gnu/libglib-2.0.so.0
#15 0x000003ff903fc8ee in g_test_run_suite () from
/usr/lib/s390x-linux-gnu/libglib-2.0.so.0
#16 0x000003ff903fc928 in g_test_run () from
/usr/lib/s390x-linux-gnu/libglib-2.0.so.0
#17 0x000002aa1d09d8f2 in main (argc=<optimized out>, argv=<optimized
out>) at ../../tests/qtest/migration-test.c:1495
Backtrace, QEMU process 43248:
Thread 5 (Thread 0x3ff8d7fe910 (LWP 43361)):
#0 0x000003ff9d110582 in futex_abstimed_wait_cancelable (private=0,
abstime=0x0, expected=0, futex_word=0x2aa1e27dfac)
at ../sysdeps/unix/sysv/linux/futex-internal.h:205
#1 0x000003ff9d110582 in do_futex_wait (sem=sem@entry=0x2aa1e27dfa8,
abstime=0x0) at sem_waitcommon.c:111
#2 0x000003ff9d11068c in __new_sem_wait_slow
(sem=sem@entry=0x2aa1e27dfa8, abstime=0x0) at sem_waitcommon.c:181
#3 0x000003ff9d110734 in __new_sem_wait (sem=sem@entry=0x2aa1e27dfa8)
at sem_wait.c:42
#4 0x000002aa1b6dfb96 in qemu_sem_wait (sem=0x2aa1e27dfa8,
sem@entry=<error reading variable: value has been optimized out>)
at ../../util/qemu-thread-posix.c:357
#5 0x000002aa1aefe5b0 in postcopy_pause_return_path_thread
(s=0x2aa1e27dc00) at ../../migration/migration.c:2654
#6 0x000002aa1aefe5b0 in source_return_path_thread
(opaque=opaque@entry=0x2aa1e27dc00) at
../../migration/migration.c:2854
#7 0x000002aa1b6ded72 in qemu_thread_start (args=<optimized out>) at
../../util/qemu-thread-posix.c:541
#8 0x000003ff9d107aa8 in start_thread (arg=0x3ff8d7fe910) at
pthread_create.c:463
#9 0x000003ff9cffa11e in thread_start () at
../sysdeps/unix/sysv/linux/s390/s390-64/clone.S:65
Thread 4 (Thread 0x3ff8ed42910 (LWP 43252)):
#0 0x000003ff9d10d9fe in futex_wait_cancelable (private=<optimized
out>, expected=0, futex_word=0x2aa1e49ca68)
at ../sysdeps/unix/sysv/linux/futex-internal.h:88
#1 0x000003ff9d10d9fe in __pthread_cond_wait_common (abstime=0x0,
mutex=0x2aa1c1a4840 <qemu_global_mutex>, cond=0x2aa1e49ca40)
at pthread_cond_wait.c:502
#2 0x000003ff9d10d9fe in __pthread_cond_wait
(cond=cond@entry=0x2aa1e49ca40, mutex=mutex@entry=0x2aa1c1a4840
<qemu_global_mutex>)
at pthread_cond_wait.c:655
#3 0x000002aa1b6df59e in qemu_cond_wait_impl (cond=0x2aa1e49ca40,
mutex=0x2aa1c1a4840 <qemu_global_mutex>, file=0x2aa1b8a93c6
"../../softmmu/cpus.c", line=<optimized out>) at
../../util/qemu-thread-posix.c:194
#4 0x000002aa1b40764e in qemu_wait_io_event
(cpu=cpu@entry=0x2aa1e43aa50) at ../../softmmu/cpus.c:419
#5 0x000002aa1b406916 in mttcg_cpu_thread_fn
(arg=arg@entry=0x2aa1e43aa50) at
../../accel/tcg/tcg-accel-ops-mttcg.c:98
#6 0x000002aa1b6ded72 in qemu_thread_start (args=<optimized out>) at
../../util/qemu-thread-posix.c:541
#7 0x000003ff9d107aa8 in start_thread (arg=0x3ff8ed42910) at
pthread_create.c:463
#8 0x000003ff9cffa11e in thread_start () at
../sysdeps/unix/sysv/linux/s390/s390-64/clone.S:65
Thread 3 (Thread 0x3ff8f735910 (LWP 43251)):
#0 0x000003ff9cfef1b0 in __GI___poll (fds=0x3ff64003620, nfds=3,
timeout=<optimized out>) at ../sysdeps/unix/sysv/linux/poll.c:29
#1 0x000003ff9e852624 in () at /usr/lib/s390x-linux-gnu/libglib-2.0.so.0
#2 0x000003ff9e852aa8 in g_main_loop_run () at
/usr/lib/s390x-linux-gnu/libglib-2.0.so.0
#3 0x000002aa1b4eaf0e in iothread_run
(opaque=opaque@entry=0x2aa1df83b80) at ../../iothread.c:73
#4 0x000002aa1b6ded72 in qemu_thread_start (args=<optimized out>) at
../../util/qemu-thread-posix.c:541
#5 0x000003ff9d107aa8 in start_thread (arg=0x3ff8f735910) at
pthread_create.c:463
#6 0x000003ff9cffa11e in thread_start () at
../sysdeps/unix/sysv/linux/s390/s390-64/clone.S:65
Thread 2 (Thread 0x3ff90037910 (LWP 43250)):
#0 0x000003ff9cff52ea in syscall () at
../sysdeps/unix/sysv/linux/s390/s390-64/syscall.S:53
#1 0x000002aa1b6dfd5c in qemu_futex_wait (val=<optimized out>,
f=<optimized out>) at /home/ubuntu/qemu/include/qemu/futex.h:29
#2 0x000002aa1b6dfd5c in qemu_event_wait (ev=ev@entry=0x2aa1c1c3888
<rcu_call_ready_event>) at ../../util/qemu-thread-posix.c:480
#3 0x000002aa1b6d917c in call_rcu_thread (opaque=opaque@entry=0x0) at
../../util/rcu.c:258
#4 0x000002aa1b6ded72 in qemu_thread_start (args=<optimized out>) at
../../util/qemu-thread-posix.c:541
#5 0x000003ff9d107aa8 in start_thread (arg=0x3ff90037910) at
pthread_create.c:463
#6 0x000003ff9cffa11e in thread_start () at
../sysdeps/unix/sysv/linux/s390/s390-64/clone.S:65
Thread 1 (Thread 0x3ff9feb5470 (LWP 43248)):
#0 0x000003ff9cfef302 in __GI_ppoll (fds=0x2aa1ed28d00, nfds=6,
timeout=<optimized out>,
timeout@entry=0x3fff517ecf8, sigmask=sigmask@entry=0x0) at
../sysdeps/unix/sysv/linux/ppoll.c:39
#1 0x000002aa1b701fec in ppoll (__ss=0x0, __timeout=0x3fff517ecf8,
__nfds=<optimized out>, __fds=<optimized out>)
at /usr/include/s390x-linux-gnu/bits/poll2.h:77
#2 0x000002aa1b701fec in qemu_poll_ns (fds=<optimized out>,
nfds=<optimized out>, timeout=timeout@entry=1000000000)
at ../../util/qemu-timer.c:348
#3 0x000002aa1b6d2f98 in os_host_main_loop_wait (timeout=1000000000)
at ../../util/main-loop.c:250
#4 0x000002aa1b6d2f98 in main_loop_wait
(nonblocking=nonblocking@entry=0) at ../../util/main-loop.c:531
#5 0x000002aa1b496d44 in qemu_main_loop () at ../../softmmu/runstate.c:726
#6 0x000002aa1ae6d3f0 in main (argc=<optimized out>, argv=<optimized
out>, envp=<optimized out>) at ../../softmmu/main.c:50
Backtrace, QEMU process 43256:
Thread 6 (Thread 0x3ff726ff910 (LWP 43440)):
#0 0x000003ffb9f10582 in futex_abstimed_wait_cancelable (private=0,
abstime=0x0, expected=0, futex_word=0x2aa1a75d2d4)
at ../sysdeps/unix/sysv/linux/futex-internal.h:205
#1 0x000003ffb9f10582 in do_futex_wait (sem=sem@entry=0x2aa1a75d2d0,
abstime=0x0) at sem_waitcommon.c:111
#2 0x000003ffb9f1068c in __new_sem_wait_slow
(sem=sem@entry=0x2aa1a75d2d0, abstime=0x0) at sem_waitcommon.c:181
#3 0x000003ffb9f10734 in __new_sem_wait (sem=sem@entry=0x2aa1a75d2d0)
at sem_wait.c:42
#4 0x000002aa17ddfb96 in qemu_sem_wait (sem=sem@entry=0x2aa1a75d2d0)
at ../../util/qemu-thread-posix.c:357
#5 0x000002aa17599f06 in postcopy_pause_incoming (mis=<optimized
out>) at ../../migration/savevm.c:2600
#6 0x000002aa17599f06 in qemu_loadvm_state_main
(f=f@entry=0x2aa1a751610, mis=mis@entry=0x2aa1a75d130)
at ../../migration/savevm.c:2674
#7 0x000002aa1759af4a in postcopy_ram_listen_thread
(opaque=opaque@entry=0x0) at ../../migration/savevm.c:1872
#8 0x000002aa17dded72 in qemu_thread_start (args=<optimized out>) at
../../util/qemu-thread-posix.c:541
#9 0x000003ffb9f07aa8 in start_thread (arg=0x3ff726ff910) at
pthread_create.c:463
#10 0x000003ffb9dfa11e in thread_start () at
../sysdeps/unix/sysv/linux/s390/s390-64/clone.S:65
Thread 5 (Thread 0x3ff88ffe910 (LWP 43439)):
#0 0x000003ffb9f10582 in futex_abstimed_wait_cancelable (private=0,
abstime=0x0, expected=0, futex_word=0x2aa1a75d2fc)
at ../sysdeps/unix/sysv/linux/futex-internal.h:205
#1 0x000003ffb9f10582 in do_futex_wait (sem=sem@entry=0x2aa1a75d2f8,
abstime=0x0) at sem_waitcommon.c:111
#2 0x000003ffb9f1068c in __new_sem_wait_slow
(sem=sem@entry=0x2aa1a75d2f8, abstime=0x0) at sem_waitcommon.c:181
#3 0x000003ffb9f10734 in __new_sem_wait (sem=sem@entry=0x2aa1a75d2f8)
at sem_wait.c:42
#4 0x000002aa17ddfb96 in qemu_sem_wait (sem=0x2aa1a75d2f8,
sem@entry=<error reading variable: value has been optimized out>)
at ../../util/qemu-thread-posix.c:357
#5 0x000002aa177ae6aa in postcopy_pause_fault_thread (mis=<optimized
out>) at ../../migration/postcopy-ram.c:847
#6 0x000002aa177ae6aa in postcopy_ram_fault_thread
(opaque=opaque@entry=0x2aa1a75d130) at
../../migration/postcopy-ram.c:911
#7 0x000002aa17dded72 in qemu_thread_start (args=<optimized out>) at
../../util/qemu-thread-posix.c:541
#8 0x000003ffb9f07aa8 in start_thread (arg=0x3ff88ffe910) at
pthread_create.c:463
#9 0x000003ffb9dfa11e in thread_start () at
../sysdeps/unix/sysv/linux/s390/s390-64/clone.S:65
Thread 4 (Thread 0x3ff89b18910 (LWP 43271)):
Python Exception <class 'gdb.error'> PC not saved:
Thread 3 (Thread 0x3ff8a319910 (LWP 43270)):
#0 0x000003ffb9def1b0 in __GI___poll (fds=0x3ff84003620, nfds=3,
timeout=<optimized out>) at ../sysdeps/unix/sysv/linux/poll.c:29
#1 0x000003ffbb652624 in () at /usr/lib/s390x-linux-gnu/libglib-2.0.so.0
#2 0x000003ffbb652aa8 in g_main_loop_run () at
/usr/lib/s390x-linux-gnu/libglib-2.0.so.0
#3 0x000002aa17beaf0e in iothread_run
(opaque=opaque@entry=0x2aa1a3aeb80) at ../../iothread.c:73
#4 0x000002aa17dded72 in qemu_thread_start (args=<optimized out>) at
../../util/qemu-thread-posix.c:541
#5 0x000003ffb9f07aa8 in start_thread (arg=0x3ff8a319910) at
pthread_create.c:463
#6 0x000003ffb9dfa11e in thread_start () at
../sysdeps/unix/sysv/linux/s390/s390-64/clone.S:65
Thread 2 (Thread 0x3fface37910 (LWP 43267)):
#0 0x000003ffb9df52ea in syscall () at
../sysdeps/unix/sysv/linux/s390/s390-64/syscall.S:53
#1 0x000002aa17ddfd5c in qemu_futex_wait (val=<optimized out>,
f=<optimized out>) at /home/ubuntu/qemu/include/qemu/futex.h:29
#2 0x000002aa17ddfd5c in qemu_event_wait (ev=ev@entry=0x2aa188c3888
<rcu_call_ready_event>) at ../../util/qemu-thread-posix.c:480
#3 0x000002aa17dd917c in call_rcu_thread (opaque=opaque@entry=0x0) at
../../util/rcu.c:258
#4 0x000002aa17dded72 in qemu_thread_start (args=<optimized out>) at
../../util/qemu-thread-posix.c:541
#5 0x000003ffb9f07aa8 in start_thread (arg=0x3fface37910) at
pthread_create.c:463
#6 0x000003ffb9dfa11e in thread_start () at
../sysdeps/unix/sysv/linux/s390/s390-64/clone.S:65
Thread 1 (Thread 0x3ffbccb5470 (LWP 43256)):
#0 0x000003ffb9f0d9fe in futex_wait_cancelable (private=<optimized
out>, expected=0, futex_word=0x2aa188a47e8 <qemu_pause_cond+40>)
at ../sysdeps/unix/sysv/linux/futex-internal.h:88
#1 0x000003ffb9f0d9fe in __pthread_cond_wait_common (abstime=0x0,
mutex=0x2aa188a4840 <qemu_global_mutex>, cond=0x2aa188a47c0
<qemu_pause_cond>) at pthread_cond_wait.c:502
#2 0x000003ffb9f0d9fe in __pthread_cond_wait
(cond=cond@entry=0x2aa188a47c0 <qemu_pause_cond>,
mutex=mutex@entry=0x2aa188a4840 <qemu_global_mutex>) at
pthread_cond_wait.c:655
#3 0x000002aa17ddf59e in qemu_cond_wait_impl (cond=0x2aa188a47c0
<qemu_pause_cond>, mutex=0x2aa188a4840 <qemu_global_mutex>,
file=0x2aa17fa93c6 "../../softmmu/cpus.c", line=<optimized out>) at
../../util/qemu-thread-posix.c:194
#4 0x000002aa17b079e2 in pause_all_vcpus () at ../../softmmu/cpus.c:562
#5 0x000002aa17b07aec in do_vm_stop
(state=state@entry=RUN_STATE_SHUTDOWN,
send_stop=send_stop@entry=false)
at ../../softmmu/cpus.c:261
#6 0x000002aa17b07bb6 in vm_shutdown () at ../../softmmu/cpus.c:280
#7 0x000002aa17b9716e in qemu_cleanup () at ../../softmmu/runstate.c:812
#8 0x000002aa1756d3f6 in main (argc=<optimized out>, argv=<optimized
out>, envp=<optimized out>) at ../../softmmu/main.c:51
No, I dunno why thread 4 was odd. Backtracing that thread seems to
only work about one time in two. Here's the backtrace from a
success:
#0 0x000002aa17b1ca2e in load_memop (op=MO_8, haddr=0x3ff80c6d000) at
../../accel/tcg/cputlb.c:1860
#1 0x000002aa17b1ca2e in load_helper (full_load=<optimized out>,
code_read=false, op=MO_8, retaddr=4396070052416, oi=<optimized out>,
addr=1177997312, env=0x2aa1a86f890) at ../../accel/tcg/cputlb.c:1980
#2 0x000002aa17b1ca2e in full_ldub_mmu (env=0x2aa1a86f890,
addr=1177997312, oi=<optimized out>, retaddr=4396070052416)
at ../../accel/tcg/cputlb.c:1996
#3 0x000003ff8a31a35e in code_gen_buffer ()
#4 0x000002aa17bbabb4 in cpu_tb_exec (tb_exit=<synthetic pointer>,
itb=<optimized out>, cpu=<optimized out>)
at ../../accel/tcg/cpu-exec.c:353
#5 0x000002aa17bbabb4 in cpu_loop_exec_tb (tb_exit=<synthetic
pointer>, last_tb=<synthetic pointer>, tb=<optimized out>,
cpu=<optimized out>) at ../../accel/tcg/cpu-exec.c:812
#6 0x000002aa17bbabb4 in cpu_exec (cpu=<optimized out>) at
../../accel/tcg/cpu-exec.c:970
#7 0x000002aa18764620 in ()
-- PMM
