From patchwork Wed Jul 13 13:06:51 2011 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Michal Novotny X-Patchwork-Id: 104507 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from lists.gnu.org (lists.gnu.org [140.186.70.17]) (using TLSv1 with cipher AES256-SHA (256/256 bits)) (Client did not present a certificate) by ozlabs.org (Postfix) with ESMTPS id C1386B6F65 for ; Wed, 13 Jul 2011 23:23:45 +1000 (EST) Received: from localhost ([::1]:55492 helo=lists.gnu.org) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1QgzPh-0002ge-Tn for incoming@patchwork.ozlabs.org; Wed, 13 Jul 2011 09:23:42 -0400 Received: from eggs.gnu.org ([140.186.70.92]:40833) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1Qgz9V-0007sl-NM for qemu-devel@nongnu.org; Wed, 13 Jul 2011 09:06:59 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1Qgz9T-0007jo-0c for qemu-devel@nongnu.org; Wed, 13 Jul 2011 09:06:57 -0400 Received: from mx1.redhat.com ([209.132.183.28]:43814) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1Qgz9S-0007jg-Aw for qemu-devel@nongnu.org; Wed, 13 Jul 2011 09:06:54 -0400 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 p6DD6rfj004151 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-SHA bits=256 verify=OK) for ; Wed, 13 Jul 2011 09:06:53 -0400 Received: from mig-laptop.brq.redhat.com (dhcp-1-226.brq.redhat.com [10.34.1.226]) by int-mx01.intmail.prod.int.phx2.redhat.com (8.13.8/8.13.8) with ESMTP id p6DD6pVe023101; Wed, 13 Jul 2011 09:06:52 -0400 From: Michal Novotny To: qemu-devel@nongnu.org Date: Wed, 13 Jul 2011 15:06:51 +0200 Message-Id: <1310562411-30538-1-git-send-email-minovotn@redhat.com> X-Scanned-By: MIMEDefang 2.67 on 10.5.11.11 X-detected-operating-system: by eggs.gnu.org: Genre and OS details not recognized. X-Received-From: 209.132.183.28 Subject: [Qemu-devel] [PATCH] Introduce "info migrate-times" monitor command 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 Hi, this is the implementation of the "info migrate-times" command I did to get the times for the migration to get times for each migration stage. Based on the fact migration itself is just the vmsave on the source host and vmload on destination host this function can be also useful to get the save times however it's main purpose is measuring the migration times therefore it's called "info migrate-times". The total memory transferred during the last migration is being tracked there as well as total migration time, time of waiting for input data, times for various migration stages for total value, disk (if applicable) and ram memory transfer. There's also the time difference which is the inaccuracy value which is caused by block device flushing and also the qemu_get_clock_ns() is being used in there and subsequent calls of this function may result into minor inaccuracies (in the matter smaller than of milliseconds). I also did the testing with various migration speed settings (using the set_migrate_speed monitor command) for 7 GiB RHEL-6 i386 guest running bonnie++ test for 14 GiB (2x RAM) and the results were as follows: Max.speed | Memory transferred | Time (s) --------------+-----------------------------+---------------- 32m | 12 925 676 bytes | 199 s 64m | 7 745 224 bytes | 26 s 128m | 7 674 188 bytes | 16 s 256m | 7 628 988 bytes | 16 s 512m | 7 599 837 bytes | 15 s 1024m (1g) | 7 592 934 bytes | 14 s 10g | 7 583 824 bytes | 13 s This has been tested on the 1 GiB network using the remote migration. The output of the command for last iteration (shown as an example was): (qemu) info migrate-times Total transferred memory: 7583824 kbytes Total migration time: 13.552894 s Waiting for input data: 6.942414 s Time difference (inaccuracy): 0.018257 s Times for total stage 1: 0.020247 s Times for total stage 2: 6.355092 s Times for total stage 3: 0.253398 s Times for total total: 6.628737 s Times for ram stage 1: 0.020238 s Times for ram stage 2: 6.353832 s Times for ram stage 3: 0.228953 s Times for ram total: 6.603023 s (qemu) So please review. This patch could be useful for getting the migration stage times. Thanks, Michal Signed-off-by: Michal Novotny --- arch_init.c | 12 +++++- block-migration.c | 5 ++ hmp-commands.hx | 2 + migration.c | 105 +++++++++++++++++++++++++++++++++++++++++++++ migration.h | 4 ++ monitor.c | 8 +++ savevm.c | 50 ++++++++++++++++++--- sysemu.h | 6 +++ vl.c | 123 +++++++++++++++++++++++++++++++++++++++++++++++++++++ 9 files changed, 307 insertions(+), 8 deletions(-) diff --git a/arch_init.c b/arch_init.c index 484b39d..684ae3c 100644 --- a/arch_init.c +++ b/arch_init.c @@ -252,8 +252,12 @@ int ram_save_live(Monitor *mon, QEMUFile *f, int stage, void *opaque) { ram_addr_t addr; uint64_t bytes_transferred_last; + uint64_t t_start; double bwidth = 0; uint64_t expected_time = 0; + int retval = 0; + + t_start = qemu_get_clock_ns(host_clock); if (stage < 0) { cpu_physical_memory_set_dirty_tracking(0); @@ -272,6 +276,10 @@ int ram_save_live(Monitor *mon, QEMUFile *f, int stage, void *opaque) last_offset = 0; sort_ram_list(); + time_set("ram", 1, 0); + time_set("ram", 2, 0); + time_set("ram", 3, 0); + /* Make sure all dirty bits are set */ QLIST_FOREACH(block, &ram_list.blocks, next) { for (addr = block->offset; addr < block->offset + block->length; @@ -331,8 +339,10 @@ int ram_save_live(Monitor *mon, QEMUFile *f, int stage, void *opaque) qemu_put_be64(f, RAM_SAVE_FLAG_EOS); expected_time = ram_save_remaining() * TARGET_PAGE_SIZE / bwidth; + retval = (stage == 2) && (expected_time <= migrate_max_downtime()); - return (stage == 2) && (expected_time <= migrate_max_downtime()); + time_add2("ram", stage, qemu_get_clock_ns(host_clock), t_start); + return retval; } static inline void *host_from_stream_offset(QEMUFile *f, diff --git a/block-migration.c b/block-migration.c index 0936c7d..b53a1f4 100644 --- a/block-migration.c +++ b/block-migration.c @@ -17,6 +17,8 @@ #include "qemu-queue.h" #include "qemu-timer.h" #include "monitor.h" +#include "qemu-timer.h" +#include "sysemu.h" #include "block-migration.h" #include "migration.h" #include "blockdev.h" @@ -556,6 +558,7 @@ static void blk_mig_cleanup(Monitor *mon) static int block_save_live(Monitor *mon, QEMUFile *f, int stage, void *opaque) { + uint64_t t_start = qemu_get_clock_ns(host_clock); DPRINTF("Enter save live stage %d submitted %d transferred %d\n", stage, block_mig_state.submitted, block_mig_state.transferred); @@ -633,6 +636,8 @@ static int block_save_live(Monitor *mon, QEMUFile *f, int stage, void *opaque) qemu_put_be64(f, BLK_MIG_FLAG_EOS); + time_add2("disk", stage, qemu_get_clock_ns(host_clock), t_start); + return ((stage == 2) && is_stage2_completed()); } diff --git a/hmp-commands.hx b/hmp-commands.hx index 6ad8806..83b33c8 100644 --- a/hmp-commands.hx +++ b/hmp-commands.hx @@ -1345,6 +1345,8 @@ show CPU statistics show user network stack connection states @item info migrate show migration status +@item info migrate-times +show migration times for last non-active migration @item info balloon show balloon information @item info qtree diff --git a/migration.c b/migration.c index af3a1f2..dee61d4 100644 --- a/migration.c +++ b/migration.c @@ -20,6 +20,7 @@ #include "qemu_socket.h" #include "block-migration.h" #include "qemu-objects.h" +#include "qemu-timer.h" //#define DEBUG_MIGRATION @@ -39,6 +40,8 @@ static MigrationState *current_migration; static NotifierList migration_state_notifiers = NOTIFIER_LIST_INITIALIZER(migration_state_notifiers); +static uint64_t t_last_put_ready; + int qemu_start_incoming_migration(const char *uri) { const char *p; @@ -224,6 +227,99 @@ static void migrate_put_status(QDict *qdict, const char *name, qdict_put_obj(qdict, name, obj); } +static void migrate_times_print_status(Monitor *mon, const char *name, + const QDict *status_dict) +{ + QDict *qdict; + qdict = qobject_to_qdict(qdict_get(status_dict, name)); + + monitor_printf(mon, "Times for %s stage 1: %.6f s\n", name, + qdict_get_int(qdict, "stage1") / 1000000.); + monitor_printf(mon, "Times for %s stage 2: %.6f s\n", name, + qdict_get_int(qdict, "stage2") / 1000000.); + monitor_printf(mon, "Times for %s stage 3: %.6f s\n", name, + qdict_get_int(qdict, "stage3") / 1000000.); + monitor_printf(mon, "Times for %s total: %.6f s\n", name, + qdict_get_int(qdict, "total") / 1000000.); +} + +void do_info_migrate_times_print(Monitor *mon, const QObject *data) +{ + QDict *qdict; + MigrationState *s = current_migration; + + if (s && (s->get_status(s) == MIG_STATE_ACTIVE) ) { + monitor_printf(mon, "Cannot get migration result times when migration is still running\n"); + return; + } + + qdict = qobject_to_qdict(data); + + monitor_printf(mon, "Total transferred memory: %"PRIu64" kbytes\n", + qdict_get_int(qdict, "transferred-memory") >> 10); + + monitor_printf(mon, "Total migration time: %.6f s\n", + qdict_get_int(qdict, "migration-time") / 1000000.); + + monitor_printf(mon, "Waiting for input data: %.6f s\n", + qdict_get_int(qdict, "wait-input") / 1000000.); + + if (qdict_haskey(qdict, "total")) { + QDict *qdict2; + qdict2 = qobject_to_qdict(qdict_get(qdict, "total")); + + monitor_printf(mon, "Time difference (inaccuracy): %.6f s\n", + abs(qdict_get_int(qdict, "migration-time") - + qdict_get_int(qdict, "wait-input") - + qdict_get_int(qdict2, "total")) / 1000000.); + + migrate_times_print_status(mon, "total", qdict); + } + + if (qdict_haskey(qdict, "ram")) { + migrate_times_print_status(mon, "ram", qdict); + } + + if (qdict_haskey(qdict, "disk")) { + migrate_times_print_status(mon, "disk", qdict); + } +} + +static void migrate_times_put_status(QDict *qdict, const char *name) +{ + QObject *obj; + uint64_t t0, t1, t2, t3; + + t1 = time_get(name, 1) / 1000; + t2 = time_get(name, 2) / 1000; + t3 = time_get(name, 3) / 1000; + t0 = t1 + t2 + t3; + + obj = qobject_from_jsonf("{ 'stage1': %" PRId64 ", " + "'stage2': %" PRId64 ", " + "'stage3': %" PRId64 ", " + "'total' : %" PRId64 " }", t1, t2, t3, t0); + + qdict_put_obj(qdict, name, obj); +} + +void do_info_migrate_times(Monitor *mon, QObject **ret_data) +{ + QDict *qdict; + + qdict = qdict_new(); + qdict_put(qdict, "migration-time", qint_from_int( save_total_time() / 1000 ) ); + qdict_put(qdict, "wait-input", qint_from_int( time_get("wait-input", -1) / 1000 ) ); + qdict_put(qdict, "transferred-memory", qint_from_int( ram_bytes_transferred() ) ); + + migrate_times_put_status(qdict, "total"); + if (time_get("disk", 1) > 0) + migrate_times_put_status(qdict, "disk"); + migrate_times_put_status(qdict, "ram"); + + *ret_data = QOBJECT(qdict); +} + void do_info_migrate(Monitor *mon, QObject **ret_data) { QDict *qdict; @@ -344,6 +440,11 @@ void migrate_fd_connect(FdMigrationState *s) { int ret; + time_set("total", 1, 0); + time_set("total", 2, 0); + time_set("total", 3, 0); + time_set("wait-input", -1, 0); + s->file = qemu_fopen_ops_buffered(s, s->bandwidth_limit, migrate_fd_put_buffer, @@ -352,6 +453,7 @@ void migrate_fd_connect(FdMigrationState *s) migrate_fd_close); DPRINTF("beginning savevm\n"); + t_last_put_ready = qemu_get_clock_ns(host_clock); ret = qemu_savevm_state_begin(s->mon, s->file, s->mig_state.blk, s->mig_state.shared); if (ret < 0) { @@ -373,6 +475,7 @@ void migrate_fd_put_ready(void *opaque) } DPRINTF("iterate\n"); + time_add2("wait-input", -1, qemu_get_clock_ns(host_clock), t_last_put_ready); if (qemu_savevm_state_iterate(s->mon, s->file) == 1) { int state; int old_vm_running = vm_running; @@ -397,6 +500,8 @@ void migrate_fd_put_ready(void *opaque) s->state = state; notifier_list_notify(&migration_state_notifiers); } + + t_last_put_ready = qemu_get_clock_ns(host_clock); } int migrate_fd_get_status(MigrationState *mig_state) diff --git a/migration.h b/migration.h index 050c56c..ef61f3f 100644 --- a/migration.h +++ b/migration.h @@ -70,6 +70,10 @@ void do_info_migrate_print(Monitor *mon, const QObject *data); void do_info_migrate(Monitor *mon, QObject **ret_data); +void do_info_migrate_times_print(Monitor *mon, const QObject *data); + +void do_info_migrate_times(Monitor *mon, QObject **ret_data); + int exec_start_incoming_migration(const char *host_port); MigrationState *exec_start_outgoing_migration(Monitor *mon, diff --git a/monitor.c b/monitor.c index 67ceb46..ac555f3 100644 --- a/monitor.c +++ b/monitor.c @@ -3060,6 +3060,14 @@ static const mon_cmd_t info_cmds[] = { .mhandler.info_new = do_info_migrate, }, { + .name = "migrate-times", + .args_type = "", + .params = "", + .help = "show migration times", + .user_print = do_info_migrate_times_print, + .mhandler.info_new = do_info_migrate_times, + }, + { .name = "balloon", .args_type = "", .params = "", diff --git a/savevm.c b/savevm.c index 8139bc7..3ca9b8a 100644 --- a/savevm.c +++ b/savevm.c @@ -1447,6 +1447,14 @@ static void vmstate_save(QEMUFile *f, SaveStateEntry *se) #define QEMU_VM_SECTION_FULL 0x04 #define QEMU_VM_SUBSECTION 0x05 +static uint64_t t_save_start; +static uint64_t t_save_total; + +uint64_t save_total_time(void) +{ + return t_save_total; +} + bool qemu_savevm_state_blocked(Monitor *mon) { SaveStateEntry *se; @@ -1465,6 +1473,9 @@ int qemu_savevm_state_begin(Monitor *mon, QEMUFile *f, int blk_enable, int shared) { SaveStateEntry *se; + int ret = 0; + + t_save_start = qemu_get_clock_ns(host_clock); QTAILQ_FOREACH(se, &savevm_handlers, entry) { if(se->set_params == NULL) { @@ -1472,7 +1483,7 @@ int qemu_savevm_state_begin(Monitor *mon, QEMUFile *f, int blk_enable, } se->set_params(blk_enable, shared, se->opaque); } - + qemu_put_be32(f, QEMU_VM_FILE_MAGIC); qemu_put_be32(f, QEMU_VM_FILE_VERSION); @@ -1499,17 +1510,21 @@ int qemu_savevm_state_begin(Monitor *mon, QEMUFile *f, int blk_enable, if (qemu_file_has_error(f)) { qemu_savevm_state_cancel(mon, f); - return -EIO; + ret = -EIO; } - return 0; + time_add2("total", 1, qemu_get_clock_ns(host_clock), t_save_start); + return ret; } int qemu_savevm_state_iterate(Monitor *mon, QEMUFile *f) { SaveStateEntry *se; + uint64_t t_start; int ret = 1; + t_start = qemu_get_clock_ns(host_clock); + QTAILQ_FOREACH(se, &savevm_handlers, entry) { if (se->save_live_state == NULL) continue; @@ -1528,20 +1543,30 @@ int qemu_savevm_state_iterate(Monitor *mon, QEMUFile *f) } } - if (ret) - return 1; + if (ret) { + ret = 1; + goto out; + } if (qemu_file_has_error(f)) { qemu_savevm_state_cancel(mon, f); - return -EIO; + ret = -EIO; } + else + ret = 0; - return 0; +out: + time_add2("total", 2, qemu_get_clock_ns(host_clock), t_start); + return ret; } int qemu_savevm_state_complete(Monitor *mon, QEMUFile *f) { SaveStateEntry *se; + uint64_t t_start; + uint64_t t_help; + + t_start = qemu_get_clock_ns(host_clock); cpu_synchronize_all_states(); @@ -1582,6 +1607,10 @@ int qemu_savevm_state_complete(Monitor *mon, QEMUFile *f) if (qemu_file_has_error(f)) return -EIO; + t_help = qemu_get_clock_ns(host_clock); + t_save_total = t_help - t_save_start; + time_add2("total", 3, t_help, t_start); + return 0; } @@ -1589,6 +1618,13 @@ void qemu_savevm_state_cancel(Monitor *mon, QEMUFile *f) { SaveStateEntry *se; + time_set("ram", 1, 0); + time_set("ram", 2, 0); + time_set("ram", 3, 0); + time_set("disk", 1, 0); + time_set("disk", 2, 0); + time_set("disk", 3, 0); + QTAILQ_FOREACH(se, &savevm_handlers, entry) { if (se->save_live_state) { se->save_live_state(mon, f, -1, se->opaque); diff --git a/sysemu.h b/sysemu.h index d3013f5..c533706 100644 --- a/sysemu.h +++ b/sysemu.h @@ -77,6 +77,12 @@ int qemu_savevm_state_complete(Monitor *mon, QEMUFile *f); void qemu_savevm_state_cancel(Monitor *mon, QEMUFile *f); int qemu_loadvm_state(QEMUFile *f); +uint64_t time_get(const char *name, int stage); +void time_set(const char *name, int stage, uint64_t tv); +void time_add(const char *name, int stage, uint64_t tv); +void time_add2(const char *name, int stage, uint64_t time1, uint64_t time2); +uint64_t save_total_time(void); + /* SLIRP */ void do_info_slirp(Monitor *mon); diff --git a/vl.c b/vl.c index fcd7395..340cbe3 100644 --- a/vl.c +++ b/vl.c @@ -229,6 +229,12 @@ unsigned int nb_prom_envs = 0; const char *prom_envs[MAX_PROM_ENVS]; int boot_menu; +/* Times */ +static uint64_t time_save_total[3]; +static uint64_t time_save_disk[3]; +static uint64_t time_save_ram[3]; +static uint64_t time_save_wait_input; + typedef struct FWBootEntry FWBootEntry; struct FWBootEntry { @@ -348,6 +354,123 @@ int qemu_timedate_diff(struct tm *tm) return seconds - time(NULL); } +static void time_set_ram(int stage, uint64_t tv) +{ + if ((stage < 0) || (stage > 3)) + return; + + time_save_ram[stage - 1] = tv; +} + +static void time_set_disk(int stage, uint64_t tv) +{ + if ((stage < 0) || (stage > 3)) + return; + + time_save_disk[stage - 1] = tv; +} + +static void time_set_total(int stage, uint64_t tv) +{ + if ((stage < 0) || (stage > 3)) + return; + + time_save_total[stage - 1] = tv; +} + +void time_set(const char *name, int stage, uint64_t tv) +{ + if (strcmp(name, "ram") == 0) + time_set_ram(stage, tv); + if (strcmp(name, "disk") == 0) + time_set_disk(stage, tv); + if (strcmp(name, "wait-input") == 0) + time_save_wait_input = tv; + if (strcmp(name, "total") == 0) + time_set_total(stage, tv); +} + +static uint64_t time_get_ram(int stage) { + if ((stage < 0) || (stage > 3)) + return 0; + + return time_save_ram[stage - 1]; +} + +static uint64_t time_get_disk(int stage) { + if ((stage < 0) || (stage > 3)) + return 0; + + return time_save_disk[stage - 1]; +} + +static uint64_t time_get_total(int stage) { + if ((stage < 0) || (stage > 3)) + return 0; + + return time_save_total[stage - 1]; +} + +uint64_t time_get(const char *name, int stage) +{ + if (strcmp(name, "ram") == 0) + return time_get_ram(stage); + if (strcmp(name, "disk") == 0) + return time_get_disk(stage); + if (strcmp(name, "wait-input") == 0) + return time_save_wait_input; + if (strcmp(name, "total") == 0) + return time_get_total(stage); + + return 0; +} + +static void time_add_ram(int stage, uint64_t tv) +{ + if ((stage < 0) || (stage > 3)) + return; + + time_save_ram[stage - 1] += tv; +} + +static void time_add_disk(int stage, uint64_t tv) +{ + if ((stage < 0) || (stage > 3)) + return; + + time_save_disk[stage - 1] += tv; +} + +static void time_add_wait_input(uint64_t tv) +{ + time_save_wait_input += tv; +} + +static void time_add_total(int stage, uint64_t tv) +{ + if ((stage < 0) || (stage > 3)) + return; + + time_save_total[stage - 1] += tv; +} + +void time_add(const char *name, int stage, uint64_t tv) +{ + if (strcmp(name, "ram") == 0) + time_add_ram(stage, tv); + if (strcmp(name, "disk") == 0) + time_add_disk(stage, tv); + if (strcmp(name, "wait-input") == 0) + time_add_wait_input(tv); + if (strcmp(name, "total") == 0) + time_add_total(stage, tv); +} + +void time_add2(const char *name, int stage, uint64_t time1, uint64_t time2) +{ + time_add(name, stage, time1 - time2); +} + void rtc_change_mon_event(struct tm *tm) { QObject *data;