Patchwork [14/14] migration: print times for end phase

login
register
mail settings
Submitter Juan Quintela
Date Sept. 21, 2012, 2:08 p.m.
Message ID <1348236500-2565-15-git-send-email-quintela@redhat.com>
Download mbox | patch
Permalink /patch/185746/
State New
Headers show

Comments

Juan Quintela - Sept. 21, 2012, 2:08 p.m.
Signed-off-by: Juan Quintela <quintela@redhat.com>
---
 block.c     |  6 ++++++
 cpus.c      | 17 +++++++++++++++++
 migration.c | 10 +++++++++-
 savevm.c    | 13 +++++++++++++
 4 files changed, 45 insertions(+), 1 deletion(-)
Paolo Bonzini - Sept. 21, 2012, 3:13 p.m.
Not sure you want these in master. :)

Paolo

Il 21/09/2012 16:08, Juan Quintela ha scritto:
> Signed-off-by: Juan Quintela <quintela@redhat.com>
> ---
>  block.c     |  6 ++++++
>  cpus.c      | 17 +++++++++++++++++
>  migration.c | 10 +++++++++-
>  savevm.c    | 13 +++++++++++++
>  4 files changed, 45 insertions(+), 1 deletion(-)
> 
> diff --git a/block.c b/block.c
> index e78039b..d6e7a59 100644
> --- a/block.c
> +++ b/block.c
> @@ -2269,9 +2269,15 @@ int bdrv_get_flags(BlockDriverState *bs)
>  void bdrv_flush_all(void)
>  {
>      BlockDriverState *bs;
> +    int64_t start_time, end_time;
> +
> +    start_time = qemu_get_clock_ms(rt_clock);
> 
>      QTAILQ_FOREACH(bs, &bdrv_states, list) {
>          bdrv_flush(bs);
> +        end_time = qemu_get_clock_ms(rt_clock);
> +        printf("time flush device %s: %ld\n", bs->filename,
> +               end_time - start_time);
>      }
>  }
> 
> diff --git a/cpus.c b/cpus.c
> index 1b7061a..0ccc1e0 100644
> --- a/cpus.c
> +++ b/cpus.c
> @@ -439,14 +439,31 @@ int cpu_is_stopped(CPUArchState *env)
> 
>  static void do_vm_stop(RunState state)
>  {
> +    int64_t start_time, end_time;
> +
>      if (runstate_is_running()) {
> +        start_time = qemu_get_clock_ms(rt_clock);
>          cpu_disable_ticks();
> +        end_time = qemu_get_clock_ms(rt_clock);
> +        printf("time cpu_disable_ticks %ld\n", end_time - start_time);
>          pause_all_vcpus();
> +        end_time = qemu_get_clock_ms(rt_clock);
> +        printf("time pause_all_vcpus %ld\n", end_time - start_time);
>          runstate_set(state);
> +        end_time = qemu_get_clock_ms(rt_clock);
> +        printf("time runstate_set %ld\n", end_time - start_time);
>          vm_state_notify(0, state);
> +        end_time = qemu_get_clock_ms(rt_clock);
> +        printf("time vmstate_notify %ld\n", end_time - start_time);
>          bdrv_drain_all();
> +        end_time = qemu_get_clock_ms(rt_clock);
> +        printf("time bdrv_drain_all %ld\n", end_time - start_time);
>          bdrv_flush_all();
> +        end_time = qemu_get_clock_ms(rt_clock);
> +        printf("time bdrv_flush_all %ld\n", end_time - start_time);
>          monitor_protocol_event(QEVENT_STOP, NULL);
> +        end_time = qemu_get_clock_ms(rt_clock);
> +        printf("time monitor_protocol_event %ld\n", end_time - start_time);
>      }
>  }
> 
> diff --git a/migration.c b/migration.c
> index 8054a77..9c62614 100644
> --- a/migration.c
> +++ b/migration.c
> @@ -340,18 +340,24 @@ bool migrate_fd_put_ready(MigrationState *s, uint64_t max_size)
>          DPRINTF("done iterating\n");
>          start_time = qemu_get_clock_ms(rt_clock);
>          qemu_system_wakeup_request(QEMU_WAKEUP_REASON_OTHER);
> +        end_time = qemu_get_clock_ms(rt_clock);
> +        printf("wakeup_request %ld\n", end_time - start_time);
>          if (old_vm_running) {
>              vm_stop(RUN_STATE_FINISH_MIGRATE);
>          } else {
>              vm_stop_force_state(RUN_STATE_FINISH_MIGRATE);
>          }
> -
> +        end_time = qemu_get_clock_ms(rt_clock);
> +        printf("vm_stop 2 %ld\n", end_time - start_time);
>          if (qemu_savevm_state_complete(s->file) < 0) {
>              migrate_fd_error(s);
>          } else {
> +            end_time = qemu_get_clock_ms(rt_clock);
> +            printf("complete without error 3a %ld\n", end_time - start_time);
>              migrate_fd_completed(s);
>          }
>          end_time = qemu_get_clock_ms(rt_clock);
> +        printf("completed %ld\n", end_time - start_time);
>          s->total_time = end_time - s->total_time;
>          s->downtime = end_time - start_time;
>          if (s->state != MIG_STATE_COMPLETED) {
> @@ -359,6 +365,8 @@ bool migrate_fd_put_ready(MigrationState *s, uint64_t max_size)
>                  vm_start();
>              }
>          }
> +        end_time = qemu_get_clock_ms(rt_clock);
> +        printf("end completed stage %ld\n", end_time - start_time);
>          last_round = true;
>      }
>      qemu_mutex_unlock_iothread();
> diff --git a/savevm.c b/savevm.c
> index bdc70c2..ba399f1 100644
> --- a/savevm.c
> +++ b/savevm.c
> @@ -1629,9 +1629,14 @@ int qemu_savevm_state_complete(QEMUFile *f)
>  {
>      SaveStateEntry *se;
>      int ret;
> +    int64_t t1;
> +    int64_t t0 = qemu_get_clock_ms(rt_clock);
> 
>      cpu_synchronize_all_states();
> +    t1 = qemu_get_clock_ms(rt_clock);
> +    printf("synchronize_all_states %ld\n", t1 - t0);
> 
> +    t0 = t1;
>      QTAILQ_FOREACH(se, &savevm_handlers, entry) {
>          if (!se->ops || !se->ops->save_live_complete) {
>              continue;
> @@ -1652,6 +1657,11 @@ int qemu_savevm_state_complete(QEMUFile *f)
>              return ret;
>          }
>      }
> +    t1 = qemu_get_clock_ms(rt_clock);
> +
> +    printf("migrate RAM %ld\n", t1 - t0);
> +
> +    t0 = t1;
> 
>      QTAILQ_FOREACH(se, &savevm_handlers, entry) {
>          int len;
> @@ -1676,6 +1686,9 @@ int qemu_savevm_state_complete(QEMUFile *f)
>          trace_savevm_section_end(se->section_id);
>      }
> 
> +    t1 = qemu_get_clock_ms(rt_clock);
> +
> +    printf("migrate rest devices %ld\n", t1 - t0);
>      qemu_put_byte(f, QEMU_VM_EOF);
> 
>      return qemu_file_get_error(f);
>
Juan Quintela - Sept. 21, 2012, 3:27 p.m.
Paolo Bonzini <pbonzini@redhat.com> wrote:
> Not sure you want these in master. :)
>
> Paolo

