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.
Differences between v1 and v2:
- Time functions have been implemented as macros instead
- Handling for both save and load code has been implemented
- Monitor command implementation moved to savevm.c source file
So please review. This patch could be useful for getting
the migration stage times.
Thanks,
Michal
Signed-off-by: Michal Novotny <minovotn@redhat.com>
---
arch_init.c | 22 +++++-
block-migration.c | 12 +++
hmp-commands.hx | 2 +
migration.c | 19 +++++
migration.h | 30 +++++++
monitor.c | 8 ++
savevm.c | 234 +++++++++++++++++++++++++++++++++++++++++++++++++++--
7 files changed, 318 insertions(+), 9 deletions(-)
@@ -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(save, ram, 1, 0);
+ TIME_SET(save, ram, 2, 0);
+ TIME_SET(save, 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,18 @@ 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;
-
- return (stage == 2) && (expected_time <= migrate_max_downtime());
+ retval = (stage == 2) && (expected_time <= migrate_max_downtime());
+
+ if (stage == 1)
+ TIME_ADD(save, ram, 1, qemu_get_clock_ns(host_clock) - t_start);
+ else
+ if (stage == 2)
+ TIME_ADD(save, ram, 2, qemu_get_clock_ns(host_clock) - t_start);
+ else
+ if (stage == 3)
+ TIME_ADD(save, ram, 3, qemu_get_clock_ns(host_clock) - t_start);
+
+ return retval;
}
static inline void *host_from_stream_offset(QEMUFile *f,
@@ -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,15 @@ static int block_save_live(Monitor *mon, QEMUFile *f, int stage, void *opaque)
qemu_put_be64(f, BLK_MIG_FLAG_EOS);
+ if (stage == 1)
+ TIME_ADD(save, disk, 1, qemu_get_clock_ns(host_clock) - t_start);
+ else
+ if (stage == 2)
+ TIME_ADD(save, disk, 2, qemu_get_clock_ns(host_clock) - t_start);
+ else
+ if (stage == 3)
+ TIME_ADD(save, disk, 3, qemu_get_clock_ns(host_clock) - t_start);
+
return ((stage == 2) && is_stage2_completed());
}
@@ -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
@@ -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,9 @@ static MigrationState *current_migration;
static NotifierList migration_state_notifiers =
NOTIFIER_LIST_INITIALIZER(migration_state_notifiers);
+/* Time of last put_ready state */
+static uint64_t t_last_put_ready;
+
int qemu_start_incoming_migration(const char *uri)
{
const char *p;
@@ -63,6 +67,10 @@ int qemu_start_incoming_migration(const char *uri)
void process_incoming_migration(QEMUFile *f)
{
+ uint64_t t_start;
+
+ t_start = qemu_get_clock_ns(host_clock);
+
if (qemu_loadvm_state(f) < 0) {
fprintf(stderr, "load of migration failed\n");
exit(0);
@@ -70,6 +78,8 @@ void process_incoming_migration(QEMUFile *f)
qemu_announce_self();
DPRINTF("successfully loaded vm state\n");
+ time_load_measured = qemu_get_clock_ns(host_clock) - t_start;
+
incoming_expected = false;
if (autostart)
@@ -344,6 +354,11 @@ void migrate_fd_connect(FdMigrationState *s)
{
int ret;
+ TIME_SET(save, total, 1, 0);
+ TIME_SET(save, total, 2, 0);
+ TIME_SET(save, total, 3, 0);
+ TIME_SET(save, wait_input, 0, 0);
+
s->file = qemu_fopen_ops_buffered(s,
s->bandwidth_limit,
migrate_fd_put_buffer,
@@ -352,6 +367,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 +389,7 @@ void migrate_fd_put_ready(void *opaque)
}
DPRINTF("iterate\n");
+ TIME_ADD(save, wait_input, 0, 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 +414,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)
@@ -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,
@@ -148,4 +152,30 @@ int ram_load(QEMUFile *f, void *opaque, int version_id);
extern int incoming_expected;
+/* Time measuring facility */
+extern int time_measurement_type;
+extern uint64_t time_saveram1;
+extern uint64_t time_saveram2;
+extern uint64_t time_saveram3;
+extern uint64_t time_savedisk1;
+extern uint64_t time_savedisk2;
+extern uint64_t time_savedisk3;
+extern uint64_t time_savetotal1;
+extern uint64_t time_savetotal2;
+extern uint64_t time_savetotal3;
+extern uint64_t time_savewait_input0;
+extern uint64_t time_save_measured;
+extern uint64_t time_loadpart1;
+extern uint64_t time_loadpart2;
+extern uint64_t time_loadpart3;
+extern uint64_t time_loadpart4;
+extern uint64_t time_load_measured;
+
+#define TIME_MEASUREMENT_NONE 0x00
+#define TIME_MEASUREMENT_SAVE 0x01
+#define TIME_MEASUREMENT_LOAD 0x02
+#define TIME_GET(type, name, stage) time_##type##name##stage
+#define TIME_SET(type, name, stage, tv) time_##type##name##stage = tv
+#define TIME_ADD(type, name, stage, tv) time_##type##name##stage += tv
+
#endif
@@ -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 = "",
@@ -82,6 +82,8 @@
#include "qemu_socket.h"
#include "qemu-queue.h"
#include "cpus.h"
+#include "qjson.h"
+#include "qint.h"
#define SELF_ANNOUNCE_ROUNDS 5
@@ -92,6 +94,24 @@
#define ARP_PTYPE_IP 0x0800
#define ARP_OP_REQUEST_REV 0x3
+int time_measurement_type = TIME_MEASUREMENT_NONE;
+uint64_t time_saveram1;
+uint64_t time_saveram2;
+uint64_t time_saveram3;
+uint64_t time_savedisk1;
+uint64_t time_savedisk2;
+uint64_t time_savedisk3;
+uint64_t time_savetotal1;
+uint64_t time_savetotal2;
+uint64_t time_savetotal3;
+uint64_t time_savewait_input0;
+uint64_t time_save_measured;
+uint64_t time_loadpart1;
+uint64_t time_loadpart2;
+uint64_t time_loadpart3;
+uint64_t time_loadpart4;
+uint64_t time_load_measured;
+
static int announce_self_create(uint8_t *buf,
uint8_t *mac_addr)
{
@@ -1447,6 +1467,8 @@ 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;
+
bool qemu_savevm_state_blocked(Monitor *mon)
{
SaveStateEntry *se;
@@ -1465,6 +1487,10 @@ int qemu_savevm_state_begin(Monitor *mon, QEMUFile *f, int blk_enable,
int shared)
{
SaveStateEntry *se;
+ int ret = 0;
+
+ time_measurement_type = TIME_MEASUREMENT_SAVE;
+ t_save_start = qemu_get_clock_ns(host_clock);
QTAILQ_FOREACH(se, &savevm_handlers, entry) {
if(se->set_params == NULL) {
@@ -1472,7 +1498,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 +1525,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_ADD(save, 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 +1558,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_ADD(save, 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 +1622,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);
+ time_save_measured = t_help - t_save_start;
+ TIME_ADD(save, total, 3, t_help - t_start);
+
return 0;
}
@@ -1589,6 +1633,13 @@ void qemu_savevm_state_cancel(Monitor *mon, QEMUFile *f)
{
SaveStateEntry *se;
+ TIME_SET(save, ram, 1, 0);
+ TIME_SET(save, ram, 2, 0);
+ TIME_SET(save, ram, 3, 0);
+ TIME_SET(save, disk, 1, 0);
+ TIME_SET(save, disk, 2, 0);
+ TIME_SET(save, disk, 3, 0);
+
QTAILQ_FOREACH(se, &savevm_handlers, entry) {
if (se->save_live_state) {
se->save_live_state(mon, f, -1, se->opaque);
@@ -1732,6 +1783,7 @@ int qemu_loadvm_state(QEMUFile *f)
LoadStateEntry *le, *new_le;
uint8_t section_type;
unsigned int v;
+ uint64_t t_start;
int ret;
if (qemu_savevm_state_blocked(default_mon)) {
@@ -1750,12 +1802,17 @@ int qemu_loadvm_state(QEMUFile *f)
if (v != QEMU_VM_FILE_VERSION)
return -ENOTSUP;
+ time_measurement_type = TIME_MEASUREMENT_LOAD;
+ t_start = qemu_get_clock_ns(host_clock);
+
while ((section_type = qemu_get_byte(f)) != QEMU_VM_EOF) {
uint32_t instance_id, version_id, section_id;
+ uint64_t t_start_part;
SaveStateEntry *se;
char idstr[257];
int len;
+ t_start_part = qemu_get_clock_ns(host_clock);
switch (section_type) {
case QEMU_VM_SECTION_START:
case QEMU_VM_SECTION_FULL:
@@ -1797,6 +1854,12 @@ int qemu_loadvm_state(QEMUFile *f)
instance_id, idstr);
goto out;
}
+
+ if (section_type == QEMU_VM_SECTION_START)
+ TIME_ADD(load, part, 1, qemu_get_clock_ns(host_clock) - t_start_part);
+ else
+ TIME_ADD(load, part, 4, qemu_get_clock_ns(host_clock) - t_start_part);
+
break;
case QEMU_VM_SECTION_PART:
case QEMU_VM_SECTION_END:
@@ -1819,6 +1882,12 @@ int qemu_loadvm_state(QEMUFile *f)
section_id);
goto out;
}
+
+ if (section_type == QEMU_VM_SECTION_PART)
+ TIME_ADD(load, part, 2, qemu_get_clock_ns(host_clock) - t_start_part);
+ else
+ TIME_ADD(load, part, 3, qemu_get_clock_ns(host_clock) - t_start_part);
+
break;
default:
fprintf(stderr, "Unknown savevm section type %d\n", section_type);
@@ -1827,6 +1896,8 @@ int qemu_loadvm_state(QEMUFile *f)
}
}
+ time_load_measured = qemu_get_clock_ns(host_clock) - t_start;
+
cpu_synchronize_all_post_init();
ret = 0;
@@ -2177,3 +2248,152 @@ void do_info_snapshots(Monitor *mon)
qemu_free(available_snapshots);
}
+
+/* Monitor command implementation to get the load/save stage times */
+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;
+
+ if (!time_save_measured && !time_load_measured) {
+ monitor_printf(mon, "Cannot get result times when action is still running\n");
+ return;
+ }
+
+ qdict = qobject_to_qdict(data);
+
+ monitor_printf(mon, "Measured values type: %s\n",
+ qdict_get_str(qdict, "type"));
+
+ monitor_printf(mon, "Total transferred memory: %"PRIu64" kbytes\n",
+ qdict_get_int(qdict, "transferred-memory") >> 10);
+
+ monitor_printf(mon, "Total process time: %.6f s\n",
+ qdict_get_int(qdict, "total-time") / 1000000.);
+
+ if (time_measurement_type == TIME_MEASUREMENT_SAVE) {
+ 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);
+ }
+ }
+ else
+ if (time_measurement_type == TIME_MEASUREMENT_LOAD) {
+ monitor_printf(mon, "Load part 1: %.6f s\n",
+ qdict_get_int(qdict, "part1") / 1000000.);
+ monitor_printf(mon, "Load part 2: %.6f s\n",
+ qdict_get_int(qdict, "part2") / 1000000.);
+ monitor_printf(mon, "Load part 3: %.6f s\n",
+ qdict_get_int(qdict, "part3") / 1000000.);
+ monitor_printf(mon, "Load part 4: %.6f s\n",
+ qdict_get_int(qdict, "part4") / 1000000.);
+ }
+ else {
+ monitor_printf(mon, "Error: Invalid time measurement type 0x%02x\n", time_measurement_type);
+ }
+}
+
+static void migrate_times_put_status(QDict *qdict, const char *name)
+{
+ QObject *obj;
+ uint64_t t0 = 0;
+ uint64_t t1 = 0;
+ uint64_t t2 = 0;
+ uint64_t t3 = 0;
+
+ if (strcmp(name, "ram") == 0) {
+ t1 = TIME_GET(save, ram, 1) / 1000;
+ t2 = TIME_GET(save, ram, 2) / 1000;
+ t3 = TIME_GET(save, ram, 3) / 1000;
+ }
+ else
+ if (strcmp(name, "disk") == 0) {
+ t1 = TIME_GET(save, disk, 1) / 1000;
+ t2 = TIME_GET(save, disk, 2) / 1000;
+ t3 = TIME_GET(save, disk, 3) / 1000;
+ }
+ else
+ if (strcmp(name, "total") == 0) {
+ t1 = TIME_GET(save, total, 1) / 1000;
+ t2 = TIME_GET(save, total, 2) / 1000;
+ t3 = TIME_GET(save, total, 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;
+
+ if (time_measurement_type == TIME_MEASUREMENT_NONE) {
+ monitor_printf(mon, "No last operation has been found\n");
+ return;
+ }
+
+ qdict = qdict_new();
+ if (time_measurement_type == TIME_MEASUREMENT_SAVE) {
+ qdict_put(qdict, "type", qstring_from_str("save") );
+ qdict_put(qdict, "total-time", qint_from_int( time_save_measured / 1000 ) );
+ qdict_put(qdict, "wait-input", qint_from_int( TIME_GET(save, wait_input, 0) / 1000 ) );
+ qdict_put(qdict, "transferred-memory", qint_from_int( ram_bytes_transferred() ) );
+
+ migrate_times_put_status(qdict, "total");
+ if (TIME_GET(save, disk, 1) > 0)
+ migrate_times_put_status(qdict, "disk");
+ migrate_times_put_status(qdict, "ram");
+ }
+ else
+ if (time_measurement_type == TIME_MEASUREMENT_LOAD) {
+ qdict_put(qdict, "type", qstring_from_str("load") );
+ qdict_put(qdict, "total-time", qint_from_int( time_load_measured / 1000 ) );
+ qdict_put(qdict, "part1", qint_from_int( TIME_GET(load, part, 1) / 1000 ) );
+ qdict_put(qdict, "part2", qint_from_int( TIME_GET(load, part, 2) / 1000 ) );
+ qdict_put(qdict, "part3", qint_from_int( TIME_GET(load, part, 3) / 1000 ) );
+ qdict_put(qdict, "part4", qint_from_int( TIME_GET(load, part, 4) / 1000 ) );
+ qdict_put(qdict, "transferred-memory", qint_from_int( ram_bytes_transferred() ) );
+ }
+
+ *ret_data = QOBJECT(qdict);
+}
+