[CRIU] [PATCH] Added option to display dump/restore stats

[Adrian Reber]

From: Adrian Reber <areber at redhat.com>

Currently criu writes dump/restore statistics to a file. This patch adds
the option '--display-stats' which additionally displays the same
information on the console:

 # criu dump --display-stats -D /tmp/cp -t <PID>
 Displaying dump stats:
 Freezing time: 133 us
 Frozen time: 135173 us
 Memory dump time: 114760 us
 Memory write time: 85107 us
 IRMAP resolve time: 0 us
 Memory pages scanned: 2099 (0x833)
 Memory pages skipped from parent: 0 (0x0)
 Memory pages written: 1052 (0x41c)
 Zero memory pages: 0 (0x0)
 Lazy memory pages: 0 (0x0)

 # criu restore --display-stats -D /tmp/cp
 Displaying restore stats:
 Pages compared: 0 (0x0)
 Pages skipped COW: 0 (0x0)
 Pages restored: 51227 (0xc81b)
 Restore time: 57428 us
 Forking time: 51473 us

Signed-off-by: Adrian Reber <areber at redhat.com>
---
 criu/crtools.c            |  5 +++++
 criu/include/cr_options.h |  1 +
 criu/stats.c              | 40 ++++++++++++++++++++++++++++++++++++++++
 3 files changed, 46 insertions(+)

diff --git a/criu/crtools.c b/criu/crtools.c
index 0e853ee..8b5ec5d 100644
--- a/criu/crtools.c
+++ b/criu/crtools.c
@@ -279,6 +279,7 @@ int main(int argc, char *argv[], char *envp[])
 		{ "cgroup-dump-controller",	required_argument,	0, 1082	},
 		{ SK_INFLIGHT_PARAM,		no_argument,		0, 1083	},
 		{ "deprecated",			no_argument,		0, 1084 },
+		{ "display-stats",		no_argument,		0, 1086 },
 		{ },
 	};
 
@@ -594,6 +595,9 @@ int main(int argc, char *argv[], char *envp[])
 			pr_msg("Turn deprecated stuff ON\n");
 			opts.deprecated_ok = true;
 			break;
+		case 1086:
+			opts.display_stats = true;
+			break;
 		case 'V':
 			pr_msg("Version: %s\n", CRIU_VERSION);
 			if (strcmp(CRIU_GITID, "0"))
@@ -919,6 +923,7 @@ usage:
 "                          -v2|-vv   - also warnings (default level)\n"
 "                          -v3|-vvv  - also information messages and timestamps\n"
 "                          -v4|-vvvv - lots of debug\n"
+"  --display-stats       print out dump/restore stats\n"
 "\n"
 "* Memory dumping options:\n"
 "  --track-mem           turn on memory changes tracker in kernel\n"
diff --git a/criu/include/cr_options.h b/criu/include/cr_options.h
index 8a9427b..521a896 100644
--- a/criu/include/cr_options.h
+++ b/criu/include/cr_options.h
@@ -114,6 +114,7 @@ struct cr_options {
 	 * to turn one ON while the code is in.
 	 */
 	bool			deprecated_ok;
+	bool			display_stats;
 };
 
 extern struct cr_options opts;
diff --git a/criu/stats.c b/criu/stats.c
index a575e77..6c52a9e 100644
--- a/criu/stats.c
+++ b/criu/stats.c
@@ -2,6 +2,7 @@
 #include <fcntl.h>
 #include <sys/time.h>
 #include "asm/atomic.h"
+#include "cr_options.h"
 #include "rst-malloc.h"
 #include "protobuf.h"
 #include "stats.h"
@@ -100,6 +101,42 @@ static void encode_time(int t, u_int32_t *to)
 	*to = tm->total.tv_sec * USEC_PER_SEC + tm->total.tv_usec;
 }
 
+static void display_stats(int what, StatsEntry *stats)
+{
+	if (what == DUMP_STATS) {
+		pr_msg("Displaying dump stats:\n");
+		pr_msg("Freezing time: %d us\n", stats->dump->freezing_time);
+		pr_msg("Frozen time: %d us\n", stats->dump->frozen_time);
+		pr_msg("Memory dump time: %d us\n", stats->dump->memdump_time);
+		pr_msg("Memory write time: %d us\n", stats->dump->memwrite_time);
+		if (stats->dump->has_irmap_resolve)
+			pr_msg("IRMAP resolve time: %d us\n", stats->dump->irmap_resolve);
+		pr_msg("Memory pages scanned: %ld (0x%lx)\n", stats->dump->pages_scanned,
+				stats->dump->pages_scanned);
+		pr_msg("Memory pages skipped from parent: %ld (0x%lx)\n",
+				stats->dump->pages_skipped_parent,
+				stats->dump->pages_skipped_parent);
+		pr_msg("Memory pages written: %ld (0x%lx)\n", stats->dump->pages_written,
+				stats->dump->pages_written);
+		pr_msg("Zero memory pages: %ld (0x%lx)\n", stats->dump->pages_zero,
+				stats->dump->pages_zero);
+		pr_msg("Lazy memory pages: %ld (0x%lx)\n", stats->dump->pages_lazy,
+				stats->dump->pages_lazy);
+	} else if (what == RESTORE_STATS) {
+		pr_msg("Displaying restore stats:\n");
+		pr_msg("Pages compared: %ld (0x%lx)\n", stats->restore->pages_compared,
+				stats->restore->pages_compared);
+		pr_msg("Pages skipped COW: %ld (0x%lx)\n", stats->restore->pages_skipped_cow,
+				stats->restore->pages_skipped_cow);
+		if (stats->restore->has_pages_restored)
+			pr_msg("Pages restored: %ld (0x%lx)\n", stats->restore->pages_restored,
+					stats->restore->pages_restored);
+		pr_msg("Restore time: %d us\n", stats->restore->restore_time);
+		pr_msg("Forking time: %d us\n", stats->restore->forking_time);
+	} else
+		return;
+}
+
 void write_stats(int what)
 {
 	StatsEntry stats = STATS_ENTRY__INIT;
@@ -146,6 +183,9 @@ void write_stats(int what)
 		pb_write_one(img, &stats, PB_STATS);
 		close_image(img);
 	}
+
+	if (opts.display_stats)
+		display_stats(what, &stats);
 }
 
 int init_stats(int what)
-- 
2.9.3