[CRIU] [PATCH 7/7] stats: Add irmap resolve time

[Pavel Emelyanov]

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 at parallels.com>
---
 cr-show.c            | 2 +-
 include/stats.h      | 1 +
 irmap.c              | 4 ++++
 protobuf/stats.proto | 2 ++
 stats.c              | 2 ++
 5 files changed, 10 insertions(+), 1 deletion(-)

diff --git a/cr-show.c b/cr-show.c
index 87aa6b6..8f808bc 100644
--- a/cr-show.c
+++ b/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", },
diff --git a/include/stats.h b/include/stats.h
index aa25050..ce33e88 100644
--- a/include/stats.h
+++ b/include/stats.h
@@ -6,6 +6,7 @@ enum {
 	TIME_FROZEN,
 	TIME_MEMDUMP,
 	TIME_MEMWRITE,
+	TIME_IRMAP_RESOLVE,
 
 	DUMP_TIME_NR_STATS,
 };
diff --git a/irmap.c b/irmap.c
index 367e082..dc37e07 100644
--- a/irmap.c
+++ b/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;
 }
 
diff --git a/protobuf/stats.proto b/protobuf/stats.proto
index 78d3285..38301a1 100644
--- a/protobuf/stats.proto
+++ b/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 {
diff --git a/stats.c b/stats.c
index 8af9942..6cbb54f 100644
--- a/stats.c
+++ b/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];
-- 
1.8.4.2