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

[Orit Wasserman]

This is for debugging?
Why not trace events?

Regards,
Orit
On 01/18/2013 01:53 PM, Juan Quintela wrote:
> Signed-off-by: Juan Quintela <address@hidden>
> ---
>  block.c     |  6 ++++++
>  cpus.c      | 17 +++++++++++++++++
>  migration.c | 13 +++++++++++++
>  savevm.c    | 13 +++++++++++++
>  4 files changed, 49 insertions(+)
> 
> diff --git a/block.c b/block.c
> index 6fa7c90..c121db3 100644
> --- a/block.c
> +++ b/block.c
> @@ -2693,9 +2693,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 a4390c3..15534ba 100644
> --- a/cpus.c
> +++ b/cpus.c
> @@ -439,14 +439,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 de665f7..5e965cc 100644
> --- a/migration.c
> +++ b/migration.c
> @@ -712,12 +712,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(s->file, free_space))
>                      > 8) {
> @@ -728,15 +733,21 @@ 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(s->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(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) {
> @@ -744,6 +755,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 3447f91..113c1dd 100644
> --- a/savevm.c
> +++ b/savevm.c
> @@ -1660,9 +1660,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;
> @@ -1683,6 +1688,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;
> @@ -1707,6 +1717,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);
>