/me points to PATCH 00 O;-)

> - last patch just shows printfs to see where the time is being spent
>   on the migration complete phase.
>  (yes it pollutes all uses of stop on the monitor)

There are other users that are having long downtimes (with/without
migration thread).  I just want to know where, and then will start
pointing fingers O;-)

Later, Juan.

Patch

diff --git a/block.c b/block.c
index e78039b..d6e7a59 100644
--- a/block.c
+++ b/block.c
@@ -2269,9 +2269,15 @@  int bdrv_get_flags(BlockDriverState *bs)
 void bdrv_flush_all(void)
 {
     BlockDriverState *bs;
+    int64_t start_time, end_time;
+
+    start_time = qemu_get_clock_ms(rt_clock);

     QTAILQ_FOREACH(bs, &bdrv_states, list) {
         bdrv_flush(bs);
+        end_time = qemu_get_clock_ms(rt_clock);
+        printf("time flush device %s: %ld\n", bs->filename,
+               end_time - start_time);
     }
 }

diff --git a/cpus.c b/cpus.c
index 1b7061a..0ccc1e0 100644
--- a/cpus.c
+++ b/cpus.c
@@ -439,14 +439,31 @@  int cpu_is_stopped(CPUArchState *env)

 static void do_vm_stop(RunState state)
 {
+    int64_t start_time, end_time;
+
     if (runstate_is_running()) {
+        start_time = qemu_get_clock_ms(rt_clock);
         cpu_disable_ticks();
+        end_time = qemu_get_clock_ms(rt_clock);
+        printf("time cpu_disable_ticks %ld\n", end_time - start_time);
         pause_all_vcpus();
+        end_time = qemu_get_clock_ms(rt_clock);
+        printf("time pause_all_vcpus %ld\n", end_time - start_time);
         runstate_set(state);
+        end_time = qemu_get_clock_ms(rt_clock);
+        printf("time runstate_set %ld\n", end_time - start_time);
         vm_state_notify(0, state);
+        end_time = qemu_get_clock_ms(rt_clock);
+        printf("time vmstate_notify %ld\n", end_time - start_time);
         bdrv_drain_all();
+        end_time = qemu_get_clock_ms(rt_clock);
+        printf("time bdrv_drain_all %ld\n", end_time - start_time);
         bdrv_flush_all();
+        end_time = qemu_get_clock_ms(rt_clock);
+        printf("time bdrv_flush_all %ld\n", end_time - start_time);
         monitor_protocol_event(QEVENT_STOP, NULL);
+        end_time = qemu_get_clock_ms(rt_clock);
+        printf("time monitor_protocol_event %ld\n", end_time - start_time);
     }
 }

