Re: [PATCH v3 5/5] bitmap: add trace2 outputs during open "bitmap" file

From: Taylor Blau <me@ttaylorr.com>
To: Teng Long <dyroneteng@gmail.com>
Cc: avarab@gmail.com, derrickstolee@github.com, git@vger.kernel.org,
	gitster@pobox.com, tenglong.tl@alibaba-inc.com
Subject: Re: [PATCH v3 5/5] bitmap: add trace2 outputs during open "bitmap" file
Date: Mon, 13 Jun 2022 21:40:10 -0400	[thread overview]
Message-ID: <Yqfm+rsP5DWyj95L@nand.local> (raw)
In-Reply-To: <e118758d1dada378d65d58579cc1372fa547d720.1655018322.git.dyroneteng@gmail.com>

On Sun, Jun 12, 2022 at 03:44:20PM +0800, Teng Long wrote:
> It's supported for a repo to use bitmap in both "NORMAL" bitmap way

I'm nitpicking, but I usually say "single-pack bitmap" or "multi-pack
(MIDX) bitmap" when distinguishing between the two.

> or a MIDX (multi-pack-index) bitmap. Either of two bitmap kinds can
> exist in the repository, or both can be stored but let the config
> controls which kind of bitmap is used (like "core.multipackIndex",
> etc.). Because of this, sometimes the bitmap debug path is not
> obvious enough, for example, when executing:
>
>  $git rev-list  --test-bitmap  HEAD
>  fatal: failed to load bitmap indexes

Odd spacing, and there should be a single space character separating "$"
from "git" (like "$ git").

While I'm thinking about it: is the error message here up-to-date with
the changes made by the previous patch?

> If we see the output like this, It's not sure for us to know
> what's happened concretely, because the cause should be :
>
>   1. Neither normal nor MIDX bitmap exists.
>   2. Only MIDX bitmap exists but core.multipackIndex="false".
>   3. Config core.multipackIndex set to "true" but MIDX  bitmap is
>      corrupted.
>   4. Config core.multipackIndex set to "true" and no MIDX bitmap
>      exists but normal bitmap file is corrupted.
>   ....
>
> These are some of the scenarios I briefly tested, but maybe there are
> others (some scenarios is produced manually like "corrupted bitmap file",
> but it's not represent it's an existed bug.).

This could probably be trimmed down for brevity, but I don't feel
strongly about it. If you wanted to make your commit message a tad
shorter, perhaps something like:

  When a user sees output like this, it's unclear which kind(s) of
  .bitmap exist, and which were read. For example, it's possible a MIDX
  bitmap exists, but was not read (e.g., because
  core.multiPackIndex=false), among many other scenarios.

would suffice.

> Therefore, we added some TRACE2 code so that when we read the bitmap

s/TRACE2/trace2

> we can be more clear about the decision path, such as whether it is
> working on MIDX or NORMAL bitmap at present, or the related config is

s/NORMAL/pack

> enabled or not. This may help with logging, user troubleshooting, and
> development debugging.
>
> Here are some brief output examples on different scenarios when
> executing:
>
>   $GIT_TRACE2_PERF=1 git rev-list --test-bitmap HEAD

s/$GIT/$ GIT

> Scenario 1: core.multipackIndex [false], midx bitmap exists [Y],
> normal bitmap exists [N]

The output here is quite wide, and I wonder if this whole section could
be shortened. For example, scenario 2 is arguably more interesting than
scenario 1 (I think readers would reasonably infer what happens in
scenario 1 by reading what happens in scenario 2).

