[PATCH v1 3/3] bitmap: add trace outputs during open "bitmap" file

From: Teng Long <dyroneteng@gmail.com>
Date: Mar 24, 2022, 11:44 UTC
Message-ID: <9912450fc11f869ad1b6409d7adcfe20f06c17ff.1648119652.git.dyroneteng@gmail.com>
In-Reply-To: <cover.1648119652.git.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 of the outputs of

     "$GIT_TRACE2_PERF=1 git rev-list --test-bitmap HEAD"

based on this commit:

      1. core.multipackindex="true" and midx bitmap exists

	17:12:50.496112 common-main.c:49             | d0 | main                     | version      |     |           |           |              | 2.35.1.579.g70500b6343.dirty
	17:12:50.496141 common-main.c:50             | d0 | main                     | start        |     |  0.000306 |           |              | /opt/git/master/bin/git rev-list --test-bitmap HEAD
	17:12:50.496208 compat/linux/procinfo.c:170  | d0 | main                     | cmd_ancestry |     |           |           |              | ancestry:[bash sshd sshd sshd systemd]
	17:12:50.496333 git.c:460                    | d0 | main                     | cmd_name     |     |           |           |              | rev-list (rev-list)
	17:12:50.496536 midx.c:395                   | d0 | main                     | data         | r0  |  0.000706 |  0.000706 | midx         | core.multipackIndex:true
	17:12:50.496563 midx.c:185                   | d0 | main                     | data         | r0  |  0.000733 |  0.000733 | midx         | load/num_packs:1
	17:12:50.496571 midx.c:186                   | d0 | main                     | data         | r0  |  0.000741 |  0.000741 | midx         | load/num_objects:15
	17:12:50.496677 pack-revindex.c:315          | d0 | main                     | data         | r0  |  0.000847 |  0.000847 | load_midx_re | source:midx
	17:12:50.496685 pack-bitmap.c:512            | d0 | main                     | data         | r0  |  0.000856 |  0.000856 | midx         | open bitmap (midx):ok
	Bitmap v1 test (4 entries loaded)
	Found bitmap for 9a0a2928a280d91f5c8ded46e952add4c4296979. 64 bits / f15de25e checksum
	17:12:50.497016 progress.c:268               | d0 | main                     | region_enter | r0  |  0.001186 |           | progress     | label:Verifying bitmap entries
	Verifying bitmap entries: 100% (15/15), done.
	17:12:50.497179 progress.c:339               | d0 | main                     | data         | r0  |  0.001350 |  0.000164 | progress     | ..total_objects:15
	17:12:50.497188 progress.c:346               | d0 | main                     | region_leave | r0  |  0.001358 |  0.000172 | progress     | label:Verifying bitmap entries
	OK!
	17:12:50.497204 git.c:718                    | d0 | main                     | exit         |     |  0.001374 |           |              | code:0
	17:12:50.497213 trace2/tr2_tgt_perf.c:215    | d0 | main                     | atexit       |     |  0.001384 |           |              | code:0

      2. core.multipackindex="false" and only midx bitmap exists

	17:18:38.423328 common-main.c:49             | d0 | main                     | version      |     |           |           |              | 2.35.1.579.g70500b6343.dirty
	17:18:38.423357 common-main.c:50             | d0 | main                     | start        |     |  0.000263 |           |              | /opt/git/master/bin/git rev-list --test-bitmap HEAD
	17:18:38.423443 compat/linux/procinfo.c:170  | d0 | main                     | cmd_ancestry |     |           |           |              | ancestry:[bash sshd sshd sshd systemd]
	17:18:38.423587 git.c:460                    | d0 | main                     | cmd_name     |     |           |           |              | rev-list (rev-list)
	17:18:38.423809 midx.c:395                   | d0 | main                     | data         | r0  |  0.000720 |  0.000720 | midx         | core.multipackIndex:false
	17:18:38.423933 pack-bitmap.c:512            | d0 | main                     | data         | r0  |  0.000845 |  0.000845 | midx         | open bitmap (midx):failed
	17:18:38.423947 pack-bitmap.c:493            | d0 | main                     | data         | r0  |  0.000858 |  0.000858 | bitmap       | open bitmap (non-midx):failed
	17:18:38.423956 usage.c:60                   | d0 | main                     | error        |     |           |           |              | failed to load bitmap indexes
	fatal: failed to load bitmap indexes
	17:18:38.423967 usage.c:74                   | d0 | main                     | exit         |     |  0.000879 |           |              | code:128
	17:18:38.423976 trace2/tr2_tgt_perf.c:215    | d0 | main                     | atexit       |     |  0.000888 |           |              | code:128

      3. core.multipackindex="false" and only normal bitmap exists

	17:21:25.519233 common-main.c:49             | d0 | main                     | version      |     |           |           |              | 2.35.1.579.g70500b6343.dirty
	17:21:25.519261 common-main.c:50             | d0 | main                     | start        |     |  0.000284 |           |              | /opt/git/master/bin/git rev-list --test-bitmap HEAD
	17:21:25.519335 compat/linux/procinfo.c:170  | d0 | main                     | cmd_ancestry |     |           |           |              | ancestry:[bash sshd sshd sshd systemd]
	17:21:25.519468 git.c:460                    | d0 | main                     | cmd_name     |     |           |           |              | rev-list (rev-list)
	17:21:25.519673 midx.c:395                   | d0 | main                     | data         | r0  |  0.000701 |  0.000701 | midx         | core.multipackIndex:false
	17:21:25.520051 pack-bitmap.c:512            | d0 | main                     | data         | r0  |  0.001080 |  0.001080 | midx         | open bitmap (midx):failed
	17:21:25.520070 pack-bitmap.c:493            | d0 | main                     | data         | r0  |  0.001099 |  0.001099 | bitmap       | open bitmap (non-midx):ok
	Bitmap v1 test (4 entries loaded)
	Found bitmap for 9a0a2928a280d91f5c8ded46e952add4c4296979. 64 bits / f15de25e checksum
	17:21:25.520395 progress.c:268               | d0 | main                     | region_enter | r0  |  0.001423 |           | progress     | label:Verifying bitmap entries
	Verifying bitmap entries: 100% (15/15), done.
	17:21:25.520526 progress.c:339               | d0 | main                     | data         | r0  |  0.001555 |  0.000132 | progress     | ..total_objects:15
	17:21:25.520533 progress.c:346               | d0 | main                     | region_leave | r0  |  0.001562 |  0.000139 | progress     | label:Verifying bitmap entries
	OK!
	17:21:25.520549 git.c:718                    | d0 | main                     | exit         |     |  0.001578 |           |              | code:0
	17:21:25.520557 trace2/tr2_tgt_perf.c:215    | d0 | main                     | atexit       |     |  0.001586 |           |              | code:0

      4. core.multipackindex="false" and both midx and normal bitmaps do not exists

	17:22:27.680275 common-main.c:49             | d0 | main                     | version      |     |           |           |              | 2.35.1.579.g70500b6343.dirty
	17:22:27.680298 common-main.c:50             | d0 | main                     | start        |     |  0.000284 |           |              | /opt/git/master/bin/git rev-list --test-bitmap HEAD
	17:22:27.680375 compat/linux/procinfo.c:170  | d0 | main                     | cmd_ancestry |     |           |           |              | ancestry:[bash sshd sshd sshd systemd]
	17:22:27.680511 git.c:460                    | d0 | main                     | cmd_name     |     |           |           |              | rev-list (rev-list)
	17:22:27.680718 midx.c:395                   | d0 | main                     | data         | r0  |  0.000709 |  0.000709 | midx         | core.multipackIndex:false
	17:22:27.681085 pack-bitmap.c:512            | d0 | main                     | data         | r0  |  0.001075 |  0.001075 | midx         | open bitmap (midx):failed
	17:22:27.681102 pack-bitmap.c:493            | d0 | main                     | data         | r0  |  0.001093 |  0.001093 | bitmap       | open bitmap (non-midx):failed
	17:22:27.681110 usage.c:60                   | d0 | main                     | error        |     |           |           |              | failed to load bitmap indexes
	fatal: failed to load bitmap indexes
	17:22:27.681120 usage.c:74                   | d0 | main                     | exit         |     |  0.001112 |           |              | code:128
	17:22:27.681129 trace2/tr2_tgt_perf.c:215    | d0 | main                     | atexit       |     |  0.001120 |           |              | code:128

