Message ID | 1358510033-17268-5-git-send-email-quintela@redhat.com |
---|---|
State | New |
Headers | show |
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 <quintela@redhat.com> > --- > 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); >
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);
Signed-off-by: Juan Quintela <quintela@redhat.com> --- block.c | 6 ++++++ cpus.c | 17 +++++++++++++++++ migration.c | 13 +++++++++++++ savevm.c | 13 +++++++++++++ 4 files changed, 49 insertions(+)