[PATCH v2 4/5] bitmap: add trace2 outputs during open "bitmap" file

[Teng Long <dyroneteng@gmail.com>]

It's supported for a Git repo to use bitmap in both normal bitmap way
or a multi-pack-index bitmap.

Sometimes the debug path is not obvious, for example, when executing:

 $git rev-list  --test-bitmap  HEAD
 fatal: failed to load bitmap indexes

If we see the output like this, we are not sure about what's happened,
because the cause should be :

  1. neither normal nor midx bitmap exists
  2. only midx bitmap exists but core.multipackIndex="false"
  3. core.multipackIndex="true" but midx bitmap file is currupt
  4. core.multipackIndex="true" and no midx bitmap exists but
     normal bitmap file is currupt
  ....

These are some of the scenarios I briefly tested, but maybe there are
others (some scenarios is produced manually like "currupt bitmap file",
but it's not represent it's an existed bug.).

Therefore, we added some TRACE2 code so that when we read the bitmap
we can be more clear about the decision path, such as whether it is
working on midx bitmap or normal bitmap, or is it simply because the
related configuration is disabled. This may help with logging, user
troubleshooting, and development debugging.

Here are some output examples when executing
"$GIT_TRACE2_PERF=1 git rev-list --test-bitmap HEAD" under different
situations:

1. _HAVE_ MIDX bitmap and NORMAL bitmap file, but the
"core.multipackIndex" configures as "false":

  19:38:43.007840 common-main.c:49             | d0 | main                     | version      |     |           |           |              | 2.35.1.582.g8e9092487a
  19:38:43.007874 common-main.c:50             | d0 | main                     | start        |     |  0.000305 |           |              | /opt/git/master/bin/git rev-list --test-bitmap HEAD
  19:38:43.007950 compat/linux/procinfo.c:170  | d0 | main                     | cmd_ancestry |     |           |           |              | ancestry:[bash sshd sshd sshd systemd]
  19:38:43.008091 git.c:460                    | d0 | main                     | cmd_name     |     |           |           |              | rev-list (rev-list)
  19:38:43.008284 repo-settings.c:11           | d0 | main                     | data         | r0  |  0.000720 |  0.000720 | config       | feature.manyfiles:false
  19:38:43.008297 repo-settings.c:11           | d0 | main                     | data         | r0  |  0.000734 |  0.000734 | config       | feature.experimental:false
  19:38:43.008305 repo-settings.c:11           | d0 | main                     | data         | r0  |  0.000742 |  0.000742 | config       | core.commitgraph:true
  19:38:43.008313 repo-settings.c:11           | d0 | main                     | data         | r0  |  0.000749 |  0.000749 | config       | commitgraph.readchangedpaths:true
  19:38:43.008320 repo-settings.c:11           | d0 | main                     | data         | r0  |  0.000756 |  0.000756 | config       | gc.writecommitgraph:true
  19:38:43.008327 repo-settings.c:11           | d0 | main                     | data         | r0  |  0.000764 |  0.000764 | config       | fetch.writecommitgraph:false
  19:38:43.008334 repo-settings.c:11           | d0 | main                     | data         | r0  |  0.000770 |  0.000770 | config       | pack.usesparse:true
  19:38:43.008341 repo-settings.c:11           | d0 | main                     | data         | r0  |  0.000777 |  0.000777 | config       | core.multipackindex:false
  19:38:43.008348 repo-settings.c:11           | d0 | main                     | data         | r0  |  0.000784 |  0.000784 | config       | index.sparse:false
  19:38:43.008724 pack-bitmap.c:536            | d0 | main                     | region_enter | r0  |  0.001160 |           | pack-bitmap  | label:open_bitmap
  19:38:43.008738 pack-bitmap.c:390            | d0 | main                     | data         | r0  |  0.001173 |  0.000013 | bitmap       | ..try to open bitmap:/home/tenglong.tl/test/dyrone/.git/objects/pack/pack-2d1b3f749fb859b874710e33263d0847ef009e03.bitmap
  19:38:43.008754 pack-bitmap.c:543            | d0 | main                     | region_leave | r0  |  0.001191 |  0.000031 | pack-bitmap  | label:open_bitmap
  Bitmap v1 test (8 entries loaded)
  Found bitmap for 0a7df7ae92f8d8ed879c240f8ae9cdd33d18085e. 64 bits / 1801edc6 checksum
  19:38:43.009099 progress.c:268               | d0 | main                     | region_enter | r0  |  0.001535 |           | progress     | label:Verifying bitmap entries
  Verifying bitmap entries: 100% (27/27), done.
  19:38:43.009294 progress.c:339               | d0 | main                     | data         | r0  |  0.001730 |  0.000195 | progress     | ..total_objects:27
  19:38:43.009302 progress.c:346               | d0 | main                     | region_leave | r0  |  0.001739 |  0.000204 | progress     | label:Verifying bitmap entries
  OK!
  19:38:43.009321 git.c:718                    | d0 | main                     | exit         |     |  0.001757 |           |              | code:0
  19:38:43.009329 trace2/tr2_tgt_perf.c:215    | d0 | main                     | atexit       |     |  0.001766 |           |              | code:0

