From patchwork Tue Dec 11 12:47:11 2012 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Juan Quintela X-Patchwork-Id: 205210 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from lists.gnu.org (lists.gnu.org [208.118.235.17]) (using TLSv1 with cipher AES256-SHA (256/256 bits)) (Client did not present a certificate) by ozlabs.org (Postfix) with ESMTPS id 82B132C008C for ; Wed, 12 Dec 2012 00:11:00 +1100 (EST) Received: from localhost ([::1]:58278 helo=lists.gnu.org) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1TiPGQ-0007vD-Dc for incoming@patchwork.ozlabs.org; Tue, 11 Dec 2012 07:48:46 -0500 Received: from eggs.gnu.org ([208.118.235.92]:51238) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1TiPFe-00079b-9V for qemu-devel@nongnu.org; Tue, 11 Dec 2012 07:47:59 -0500 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1TiPFb-0004Xc-FB for qemu-devel@nongnu.org; Tue, 11 Dec 2012 07:47:58 -0500 Received: from mx1.redhat.com ([209.132.183.28]:2994) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1TiPFb-0004XS-7Y for qemu-devel@nongnu.org; Tue, 11 Dec 2012 07:47:55 -0500 Received: from int-mx01.intmail.prod.int.phx2.redhat.com (int-mx01.intmail.prod.int.phx2.redhat.com [10.5.11.11]) by mx1.redhat.com (8.14.4/8.14.4) with ESMTP id qBBClsKd018327 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-SHA bits=256 verify=OK) for ; Tue, 11 Dec 2012 07:47:54 -0500 Received: from trasno.mitica (ovpn-113-46.phx2.redhat.com [10.3.113.46]) by int-mx01.intmail.prod.int.phx2.redhat.com (8.13.8/8.13.8) with ESMTP id qBBClCW1027513; Tue, 11 Dec 2012 07:47:53 -0500 From: Juan Quintela To: qemu-devel@nongnu.org Date: Tue, 11 Dec 2012 13:47:11 +0100 Message-Id: <1355230031-28233-36-git-send-email-quintela@redhat.com> In-Reply-To: <1355230031-28233-1-git-send-email-quintela@redhat.com> References: <1355230031-28233-1-git-send-email-quintela@redhat.com> X-Scanned-By: MIMEDefang 2.67 on 10.5.11.11 X-detected-operating-system: by eggs.gnu.org: GNU/Linux 3.x X-Received-From: 209.132.183.28 Subject: [Qemu-devel] [PATCH 35/35] migration: print times for end phase X-BeenThere: qemu-devel@nongnu.org X-Mailman-Version: 2.1.14 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: qemu-devel-bounces+incoming=patchwork.ozlabs.org@nongnu.org Sender: qemu-devel-bounces+incoming=patchwork.ozlabs.org@nongnu.org Signed-off-by: Juan Quintela --- 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);