trace2:gvfs:experiment: read-cache: time read/write of cache-tree ext…

…ension

Add regions around code to read and write the cache-tree extension
when the index is read or written.

This is an experiment and may be dropped in future releases if
we don't need it anymore.

This experiment demonstrates that it takes more time to parse and
deserialize the cache-tree extension than it does to read the
cache-entries.

Commits [1] and [2] spreads cache-entry reading across N-1 cores
and dedicates a single core to simultaneously read the index extensions.

Local testing (on my machine) shows that reading the cache-tree extension
takes ~0.28 seconds.  The 11 cache-entry threads take ~0.08 seconds.
The main thread is blocked for 0.15 to 0.20 seconds waiting for the
extension thread to finish.

Let's use this commit to gather some telemetry and confirm this.

My point is that improvements, such as index V5 which makes the
cache entries smaller, may improve performance, but the gains may
be limited because of this extension.  And that we may need to
look inside the cache-tree extension to truly improve do_read_index()
performance.

[1] abb4bb8 read-cache: load cache extensions on a worker thread
[2] 77ff112 read-cache: load cache entries on worker threads

Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com>

read-cache.c

@@ -1767,7 +1767,10 @@ static int read_index_extension(struct index_state *istate,
 {
 	switch (CACHE_EXT(ext)) {
 	case CACHE_EXT_TREE:
+		trace2_region_enter("index", "read/extension/cache_tree", NULL);
 		istate->cache_tree = cache_tree_read(data, sz);
+		trace2_data_intmax("index", NULL, "read/extension/cache_tree/bytes", (intmax_t)sz);
+		trace2_region_leave("index", "read/extension/cache_tree", NULL);
 		break;
 	case CACHE_EXT_RESOLVE_UNDO:
 		istate->resolve_undo = resolve_undo_read(data, sz);
@@ -3049,9 +3052,13 @@ static int do_write_index(struct index_state *istate, struct tempfile *tempfile,
 	    !drop_cache_tree && istate->cache_tree) {
 		struct strbuf sb = STRBUF_INIT;
 
+		trace2_region_enter("index", "write/extension/cache_tree", NULL);
 		cache_tree_write(&sb, istate->cache_tree);
 		err = write_index_ext_header(f, eoie_c, CACHE_EXT_TREE, sb.len) < 0;
 		hashwrite(f, sb.buf, sb.len);
+		trace2_data_intmax("index", NULL, "write/extension/cache_tree/bytes", (intmax_t)sb.len);
+		trace2_region_leave("index", "write/extension/cache_tree", NULL);
+
 		strbuf_release(&sb);
 		if (err)
 			return -1;