Re: [Qemu-devel] [Migration Bug? ] Occasionally, the content of VM's memory is inconsistent between Source and Destination of migration

[Dr. David Alan Gilbert]

* zhanghailiang (address@hidden) wrote:
> On 2015/3/30 15:59, Dr. David Alan Gilbert wrote:
> >* zhanghailiang (address@hidden) wrote:
> >>On 2015/3/27 18:18, Dr. David Alan Gilbert wrote:
> >>>* zhanghailiang (address@hidden) wrote:
> >>>>On 2015/3/26 11:52, Li Zhijian wrote:
> >>>>>On 03/26/2015 11:12 AM, Wen Congyang wrote:
> >>>>>>On 03/25/2015 05:50 PM, Juan Quintela wrote:
> >>>>>>>zhanghailiang<address@hidden>  wrote:
> >>>>>>>>Hi all,
> >>>>>>>>
> >>>>>>>>We found that, sometimes, the content of VM's memory is inconsistent 
> >>>>>>>>between Source side and Destination side
> >>>>>>>>when we check it just after finishing migration but before VM 
> >>>>>>>>continue to Run.
> >>>>>>>>
> >>>>>>>>We use a patch like bellow to find this issue, you can find it from 
> >>>>>>>>affix,
> >>>>>>>>and Steps to reprduce:
> >>>>>>>>
> >>>>>>>>(1) Compile QEMU:
> >>>>>>>>  ./configure --target-list=x86_64-softmmu  --extra-ldflags="-lssl" 
> >>>>>>>> && make
> >>>>>>>>
> >>>>>>>>(2) Command and output:
> >>>>>>>>SRC: # x86_64-softmmu/qemu-system-x86_64 -enable-kvm -cpu 
> >>>>>>>>qemu64,-kvmclock -netdev tap,id=hn0-device 
> >>>>>>>>virtio-net-pci,id=net-pci0,netdev=hn0 -boot c -drive 
> >>>>>>>>file=/mnt/sdb/pure_IMG/sles/sles11_sp3.img,if=none,id=drive-virtio-disk0,cache=unsafe
> >>>>>>>> -device 
> >>>>>>>>virtio-blk-pci,bus=pci.0,addr=0x4,drive=drive-virtio-disk0,id=virtio-disk0
> >>>>>>>> -vnc :7 -m 2048 -smp 2 -device piix3-usb-uhci -device usb-tablet 
> >>>>>>>>-monitor stdio
> >>>>>>>Could you try to reproduce:
> >>>>>>>- without vhost
> >>>>>>>- without virtio-net
> >>>>>>>- cache=unsafe is going to give you trouble, but trouble should only
> >>>>>>>   happen after migration of pages have finished.
> >>>>>>If I use ide disk, it doesn't happen.
> >>>>>>Even if I use virtio-net with vhost=on, it still doesn't happen. I guess
> >>>>>>it is because I migrate the guest when it is booting. The virtio net
> >>>>>>device is not used in this case.
> >>>>>Er??????
> >>>>>it reproduces in my ide disk
> >>>>>there is no any virtio device, my command line like below
> >>>>>
> >>>>>x86_64-softmmu/qemu-system-x86_64 -enable-kvm -cpu qemu64,-kvmclock -net 
> >>>>>none
> >>>>>-boot c -drive file=/home/lizj/ubuntu.raw -vnc :7 -m 2048 -smp 2 -machine
> >>>>>usb=off -no-user-config -nodefaults -monitor stdio -vga std
> >>>>>
> >>>>>it seems easily to reproduce this issue by following steps in _ubuntu_ 
> >>>>>guest
> >>>>>1.  in source side, choose memtest in grub
> >>>>>2. do live migration
> >>>>>3. exit memtest(type Esc in when memory testing)
> >>>>>4. wait migration complete
> >>>>>
> >>>>
> >>>>Yes???it is a thorny problem. It is indeed easy to reproduce, just as
> >>>>your steps in the above.
> >>>>
> >>>>This is my test result: (I also test accel=tcg, it can be reproduced 
> >>>>also.)
> >>>>Source side:
> >>>># x86_64-softmmu/qemu-system-x86_64 -machine 
> >>>>pc-i440fx-2.3,accel=kvm,usb=off -no-user-config -nodefaults  -cpu 
> >>>>qemu64,-kvmclock -boot c -drive 
> >>>>file=/mnt/sdb/pure_IMG/ubuntu/ubuntu_14.04_server_64_2U_raw -device 
> >>>>cirrus-vga,id=video0,vgamem_mb=8 -vnc :7 -m 2048 -smp 2 -monitor stdio
> >>>>(qemu) ACPI_BUILD: init ACPI tables
> >>>>ACPI_BUILD: init ACPI tables
> >>>>migrate tcp:9.61.1.8:3004
> >>>>ACPI_BUILD: init ACPI tables
> >>>>before cpu_synchronize_all_states
> >>>>5a8f72d66732cac80d6a0d5713654c0e
> >>>>md_host : before saving ram complete
> >>>>5a8f72d66732cac80d6a0d5713654c0e
> >>>>md_host : after saving ram complete
> >>>>5a8f72d66732cac80d6a0d5713654c0e
> >>>>(qemu)
> >>>>
> >>>>Destination side:
> >>>># x86_64-softmmu/qemu-system-x86_64 -machine 
> >>>>pc-i440fx-2.3,accel=kvm,usb=off -no-user-config -nodefaults  -cpu 
> >>>>qemu64,-kvmclock -boot c -drive 
> >>>>file=/mnt/sdb/pure_IMG/ubuntu/ubuntu_14.04_server_64_2U_raw -device 
> >>>>cirrus-vga,id=video0,vgamem_mb=8 -vnc :7 -m 2048 -smp 2 -monitor stdio 
> >>>>-incoming tcp:0:3004
> >>>>(qemu) QEMU_VM_SECTION_END, after loading ram
> >>>>d7cb0d8a4bdd1557fb0e78baee50c986
> >>>>md_host : after loading all vmstate
> >>>>d7cb0d8a4bdd1557fb0e78baee50c986
> >>>>md_host : after cpu_synchronize_all_post_init
> >>>>d7cb0d8a4bdd1557fb0e78baee50c986
> >>>
> >>>Hmm, that's not good.  I suggest you md5 each of the RAMBlock's 
> >>>individually;
> >>>to see if it's main RAM that's different or something more subtle like
> >>>video RAM.
> >>>
> >>
> >>Er, all my previous tests are md5 'pc.ram' block only.
> >>
> >>>But then maybe it's easier just to dump the whole of RAM to file
> >>>and byte compare it (hexdump the two dumps and diff ?)
> >>
> >>Hmm, we also used memcmp function to compare every page, but the addresses
> >>seem to be random.
> >>
> >>Besides, in our previous test, we found it seems to be more easy to 
> >>reproduce
> >>when migration occurs during VM's start-up or reboot process.
> >>
> >>Is there any possible that some devices have special treatment when VM 
> >>start-up
> >>which may miss setting dirty-bitmap ?
> >
> >I don't think there should be, but the code paths used during startup are
> >probably much less tested with migration.  I'm sure the startup code
> >uses different part of device emulation.   I do know we have some bugs
> 
> Er, Maybe there is a special case:
> 
> During VM's start-up, i found that the KVMslot changed many times, it was a 
> process of
> smashing total memory space into small slot.
> 
> If some pages was dirtied and its dirty-bitmap has been set in KVM module,
> but we didn't sync the bitmaps to QEMU user-space before this slot was 
> smashed,
> with its previous bitmap been destroyed.
> The bitmap of dirty pages in the previous KVMslot maybe be missed.
> 
> What's your opinion? Can this situation i described in the above happen?
> 
> The bellow log was grabbed, when i tried to figure out a quite same question 
> (some pages miss dirty-bitmap setting) we found in COLO:
> Occasionally, there will be an error report in SLAVE side:
> 
>     qemu: warning: error while loading state for instance 0x0 of device
>     'kvm-tpr-opt'                                                 '
>     qemu-system-x86_64: loadvm failed
> 
> We found that it related to three address (gpa: 0xca000,0xcb000,0xcc000, 
> which are the address of 'kvmvapic.rom ?'), and sometimes
> their corresponding dirty-map will be missed in Master side, because their 
> KVMSlot is destroyed before we sync its dirty-bitmap to qemu.
> 
> (I'm still not quite sure if this can also happen in common migration, i will 
> try to test it in normal migration)