diff --git a/migration.c b/migration.c
index 8054a77..9c62614 100644
--- a/migration.c
+++ b/migration.c
@@ -340,18 +340,24 @@  bool migrate_fd_put_ready(MigrationState *s, uint64_t max_size)
         DPRINTF("done iterating\n");
         start_time = qemu_get_clock_ms(rt_clock);
         qemu_system_wakeup_request(QEMU_WAKEUP_REASON_OTHER);
+        end_time = qemu_get_clock_ms(rt_clock);
+        printf("wakeup_request %ld\n", end_time - start_time);
         if (old_vm_running) {
             vm_stop(RUN_STATE_FINISH_MIGRATE);
         } else {
             vm_stop_force_state(RUN_STATE_FINISH_MIGRATE);
         }
-
+        end_time = qemu_get_clock_ms(rt_clock);
+        printf("vm_stop 2 %ld\n", end_time - start_time);
         if (qemu_savevm_state_complete(s->file) < 0) {
             migrate_fd_error(s);
         } else {
+            end_time = qemu_get_clock_ms(rt_clock);
+            printf("complete without error 3a %ld\n", end_time - start_time);
             migrate_fd_completed(s);
         }
         end_time = qemu_get_clock_ms(rt_clock);
+        printf("completed %ld\n", end_time - start_time);
         s->total_time = end_time - s->total_time;
         s->downtime = end_time - start_time;
         if (s->state != MIG_STATE_COMPLETED) {
@@ -359,6 +365,8 @@  bool migrate_fd_put_ready(MigrationState *s, uint64_t max_size)
                 vm_start();
             }
         }
+        end_time = qemu_get_clock_ms(rt_clock);
+        printf("end completed stage %ld\n", end_time - start_time);
         last_round = true;
     }
     qemu_mutex_unlock_iothread();
diff --git a/savevm.c b/savevm.c
index bdc70c2..ba399f1 100644
--- a/savevm.c
+++ b/savevm.c
@@ -1629,9 +1629,14 @@  int qemu_savevm_state_complete(QEMUFile *f)
 {
     SaveStateEntry *se;
     int ret;
+    int64_t t1;
+    int64_t t0 = qemu_get_clock_ms(rt_clock);

     cpu_synchronize_all_states();
+    t1 = qemu_get_clock_ms(rt_clock);
+    printf("synchronize_all_states %ld\n", t1 - t0);

+    t0 = t1;
     QTAILQ_FOREACH(se, &savevm_handlers, entry) {
         if (!se->ops || !se->ops->save_live_complete) {
             continue;
@@ -1652,6 +1657,11 @@  int qemu_savevm_state_complete(QEMUFile *f)
             return ret;
         }
     }
+    t1 = qemu_get_clock_ms(rt_clock);
+
+    printf("migrate RAM %ld\n", t1 - t0);
+
+    t0 = t1;

     QTAILQ_FOREACH(se, &savevm_handlers, entry) {
         int len;
@@ -1676,6 +1686,9 @@  int qemu_savevm_state_complete(QEMUFile *f)
         trace_savevm_section_end(se->section_id);
     }

+    t1 = qemu_get_clock_ms(rt_clock);
+
+    printf("migrate rest devices %ld\n", t1 - t0);
     qemu_put_byte(f, QEMU_VM_EOF);

     return qemu_file_get_error(f);