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

[zhanghailiang <zhang.zhanghailiang@huawei.com>]

On 2015/3/25 17:46, Dr. David Alan Gilbert wrote:
> * zhanghailiang (zhang.zhanghailiang@huawei.com) 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 reproduce:
>>
>> (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
>> (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.
>>
>> 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.
>>
>> 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?
>
> That does sound like a bug.
> The only other explanation I have is that memory is being changed by a device emulation
> that happens after the end of a saving the vm, or after loading the memory.  That's
> certainly possible - especially if a device (say networking) hasn't been properly
> stopped.
>
>> This issue has blocked our COLO development... :(
>>
>> Any help will be greatly appreciated!
>

Hi Dave，

> I suggest:
>     1) Does it happen with devices other than virtio?
>     2) Strip the devices down - e.g. just run with serial and no video/usb

I will try this ...

>     3) Try doing the md5 comparison at the end of ram_save_complete

Yes, we have done this test at the end of ram_save_complete.

>     4) mprotect RAM after the ram_save_complete and see if anything faults.

I have tried, and there will be kvm error reports. like bellow:

KVM: entry failed, hardware error 0x7
EAX=00000000 EBX=0000e000 ECX=00009578 EDX=0000434f
ESI=0000fc10 EDI=0000434f EBP=00000000 ESP=00001fca
EIP=00009594 EFL=00010246 [---Z-P-] CPL=0 II=0 A20=1 SMM=0 HLT=0
ES =0040 00000400 0000ffff 00009300
CS =f000 000f0000 0000ffff 00009b00
SS =434f 000434f0 0000ffff 00009300
DS =434f 000434f0 0000ffff 00009300
FS =0000 00000000 0000ffff 00009300
GS =0000 00000000 0000ffff 00009300
LDT=0000 00000000 0000ffff 00008200
TR =0000 00000000 0000ffff 00008b00
GDT=     0002dcc8 00000047
IDT=     00000000 0000ffff
CR0=00000010 CR2=ffffffff CR3=00000000 CR4=00000000
DR0=0000000000000000 DR1=0000000000000000 DR2=0000000000000000 DR3=0000000000000000
DR6=00000000ffff0ff0 DR7=0000000000000400
EFER=0000000000000000
Code=c0 74 0f 66 b9 78 95 00 00 66 31 d2 66 31 c0 e9 47 e0 fb 90 <f3> 90 fa fc 66 c3 66 53 66 89 c3 66 e8 9d e8 ff ff 66 01 c3 66 89 d8 66 e8 40 e9 ff ff 66
ERROR: invalid runstate transition: 'internal-error' -> 'colo'

>     5) Can you trigger this with normal migration or just COLO?

Yes, we have reproduced it without COLO, just in normal migration

>        I'm wondering if something is doing something on a running/paused/etc state
>        change and isn't expecting the new COLO states.
>

Actually, we can also reproduce this with COLO, only in master side, we store all RAM to ram-cache, and also duplicate migration_bitmap,
and after a checkpoint, before VM continue to run, we compare cache memory and current memory, if they are different but whose
dirty bitmap is not set, we thought this page is missing tracing by migration bitmap. The result is  result will be like:
(Certainly, this happens also occasionally, sometimes, there will be none page un-traced.)
pc.ram[0xc7000](mis_dirty)
pc.ram[0xec000](mis_dirty)
pc.ram[0xf4000](mis_dirty)
pc.ram[0xfa000](mis_dirty)
pc.ram[0xbf93000](mis_dirty)
pc.ram[0xbf94000](mis_dirty)
pc.ram[0xbf95000](mis_dirty)
pc.ram[0xbf96000](mis_dirty)
pc.ram[0xbf97000](mis_dirty)
pc.ram[0xbf98000](mis_dirty)
pc.ram[0xbf99000](mis_dirty)
pc.ram[0xbf9a000](mis_dirty)
pc.ram[0xbf9b000](mis_dirty)
pc.ram[0xbf9c000](mis_dirty)
...

Thanks,
zhang