Ah, kvm-tpr-opt.
I also hit this today with colo; it didn't happen on a new machine, but it 
happens on an older machine, or in
this case a nested setup.

-global kvm-apic.vapic=false

Turns the vapic off, and seems to have got me further.

I don't understand the details of kvm-tpr-opt; but it's a hack for speeding up 
access
to the 'tpr' (Task priority register) which apparently Windows does a lot and 
used
to slow things down;  the hack does involve modifying some stuff on the fly, 
and it
doesn't happen if the host has some new features (tpr shadow I think also look 
for flexpriority).

Dave
> 
> Thanks,
> zhanghailiang
> 
> /var/log/message:
> Mar 31 18:32:53 master kernel: [15908.524721] memslot dirty bitmap of '4' was 
> destroyed, base_gfn 0x100, npages 524032
> Mar 31 18:32:53 master kernel: [15908.657853] +++ gfn=0xcc is marked dirty, 
> id=2, base_gfn=0xc0, npages=524096
> Mar 31 18:32:53 master kernel: [15908.665105] +++ gfn=0xcb is marked dirty, 
> id=2, base_gfn=0xc0, npages=524096
> Mar 31 18:32:53 master kernel: [15908.672360] +++ gfn=0xca is marked dirty, 
> id=2, base_gfn=0xc0, npages=524096
> Mar 31 18:32:53 master kernel: [15908.682058] memslot dirty bitmap of '4' was 
> destroyed, base_gfn 0xfebc0, npages 16
> Mar 31 18:32:53 master kernel: [15908.849527] +++ gfn=0xca is marked dirty, 
> id=2, base_gfn=0xc0, npages=524096
> Mar 31 18:32:53 master kernel: [15908.856845] +++ gfn=0xcb is marked dirty, 
> id=2, base_gfn=0xc0, npages=524096
> Mar 31 18:32:53 master kernel: [15908.864161] +++ gfn=0xcc is marked dirty, 
> id=2, base_gfn=0xc0, npages=524096
> Mar 31 18:32:53 master kernel: [15908.872676] memslot dirty bitmap of '4' was 
> destroyed, base_gfn 0xfeb80, npages 64
> Mar 31 18:32:53 master kernel: [15908.882694] +++ gfn=0xca is marked dirty, 
> id=2, base_gfn=0xc0, npages=524096
> Mar 31 18:32:53 master kernel: [15908.889948] +++ gfn=0xcb is marked dirty, 
> id=2, base_gfn=0xc0, npages=524096
> Mar 31 18:32:53 master kernel: [15908.897202] +++ gfn=0xcc is marked dirty, 
> id=2, base_gfn=0xc0, npages=524096
> Mar 31 18:32:53 master kernel: [15908.911652] +++ gfn=0xca is marked dirty, 
> id=2, base_gfn=0xc0, npages=524096
> Mar 31 18:32:53 master kernel: [15908.919543] +++ gfn=0xca is marked dirty, 
> id=2, base_gfn=0xc0, npages=524096
> Mar 31 18:32:53 master kernel: [15908.927419] +++ gfn=0xcb is marked dirty, 
> id=2, base_gfn=0xc0, npages=524096
> Mar 31 18:32:53 master kernel: [15908.935317] +++ gfn=0xcb is marked dirty, 
> id=2, base_gfn=0xc0, npages=524096
> Mar 31 18:32:53 master kernel: [15908.943209] +++ gfn=0xcb is marked dirty, 
> id=2, base_gfn=0xc0, npages=524096
> Mar 31 18:32:53 master kernel: [15908.951083] +++ gfn=0xcb is marked dirty, 
> id=2, base_gfn=0xc0, npages=524096
> Mar 31 18:32:53 master kernel: [15908.958971] +++ gfn=0xcc is marked dirty, 
> id=2, base_gfn=0xc0, npages=524096
> Mar 31 18:32:53 master kernel: [15908.966837] +++ gfn=0xcc is marked dirty, 
> id=2, base_gfn=0xc0, npages=524096
> Mar 31 18:32:53 master kernel: [15908.974707] +++ gfn=0xcc is marked dirty, 
> id=2, base_gfn=0xc0, npages=524096
> Mar 31 18:32:53 master kernel: [15908.988470] memslot dirty bitmap of '2' was 
> destroyed, base_gfn 0xc0, npages 524096
> Mar 31 18:32:53 master kernel: [15909.002403] kvm: zapping shadow pages for 
> mmio generation wraparound
> Mar 31 18:32:53 master kernel: [15909.002523] memslot dirty bitmap of '2' was 
> destroyed, base_gfn 0xc0, npages 8
> Mar 31 18:32:53 master kernel: [15909.010110] memslot dirty bitmap of '4' was 
> destroyed, base_gfn 0xc8, npages 524088
> Mar 31 18:32:53 master kernel: [15909.023988] memslot dirty bitmap of '5' was 
> destroyed, base_gfn 0xcd, npages 3
> Mar 31 18:32:53 master kernel: [15909.031594] memslot dirty bitmap of '6' was 
> destroyed, base_gfn 0xd0, npages 524080
> Mar 31 18:32:53 master kernel: [15909.044708] memslot dirty bitmap of '5' was 
> destroyed, base_gfn 0xcd, npages 11
> Mar 31 18:32:53 master kernel: [15909.052392] memslot dirty bitmap of '6' was 
> destroyed, base_gfn 0xd8, npages 524072
> Mar 31 18:32:53 master kernel: [15909.065651] memslot dirty bitmap of '5' was 
> destroyed, base_gfn 0xcd, npages 19
> Mar 31 18:32:53 master kernel: [15909.073329] memslot dirty bitmap of '6' was 
> destroyed, base_gfn 0xe0, npages 524064
> Mar 31 18:32:53 master kernel: [15909.086379] memslot dirty bitmap of '5' was 
> destroyed, base_gfn 0xcd, npages 27
> Mar 31 18:32:53 master kernel: [15909.094084] memslot dirty bitmap of '6' was 
> destroyed, base_gfn 0xe8, npages 524056
> Mar 31 18:32:53 master kernel: [15909.107354] memslot dirty bitmap of '6' was 
> destroyed, base_gfn 0xec, npages 524052
> Mar 31 18:32:54 master dhcpcd[5408]: eth0: timed out
> Mar 31 18:32:54 master dhcpcd[5408]: eth0: trying to use old lease in 
> `/var/lib/dhcpcd/dhcpcd-eth0.info'
> Mar 31 18:32:54 master dhcpcd[5408]: eth0: lease expired 30265 seconds ago
> Mar 31 18:32:54 master dhcpcd[5408]: eth0: broadcasting for a lease
> Mar 31 18:33:02 master qemu-system-x86_64: ====qemu: The 0 times do 
> checkpoing===
> Mar 31 18:33:02 master qemu-system-x86_64: == migration_bitmap_sync ==
> Mar 31 18:33:02 master qemu-system-x86_64: qemu:  --- addr=0xca000 
> (hva=0x7f4fa32ca000), who's bitmap not set ---
> Mar 31 18:33:02 master qemu-system-x86_64: qemu:  --- addr=0xcb000 
> (hva=0x7f4fa32cb000), who's bitmap not set ---
> Mar 31 18:33:02 master qemu-system-x86_64: qemu:  --- addr=0xcc000 
> (hva=0x7f4fa32cc000), who's bitmap not set ---
> Mar 31 18:33:05 master kernel: [15921.057246] device eth2 left promiscuous 
> mode
> Mar 31 18:33:07 master avahi-daemon[5773]: Withdrawing address record for 
> fe80::90be:cfff:fe9e:f03e on tap0.
> Mar 31 18:33:07 master kernel: [15922.513313] br0: port 2(tap0) entered 
> disabled state
> Mar 31 18:33:07 master kernel: [15922.513480] device tap0 left promiscuous 
> mode
> Mar 31 18:33:07 master kernel: [15922.513508] br0: port 2(tap0) entered 
> disabled state
> Mar 31 18:33:07 master kernel: [15922.562591] memslot dirty bitmap of '8' was 
> destroyed, base_gfn 0x100, npages 524032
> Mar 31 18:33:07 master kernel: [15922.570948] memslot dirty bitmap of '3' was 
> destroyed, base_gfn 0xfd000, npages 4096
> Mar 31 18:33:07 master kernel: [15922.578967] memslot dirty bitmap of '0' was 
> destroyed, base_gfn 0x0, npages 160
> Mar 31 18:33:07 master kernel: [15922.586556] memslot dirty bitmap of '1' was 
> destroyed, base_gfn 0xfffc0, npages 64
> Mar 31 18:33:07 master kernel: [15922.586574] memslot dirty bitmap of '5' was 
> destroyed, base_gfn 0xcd, npages 31
> Mar 31 18:33:07 master kernel: [15922.586575] memslot dirty bitmap of '7' was 
> destroyed, base_gfn 0xf0, npages 16
> Mar 31 18:33:07 master kernel: [15922.586577] memslot dirty bitmap of '2' was 
> destroyed, base_gfn 0xc0, npages 10
> Mar 31 18:33:07 master kernel: [15922.586578] memslot dirty bitmap of '6' was 
> destroyed, base_gfn 0xec, npages 4
> Mar 31 18:33:07 master kernel: [15922.586579] memslot dirty bitmap of '4' was 
> destroyed, base_gfn 0xca, npages 3
> 
> PS:
> QEMU:
> static void migration_bitmap_sync(void)
> {
>     trace_migration_bitmap_sync_end(migration_dirty_pages
>                                     - num_dirty_pages_init);
>     num_dirty_pages_period += migration_dirty_pages - num_dirty_pages_init;
>     end_time = qemu_clock_get_ms(QEMU_CLOCK_REALTIME);
> +    syslog(LOG_INFO, "== migration_bitmap_sync ==");
> +    check_bitmap(();
> 
> +void check_bitmap(void)
> +{
> +    int i;
> +    char *host;
> +    ram_addr_t addr[3] = { 0xca000, 0xcb000, 0xcc000 };
> +    RAMBlock *block = NULL;
> +    int ret;
> +
> +    block = QLIST_FIRST_RCU(&ram_list.blocks);
> +    for (i = 0; i < 3; i++) {
> +        unsigned long nr = block->mr->ram_addr + (addr[i] >> 
> TARGET_PAGE_BITS);
> +        host =  memory_region_get_ram_ptr(block->mr) + addr[i];
> +        ret = test_bit(nr, migration_bitmap);
> +        if (ret == 0) {
> +            syslog(LOG_INFO, "qemu:  --- addr=0x%llx (hva=%p), who's bitmap 
> not set ---\n",
> +                       addr[i], host);
> +        } else {
> +            syslog(LOG_INFO, "qemu: +++ OK, addr=0x%llx (hva=%p) , who's 
> bitap is set +++\n",
> +                       addr[i], host);;
> +        }
> +    }
> +}
> 
> KVM???
> static void mark_page_dirty_in_slot(struct kvm *kvm,
>                     struct kvm_memory_slot *memslot,
>                     gfn_t gfn)
> {
> +    if ((gfn == 0xca || gfn == 0xcb || gfn == 0xcc) && 
> !memslot->dirty_bitmap) {
> +        printk("oops, dirty_bitmap is null, gfn=0x%llx\n",gfn);
> +    }
>     if (memslot && memslot->dirty_bitmap) {
>         unsigned long rel_gfn = gfn - memslot->base_gfn;
> +        if (gfn == 0xca || gfn == 0xcb || gfn == 0xcc) {
> +            printk("+++ gfn=0x%llx is marked dirty, id=%d, base_gfn=0x%llx, 
> npages=%d\n",
> +                   gfn, memslot->id, memslot->base_gfn, memslot->npages);
> +        }
>         set_bit_le(rel_gfn, memslot->dirty_bitmap);
>     }
> }
> 
> static void kvm_destroy_dirty_bitmap(struct kvm_memory_slot *memslot)
> {
>     if (!memslot->dirty_bitmap)
>         return;
> +    if (memslot->id != 9) {
> +        printk("memslot dirty bitmap of '%d' was destroyed, base_gfn 0x%llx, 
> npages %lld\n",
> +           memslot->id, memslot->base_gfn, memslot->npages);
> +    }
>     kvm_kvfree(memslot->dirty_bitmap);
>     memslot->dirty_bitmap = NULL;
> }
> 
> 
> >filed against migration during windows boot, I'd not considered that it might
> >be devices not updating the bitmap.
> >
> >Dave
> >
> >>
> >>
> >>Thanks,
> >>zhanghailiang
> >>
> >>
> >>>>>>
> >>>>>>>What kind of load were you having when reproducing this issue?
> >>>>>>>Just to confirm, you have been able to reproduce this without COLO
> >>>>>>>patches, right?
> >>>>>>>
> >>>>>>>>(qemu) migrate tcp:192.168.3.8:3004
> >>>>>>>>before saving ram complete
> >>>>>>>>ff703f6889ab8701e4e040872d079a28
> >>>>>>>>md_host : after saving ram complete
> >>>>>>>>ff703f6889ab8701e4e040872d079a28
> >>>>>>>>
> >>>>>>>>DST: # x86_64-softmmu/qemu-system-x86_64 -enable-kvm -cpu 
> >>>>>>>>qemu64,-kvmclock -netdev tap,id=hn0,vhost=on -device 
> >>>>>>>>virtio-net-pci,id=net-pci0,netdev=hn0 -boot c -drive 
> >>>>>>>>file=/mnt/sdb/pure_IMG/sles/sles11_sp3.img,if=none,id=drive-virtio-disk0,cache=unsafe
> >>>>>>>> -device 
> >>>>>>>>virtio-blk-pci,bus=pci.0,addr=0x4,drive=drive-virtio-disk0,id=virtio-disk0
> >>>>>>>> -vnc :7 -m 2048 -smp 2 -device piix3-usb-uhci -device usb-tablet 
> >>>>>>>>-monitor stdio -incoming tcp:0:3004
> >>>>>>>>(qemu) QEMU_VM_SECTION_END, after loading ram
> >>>>>>>>230e1e68ece9cd4e769630e1bcb5ddfb
> >>>>>>>>md_host : after loading all vmstate
> >>>>>>>>230e1e68ece9cd4e769630e1bcb5ddfb
> >>>>>>>>md_host : after cpu_synchronize_all_post_init
> >>>>>>>>230e1e68ece9cd4e769630e1bcb5ddfb
> >>>>>>>>
> >>>>>>>>This happens occasionally, and it is more easy to reproduce when 
> >>>>>>>>issue migration command during VM's startup time.
> >>>>>>>OK, a couple of things.  Memory don't have to be exactly identical.
> >>>>>>>Virtio devices in particular do funny things on "post-load".  There
> >>>>>>>aren't warantees for that as far as I know, we should end with an
> >>>>>>>equivalent device state in memory.
> >>>>>>>
> >>>>>>>>We have done further test and found that some pages has been dirtied 
> >>>>>>>>but its corresponding migration_bitmap is not set.
> >>>>>>>>We can't figure out which modules of QEMU has missed setting bitmap 
> >>>>>>>>when dirty page of VM,
> >>>>>>>>it is very difficult for us to trace all the actions of dirtying VM's 
> >>>>>>>>pages.
> >>>>>>>This seems to point to a bug in one of the devices.
> >>>>>>>
> >>>>>>>>Actually, the first time we found this problem was in the COLO FT 
> >>>>>>>>development, and it triggered some strange issues in
> >>>>>>>>VM which all pointed to the issue of inconsistent of VM's memory. (We 
> >>>>>>>>have try to save all memory of VM to slave side every time
> >>>>>>>>when do checkpoint in COLO FT, and everything will be OK.)
> >>>>>>>>
> >>>>>>>>Is it OK for some pages that not transferred to destination when do 
> >>>>>>>>migration ? Or is it a bug?
> >>>>>>>Pages transferred should be the same, after device state transmission 
> >>>>>>>is
> >>>>>>>when things could change.
> >>>>>>>
> >>>>>>>>This issue has blocked our COLO development... :(
> >>>>>>>>
> >>>>>>>>Any help will be greatly appreciated!
> >>>>>>>Later, Juan.
> >>>>>>>
> >>>>>>.
> >>>>>>
> >>>>>
> >>>>>
> >>>>
> >>>>
> >>>--
> >>>Dr. David Alan Gilbert / address@hidden / Manchester, UK
> >>>
> >>>.
> >>>
> >>
> >>
> >--
> >Dr. David Alan Gilbert / address@hidden / Manchester, UK
> >
> >.
> >
> 
> 
--
Dr. David Alan Gilbert / address@hidden / Manchester, UK