git/list[1] front-page[2] threads[3] people[4] search[5] about
 

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

From
Nguyễn Thái Ngọc Duy <pclouds@gmail.com>
Date
Jan 27, 2018, 01:39 UTC
Message-ID
<20180127013956.21420-1-pclouds@gmail.com>
In-Reply-To
<CACsJy8BpO0s6facg+zcKC9icijpefkipM326n6xOArjn=ZW6+w@mail.gmail.com>

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/diff-lib.c b/diff-lib.c
index 8104603a3b..a228e1a219 100644
--- a/diff-lib.c
+++ b/diff-lib.c
@@ -92,6 +92,7 @@ int run_diff_files(struct rev_info *revs, unsigned int option)
 	int diff_unmerged_stage = revs->max_count;
 	unsigned ce_option = ((option & DIFF_RACY_IS_MODIFIED)
 			      ? CE_MATCH_RACY_IS_DIRTY : 0);
+	uint64_t start = getnanotime();
 
 	diff_set_mnemonic_prefix(&revs->diffopt, "i/", "w/");
 
@@ -246,6 +247,7 @@ int run_diff_files(struct rev_info *revs, unsigned int option)
 	}
 	diffcore_std(&revs->diffopt);
 	diff_flush(&revs->diffopt);
+	trace_performance_since(start, "diff-files");
 	return 0;
 }
 
@@ -512,6 +514,7 @@ static int diff_cache(struct rev_info *revs,
 int run_diff_index(struct rev_info *revs, int cached)
 {
 	struct object_array_entry *ent;
+	uint64_t start = getnanotime();
 
 	ent = revs->pending.objects;
 	if (diff_cache(revs, &ent->item->oid, ent->name, cached))
@@ -521,6 +524,7 @@ int run_diff_index(struct rev_info *revs, int cached)
 	diffcore_fix_diff_index(&revs->diffopt);
 	diffcore_std(&revs->diffopt);
 	diff_flush(&revs->diffopt);
+	trace_performance_since(start, "diff-index");
 	return 0;
 }
 
diff --git a/dir.c b/dir.c
index 7c4b45e30e..4479a02a49 100644
--- a/dir.c
+++ b/dir.c
@@ -2248,6 +2248,7 @@ int read_directory(struct dir_struct *dir, struct index_state *istate,
 		   const char *path, int len, const struct pathspec *pathspec)
 {
 	struct untracked_cache_dir *untracked;
+	uint64_t start = getnanotime();
 
 	if (has_symlink_leading_path(path, len))
 		return dir->nr;
@@ -2286,6 +2287,7 @@ int read_directory(struct dir_struct *dir, struct index_state *istate,
 		dir->nr = i;
 	}
 
+	trace_performance_since(start, "read directory %.*s", len, path);
 	if (dir->untracked) {
 		static struct trace_key trace_untracked_stats = TRACE_KEY_INIT(UNTRACKED_STATS);
 		trace_printf_key(&trace_untracked_stats,
diff --git a/name-hash.c b/name-hash.c
index 45c98db0a0..ada66f066a 100644
--- a/name-hash.c
+++ b/name-hash.c
@@ -578,6 +578,8 @@ static void threaded_lazy_init_name_hash(
 
 static void lazy_init_name_hash(struct index_state *istate)
 {
+	uint64_t start = getnanotime();
+
 	if (istate->name_hash_initialized)
 		return;
 	hashmap_init(&istate->name_hash, cache_entry_cmp, NULL, istate->cache_nr);
@@ -600,6 +602,7 @@ static void lazy_init_name_hash(struct index_state *istate)
 	}
 
 	istate->name_hash_initialized = 1;
+	trace_performance_since(start, "initialize name hash");
 }
 
 /*
diff --git a/preload-index.c b/preload-index.c
index 2a83255e4e..4d08d44874 100644
--- a/preload-index.c
+++ b/preload-index.c
@@ -78,6 +78,7 @@ static void preload_index(struct index_state *index,
 {
 	int threads, i, work, offset;
 	struct thread_data data[MAX_PARALLEL];
+	uint64_t start = getnanotime();
 
 	if (!core_preload_index)
 		return;
@@ -108,6 +109,7 @@ static void preload_index(struct index_state *index,
 		if (pthread_join(p->pthread, NULL))
 			die("unable to join threaded lstat");
 	}
+	trace_performance_since(start, "preload index");
 }
 #endif
 
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)));
 	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
Previous: Duy NguyenNext: Thomas Gummerer
Message 3 of 30 in “Some rough edges of core.fsmonitor”
  1. Ævar Arnfjörð BjarmasonJan 27, 2018
  2. Duy NguyenJan 27, 2018
  3. trace: measure where the time is spent in the index-heavy operationsNguyễn Thái Ngọc Duy, Jan 27, 2018
  4. Thomas GummererJan 27, 2018
  5. trace: measure where the time is spent in the index-heavy operationsNguyễn Thái Ngọc Duy, Jan 27, 2018
  6. Ævar Arnfjörð BjarmasonJan 27, 2018
  7. Duy NguyenJan 27, 2018
  8. Duy NguyenJan 27, 2018
  9. Ævar Arnfjörð BjarmasonJan 27, 2018
  10. Ben PeartJan 30, 2018
  11. Duy NguyenJan 29, 2018
  12. Ben PeartJan 29, 2018
  13. Duy NguyenFeb 1, 2018
  14. Johannes SchindelinJan 28, 2018
  15. Ævar Arnfjörð BjarmasonJan 28, 2018
  16. Ben PeartJan 30, 2018
  17. Duy NguyenJan 31, 2018
  18. dir.c: ignore paths containing .git when invalidating untracked cacheNguyễn Thái Ngọc Duy, Feb 4, 2018
  19. Ben PeartFeb 5, 2018
  20. Duy NguyenFeb 6, 2018
  21. dir.c: ignore paths containing .git when invalidating untracked cacheNguyễn Thái Ngọc Duy, Feb 7, 2018
  22. dir.c: ignore paths containing .git when invalidating untracked cacheNguyễn Thái Ngọc Duy, Feb 7, 2018
  23. Ben PeartFeb 7, 2018
  24. Duy NguyenFeb 13, 2018
  25. Junio C HamanoFeb 13, 2018
  26. Duy NguyenFeb 14, 2018
  27. Junio C HamanoFeb 14, 2018
  28. Ben PeartJan 30, 2018
  29. Ævar Arnfjörð BjarmasonJan 30, 2018
  30. Ben PeartJan 31, 2018

Read the whole thread, see it on lore, or plain text.

$ cat FOOTERMessages come from the public archive at lore.kernel.org/git, fetched every hour. The front page is chosen and written each morning by an AI editor and can be wrong; the threads themselves are the record. About and API. For agents: an MCP server at https://gitlist.dev/mcp, and any thread, story or person page as Markdown by adding .md to its URL (or sending Accept: text/markdown). Details in /llms.txt.