>> --- a/savevm.c
>> +++ b/savevm.c
>> @@ -51,6 +51,26 @@
>>   #define ARP_PTYPE_IP 0x0800
>>   #define ARP_OP_REQUEST_REV 0x3
>>
>> +#include "qemu/rcu_queue.h"
>> +#include <openssl/md5.h>
>> +
>> +static void check_host_md5(void)
>> +{
>> +    int i;
>> +    unsigned char md[MD5_DIGEST_LENGTH];
>> +    MD5_CTX ctx;
>> +    RAMBlock *block = QLIST_FIRST_RCU(&ram_list.blocks);/* Only check 'pc.ram' block */
>> +
>> +    MD5_Init(&ctx);
>> +    MD5_Update(&ctx, (void *)block->host, block->used_length);
>> +    MD5_Final(md, &ctx);
>> +    printf("md_host : ");
>> +    for(i = 0; i < MD5_DIGEST_LENGTH; i++) {
>> +        fprintf(stderr, "%02x", md[i]);
>> +    }
>> +    fprintf(stderr, "\n");
>> +}
>> +
>>   static int announce_self_create(uint8_t *buf,
>>                                   uint8_t *mac_addr)
>>   {
>> @@ -741,7 +761,13 @@ void qemu_savevm_state_complete(QEMUFile *f)
>>           qemu_put_byte(f, QEMU_VM_SECTION_END);
>>           qemu_put_be32(f, se->section_id);
>>
>> +        printf("before saving %s complete\n", se->idstr);
>> +        check_host_md5();
>> +
>>           ret = se->ops->save_live_complete(f, se->opaque);
>> +        printf("after saving %s complete\n", se->idstr);
>> +        check_host_md5();
>> +
>>           trace_savevm_section_end(se->idstr, se->section_id, ret);
>>           if (ret < 0) {
>>               qemu_file_set_error(f, ret);
>> @@ -1030,6 +1063,11 @@ int qemu_loadvm_state(QEMUFile *f)
>>               }
>>
>>               ret = vmstate_load(f, le->se, le->version_id);
>> +            if (section_type == QEMU_VM_SECTION_END) {
>> +                printf("QEMU_VM_SECTION_END, after loading %s\n", le->se->idstr);
>> +                check_host_md5();
>> +            }
>> +
>>               if (ret < 0) {
>>                   error_report("error while loading state section id %d(%s)",
>>                                section_id, le->se->idstr);
>> @@ -1061,7 +1099,11 @@ int qemu_loadvm_state(QEMUFile *f)
>>           g_free(buf);
>>       }
>>
>> +    printf("after loading all vmstate\n");
>> +    check_host_md5();
>>       cpu_synchronize_all_post_init();
>> +    printf("after cpu_synchronize_all_post_init\n");
>> +    check_host_md5();
>>
>>       ret = 0;
>>
>> --
>
>>  From ecb789cf7f383b112da3cce33eb9822a94b9497a Mon Sep 17 00:00:00 2001
>> From: Li Zhijian <lizhijian@cn.fujitsu.com>
>> Date: Tue, 24 Mar 2015 21:53:26 -0400
>> Subject: [PATCH] check pc.ram block md5sum between migration Source and
>>   Destination
>>
>> Signed-off-by: Li Zhijian <lizhijian@cn.fujitsu.com>
>> ---
>>   savevm.c | 42 ++++++++++++++++++++++++++++++++++++++++++
>>   1 file changed, 42 insertions(+)
>>   mode change 100644 => 100755 savevm.c
>>
>> diff --git a/savevm.c b/savevm.c
>> old mode 100644
>> new mode 100755
>> index 3b0e222..3d431dc
>> --- a/savevm.c
>> +++ b/savevm.c
>> @@ -51,6 +51,26 @@
>>   #define ARP_PTYPE_IP 0x0800
>>   #define ARP_OP_REQUEST_REV 0x3
>>
>> +#include "qemu/rcu_queue.h"
>> +#include <openssl/md5.h>
>> +
>> +static void check_host_md5(void)
>> +{
>> +    int i;
>> +    unsigned char md[MD5_DIGEST_LENGTH];
>> +    MD5_CTX ctx;
>> +    RAMBlock *block = QLIST_FIRST_RCU(&ram_list.blocks);/* Only check 'pc.ram' block */
>> +
>> +    MD5_Init(&ctx);
>> +    MD5_Update(&ctx, (void *)block->host, block->used_length);
>> +    MD5_Final(md, &ctx);
>> +    printf("md_host : ");
>> +    for(i = 0; i < MD5_DIGEST_LENGTH; i++) {
>> +        fprintf(stderr, "%02x", md[i]);
>> +    }
>> +    fprintf(stderr, "\n");
>> +}
>> +
>>   static int announce_self_create(uint8_t *buf,
>>                                   uint8_t *mac_addr)
>>   {
>> @@ -741,7 +761,13 @@ void qemu_savevm_state_complete(QEMUFile *f)
>>           qemu_put_byte(f, QEMU_VM_SECTION_END);
>>           qemu_put_be32(f, se->section_id);
>>
>> +        printf("before saving %s complete\n", se->idstr);
>> +        check_host_md5();
>> +
>>           ret = se->ops->save_live_complete(f, se->opaque);
>> +        printf("after saving %s complete\n", se->idstr);
>> +        check_host_md5();
>> +
>>           trace_savevm_section_end(se->idstr, se->section_id, ret);
>>           if (ret < 0) {
>>               qemu_file_set_error(f, ret);
>> @@ -1007,6 +1033,13 @@ int qemu_loadvm_state(QEMUFile *f)
>>               QLIST_INSERT_HEAD(&loadvm_handlers, le, entry);
>>
>>               ret = vmstate_load(f, le->se, le->version_id);
>> +#if 0
>> +            if (section_type == QEMU_VM_SECTION_FULL) {
>> +                printf("QEMU_VM_SECTION_FULL, after loading %s\n", le->se->idstr);
>> +                check_host_md5();
>> +            }
>> +#endif
>> +
>>               if (ret < 0) {
>>                   error_report("error while loading state for instance 0x%x of"
>>                                " device '%s'", instance_id, idstr);
>> @@ -1030,6 +1063,11 @@ int qemu_loadvm_state(QEMUFile *f)
>>               }
>>
>>               ret = vmstate_load(f, le->se, le->version_id);
>> +            if (section_type == QEMU_VM_SECTION_END) {
>> +                printf("QEMU_VM_SECTION_END, after loading %s\n", le->se->idstr);
>> +                check_host_md5();
>> +            }
>> +
>>               if (ret < 0) {
>>                   error_report("error while loading state section id %d(%s)",
>>                                section_id, le->se->idstr);
>> @@ -1061,7 +1099,11 @@ int qemu_loadvm_state(QEMUFile *f)
>>           g_free(buf);
>>       }
>>
>> +    printf("after loading all vmstate\n");
>> +    check_host_md5();
>>       cpu_synchronize_all_post_init();
>> +    printf("after cpu_synchronize_all_post_init\n");
>> +    check_host_md5();
>>
>>       ret = 0;
>>
>> --
>> 1.7.12.4
>>
>
> --
> Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK
>
> .
>