Signed-off-by: Teng Long <dyroneteng@gmail.com>
---
 midx.c        | 2 ++
 pack-bitmap.c | 4 ++++
 2 files changed, 6 insertions(+)

diff --git a/midx.c b/midx.c
index 865170bad0..fda9644028 100644
--- a/midx.c
+++ b/midx.c
@@ -392,6 +392,8 @@ int prepare_multi_pack_index_one(struct repository *r, const char *object_dir, i
 	struct multi_pack_index *m_search;
 
 	prepare_repo_settings(r);
+	trace2_data_string("midx", r, "core.multipackIndex",
+					   r->settings.core_multi_pack_index ? "true" : "false");
 	if (!r->settings.core_multi_pack_index)
 		return 0;
 
diff --git a/pack-bitmap.c b/pack-bitmap.c
index b1357137bf..14cf8abebd 100644
--- a/pack-bitmap.c
+++ b/pack-bitmap.c
@@ -490,6 +490,8 @@ static int open_pack_bitmap(struct repository *r,
 		}
 	}
 
+	trace2_data_string("bitmap", the_repository, "open bitmap (non-midx)",
+					   ret ? "failed" : "ok");
 	return ret;
 }
 
@@ -507,6 +509,8 @@ static int open_midx_bitmap(struct repository *r,
 			break;
 		}
 	}
+	trace2_data_string("midx", the_repository, "open bitmap (midx)",
+					   ret ? "failed" : "ok");
 	return ret;
 }

-- 
2.35.1.579.g70500b6343.dirty