Re: [PATCH] trace: measure where the time is spent in the index-heavy operations

From: Thomas Gummerer <t.gummerer@gmail.com>
Date: Jan 27, 2018, 11:58 UTC
Message-ID: <20180127115811.GB2130@hank>
In-Reply-To: <20180127013956.21420-1-pclouds@gmail.com>

On 01/27, Nguyễn Thái Ngọc Duy wrote:

Show 74 quoted lines

> All the known heavy code blocks are measured (except object database
> access). This should help identify if an optimization is effective or
> not. An unoptimized git-status would give something like below (92% of
> time is accounted).
> 
> Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
> ---
>  This was in my old index-helper series. The series was replaced by
>  fsmonitor but perhaps some measurements like this still helps.
> 
>  In my old version I measured packed-refs read time too. But
>  packed-refs is mmap'd now, no need to worry about it (or at least its
>  initial cost).
> 
>  diff-lib.c      |  4 ++++
>  dir.c           |  2 ++
>  name-hash.c     |  3 +++
>  preload-index.c |  2 ++
>  read-cache.c    | 11 +++++++++++
>  5 files changed, 22 insertions(+)
>
> [...]
>  
> diff --git a/read-cache.c b/read-cache.c
> index 2eb81a66b9..1f00aee6a2 100644
> --- a/read-cache.c
> +++ b/read-cache.c
> @@ -1372,6 +1372,7 @@ int refresh_index(struct index_state *istate, unsigned int flags,
>  	const char *typechange_fmt;
>  	const char *added_fmt;
>  	const char *unmerged_fmt;
> +	uint64_t start = getnanotime();
>  
>  	modified_fmt = (in_porcelain ? "M\t%s\n" : "%s: needs update\n");
>  	deleted_fmt = (in_porcelain ? "D\t%s\n" : "%s: needs update\n");
> @@ -1442,6 +1443,7 @@ int refresh_index(struct index_state *istate, unsigned int flags,
>  
>  		replace_index_entry(istate, i, new);
>  	}
> +	trace_performance_since(start, "refresh index");
>  	return has_errors;
>  }
>  
> @@ -1877,12 +1879,15 @@ int read_index_from(struct index_state *istate, const char *path)
>  	int ret;
>  	char *base_sha1_hex;
>  	const char *base_path;
> +	uint64_t start;
>  
>  	/* istate->initialized covers both .git/index and .git/sharedindex.xxx */
>  	if (istate->initialized)
>  		return istate->cache_nr;
>  
> +	start = getnanotime();
>  	ret = do_read_index(istate, path, 0);
> +	trace_performance_since(start, "read cache %s", path);
>  
>  	split_index = istate->split_index;
>  	if (!split_index || is_null_sha1(split_index->base_sha1)) {
> @@ -1897,6 +1902,7 @@ int read_index_from(struct index_state *istate, const char *path)
>  
>  	base_sha1_hex = sha1_to_hex(split_index->base_sha1);
>  	base_path = git_path("sharedindex.%s", base_sha1_hex);
> +	start = getnanotime();
>  	ret = do_read_index(split_index->base, base_path, 1);
>  	if (hashcmp(split_index->base_sha1, split_index->base->sha1))
>  		die("broken index, expect %s in %s, got %s",
> @@ -1906,6 +1912,9 @@ int read_index_from(struct index_state *istate, const char *path)
>  	freshen_shared_index(base_sha1_hex, 0);
>  	merge_base_index(istate);
>  	post_read_index_from(istate);
> +	trace_performance_since(start, "read cache %s",
> +				git_path("sharedindex.%s",
> +					 sha1_to_hex(split_index->base_sha1)));

Would it be worth doing this on top of tg/split-index-fixes? OTOH this will only give a wrong output when tracing performance is on, and it should be easy enough to figure out where the sharedindex actually is. So it might be better to keep this separate, and then just add a patch on top for fixing the path later, which might be less work for Junio.

So dunno what the best way is, just wanted to mention it.

Show 22 quoted lines

>  	return ret;
>  }
>  
> @@ -2244,6 +2253,7 @@ static int do_write_index(struct index_state *istate, struct tempfile *tempfile,
>  	struct ondisk_cache_entry_extended ondisk;
>  	struct strbuf previous_name_buf = STRBUF_INIT, *previous_name;
>  	int drop_cache_tree = 0;
> +	uint64_t start = getnanotime();
>  
>  	for (i = removed = extended = 0; i < entries; i++) {
>  		if (cache[i]->ce_flags & CE_REMOVE)
> @@ -2374,6 +2384,7 @@ static int do_write_index(struct index_state *istate, struct tempfile *tempfile,
>  		return -1;
>  	istate->timestamp.sec = (unsigned int)st.st_mtime;
>  	istate->timestamp.nsec = ST_MTIME_NSEC(st);
> +	trace_performance_since(start, "write index, changed mask = %x", istate->cache_changed);
>  	return 0;
>  }
>  
> -- 
> 2.16.1.205.g271f633410
>