[Qemu-devel] [PATCH 35/35] migration: print times for end phase

[Juan Quintela]

Signed-off-by: Juan Quintela <address@hidden>
---
 block.c     |  6 ++++++
 cpus.c      | 17 +++++++++++++++++
 migration.c | 12 ++++++++++++
 savevm.c    | 13 +++++++++++++
 4 files changed, 48 insertions(+)

diff --git a/block.c b/block.c
index c05875f..2fa0827 100644
--- a/block.c
+++ b/block.c
@@ -2680,9 +2680,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 d9c332f..a920a06 100644
--- a/cpus.c
+++ b/cpus.c
@@ -437,14 +437,31 @@ bool cpu_is_stopped(CPUState *cpu)

 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 dd6a401..fc0548c 100644
--- a/migration.c
+++ b/migration.c
@@ -723,12 +723,17 @@ static void *buffered_file_thread(void *opaque)
                 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 %ld\n", end_time - start_time);
+
                 /* 8 is the size of an end of section mark, so empty section */
                 while ((ret = qemu_savevm_state_iterate(m->file, free_space))
                     > 8) {
@@ -739,15 +744,20 @@ static void *buffered_file_thread(void *opaque)
                     }
                     free_space = s->buffer_capacity - s->buffer_size;
                 }
+                end_time = qemu_get_clock_ms(rt_clock);
+                printf("iterate phase %ld\n", end_time - start_time);

                 ret = qemu_savevm_state_complete(m->file);
                 if (ret < 0) {
                     qemu_mutex_unlock_iothread();
                     break;
                 } else {
+                    end_time = qemu_get_clock_ms(rt_clock);
+                    printf("complete without error 3a %ld\n", end_time - 
start_time);
                     migrate_fd_completed(m);
                 }
                 end_time = qemu_get_clock_ms(rt_clock);
+                printf("completed %ld\n", end_time - start_time);
                 m->total_time = end_time - m->total_time;
                 m->downtime = end_time - start_time;
                 if (m->state != MIG_STATE_COMPLETED) {
@@ -755,6 +765,8 @@ static void *buffered_file_thread(void *opaque)
                         vm_start();
                     }
                 }
+                end_time = qemu_get_clock_ms(rt_clock);
+                printf("end completed stage %ld\n", end_time - start_time);
                 last_round = true;
             }
         }
diff --git a/savevm.c b/savevm.c
index 4b7715a..c964b66 100644
--- a/savevm.c
+++ b/savevm.c
@@ -1706,9 +1706,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;
@@ -1729,6 +1734,11 @@ int qemu_savevm_state_complete(QEMUFile *f)
             return ret;
         }
     }
+    t1 = qemu_get_clock_ms(rt_clock);
+
+    printf("migrate save live complete %ld\n", t1 - t0);
+
+    t0 = t1;

     QTAILQ_FOREACH(se, &savevm_handlers, entry) {
         int len;
@@ -1753,6 +1763,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);
-- 
1.7.11.7