2. _HAVE_ MIDX bitmap and NORMAL bitmap file, but the
"core.multipackIndex" configures as "true":

  (omit duplicate outputs)
  ...
  20:02:31.288797 repo-settings.c:11           | d0 | main                     | data         | r0  |  0.000811 |  0.000811 | config       | core.multipackindex:true
  20:02:31.288806 repo-settings.c:11           | d0 | main                     | data         | r0  |  0.000819 |  0.000819 | config       | index.sparse:false
  20:02:31.288836 midx.c:185                   | d0 | main                     | data         | r0  |  0.000849 |  0.000849 | midx         | load/num_packs:1
  20:02:31.288843 midx.c:186                   | d0 | main                     | data         | r0  |  0.000857 |  0.000857 | midx         | load/num_objects:27
  20:02:31.289217 pack-bitmap.c:536            | d0 | main                     | region_enter | r0  |  0.001229 |           | pack-bitmap  | label:open_bitmap
  20:02:31.289230 pack-bitmap.c:318            | d0 | main                     | data         | r0  |  0.001242 |  0.000013 | midx         | ..try to open bitmap:/home/tenglong.tl/test/dyrone/.git/objects/pack/multi-pack-index-b6b04fbe053bd500d9ca13354466d3249dc275ac.bitmap
  20:02:31.289252 pack-revindex.c:315          | d0 | main                     | data         | r0  |  0.001265 |  0.000036 | load_midx_re | ..source:midx
  20:02:31.289261 pack-bitmap.c:543            | d0 | main                     | region_leave | r0  |  0.001274 |  0.000045 | pack-bitmap  | label:open_bitmap
  Bitmap v1 test (8 entries loaded)
  Found bitmap for 0a7df7ae92f8d8ed879c240f8ae9cdd33d18085e. 64 bits / 1801edc6 checksum
  20:02:31.289594 progress.c:268               | d0 | main                     | region_enter | r0  |  0.001607 |           | progress     | label:Verifying bitmap entries
  Verifying bitmap entries: 100% (27/27), done.
  20:02:31.289810 progress.c:339               | d0 | main                     | data         | r0  |  0.001823 |  0.000216 | progress     | ..total_objects:27
  20:02:31.289824 progress.c:346               | d0 | main                     | region_leave | r0  |  0.001837 |  0.000230 | progress     | label:Verifying bitmap entries
  OK!
  20:02:31.289843 git.c:718                    | d0 | main                     | exit         |     |  0.001856 |           |              | code:0
  20:02:31.289860 trace2/tr2_tgt_perf.c:215    | d0 | main                     | atexit       |     |  0.001873 |           |              | code:0

