stats: Dump-time statistics

Basic timings for dump (freeze, frozen, mem dump).
Signed-off-by: Pavel Emelyanov <xemul@parallels.com>

cr-dump.c

@@ -1047,6 +1047,8 @@ static int collect_pstree(pid_t pid, const struct cr_options *opts)
 {
 	int ret, attempts = 5;
 
+	timing_start(TIME_FREEZING);
+
 	while (1) {
 		root_item = alloc_pstree_item();
 		if (root_item == NULL)
@@ -1085,6 +1087,9 @@ try_again:
 		free_pstree(root_item);
 	}
 
+	timing_stop(TIME_FREEZING);
+	timing_start(TIME_FROZEN);
+
 	return collect_pstree_ids();
 }
 
@@ -1631,6 +1636,7 @@ err:
 		network_unlock();
 	pstree_switch_state(root_item,
 			ret ? TASK_ALIVE : opts->final_state);
+	timing_stop(TIME_FROZEN);
 	free_pstree(root_item);
 	free_file_locks();
 

include/stats.h

 #ifndef __CR_STATS_H__
 #define __CR_STATS_H__
 void show_stats(int fd);
+
+enum {
+	TIME_FREEZING,
+	TIME_FROZEN,
+	TIME_MEMDUMP,
+
+	TIME_NR_STATS,
+};
+
+void timing_start(int t);
+void timing_stop(int t);
+
 #define DUMP_STATS	1
 void write_stats(int what);
 

mem.c

@@ -11,6 +11,7 @@
 #include "page-xfer.h"
 #include "log.h"
 #include "kerndat.h"
+#include "stats.h"
 
 #include "protobuf.h"
 #include "protobuf/pagemap.pb-c.h"
@@ -301,6 +302,8 @@ static int __parasite_dump_pages_seized(struct parasite_ctl *ctl,
 	pr_info("Dumping pages (type: %d pid: %d)\n", CR_FD_PAGES, ctl->pid.real);
 	pr_info("----------------------------------------\n");
 
+	timing_start(TIME_MEMDUMP);
+
 	pr_debug("   Private vmas %lu/%lu pages\n",
 			vma_area_list->longest, vma_area_list->priv_size);
 
@@ -376,6 +379,8 @@ out_snap:
 	mem_snap_close(snap);
 out:
 	pr_info("----------------------------------------\n");
+	if (!ret)
+		timing_stop(TIME_MEMDUMP);
 	return ret;
 }
 

protobuf/stats.proto

 // This one contains statistics about dump/restore process
 message dump_stats_entry {
+	required uint32 freezing_time = 1;
+	required uint32 frozen_time = 2;
+	required uint32 memdump_time = 3;
 }
 
 message stats_entry {

stats.c

 #include <unistd.h>
+#include <sys/time.h>
 #include "protobuf.h"
 #include "stats.h"
 #include "crtools.h"
 #include "protobuf/stats.pb-c.h"
 
+struct timing {
+	struct timeval start;
+	struct timeval total;
+};
+
+static struct timing timings[TIME_NR_STATS];
+
+static void timeval_accumulate(const struct timeval *from, const struct timeval *to,
+		struct timeval *res)
+{
+	suseconds_t usec;
+
+	res->tv_sec += to->tv_sec - from->tv_sec;
+	usec = to->tv_usec;
+	if (usec < from->tv_usec) {
+		usec += USEC_PER_SEC;
+		res->tv_sec -= 1;
+	}
+	res->tv_usec += usec - from->tv_usec;
+	if (res->tv_usec > USEC_PER_SEC) {
+		res->tv_usec -= USEC_PER_SEC;
+		res->tv_sec += 1;
+	}
+}
+
+void timing_start(int t)
+{
+	BUG_ON(t >= TIME_NR_STATS);
+	gettimeofday(&timings[t].start, NULL);
+}
+
+void timing_stop(int t)
+{
+	struct timeval now;
+
+	gettimeofday(&now, NULL);
+	timeval_accumulate(&timings[t].start, &now, &timings[t].total);
+}
+
 void show_stats(int fd)
 {
-	pb_show_vertical(fd, PB_STATS);
+	do_pb_show_plain(fd, PB_STATS, 1, NULL, "1.1:%u 1.2:%u 1.3:%u");
+}
+
+static void encode_time(int t, u_int32_t *to)
+{
+	*to = timings[t].total.tv_sec * USEC_PER_SEC + timings[t].total.tv_usec;
 }
 
 void write_stats(int what)
@@ -19,6 +64,11 @@ void write_stats(int what)
 	pr_info("Writing stats\n");
 	if (what == DUMP_STATS) {
 		stats.dump = &dstats;
+
+		encode_time(TIME_FREEZING, &dstats.freezing_time);
+		encode_time(TIME_FROZEN, &dstats.frozen_time);
+		encode_time(TIME_MEMDUMP, &dstats.memdump_time);
+
 		name = "dump";
 	} else
 		return;