On 2017/3/3 18:42, Fam Zheng wrote:
> On Fri, 03/03 09:29, Gonglei (Arei) wrote:
>> Hello Juan & Dave,
>>
>> We hit a bug in our test:
>> Network error occurs when migrating a guest, libvirt then rollback the
>> migration, causes qemu coredump
>> qemu log:
>> 2017-03-01T12:54:33.904949+08:00|info|qemu[17672]|[33614]|monitor_qapi_event_emit[479]|:
>> {"timestamp": {"seconds": 1488344073, "microseconds": 904914}, "event":
>> "STOP"}
>> 2017-03-01T12:54:37.522500+08:00|info|qemu[17672]|[17672]|handle_qmp_command[3930]|:
>> qmp_cmd_name: migrate_cancel
>> 2017-03-01T12:54:37.522607+08:00|info|qemu[17672]|[17672]|monitor_qapi_event_emit[479]|:
>> {"timestamp": {"seconds": 1488344077, "microseconds": 522556}, "event":
>> "MIGRATION", "data": {"status": "cancelling"}}
>> 2017-03-01T12:54:37.524671+08:00|info|qemu[17672]|[17672]|handle_qmp_command[3930]|:
>> qmp_cmd_name: cont
>> 2017-03-01T12:54:37.524733+08:00|info|qemu[17672]|[17672]|virtio_set_status[725]|:
>> virtio-balloon device status is 7 that means DRIVER OK
>> 2017-03-01T12:54:37.525434+08:00|info|qemu[17672]|[17672]|virtio_set_status[725]|:
>> virtio-net device status is 7 that means DRIVER OK
>> 2017-03-01T12:54:37.525484+08:00|info|qemu[17672]|[17672]|virtio_set_status[725]|:
>> virtio-blk device status is 7 that means DRIVER OK
>> 2017-03-01T12:54:37.525562+08:00|info|qemu[17672]|[17672]|virtio_set_status[725]|:
>> virtio-serial device status is 7 that means DRIVER OK
>> 2017-03-01T12:54:37.527653+08:00|info|qemu[17672]|[17672]|vm_start[981]|:
>> vm_state-notify:3ms
>> 2017-03-01T12:54:37.528523+08:00|info|qemu[17672]|[17672]|monitor_qapi_event_emit[479]|:
>> {"timestamp": {"seconds": 1488344077, "microseconds": 527699}, "event":
>> "RESUME"}
>> 2017-03-01T12:54:37.530680+08:00|info|qemu[17672]|[33614]|migration_bitmap_sync[720]|:
>> this iteration cycle takes 3s, new dirtied data:0MB
>> 2017-03-01T12:54:37.530909+08:00|info|qemu[17672]|[33614]|monitor_qapi_event_emit[479]|:
>> {"timestamp": {"seconds": 1488344077, "microseconds": 530733}, "event":
>> "MIGRATION_PASS", "data": {"pass": 3}}
>> 2017-03-01T04:54:37.530997Z qemu-kvm: socket_writev_buffer: Got err=32 for
>> (131583/18446744073709551615)
>> qemu-kvm:
>> /home/abuild/rpmbuild/BUILD/qemu-kvm-2.6.0/hw/net/virtio_net.c:1519:
>> virtio_net_save: Assertion `!n->vhost_started' failed.
>> 2017-03-01 12:54:43.028: shutting down
>>
>> From qemu log, qemu received and processed migrate_cancel/cont qmp commands
>> after guest been stopped and entered the last round of migration. Then
>> migration thread try to save device state when guest is running(started by
>> cont command), causes assert and coredump.
>> This is because in last iter, we call cpu_synchronize_all_states() to
>> synchronize vcpu states, this call will release qemu_global_mutex and wait
>> for do_kvm_cpu_synchronize_state() to be executed on target vcpu:
>> (gdb) bt
>> #0 0x00007f763d1046d5 in pthread_cond_wait@@GLIBC_2.3.2 () from
>> /lib64/libpthread.so.0
>> #1 0x00007f7643e51d7f in qemu_cond_wait (cond=0x7f764445eca0
>> <qemu_work_cond>, mutex=0x7f764445eba0 <qemu_global_mutex>) at
>> util/qemu-thread-posix.c:132
>> #2 0x00007f7643a2e154 in run_on_cpu (cpu=0x7f7644e06d80,
>> func=0x7f7643a46413 <do_kvm_cpu_synchronize_state>, data=0x7f7644e06d80) at
>> /mnt/public/yanghy/qemu-kvm/cpus.c:995
>> #3 0x00007f7643a46487 in kvm_cpu_synchronize_state (cpu=0x7f7644e06d80) at
>> /mnt/public/yanghy/qemu-kvm/kvm-all.c:1805
>> #4 0x00007f7643a2c700 in cpu_synchronize_state (cpu=0x7f7644e06d80) at
>> /mnt/public/yanghy/qemu-kvm/include/sysemu/kvm.h:457
>> #5 0x00007f7643a2db0c in cpu_synchronize_all_states () at
>> /mnt/public/yanghy/qemu-kvm/cpus.c:766
>> #6 0x00007f7643a67b5b in qemu_savevm_state_complete_precopy
>> (f=0x7f76462f2d30, iterable_only=false) at
>> /mnt/public/yanghy/qemu-kvm/migration/savevm.c:1051
>> #7 0x00007f7643d121e9 in migration_completion (s=0x7f76443e78c0
>> <current_migration.37571>, current_active_state=4,
>> old_vm_running=0x7f74343fda00, start_time=0x7f74343fda08) at
>> migration/migration.c:1753
>> #8 0x00007f7643d126c5 in migration_thread (opaque=0x7f76443e78c0
>> <current_migration.37571>) at migration/migration.c:1922
>> #9 0x00007f763d100dc5 in start_thread () from /lib64/libpthread.so.0
>> #10 0x00007f763ce2e71d in clone () from /lib64/libc.so.6
>> (gdb) p iothread_locked
>> $1 = true
>>
>> and then, qemu main thread been executed, it won't block because migration
>> thread released the qemu_global_mutex:
>> (gdb) thr 1
>> [Switching to thread 1 (Thread 0x7fe298e08bc0 (LWP 30767))]
>> #0 os_host_main_loop_wait (timeout=931565) at main-loop.c:270
>> 270 QEMU_LOG(LOG_INFO,"***** after qemu_pool_ns: timeout
>> %d\n", timeout);
>> (gdb) p iothread_locked
>> $2 = true
>> (gdb) l 268
>> 263
>> 264 ret = qemu_poll_ns((GPollFD *)gpollfds->data, gpollfds->len,
>> timeout);
>> 265
>> 266
>> 267 if (timeout) {
>> 268 qemu_mutex_lock_iothread();
>> 269 if (runstate_check(RUN_STATE_FINISH_MIGRATE)) {
>> 270 QEMU_LOG(LOG_INFO,"***** after qemu_pool_ns: timeout
>> %d\n", timeout);
>> 271 }
>> 272 }
>> (gdb)
>>
>> So, although we've hold iothread_lock in stop© phase of migration, we
>> can't guarantee the iothread been locked all through the stop & copy phase,
>> any thoughts on how to solve this problem?
>
> Could you post a backtrace of the assertion?
#0 0x00007f97b1fbe5d7 in raise () from /usr/lib64/libc.so.6
#1 0x00007f97b1fbfcc8 in abort () from /usr/lib64/libc.so.6
#2 0x00007f97b1fb7546 in __assert_fail_base () from /usr/lib64/libc.so.6
#3 0x00007f97b1fb75f2 in __assert_fail () from /usr/lib64/libc.so.6
#4 0x000000000049fd19 in virtio_net_save (f=0x7f97a8ca44d0,
opaque=0x7f97a86e9018) at /usr/src/debug/qemu-kvm-2.6.0/hw/
#5 0x000000000047e380 in vmstate_save_old_style (f=f@entry=0x7f97a8ca44d0,
vmdesc=vmdesc@entry=0x7f97a82f2210, se=0x7f9
#6 0x000000000047fb93 in vmstate_save (f=f@entry=0x7f97a8ca44d0,
se=se@entry=0x7f97a8558680, vmdesc=vmdesc@entry=0x7f97
#7 0x0000000000481ad2 in qemu_savevm_state_complete_precopy (f=0x7f97a8ca44d0,
iterable_only=iterable_only@entry=false)
#8 0x00000000006c6b60 in migration_completion (s=s@entry=0xdb7de0
<current_migration.38312>, current_active_state=curre
start_time=start_time@entry=0x7f96263fd9f8) at migration/migration.c:1761
#9 0x00000000006c71db in migration_thread (opaque=opaque@entry=0xdb7de0
<current_migration.38312>) at migration/migrati
>
> Fam
>
--
Thanks,
Yang