3. _HAVE_ MIDX bitmap and a corrupt NORMAL bitmap file, but the
"core.multipackIndex" configures as "false" :

  (omit duplicate outputs)
  ...
  20:14:06.539305 repo-settings.c:11           | d0 | main                     | data         | r0  |  0.000794 |  0.000794 | config       | core.multipackindex:false
  20:14:06.539310 repo-settings.c:11           | d0 | main                     | data         | r0  |  0.000799 |  0.000799 | config       | index.sparse:false
  20:14:06.539658 pack-bitmap.c:536            | d0 | main                     | region_enter | r0  |  0.001146 |           | pack-bitmap  | label:open_bitmap
  20:14:06.539671 pack-bitmap.c:390            | d0 | main                     | data         | r0  |  0.001160 |  0.000014 | bitmap       | ..try to open bitmap:/home/tenglong.tl/test/dyrone/.git/objects/pack/pack-2d1b3f749fb859b874710e33263d0847ef009e03.bitmap
  20:14:06.539686 usage.c:79                   | d0 | main                     | error        |     |           |           |              | ..Corrupted bitmap index file (wrong header)
  error: Corrupted bitmap index file (wrong header)
  20:14:06.539696 pack-bitmap.c:426            | d0 | main                     | data         | r0  |  0.001185 |  0.000039 | bitmap       | ..load bitmap header:failed
  20:14:06.539709 usage.c:79                   | d0 | main                     | error        |     |           |           |              | ..bitmap header is invalid
  error: bitmap header is invalid
  20:14:06.539719 pack-bitmap.c:543            | d0 | main                     | region_leave | r0  |  0.001208 |  0.000062 | pack-bitmap  | label:open_bitmap
  20:14:06.539726 usage.c:60                   | d0 | main                     | error        |     |           |           |              | failed to load bitmap indexes
  fatal: failed to load bitmap indexes
  20:14:06.539735 usage.c:74                   | d0 | main                     | exit         |     |  0.001224 |           |              | code:128
  20:14:06.539744 trace2/tr2_tgt_perf.c:215    | d0 | main                     | atexit       |     |  0.001233 |           |              | code:128

Signed-off-by: Teng Long <dyroneteng@gmail.com>
---
 pack-bitmap.c           | 40 +++++++++++++++++++++++++++++++++-------
 repo-settings.c         |  1 +
 t/t5310-pack-bitmaps.sh |  4 ++--
 3 files changed, 36 insertions(+), 9 deletions(-)

