Re: [PULL 00/18] migration queue

[Peter Maydell]

On Tue, 8 Mar 2022 at 18:47, Dr. David Alan Gilbert <dgilbert@redhat.com> wrote:
>
> * Philippe Mathieu-Daudé (philippe.mathieu.daude@gmail.com) wrote:
> > I'm seeing an error on the s390x runner:
> >
> > ▶  26/547 ERROR:../tests/qtest/migration-test.c:276:check_guests_ram:
> > assertion failed: (bad == 0) ERROR
> >
> >  26/547 qemu:qtest+qtest-i386 / qtest-i386/migration-test            ERROR
> > 78.87s   killed by signal 6 SIGABRT
> >
> > https://app.travis-ci.com/gitlab/qemu-project/qemu/jobs/562515884#L7848
>
> Yeh, thuth mentioned that, it seems to only be s390 which is odd.
> I'm not seeing anything obviously architecture dependent in that set, or
> for that matter that plays with the ram migration stream much.
> Is this reliable enough that someone with a tame s390 could bisect?

Didn't see a SIGABRT, but here's a gdb backtrace of a hang
in the migration test on s390 host. I have also observed the
migration test hanging on macos host, so I don't think this is
s390-specific.

Process tree:
migration-test(455775)-+-qemu-system-i38(456194)
                       |-qemu-system-i38(456200)
                       `-qemu-system-i38(456266)
===========================================================
PROCESS: 455775
linux1    455775  312266  5 14:36 pts/0    00:07:19
./tests/qtest/migration-test -tap -k
[New LWP 455776]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/s390x-linux-gnu/libthread_db.so.1".
__libc_read (nbytes=1, buf=0x3ffe69fd816, fd=4) at
../sysdeps/unix/sysv/linux/read.c:26
26      ../sysdeps/unix/sysv/linux/read.c: No such file or directory.

Thread 2 (Thread 0x3ff9c7ff900 (LWP 455776)):
#0  syscall () at ../sysdeps/unix/sysv/linux/s390/s390-64/syscall.S:37
#1  0x000002aa1e8d24ca in qemu_futex_wait (f=0x2aa1e920cbc
<rcu_call_ready_event>, val=4294967295) at
/home/linux1/qemu/include/qemu/futex.h:29
#2  0x000002aa1e8d276e in qemu_event_wait (ev=0x2aa1e920cbc
<rcu_call_ready_event>) at ../../util/qemu-thread-posix.c:481
#3  0x000002aa1e8e6ce2 in call_rcu_thread (opaque=0x0) at ../../util/rcu.c:261
#4  0x000002aa1e8d2998 in qemu_thread_start (args=0x2aa200e51e0) at
../../util/qemu-thread-posix.c:556
#5  0x000003ff9ca87e66 in start_thread (arg=0x3ff9c7ff900) at
pthread_create.c:477
#6  0x000003ff9c97cbf6 in thread_start () at
../sysdeps/unix/sysv/linux/s390/s390-64/clone.S:65

Thread 1 (Thread 0x3ff9ce75430 (LWP 455775)):
#0  __libc_read (nbytes=1, buf=0x3ffe69fd816, fd=4) at
../sysdeps/unix/sysv/linux/read.c:26
#1  __libc_read (fd=<optimized out>, buf=0x3ffe69fd816, nbytes=1) at
../sysdeps/unix/sysv/linux/read.c:24
#2  0x000002aa1e894652 in qmp_fd_receive (fd=4) at
../../tests/qtest/libqtest.c:613
#3  0x000002aa1e894816 in qtest_qmp_receive_dict (s=0x2aa200f6a20) at
../../tests/qtest/libqtest.c:648
#4  0x000002aa1e894782 in qtest_qmp_receive (s=0x2aa200f6a20) at
../../tests/qtest/libqtest.c:636
#5  0x000002aa1e894ede in qtest_vqmp (s=0x2aa200f6a20,
fmt=0x2aa1e8f140c "{ 'execute': 'query-migrate' }", ap=0x3ffe69fdb80)
at ../../tests/qtest/libqtest.c:749
#6  0x000002aa1e891ac0 in wait_command (who=0x2aa200f6a20,
command=0x2aa1e8f140c "{ 'execute': 'query-migrate' }") at
../../tests/qtest/migration-helpers.c:63
#7  0x000002aa1e891de8 in migrate_query (who=0x2aa200f6a20) at
../../tests/qtest/migration-helpers.c:107
#8  0x000002aa1e891e1a in migrate_query_status (who=0x2aa200f6a20) at
../../tests/qtest/migration-helpers.c:116
#9  0x000002aa1e891ef6 in check_migration_status (who=0x2aa200f6a20,
goal=0x2aa1e8f0f0e "cancelled", ungoals=0x0) at
../../tests/qtest/migration-helpers.c:132
#10 0x000002aa1e892150 in wait_for_migration_status
(who=0x2aa200f6a20, goal=0x2aa1e8f0f0e "cancelled", ungoals=0x0) at
../../tests/qtest/migration-helpers.c:156
#11 0x000002aa1e8910fa in test_multifd_tcp_cancel () at
../../tests/qtest/migration-test.c:1379
#12 0x000003ff9cc7e608 in ?? () from /lib/s390x-linux-gnu/libglib-2.0.so.0
#13 0x000003ff9cc7e392 in ?? () from /lib/s390x-linux-gnu/libglib-2.0.so.0
#14 0x000003ff9cc7e392 in ?? () from /lib/s390x-linux-gnu/libglib-2.0.so.0
#15 0x000003ff9cc7e392 in ?? () from /lib/s390x-linux-gnu/libglib-2.0.so.0
#16 0x000003ff9cc7e392 in ?? () from /lib/s390x-linux-gnu/libglib-2.0.so.0
#17 0x000003ff9cc7eada in g_test_run_suite () from
/lib/s390x-linux-gnu/libglib-2.0.so.0
#18 0x000003ff9cc7eb10 in g_test_run () from
/lib/s390x-linux-gnu/libglib-2.0.so.0
#19 0x000002aa1e891578 in main (argc=2, argv=0x3ffe69fece8) at
../../tests/qtest/migration-test.c:1491
[Inferior 1 (process 455775) detached]

===========================================================
PROCESS: 456194
linux1    456194  455775 85 14:39 pts/0    01:54:06 ./qemu-system-i386
-qtest unix:/tmp/qtest-455775.sock -qtest-log /dev/null -chardev
socket,path=/tmp/qtest-455775.qmp,id=char0 -mon
chardev=char0,mode=control -display none -accel kvm -accel tcg -name
source,debug-threads=on -m 150M -serial
file:/tmp/migration-test-dmqzpM/src_serial -drive
file=/tmp/migration-test-dmqzpM/bootsect,format=raw -accel qtest
[New LWP 456196]
[New LWP 456197]
[New LWP 456198]
[New LWP 456229]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/s390x-linux-gnu/libthread_db.so.1".
0x000003ff9a071c9c in __ppoll (fds=0x2aa2c46c2f0, nfds=5,
timeout=<optimized out>, sigmask=0x0) at
../sysdeps/unix/sysv/linux/ppoll.c:44
44      ../sysdeps/unix/sysv/linux/ppoll.c: No such file or directory.

Thread 5 (Thread 0x3fee0ff9900 (LWP 456229)):
#0  futex_abstimed_wait_cancelable (private=0, abstime=0x0, clockid=0,
expected=0, futex_word=0x2aa2c46e7e4) at
../sysdeps/nptl/futex-internal.h:320
#1  do_futex_wait (sem=sem@entry=0x2aa2c46e7e0, abstime=0x0,
clockid=0) at sem_waitcommon.c:112
#2  0x000003ff9a191870 in __new_sem_wait_slow (sem=0x2aa2c46e7e0,
abstime=0x0, clockid=0) at sem_waitcommon.c:184
#3  0x000003ff9a19190e in __new_sem_wait (sem=<optimized out>) at sem_wait.c:42
#4  0x000002aa2923da1e in qemu_sem_wait (sem=0x2aa2c46e7e0) at
../../util/qemu-thread-posix.c:358
#5  0x000002aa289483cc in multifd_send_sync_main (f=0x2aa2b5f92d0) at
../../migration/multifd.c:610
#6  0x000002aa28dfa30c in ram_save_iterate (f=0x2aa2b5f92d0,
opaque=0x2aa29bf75d0 <ram_state>) at ../../migration/ram.c:3049
#7  0x000002aa28958fee in qemu_savevm_state_iterate (f=0x2aa2b5f92d0,
postcopy=false) at ../../migration/savevm.c:1296
#8  0x000002aa28942d40 in migration_iteration_run (s=0x2aa2b3f9800) at
../../migration/migration.c:3607
#9  0x000002aa289434da in migration_thread (opaque=0x2aa2b3f9800) at
../../migration/migration.c:3838
#10 0x000002aa2923e020 in qemu_thread_start (args=0x2aa2b8b29e0) at
../../util/qemu-thread-posix.c:556
#11 0x000003ff9a187e66 in start_thread (arg=0x3fee0ff9900) at
pthread_create.c:477
#12 0x000003ff9a07cbf6 in thread_start () at
../sysdeps/unix/sysv/linux/s390/s390-64/clone.S:65

Thread 4 (Thread 0x3ff89f2f900 (LWP 456198)):
#0  env_neg (env=0x2aa2b5f5030) at /home/linux1/qemu/include/exec/cpu-all.h:478
#1  0x000002aa28f5376a in env_tlb (env=0x2aa2b5f5030) at
/home/linux1/qemu/include/exec/cpu-all.h:502
#2  0x000002aa28f538a8 in tlb_index (env=0x2aa2b5f5030, mmu_idx=2,
addr=73265152) at /home/linux1/qemu/include/exec/cpu_ldst.h:366
#3  0x000002aa28f574bc in tlb_set_page_with_attrs (cpu=0x2aa2b5ec750,
vaddr=73265152, paddr=73265152, attrs=..., prot=7, mmu_idx=2,
size=4096) at ../../accel/tcg/cputlb.c:1194
#4  0x000002aa28cdfd3e in handle_mmu_fault (cs=0x2aa2b5ec750,
addr=73265152, size=1, is_write1=0, mmu_idx=2) at
../../target/i386/tcg/sysemu/excp_helper.c:442
#5  0x000002aa28cdfe90 in x86_cpu_tlb_fill (cs=0x2aa2b5ec750,
addr=73265152, size=1, access_type=MMU_DATA_LOAD, mmu_idx=2,
probe=false, retaddr=4393820748608) at
../../target/i386/tcg/sysemu/excp_helper.c:468
#6  0x000002aa28f5794e in tlb_fill (cpu=0x2aa2b5ec750, addr=73265152,
size=1, access_type=MMU_DATA_LOAD, mmu_idx=2, retaddr=4393820748608)
at ../../accel/tcg/cputlb.c:1313
#7  0x000002aa28f59982 in load_helper (env=0x2aa2b5f5030,
addr=73265152, oi=3586, retaddr=4393820748608, op=MO_8,
code_read=false, full_load=0x2aa28f59db0 <full_ldub_mmu>) at
../../accel/tcg/cputlb.c:1934
#8  0x000002aa28f59e2e in full_ldub_mmu (env=0x2aa2b5f5030,
addr=73265152, oi=3586, retaddr=4393820748608) at
../../accel/tcg/cputlb.c:2025
#9  0x000002aa28f59e94 in helper_ret_ldub_mmu (env=0x2aa2b5f5030,
addr=73265152, oi=3586, retaddr=4393820748608) at
../../accel/tcg/cputlb.c:2031
#10 0x000003ff041ffbfa in code_gen_buffer ()
#11 0x000002aa28f3cfba in cpu_tb_exec (cpu=0x2aa2b5ec750,
itb=0x3ff441ffa00, tb_exit=0x3ff89f2af44) at
../../accel/tcg/cpu-exec.c:357
#12 0x000002aa28f3e47e in cpu_loop_exec_tb (cpu=0x2aa2b5ec750,
tb=0x3ff441ffa00, last_tb=0x3ff89f2af58, tb_exit=0x3ff89f2af44) at
../../accel/tcg/cpu-exec.c:847
#13 0x000002aa28f3e970 in cpu_exec (cpu=0x2aa2b5ec750) at
../../accel/tcg/cpu-exec.c:1006
#14 0x000002aa28f71a1e in tcg_cpus_exec (cpu=0x2aa2b5ec750) at
../../accel/tcg/tcg-accel-ops.c:68
#15 0x000002aa28f71efe in mttcg_cpu_thread_fn (arg=0x2aa2b5ec750) at
../../accel/tcg/tcg-accel-ops-mttcg.c:96
#16 0x000002aa2923e020 in qemu_thread_start (args=0x2aa2b60bb00) at
../../util/qemu-thread-posix.c:556
#17 0x000003ff9a187e66 in start_thread (arg=0x3ff89f2f900) at
pthread_create.c:477
#18 0x000003ff9a07cbf6 in thread_start () at
../sysdeps/unix/sysv/linux/s390/s390-64/clone.S:65

Thread 3 (Thread 0x3ff8a821900 (LWP 456197)):
#0  0x000003ff9a071b42 in __GI___poll (fds=0x3fefc003280, nfds=3,
timeout=<optimized out>) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x000003ff9c7d4386 in  () at /lib/s390x-linux-gnu/libglib-2.0.so.0
#2  0x000003ff9c7d4790 in g_main_loop_run () at
/lib/s390x-linux-gnu/libglib-2.0.so.0
#3  0x000002aa28fd9d56 in iothread_run (opaque=0x2aa2b339750) at
../../iothread.c:73
#4  0x000002aa2923e020 in qemu_thread_start (args=0x2aa2b2e7980) at
../../util/qemu-thread-posix.c:556
#5  0x000003ff9a187e66 in start_thread (arg=0x3ff8a821900) at
pthread_create.c:477
#6  0x000003ff9a07cbf6 in thread_start () at
../sysdeps/unix/sysv/linux/s390/s390-64/clone.S:65

Thread 2 (Thread 0x3ff8b1a4900 (LWP 456196)):
#0  syscall () at ../sysdeps/unix/sysv/linux/s390/s390-64/syscall.S:37
#1  0x000002aa2923db52 in qemu_futex_wait (f=0x2aa29c14244
<rcu_call_ready_event>, val=4294967295) at
/home/linux1/qemu/include/qemu/futex.h:29
#2  0x000002aa2923ddf6 in qemu_event_wait (ev=0x2aa29c14244
<rcu_call_ready_event>) at ../../util/qemu-thread-posix.c:481
#3  0x000002aa2924cbd2 in call_rcu_thread (opaque=0x0) at ../../util/rcu.c:261
#4  0x000002aa2923e020 in qemu_thread_start (args=0x2aa2b26ac90) at
../../util/qemu-thread-posix.c:556
#5  0x000003ff9a187e66 in start_thread (arg=0x3ff8b1a4900) at
pthread_create.c:477
#6  0x000003ff9a07cbf6 in thread_start () at
../sysdeps/unix/sysv/linux/s390/s390-64/clone.S:65

Thread 1 (Thread 0x3ff9d5fe440 (LWP 456194)):
#0  0x000003ff9a071c9c in __ppoll (fds=0x2aa2c46c2f0, nfds=5,
timeout=<optimized out>, sigmask=0x0) at
../sysdeps/unix/sysv/linux/ppoll.c:44
#1  0x000002aa2927a3e4 in qemu_poll_ns (fds=0x2aa2c46c2f0, nfds=5,
timeout=27206167) at ../../util/qemu-timer.c:348
#2  0x000002aa29272280 in os_host_main_loop_wait (timeout=27206167) at
../../util/main-loop.c:250
#3  0x000002aa29272434 in main_loop_wait (nonblocking=0) at
../../util/main-loop.c:531
#4  0x000002aa28901276 in qemu_main_loop () at ../../softmmu/runstate.c:727
#5  0x000002aa2887d2ce in main (argc=25, argv=0x3fff647eac8,
envp=0x3fff647eb98) at ../../softmmu/main.c:50
[Inferior 1 (process 456194) detached]

===========================================================
PROCESS: 456200
linux1    456200  455775  0 14:39 pts/0    00:00:00 [qemu-system-i38] <defunct>
/proc/456200/exe: No such file or directory.
Could not attach to process.  If your uid matches the uid of the target
process, check the setting of /proc/sys/kernel/yama/ptrace_scope, or try
again as the root user.  For more details, see /etc/sysctl.d/10-ptrace.conf
warning: process 456200 is a zombie - the process has already terminated
ptrace: Operation not permitted.
/home/linux1/456200: No such file or directory.

===========================================================
PROCESS: 456266
linux1    456266  455775  0 14:39 pts/0    00:00:00 ./qemu-system-i386
-qtest unix:/tmp/qtest-455775.sock -qtest-log /dev/null -chardev
socket,path=/tmp/qtest-455775.qmp,id=char0 -mon
chardev=char0,mode=control -display none -accel kvm -accel tcg -name
target,debug-threads=on -m 150M -serial
file:/tmp/migration-test-dmqzpM/dest_serial -incoming defer -drive
file=/tmp/migration-test-dmqzpM/bootsect,format=raw -accel qtest
[New LWP 456268]
[New LWP 456269]
[New LWP 456270]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/s390x-linux-gnu/libthread_db.so.1".
0x000003ff9a271c9c in __ppoll (fds=0x2aa0435eb40, nfds=6,
timeout=<optimized out>, sigmask=0x0) at
../sysdeps/unix/sysv/linux/ppoll.c:44
44      ../sysdeps/unix/sysv/linux/ppoll.c: No such file or directory.

Thread 4 (Thread 0x3ff8a12f900 (LWP 456270)):
#0  futex_wait_cancelable (private=0, expected=0,
futex_word=0x2aa0459cbac) at ../sysdeps/nptl/futex-internal.h:183
#1  __pthread_cond_wait_common (abstime=0x0, clockid=0,
mutex=0x2aa02ddec88 <qemu_global_mutex>, cond=0x2aa0459cb80) at
pthread_cond_wait.c:508
#2  __pthread_cond_wait (cond=0x2aa0459cb80, mutex=0x2aa02ddec88
<qemu_global_mutex>) at pthread_cond_wait.c:638
#3  0x000002aa0243d498 in qemu_cond_wait_impl (cond=0x2aa0459cb80,
mutex=0x2aa02ddec88 <qemu_global_mutex>, file=0x2aa024e81e8
"../../softmmu/cpus.c", line=424) at
../../util/qemu-thread-posix.c:195
#4  0x000002aa01af4cc0 in qemu_wait_io_event (cpu=0x2aa0457d750) at
../../softmmu/cpus.c:424
#5  0x000002aa02172028 in mttcg_cpu_thread_fn (arg=0x2aa0457d750) at
../../accel/tcg/tcg-accel-ops-mttcg.c:124
#6  0x000002aa0243e020 in qemu_thread_start (args=0x2aa0459cbc0) at
../../util/qemu-thread-posix.c:556
#7  0x000003ff9a387e66 in start_thread (arg=0x3ff8a12f900) at
pthread_create.c:477
#8  0x000003ff9a27cbf6 in thread_start () at
../sysdeps/unix/sysv/linux/s390/s390-64/clone.S:65

Thread 3 (Thread 0x3ff8aa21900 (LWP 456269)):
#0  0x000003ff9a271b42 in __GI___poll (fds=0x3fefc003280, nfds=3,
timeout=<optimized out>) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x000003ff9c9d4386 in  () at /lib/s390x-linux-gnu/libglib-2.0.so.0
#2  0x000003ff9c9d4790 in g_main_loop_run () at
/lib/s390x-linux-gnu/libglib-2.0.so.0
#3  0x000002aa021d9d56 in iothread_run (opaque=0x2aa042ca750) at
../../iothread.c:73
#4  0x000002aa0243e020 in qemu_thread_start (args=0x2aa04278980) at
../../util/qemu-thread-posix.c:556
#5  0x000003ff9a387e66 in start_thread (arg=0x3ff8aa21900) at
pthread_create.c:477
#6  0x000003ff9a27cbf6 in thread_start () at
../sysdeps/unix/sysv/linux/s390/s390-64/clone.S:65

Thread 2 (Thread 0x3ff8b3a4900 (LWP 456268)):
#0  syscall () at ../sysdeps/unix/sysv/linux/s390/s390-64/syscall.S:37
#1  0x000002aa0243db52 in qemu_futex_wait (f=0x2aa02e14244
<rcu_call_ready_event>, val=4294967295) at
/home/linux1/qemu/include/qemu/futex.h:29
#2  0x000002aa0243ddf6 in qemu_event_wait (ev=0x2aa02e14244
<rcu_call_ready_event>) at ../../util/qemu-thread-posix.c:481
#3  0x000002aa0244cbd2 in call_rcu_thread (opaque=0x0) at ../../util/rcu.c:261
#4  0x000002aa0243e020 in qemu_thread_start (args=0x2aa041fbc90) at
../../util/qemu-thread-posix.c:556
#5  0x000003ff9a387e66 in start_thread (arg=0x3ff8b3a4900) at
pthread_create.c:477
#6  0x000003ff9a27cbf6 in thread_start () at
../sysdeps/unix/sysv/linux/s390/s390-64/clone.S:65

Thread 1 (Thread 0x3ff9d7fe440 (LWP 456266)):
#0  0x000003ff9a271c9c in __ppoll (fds=0x2aa0435eb40, nfds=6,
timeout=<optimized out>, sigmask=0x0) at
../sysdeps/unix/sysv/linux/ppoll.c:44
#1  0x000002aa0247a3e4 in qemu_poll_ns (fds=0x2aa0435eb40, nfds=6,
timeout=1000000000) at ../../util/qemu-timer.c:348
#2  0x000002aa02472280 in os_host_main_loop_wait (timeout=1000000000)
at ../../util/main-loop.c:250
#3  0x000002aa02472434 in main_loop_wait (nonblocking=0) at
../../util/main-loop.c:531
#4  0x000002aa01b01276 in qemu_main_loop () at ../../softmmu/runstate.c:727
#5  0x000002aa01a7d2ce in main (argc=27, argv=0x3ffe38fe7e8,
envp=0x3ffe38fe8c8) at ../../softmmu/main.c:50
[Inferior 1 (process 456266) detached]

thanks
-- PMM