>        19:21:56.580349 repo-settings.c:11           | d0 | main                     | data         | r1  |  0.000827 |  0.000827 | config       | core.multipackindex:false
>        19:21:56.580356 repo-settings.c:11           | d0 | main                     | data         | r1  |  0.000834 |  0.000834 | config       | index.sparse:false
>        19:21:56.580706 pack-bitmap.c:525            | d0 | main                     | region_enter | r1  |  0.001183 |           | pack-bitmap  | label:open_bitmap
>        19:21:56.580719 pack-bitmap.c:386            | d0 | main                     | data         | r1  |  0.001196 |  0.000013 | bitmap       | ..path:.git/objects/pack/pack-e9eb18e6a423057f4424a762069e13804a75d01e.bitmap
>        19:21:56.580729 pack-bitmap.c:530            | d0 | main                     | region_leave | r1  |  0.001207 |  0.000024 | pack-bitmap  | label:open_bitmap
>        19:21:56.580737 usage.c:60                   | d0 | main                     | error        |     |           |           |              | failed to load bitmap indexes
>        fatal: failed to load bitmap indexes
>        19:21:56.580746 usage.c:74                   | d0 | main                     | exit         |     |  0.001224 |           |              | code:128
>        19:21:56.580754 trace2/tr2_tgt_perf.c:215    | d0 | main                     | atexit       |     |  0.001232 |           |              | code:128
>
> Scenario 2: core.multipackIndex [false], midx bitmap exists [Y],
> normal bitmap exists [Y]
>
> 	19:23:44.692384 repo-settings.c:11           | d0 | main                     | data         | r0  |  0.000765 |  0.000765 | config       | core.multipackindex:false
> 	19:23:44.692755 pack-bitmap.c:525            | d0 | main                     | region_enter | r0  |  0.001135 |           | pack-bitmap  | label:open_bitmap
> 	19:23:44.692768 pack-bitmap.c:386            | d0 | main                     | data         | r0  |  0.001149 |  0.000014 | bitmap       | ..path:/home/tenglong.tl/test/dyrone_bitmap/.git/objects/pack/pack-e9eb18e6a423057f4424a762069e13804a75d01e.bitmap
> 	19:23:44.692790 pack-bitmap.c:530            | d0 | main                     | region_leave | r0  |  0.001171 |  0.000036 | pack-bitmap  | label:open_bitmap
> 	Bitmap v1 test (1 entries loaded)
> 	Found bitmap for d864fefa87415d6cd289c72aa9ffd45b4a8ffd84. 64 bits / 11030517 checksum
> 	19:23:44.693119 progress.c:268               | d0 | main                     | region_enter | r0  |  0.001500 |           | progress     | label:Verifying bitmap entries
> 	Verifying bitmap entries: 100% (3/3), done.
> 	19:23:44.693208 progress.c:339               | d0 | main                     | data         | r0  |  0.001589 |  0.000089 | progress     | ..total_objects:3
> 	19:23:44.693216 progress.c:346               | d0 | main                     | region_leave | r0  |  0.001597 |  0.000097 | progress     | label:Verifying bitmap entries
> 	OK!
> 	19:23:44.693234 git.c:718                    | d0 | main                     | exit         |     |  0.001615 |           |              | code:0
> 	19:23:44.693244 trace2/tr2_tgt_perf.c:215    | d0 | main                     | atexit       |     |  0.001625 |           |              | code:0

And scenario 2 could be cleaned up by just showing a few of the columns
from the trace2 output. Perhaps along the lines of:

> 	| data         | r0  |  0.000765 |  0.000765 | config       | core.multipackindex:false
> 	| region_enter | r0  |  0.001135 |           | pack-bitmap  | label:open_bitmap
> 	| data         | r0  |  0.001149 |  0.000014 | bitmap       | ..path:.git/objects/pack/pack-e9eb18e6a423057f4424a762069e13804a75d01e.bitmap
> 	| region_leave | r0  |  0.001171 |  0.000036 | pack-bitmap  | label:open_bitmap
> 	| region_enter | r0  |  0.001500 |           | progress     | label:Verifying bitmap entries

Reading the below scenarios, I think just showing this example is more
than sufficient for illustrating your point.

> Signed-off-by: Teng Long <dyroneteng@gmail.com>
> ---
>  pack-bitmap.c   | 27 +++++++++++++++++++++------
>  repo-settings.c |  1 +
>  2 files changed, 22 insertions(+), 6 deletions(-)
>
> diff --git a/pack-bitmap.c b/pack-bitmap.c
> index 5654eb7b8d..ced5993560 100644
> --- a/pack-bitmap.c
> +++ b/pack-bitmap.c
> @@ -312,9 +312,11 @@ 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, "path", bitmap_name);
> +	fd = git_open(bitmap_name);
>
>  	free(bitmap_name);
>
> @@ -343,12 +345,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");

I wonder, why don't we show these errors to the user? Should we
introduce a "ret" variable and set it to (for e.g.)

    ret = error(_("failed to load bitmap header"));

or something?

>  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");

I'm not sure we want to dump the whole repository configuration into
trace2 output. Is there a more convenient place to log any important
value(s) _after_ they have been read?

Thanks,
Taylor