diff --git a/pack-bitmap.c b/pack-bitmap.c
index 1b268f655e..a1d06c4252 100644
--- a/pack-bitmap.c
+++ b/pack-bitmap.c
@@ -312,9 +312,12 @@ char *pack_bitmap_filename(struct packed_git *p)
 static int open_midx_bitmap_1(struct bitmap_index *bitmap_git,
 			      struct multi_pack_index *midx)
 {
+	int fd;
 	struct stat st;
 	char *bitmap_name = midx_bitmap_filename(midx);
-	int fd = git_open(bitmap_name);
+	trace2_data_string("midx", the_repository, "try to open bitmap",
+			   bitmap_name);
+	fd = git_open(bitmap_name);
 
 	free(bitmap_name);
 
@@ -322,6 +325,8 @@ static int open_midx_bitmap_1(struct bitmap_index *bitmap_git,
 		return -1;
 
 	if (fstat(fd, &st)) {
+		trace2_data_string("midx", the_repository, "stat bitmap file",
+				   "failed");
 		close(fd);
 		return -1;
 	}
@@ -344,12 +349,19 @@ static int open_midx_bitmap_1(struct bitmap_index *bitmap_git,
 				MAP_PRIVATE, fd, 0);
 	close(fd);
 
-	if (load_bitmap_header(bitmap_git) < 0)
+	if (load_bitmap_header(bitmap_git) < 0) {
+		trace2_data_string("midx", the_repository, "load bitmap header",
+				   "failed");
 		goto cleanup;
+	}
 
-	if (!hasheq(get_midx_checksum(bitmap_git->midx), bitmap_git->checksum))
+	if (!hasheq(get_midx_checksum(bitmap_git->midx), bitmap_git->checksum)) {
+		trace2_data_string("midx", the_repository, "verify checksum",
+				   "mismatch");
 		goto cleanup;
 
+	}
+
 	if (load_midx_revindex(bitmap_git->midx) < 0) {
 		warning(_("multi-pack bitmap is missing required reverse index"));
 		goto cleanup;
@@ -375,6 +387,8 @@ static int open_pack_bitmap_1(struct bitmap_index *bitmap_git, struct packed_git
 		return -1;
 
 	bitmap_name = pack_bitmap_filename(packfile);
+	trace2_data_string("bitmap", the_repository, "try to open bitmap",
+			   bitmap_name);
 	fd = git_open(bitmap_name);
 	free(bitmap_name);
 
@@ -382,6 +396,8 @@ static int open_pack_bitmap_1(struct bitmap_index *bitmap_git, struct packed_git
 		return -1;
 
 	if (fstat(fd, &st)) {
+		trace2_data_string("bitmap", the_repository, "stat bitmap file",
+				   "failed");
 		close(fd);
 		return -1;
 	}
@@ -395,6 +411,7 @@ static int open_pack_bitmap_1(struct bitmap_index *bitmap_git, struct packed_git
 	}
 
 	if (!is_pack_valid(packfile)) {
+		trace2_data_string("bitmap", the_repository, "packfile", "invalid");
 		close(fd);
 		return -1;
 	}
@@ -406,6 +423,8 @@ static int open_pack_bitmap_1(struct bitmap_index *bitmap_git, struct packed_git
 	close(fd);
 
 	if (load_bitmap_header(bitmap_git) < 0) {
+		trace2_data_string("bitmap", the_repository,
+				   "load bitmap header", "failed");
 		munmap(bitmap_git->map, bitmap_git->map_size);
 		bitmap_git->map = NULL;
 		bitmap_git->map_size = 0;
@@ -511,11 +530,18 @@ static int open_midx_bitmap(struct repository *r,
 static int open_bitmap(struct repository *r,
 		       struct bitmap_index *bitmap_git)
 {
-	assert(!bitmap_git->map);
+	int ret = -1;
 
-	if (!open_midx_bitmap(r, bitmap_git))
-		return 0;
-	return open_pack_bitmap(r, bitmap_git);
+	assert(!bitmap_git->map);
+	trace2_region_enter("pack-bitmap", "open_bitmap", r);
+	if (!open_midx_bitmap(r, bitmap_git)) {
+		ret = 0;
+		goto done;
+	}
+	ret = open_pack_bitmap(r, bitmap_git);
+done:
+	trace2_region_leave("pack-bitmap", "open_bitmap", r);
+	return ret;
 }
 
 struct bitmap_index *prepare_bitmap_git(struct repository *r)
diff --git a/repo-settings.c b/repo-settings.c
index b4fbd16cdc..5bc7a97a6d 100644
--- a/repo-settings.c
+++ b/repo-settings.c
@@ -8,6 +8,7 @@ static void repo_cfg_bool(struct repository *r, const char *key, int *dest,
 {
 	if (repo_config_get_bool(r, key, dest))
 		*dest = def;
+	trace2_data_string("config", r, key, *dest ? "true" : "false");
 }
 
 void prepare_repo_settings(struct repository *r)
diff --git a/t/t5310-pack-bitmaps.sh b/t/t5310-pack-bitmaps.sh
index eb63b71852..664cb88b0b 100755
--- a/t/t5310-pack-bitmaps.sh
+++ b/t/t5310-pack-bitmaps.sh
@@ -421,8 +421,8 @@ test_expect_success 'complains about multiple pack bitmaps' '
 		test_line_count = 2 bitmaps &&
 
 		git rev-list --use-bitmap-index HEAD 2>err &&
-		grep "a bitmap has been opened" err &&
-		grep "ignoring extra bitmap file" err
+		grep "warning: a normal or midx bitmap already has been opened" err &&
+		grep "warning: ignoring extra bitmap file" err
 	)
 '
 
-- 
2.35.1.583.g30faa5f068