stats: Add irmap resolve time

It's useful to know this value.

W/o cache (first pre-dump) on minimal container the irmap
resolve time is ~0.2 sec. With cache (next pre-dumps or
final dump) on the same container the irmap resolve time
is 10 times less.
Signed-off-by: Pavel Emelyanov <xemul@parallels.com>

cr-show.c

@@ -323,7 +323,7 @@ static struct show_image_info show_infos[] = {
 	SHOW_PLAIN(IRMAP_CACHE),
 
 	{ TCP_STREAM_MAGIC,	PB_TCP_STREAM,		true,	show_tcp_stream, "1:%u 2:%u 3:%u 4:%u 12:%u", },
-	{ STATS_MAGIC,		PB_STATS,		true,	NULL, "1.1:%u 1.2:%u 1.3:%u 1.4:%u 1.5:%Lu 1.6:%Lu 1.7:%Lu", },
+	{ STATS_MAGIC,		PB_STATS,		true,	NULL, "1.1:%u 1.2:%u 1.3:%u 1.4:%u 1.5:%Lu 1.6:%Lu 1.7:%Lu 1.8:%u", },
 	{ FDINFO_MAGIC,		PB_FDINFO,		false,	NULL, "flags:%#o fd:%d", },
 	{ UNIXSK_MAGIC,		PB_UNIX_SK,		false,	NULL, "1:%#x 2:%#x 3:%d 4:%d 5:%d 6:%d 7:%d 8:%#x 11:S", },
 	{ INETSK_MAGIC,		PB_INET_SK,		false,	NULL, "1:%#x 2:%#x 3:%d 4:%d 5:%d 6:%d 7:%d 8:%d 9:%2x 11:A 12:A", },

include/stats.h

@@ -6,6 +6,7 @@ enum {
 	TIME_FROZEN,
 	TIME_MEMDUMP,
 	TIME_MEMWRITE,
+	TIME_IRMAP_RESOLVE,
 
 	DUMP_TIME_NR_STATS,
 };

irmap.c

@@ -22,6 +22,7 @@
 #include "log.h"
 #include "util.h"
 #include "image.h"
+#include "stats.h"
 
 #include "protobuf.h"
 #include "protobuf/fsnotify.pb-c.h"
@@ -213,6 +214,8 @@ char *irmap_lookup(unsigned int s_dev, unsigned long i_ino)
 
 	pr_debug("Resolving %x:%lx path\n", s_dev, i_ino);
 
+	timing_start(TIME_IRMAP_RESOLVE);
+
 	hv = irmap_hashfn(s_dev, i_ino);
 	for (p = &cache[hv]; *p; p = &(*p)->next) {
 		c = *p;
@@ -238,6 +241,7 @@ char *irmap_lookup(unsigned int s_dev, unsigned long i_ino)
 	}
 
 out:
+	timing_stop(TIME_IRMAP_RESOLVE);
 	return path;
 }
 

protobuf/stats.proto

@@ -8,6 +8,8 @@ message dump_stats_entry {
 	required uint64	pages_scanned = 5;
 	required uint64	pages_skipped_parent = 6;
 	required uint64	pages_written = 7;
+
+	optional uint32	irmap_resolve = 8;
 }
 
 message restore_stats_entry {

stats.c

@@ -115,6 +115,8 @@ void write_stats(int what)
 		encode_time(TIME_FROZEN, &ds_entry.frozen_time);
 		encode_time(TIME_MEMDUMP, &ds_entry.memdump_time);
 		encode_time(TIME_MEMWRITE, &ds_entry.memwrite_time);
+		ds_entry.has_irmap_resolve = true;
+		encode_time(TIME_IRMAP_RESOLVE, &ds_entry.irmap_resolve);
 
 		ds_entry.pages_scanned = dstats->counts[CNT_PAGES_SCANNED];
 		ds_entry.pages_skipped_parent = dstats->counts[CNT_PAGES_SKIPPED_PARENT];