diff mbox

[2/3] Migration: Add lots of trace events

Message ID 1421765283-17822-3-git-send-email-dgilbert@redhat.com
State New
Headers show

Commit Message

Dr. David Alan Gilbert Jan. 20, 2015, 2:48 p.m. UTC
From: "Dr. David Alan Gilbert" <dgilbert@redhat.com>

Mostly on the load side, so that when we get a complaint about
a migration failure we can figure out what it didn't like.

Signed-off-by: Dr. David Alan Gilbert <dgilbert@redhat.com>
---
 migration/vmstate.c | 22 +++++++++++++++++++---
 savevm.c            | 10 +++++++---
 trace-events        | 11 ++++++++++-
 3 files changed, 36 insertions(+), 7 deletions(-)

Comments

Amit Shah Jan. 21, 2015, 6:02 a.m. UTC | #1
On (Tue) 20 Jan 2015 [14:48:02], Dr. David Alan Gilbert (git) wrote:
> From: "Dr. David Alan Gilbert" <dgilbert@redhat.com>
> 
> Mostly on the load side, so that when we get a complaint about
> a migration failure we can figure out what it didn't like.

Nice!

Just one note below.

> Signed-off-by: Dr. David Alan Gilbert <dgilbert@redhat.com>
> ---
>  migration/vmstate.c | 22 +++++++++++++++++++---
>  savevm.c            | 10 +++++++---
>  trace-events        | 11 ++++++++++-
>  3 files changed, 36 insertions(+), 7 deletions(-)
> 
> diff --git a/migration/vmstate.c b/migration/vmstate.c
> index 2c0b135..7b8dc3f 100644
> --- a/migration/vmstate.c
> +++ b/migration/vmstate.c
> @@ -75,14 +75,19 @@ int vmstate_load_state(QEMUFile *f, const VMStateDescription *vmsd,
>      VMStateField *field = vmsd->fields;
>      int ret;
>  
> +    trace_vmstate_load_state(vmsd->name, version_id);
>      if (version_id > vmsd->version_id) {
> +        trace_vmstate_load_state_end(vmsd->name, "too new", -EINVAL);
>          return -EINVAL;
>      }
>      if  (version_id < vmsd->minimum_version_id) {
>          if (vmsd->load_state_old &&
>              version_id >= vmsd->minimum_version_id_old) {
> -            return vmsd->load_state_old(f, opaque, version_id);
> +            ret = vmsd->load_state_old(f, opaque, version_id);
> +            trace_vmstate_load_state_end(vmsd->name, "old path", ret);
> +            return ret;
>          }
> +        trace_vmstate_load_state_end(vmsd->name, "too old", -EINVAL);
>          return -EINVAL;
>      }
>      if (vmsd->pre_load) {
> @@ -92,6 +97,7 @@ int vmstate_load_state(QEMUFile *f, const VMStateDescription *vmsd,
>          }
>      }
>      while (field->name) {
> +        trace_vmstate_load_state_field(vmsd->name, field->name);
>          if ((field->field_exists &&
>               field->field_exists(opaque, version_id)) ||
>              (!field->field_exists &&
> @@ -134,9 +140,10 @@ int vmstate_load_state(QEMUFile *f, const VMStateDescription *vmsd,
>          return ret;
>      }
>      if (vmsd->post_load) {
> -        return vmsd->post_load(opaque, version_id);
> +        ret = vmsd->post_load(opaque, version_id);
>      }
> -    return 0;
> +    trace_vmstate_load_state_end(vmsd->name, "end", ret);
> +    return ret;
>  }

"return 0" becomes "return ret", and ret isn't assigned anywhere.

>  void vmstate_save_state(QEMUFile *f, const VMStateDescription *vmsd,
> @@ -193,6 +200,8 @@ static const VMStateDescription *
>  static int vmstate_subsection_load(QEMUFile *f, const VMStateDescription *vmsd,
>                                     void *opaque)
>  {
> +    trace_vmstate_subsection_load(vmsd->name);
> +
>      while (qemu_peek_byte(f, 0) == QEMU_VM_SUBSECTION) {
>          char idstr[256];
>          int ret;
> @@ -202,20 +211,24 @@ static int vmstate_subsection_load(QEMUFile *f, const VMStateDescription *vmsd,
>          len = qemu_peek_byte(f, 1);
>          if (len < strlen(vmsd->name) + 1) {
>              /* subsection name has be be "section_name/a" */
> +            trace_vmstate_subsection_load_bad(vmsd->name, "(short)");
>              return 0;

Nice how you use the () to differentiate from the idstr below..

>          }
>          size = qemu_peek_buffer(f, (uint8_t *)idstr, len, 2);
>          if (size != len) {
> +            trace_vmstate_subsection_load_bad(vmsd->name, "(peek fail)");
>              return 0;
>          }
>          idstr[size] = 0;
>  
>          if (strncmp(vmsd->name, idstr, strlen(vmsd->name)) != 0) {
> +            trace_vmstate_subsection_load_bad(vmsd->name, idstr);
>              /* it don't have a valid subsection name */
>              return 0;


		Amit
Dr. David Alan Gilbert Jan. 21, 2015, 9:19 a.m. UTC | #2
* Amit Shah (amit.shah@redhat.com) wrote:
> On (Tue) 20 Jan 2015 [14:48:02], Dr. David Alan Gilbert (git) wrote:
> > From: "Dr. David Alan Gilbert" <dgilbert@redhat.com>
> > 
> > Mostly on the load side, so that when we get a complaint about
> > a migration failure we can figure out what it didn't like.
> 
> Nice!
> 
> Just one note below.
> 
> > Signed-off-by: Dr. David Alan Gilbert <dgilbert@redhat.com>
> > ---
> >  migration/vmstate.c | 22 +++++++++++++++++++---
> >  savevm.c            | 10 +++++++---
> >  trace-events        | 11 ++++++++++-
> >  3 files changed, 36 insertions(+), 7 deletions(-)
> > 
> > diff --git a/migration/vmstate.c b/migration/vmstate.c
> > index 2c0b135..7b8dc3f 100644
> > --- a/migration/vmstate.c
> > +++ b/migration/vmstate.c
> > @@ -75,14 +75,19 @@ int vmstate_load_state(QEMUFile *f, const VMStateDescription *vmsd,
> >      VMStateField *field = vmsd->fields;
> >      int ret;
> >  
> > +    trace_vmstate_load_state(vmsd->name, version_id);
> >      if (version_id > vmsd->version_id) {
> > +        trace_vmstate_load_state_end(vmsd->name, "too new", -EINVAL);
> >          return -EINVAL;
> >      }
> >      if  (version_id < vmsd->minimum_version_id) {
> >          if (vmsd->load_state_old &&
> >              version_id >= vmsd->minimum_version_id_old) {
> > -            return vmsd->load_state_old(f, opaque, version_id);
> > +            ret = vmsd->load_state_old(f, opaque, version_id);
> > +            trace_vmstate_load_state_end(vmsd->name, "old path", ret);
> > +            return ret;
> >          }
> > +        trace_vmstate_load_state_end(vmsd->name, "too old", -EINVAL);
> >          return -EINVAL;
> >      }
> >      if (vmsd->pre_load) {
> > @@ -92,6 +97,7 @@ int vmstate_load_state(QEMUFile *f, const VMStateDescription *vmsd,
> >          }
> >      }
> >      while (field->name) {
> > +        trace_vmstate_load_state_field(vmsd->name, field->name);
> >          if ((field->field_exists &&
> >               field->field_exists(opaque, version_id)) ||
> >              (!field->field_exists &&
> > @@ -134,9 +140,10 @@ int vmstate_load_state(QEMUFile *f, const VMStateDescription *vmsd,
> >          return ret;
> >      }
> >      if (vmsd->post_load) {
> > -        return vmsd->post_load(opaque, version_id);
> > +        ret = vmsd->post_load(opaque, version_id);
> >      }
> > -    return 0;
> > +    trace_vmstate_load_state_end(vmsd->name, "end", ret);
> > +    return ret;
> >  }
> 
> "return 0" becomes "return ret", and ret isn't assigned anywhere.

Oops, yes, I'll reroll it.

Dave

> 
> >  void vmstate_save_state(QEMUFile *f, const VMStateDescription *vmsd,
> > @@ -193,6 +200,8 @@ static const VMStateDescription *
> >  static int vmstate_subsection_load(QEMUFile *f, const VMStateDescription *vmsd,
> >                                     void *opaque)
> >  {
> > +    trace_vmstate_subsection_load(vmsd->name);
> > +
> >      while (qemu_peek_byte(f, 0) == QEMU_VM_SUBSECTION) {
> >          char idstr[256];
> >          int ret;
> > @@ -202,20 +211,24 @@ static int vmstate_subsection_load(QEMUFile *f, const VMStateDescription *vmsd,
> >          len = qemu_peek_byte(f, 1);
> >          if (len < strlen(vmsd->name) + 1) {
> >              /* subsection name has be be "section_name/a" */
> > +            trace_vmstate_subsection_load_bad(vmsd->name, "(short)");
> >              return 0;
> 
> Nice how you use the () to differentiate from the idstr below..
> 
> >          }
> >          size = qemu_peek_buffer(f, (uint8_t *)idstr, len, 2);
> >          if (size != len) {
> > +            trace_vmstate_subsection_load_bad(vmsd->name, "(peek fail)");
> >              return 0;
> >          }
> >          idstr[size] = 0;
> >  
> >          if (strncmp(vmsd->name, idstr, strlen(vmsd->name)) != 0) {
> > +            trace_vmstate_subsection_load_bad(vmsd->name, idstr);
> >              /* it don't have a valid subsection name */
> >              return 0;
> 
> 
> 		Amit
--
Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK
diff mbox

Patch

diff --git a/migration/vmstate.c b/migration/vmstate.c
index 2c0b135..7b8dc3f 100644
--- a/migration/vmstate.c
+++ b/migration/vmstate.c
@@ -75,14 +75,19 @@  int vmstate_load_state(QEMUFile *f, const VMStateDescription *vmsd,
     VMStateField *field = vmsd->fields;
     int ret;
 
+    trace_vmstate_load_state(vmsd->name, version_id);
     if (version_id > vmsd->version_id) {
+        trace_vmstate_load_state_end(vmsd->name, "too new", -EINVAL);
         return -EINVAL;
     }
     if  (version_id < vmsd->minimum_version_id) {
         if (vmsd->load_state_old &&
             version_id >= vmsd->minimum_version_id_old) {
-            return vmsd->load_state_old(f, opaque, version_id);
+            ret = vmsd->load_state_old(f, opaque, version_id);
+            trace_vmstate_load_state_end(vmsd->name, "old path", ret);
+            return ret;
         }
+        trace_vmstate_load_state_end(vmsd->name, "too old", -EINVAL);
         return -EINVAL;
     }
     if (vmsd->pre_load) {
@@ -92,6 +97,7 @@  int vmstate_load_state(QEMUFile *f, const VMStateDescription *vmsd,
         }
     }
     while (field->name) {
+        trace_vmstate_load_state_field(vmsd->name, field->name);
         if ((field->field_exists &&
              field->field_exists(opaque, version_id)) ||
             (!field->field_exists &&
@@ -134,9 +140,10 @@  int vmstate_load_state(QEMUFile *f, const VMStateDescription *vmsd,
         return ret;
     }
     if (vmsd->post_load) {
-        return vmsd->post_load(opaque, version_id);
+        ret = vmsd->post_load(opaque, version_id);
     }
-    return 0;
+    trace_vmstate_load_state_end(vmsd->name, "end", ret);
+    return ret;
 }
 
 void vmstate_save_state(QEMUFile *f, const VMStateDescription *vmsd,
@@ -193,6 +200,8 @@  static const VMStateDescription *
 static int vmstate_subsection_load(QEMUFile *f, const VMStateDescription *vmsd,
                                    void *opaque)
 {
+    trace_vmstate_subsection_load(vmsd->name);
+
     while (qemu_peek_byte(f, 0) == QEMU_VM_SUBSECTION) {
         char idstr[256];
         int ret;
@@ -202,20 +211,24 @@  static int vmstate_subsection_load(QEMUFile *f, const VMStateDescription *vmsd,
         len = qemu_peek_byte(f, 1);
         if (len < strlen(vmsd->name) + 1) {
             /* subsection name has be be "section_name/a" */
+            trace_vmstate_subsection_load_bad(vmsd->name, "(short)");
             return 0;
         }
         size = qemu_peek_buffer(f, (uint8_t *)idstr, len, 2);
         if (size != len) {
+            trace_vmstate_subsection_load_bad(vmsd->name, "(peek fail)");
             return 0;
         }
         idstr[size] = 0;
 
         if (strncmp(vmsd->name, idstr, strlen(vmsd->name)) != 0) {
+            trace_vmstate_subsection_load_bad(vmsd->name, idstr);
             /* it don't have a valid subsection name */
             return 0;
         }
         sub_vmsd = vmstate_get_subsection(vmsd->subsections, idstr);
         if (sub_vmsd == NULL) {
+            trace_vmstate_subsection_load_bad(vmsd->name, "(lookup)");
             return -ENOENT;
         }
         qemu_file_skip(f, 1); /* subsection */
@@ -225,9 +238,12 @@  static int vmstate_subsection_load(QEMUFile *f, const VMStateDescription *vmsd,
 
         ret = vmstate_load_state(f, sub_vmsd, opaque, version_id);
         if (ret) {
+            trace_vmstate_subsection_load_bad(vmsd->name, "(child)");
             return ret;
         }
     }
+
+    trace_vmstate_subsection_load_good(vmsd->name);
     return 0;
 }
 
diff --git a/savevm.c b/savevm.c
index 48c2396..1cc0f02 100644
--- a/savevm.c
+++ b/savevm.c
@@ -674,7 +674,7 @@  int qemu_savevm_state_iterate(QEMUFile *f)
         qemu_put_be32(f, se->section_id);
 
         ret = se->ops->save_live_iterate(f, se->opaque);
-        trace_savevm_section_end(se->idstr, se->section_id);
+        trace_savevm_section_end(se->idstr, se->section_id, ret);
 
         if (ret < 0) {
             qemu_file_set_error(f, ret);
@@ -714,7 +714,7 @@  void qemu_savevm_state_complete(QEMUFile *f)
         qemu_put_be32(f, se->section_id);
 
         ret = se->ops->save_live_complete(f, se->opaque);
-        trace_savevm_section_end(se->idstr, se->section_id);
+        trace_savevm_section_end(se->idstr, se->section_id, ret);
         if (ret < 0) {
             qemu_file_set_error(f, ret);
             return;
@@ -741,7 +741,7 @@  void qemu_savevm_state_complete(QEMUFile *f)
         qemu_put_be32(f, se->version_id);
 
         vmstate_save(f, se);
-        trace_savevm_section_end(se->idstr, se->section_id);
+        trace_savevm_section_end(se->idstr, se->section_id, 0);
     }
 
     qemu_put_byte(f, QEMU_VM_EOF);
@@ -911,6 +911,7 @@  int qemu_loadvm_state(QEMUFile *f)
         char idstr[257];
         int len;
 
+        trace_qemu_loadvm_state_section(section_type);
         switch (section_type) {
         case QEMU_VM_SECTION_START:
         case QEMU_VM_SECTION_FULL:
@@ -922,6 +923,8 @@  int qemu_loadvm_state(QEMUFile *f)
             instance_id = qemu_get_be32(f);
             version_id = qemu_get_be32(f);
 
+            trace_qemu_loadvm_state_section_startfull(section_id, idstr,
+                                                      instance_id, version_id);
             /* Find savevm section */
             se = find_se(idstr, instance_id);
             if (se == NULL) {
@@ -958,6 +961,7 @@  int qemu_loadvm_state(QEMUFile *f)
         case QEMU_VM_SECTION_END:
             section_id = qemu_get_be32(f);
 
+            trace_qemu_loadvm_state_section_partend(section_id);
             QLIST_FOREACH(le, &loadvm_handlers, entry) {
                 if (le->section_id == section_id) {
                     break;
diff --git a/trace-events b/trace-events
index 8acbcce..1bf57b3 100644
--- a/trace-events
+++ b/trace-events
@@ -1133,8 +1133,11 @@  vmware_scratch_write(uint32_t index, uint32_t value) "index %d, value 0x%x"
 vmware_setmode(uint32_t w, uint32_t h, uint32_t bpp) "%dx%d @ %d bpp"
 
 # savevm.c
+qemu_loadvm_state_section(unsigned int section_type) "%d"
+qemu_loadvm_state_section_partend(uint32_t section_id) "%u"
+qemu_loadvm_state_section_startfull(uint32_t section_id, const char *idstr, uint32_t instance_id, uint32_t version_id) "%u(%s) %u %u"
 savevm_section_start(const char *id, unsigned int section_id) "%s, section_id %u"
-savevm_section_end(const char *id, unsigned int section_id) "%s, section_id %u"
+savevm_section_end(const char *id, unsigned int section_id, int ret) "%s, section_id %u -> %d"
 savevm_state_begin(void) ""
 savevm_state_iterate(void) ""
 savevm_state_complete(void) ""
@@ -1145,6 +1148,12 @@  qemu_announce_self_iter(const char *mac) "%s"
 
 # vmstate.c
 vmstate_load_field_error(const char *field, int ret) "field \"%s\" load failed, ret = %d"
+vmstate_load_state(const char *name, int version_id) "%s v%d"
+vmstate_load_state_end(const char *name, const char *reason, int val) "%s %s/%d"
+vmstate_load_state_field(const char *name, const char *field) "%s:%s"
+vmstate_subsection_load(const char *parent) "%s"
+vmstate_subsection_load_bad(const char *parent,  const char *sub) "%s: %s"
+vmstate_subsection_load_good(const char *parent) "%s"
 
 # qemu-file.c
 qemu_file_fclose(void) ""