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

["Dr. David Alan Gilbert" <dgilbert@redhat.com>]

* zhanghailiang (zhang.zhanghailiang@huawei.com) wrote:
> 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

If the RAM is mprotect'd with PROT_READ|PROT_EXEC I'm not sure why this
would happen; but then the question is why is it trying to do a KVM entry
after the end of ram_save_complete - that suggests the CPUs are trying to
run again, and that shouldn't happen in a normal migration.
If you can trigger this KVM entry on a non-colo migration, then I suggest
get the backtrace from where the KVM entry failed, because then you
should be able to see why the CPU was being restarted.

Dave

> 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
> >
> >.
> >
> 
> 
--
Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK