| Message ID | e118758d1dada378d65d58579cc1372fa547d720.1655018322.git.dyroneteng@gmail.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | trace2 output for bitmap decision path | expand |
Teng Long <dyroneteng@gmail.com> writes: > 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); The patch adds new statements at a wrong place. The block of declarations and the first statement in the block were separated by a blank line, but they no longer are. These things tend to show up in merges quite clearly. They do not cause more unnecessary conflicts but can make resolution more error prone. Thanks.
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
On Mon, 13 Jun 2022 13:59:05 -0700, Junio C Hamano wrote: > The patch adds new statements at a wrong place. The block of > declarations and the first statement in the block were separated by > a blank line, but they no longer are. > > These things tend to show up in merges quite clearly. They do not > cause more unnecessary conflicts but can make resolution more error > prone. You are absolutely right. Will fix. Thanks.
On Mon, 13 Jun 2022 21:40:10 -0400, Taylor Blau wrote: > I'm nitpicking, but I usually say "single-pack bitmap" or "multi-pack > (MIDX) bitmap" when distinguishing between the two. Ha, it's OK, I'm hungry. Your description is a better way I think. Will optimize the relevant places. > Odd spacing, and there should be a single space character separating "$" > from "git" (like "$ git"). Yeah, will Fix. > While I'm thinking about it: is the error message here up-to-date with > the changes made by the previous patch? It's still the same after the remake and test (actually it's just a case not all the cases have the same error message. now by the previous path if "core.multipackindex=false" and single-pack doesn't exist, the error message will look like this). > 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. I think yours is better, I will use it instead the listed way. > s/TRACE2/trace2 Will fix. > s/NORMAL/pack Will fix as s/NORMAL/single-pack. > s/$GIT/$ GIT Will fix. > 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). > ... > And scenario 2 could be cleaned up by just showing a few of the columns > from the trace2 output. Perhaps along the lines of: > ... > Reading the below scenarios, I think just showing this example is more > than sufficient for illustrating your point. That makes sense. I'll keep two scenarios and omit some of the output to keep it shorter in next patch. > 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? Just this "load header error", I think it's unnecessary to show more errors to uses because in "load_bitmap_header()", the function already does, but in my patch, it's unnecessary to add "trace2_data_string()" too, so here I will remove it (directly "goto cleanup" maybe) in next patch. > 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? I think maybe I can add a argument like "int trace" in next patch, so the caller can decide whether to print to trace or not. Thanks for your help, Taylor.
On 6/12/22 3:44 AM, Teng Long wrote: [...] > > 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"); > } We should not be doing. This would dump every repo-related boolean value on every command. I already have a GIT_TRACE2_CONFIG_PARAMS and trace2.configparams that will dump "interesting" config values to the trace2 log. Just set one of them to a list of regex's. Look at the comment above trace2_cmd_list_config() in trace2.h for details. We also have GIT_TRACE2_ENV_VARS and trace2.envvars that will dump the values of "interesting" env vars. You can use these in your testing to log the config and env var values that you are interested in. Jeff
On Wed, 22 Jun 2022 08:51:18 -0400, Jeff Hostetler wrote: > We should not be doing. This would dump every repo-related > boolean value on every command. Yes. in v4 patch I use a new arg in repo_cfg_bool to decide whether to trace or not, but after the above you mentioned, I think it's still not a correct solution in my v4. > I already have a GIT_TRACE2_CONFIG_PARAMS and trace2.configparams > that will dump "interesting" config values to the trace2 log. > Just set one of them to a list of regex's. Look at the comment above > trace2_cmd_list_config() in trace2.h for details. That's fresh for me, thanks for telling me that. I remove the changes of "repo_config_bool" from my v4 patch then I try to know about "GIT_TRACE2_CONFIG_PARAMS" and "trace2.configparams". Thereby, when I: Execute "GIT_TRACE2_PERF=1 GIT_TRACE2_CONFIG_PARAMS=core.multipackIndex git rev-list --test-bitmap HEAD" 15:21:38.812782 git.c:461 | d0 | main | def_param | | | | | core.multipackindex:false 15:21:38.812797 git.c:461 | d0 | main | def_param | | | | | core.multipackindex:false I checked my configs, I found if there exists multiple level configs. it'll print multiple times. Like If I config all the global, system and local on "core.multipackIndex=false" , the output will be: 15:41:50.614108 git.c:462 | d0 | main | def_param | | | | | core.multipackindex:false 15:41:50.614123 git.c:462 | d0 | main | def_param | | | | | core.multipackindex:false 15:41:50.614136 git.c:462 | d0 | main | def_param | | | | | core.multipackindex:false And if I modified the local scope of core.multipackIndex to "true", the output will be: 15:45:39.200172 git.c:462 | d0 | main | def_param | | | | | core.multipackindex:false 15:45:39.200186 git.c:462 | d0 | main | def_param | | | | | core.multipackindex:false 15:45:39.200200 git.c:462 | d0 | main | def_param | | | | | core.multipackindex:true I'm not sure it's an intentional design or here should be only print the final value that takes effect or should print all the values if config multiple scopes on the same config. Hence, I made a temporary patch below to try to add some identifying information to know why we output these lines, like: diff --git a/trace2/tr2_tgt_event.c b/trace2/tr2_tgt_event.c index c5c8cfbbaa..37a3163be1 100644 --- a/trace2/tr2_tgt_event.c +++ b/trace2/tr2_tgt_event.c @@ -479,9 +479,12 @@ static void fn_param_fl(const char *file, int line, const char *param, { const char *event_name = "def_param"; struct json_writer jw = JSON_WRITER_INIT; + enum config_scope scope = current_config_scope(); + const char *scope_name = config_scope_name(scope); commit a089800b9dbc93a5dff9a46da7e66111e6e4343e (HEAD -> master, dyrone/master, dyrone/HEAD) Author: Teng Long <dyroneteng@gmail.com> Date: Thu Jun 23 17:24:15 2022 +0800 tr2: append scope info when same configs exist in multiple scopes Signed-off-by: Teng Long <dyroneteng@gmail.com> diff --git a/trace2/tr2_tgt_event.c b/trace2/tr2_tgt_event.c index c5c8cfbbaa..37a3163be1 100644 --- a/trace2/tr2_tgt_event.c +++ b/trace2/tr2_tgt_event.c @@ -479,9 +479,12 @@ static void fn_param_fl(const char *file, int line, const char *param, { const char *event_name = "def_param"; struct json_writer jw = JSON_WRITER_INIT; + enum config_scope scope = current_config_scope(); + const char *scope_name = config_scope_name(scope); struct json_writer jw = JSON_WRITER_INIT; + enum config_scope scope = current_config_scope(); + const char *scope_name = config_scope_name(scope); jw_object_begin(&jw, 0); event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_string(&jw, "scope", scope_name); jw_object_string(&jw, "param", param); jw_object_string(&jw, "value", value); jw_end(&jw); diff --git a/trace2/tr2_tgt_normal.c b/trace2/tr2_tgt_normal.c index c42fbade7f..e1b036a60c 100644 --- a/trace2/tr2_tgt_normal.c +++ b/trace2/tr2_tgt_normal.c @@ -298,8 +298,10 @@ static void fn_param_fl(const char *file, int line, const char *param, const char *value) { struct strbuf buf_payload = STRBUF_INIT; + enum config_scope scope = current_config_scope(); + const char *scope_name = config_scope_name(scope); - strbuf_addf(&buf_payload, "def_param %s=%s", param, value); + strbuf_addf(&buf_payload, "def_param scope:%s %s=%s", scope_name, param, value); normal_io_write_fl(file, line, &buf_payload); strbuf_release(&buf_payload); } diff --git a/trace2/tr2_tgt_perf.c b/trace2/tr2_tgt_perf.c index a1eff8bea3..c21bf8e651 100644 --- a/trace2/tr2_tgt_perf.c +++ b/trace2/tr2_tgt_perf.c @@ -441,10 +441,12 @@ static void fn_param_fl(const char *file, int line, const char *param, { const char *event_name = "def_param"; struct strbuf buf_payload = STRBUF_INIT; + enum config_scope scope = current_config_scope(); + const char *scope_name = config_scope_name(scope); strbuf_addf(&buf_payload, "%s:%s", param, value); - perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL, ---- The partial tr2 log looks like: PERF: 17:00:35.933094 git.c:462 | d0 | main | def_param | | | | system | core.multipackindex:false 17:00:35.933110 git.c:462 | d0 | main | def_param | | | | global | core.multipackindex:false 17:00:35.933128 git.c:462 | d0 | main | def_param | | | | local | core.multipackindex:true NORMAL: 17:14:32.905359 git.c:462 def_param scope:system core.multipackindex=false 17:14:32.905370 git.c:462 def_param scope:global core.multipackindex=false 17:14:32.905383 git.c:462 def_param scope:local core.multipackindex=true EVENT: {"event":"def_param","sid":"20220623T092115.703660Z-H82fddc29-P0001812a","thread":"main","time":"2022-06-23T09:21:15.703920Z","file":"git.c","line":462,"scope":"system","param":"core.multipackindex","value":"false"} {"event":"def_param","sid":"20220623T092115.703660Z-H82fddc29-P0001812a","thread":"main","time":"2022-06-23T09:21:15.703936Z","file":"git.c","line":462,"scope":"global","param":"core.multipackindex","value":"false"} {"event":"def_param","sid":"20220623T092115.703660Z-H82fddc29-P0001812a","thread":"main","time":"2022-06-23T09:21:15.703952Z","file":"git.c","line":462,"scope":"local","param":"core.multipackindex","value":"true"} > We also have GIT_TRACE2_ENV_VARS and trace2.envvars that will dump > the values of "interesting" env vars. > You can use these in your testing to log the config and env var > values that you are interested in. Wow, cool as GIT_TRACE2_CONFIG_PARAMS and trace2.configparams you mentioned before. Thanks.
On 6/23/22 5:38 AM, Teng Long wrote: > On Wed, 22 Jun 2022 08:51:18 -0400, Jeff Hostetler wrote: > [...] > I remove the changes of "repo_config_bool" from my v4 patch > then I try to know about "GIT_TRACE2_CONFIG_PARAMS" and > "trace2.configparams". Thereby, when I: > > Execute "GIT_TRACE2_PERF=1 GIT_TRACE2_CONFIG_PARAMS=core.multipackIndex git rev-list --test-bitmap HEAD" > > 15:21:38.812782 git.c:461 | d0 | main | def_param | | | | | core.multipackindex:false > 15:21:38.812797 git.c:461 | d0 | main | def_param | | | | | core.multipackindex:false > > I checked my configs, I found if there exists multiple level configs. > it'll print multiple times. Like If I config all the global, system > and local on "core.multipackIndex=false" , the output will be: > > 15:41:50.614108 git.c:462 | d0 | main | def_param | | | | | core.multipackindex:false > 15:41:50.614123 git.c:462 | d0 | main | def_param | | | | | core.multipackindex:false > 15:41:50.614136 git.c:462 | d0 | main | def_param | | | | | core.multipackindex:false > > And if I modified the local scope of core.multipackIndex to "true", > the output will be: > > 15:45:39.200172 git.c:462 | d0 | main | def_param | | | | | core.multipackindex:false > 15:45:39.200186 git.c:462 | d0 | main | def_param | | | | | core.multipackindex:false > 15:45:39.200200 git.c:462 | d0 | main | def_param | | | | | core.multipackindex:true > > I'm not sure it's an intentional design or here should be only > print the final value that takes effect or should print all the > values if config multiple scopes on the same config. > > Hence, I made a temporary patch below to try to add some > identifying information to know why we output these lines, like: I had intended it to only print the final "effective" value that the command would actually use. I don't remember if I ever experimented with config values that are set at multiple levels, but testing it now shows that you're right it does print a "def_param" message for each level. I would suggest we fix it to only print the final value since we really just want to know whether the command will or will not use a feature. The inheritance is somewhat irrelevant. But the change to do that may be quite a mess, so printing the scope name as you have here is fine. And may help with support when debugging users having confusing problems, so I'm fine with it. Thanks, Jeff
Nn Thu, 23 Jun 2022 11:14:27 -0400, Jeff Hostetler wrote: > I had intended it to only print the final "effective" value > that the command would actually use. I don't remember if I > ever experimented with config values that are set at multiple > levels, but testing it now shows that you're right it does > print a "def_param" message for each level. > > I would suggest we fix it to only print the final value > since we really just want to know whether the command will > or will not use a feature. The inheritance is somewhat > irrelevant. > > But the change to do that may be quite a mess, so printing > the scope name as you have here is fine. And may help with > support when debugging users having confusing problems, so > I'm fine with it. Yes, as I replied both way is OK for me, but sorry for only replied the append-scope way. I will post a new patch v5 and include the related changes to fix this. Thanks.
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"); 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; @@ -374,6 +383,7 @@ 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, "path", bitmap_name); fd = git_open(bitmap_name); free(bitmap_name); @@ -509,11 +519,16 @@ 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 = 0; + assert(!bitmap_git->map); + trace2_region_enter("pack-bitmap", "open_bitmap", r); if (!open_midx_bitmap(r, bitmap_git)) - return 0; - return open_pack_bitmap(r, bitmap_git); + 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)
It's supported for a repo to use bitmap in both "NORMAL" bitmap way 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 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.). 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 or NORMAL bitmap at present, or the related config is 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 Scenario 1: core.multipackIndex [false], midx bitmap exists [Y], normal bitmap exists [N] 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 Scenario 3: core.multipackIndex [true], midx bitmap exists [Y], normal bitmap exists [Y] 19:26:03.625055 repo-settings.c:11 | d0 | main | data | r0 | 0.000760 | 0.000760 | config | core.multipackindex:true 19:26:03.625090 midx.c:185 | d0 | main | data | r0 | 0.000795 | 0.000795 | midx | load/num_packs:1 19:26:03.625097 midx.c:186 | d0 | main | data | r0 | 0.000803 | 0.000803 | midx | load/num_objects:3 19:26:03.625455 pack-bitmap.c:525 | d0 | main | region_enter | r0 | 0.001160 | | pack-bitmap | label:open_bitmap 19:26:03.625470 pack-bitmap.c:318 | d0 | main | data | r0 | 0.001175 | 0.000015 | midx | ..path:/home/tenglong.tl/test/dyrone_bitmap/.git/objects/pack/multi-pack-index-fe8e96790bd34926423bdf3efd762dbbea9f3213.bitmap 19:26:03.625489 pack-revindex.c:315 | d0 | main | data | r0 | 0.001194 | 0.000034 | load_midx_re | ..source:midx 19:26:03.625496 pack-bitmap.c:530 | d0 | main | region_leave | r0 | 0.001202 | 0.000042 | pack-bitmap | label:open_bitmap Bitmap v1 test (1 entries loaded) Found bitmap for d864fefa87415d6cd289c72aa9ffd45b4a8ffd84. 64 bits / 11030517 checksum 19:26:03.625818 progress.c:268 | d0 | main | region_enter | r0 | 0.001523 | | progress | label:Verifying bitmap entries Verifying bitmap entries: 100% (3/3), done. 19:26:03.625916 progress.c:339 | d0 | main | data | r0 | 0.001622 | 0.000099 | progress | ..total_objects:3 19:26:03.625925 progress.c:346 | d0 | main | region_leave | r0 | 0.001630 | 0.000107 | progress | label:Verifying bitmap entries OK! 19:26:03.625943 git.c:718 | d0 | main | exit | | 0.001648 | | | code:0 19:26:03.625952 trace2/tr2_tgt_perf.c:215 | d0 | main | atexit | | 0.001658 | | | code:0 Situation 4: core.multipackIndex [false], midx bitmap exists [N], normal bitmap exists [Y]. 19:27:15.383037 repo-settings.c:11 | d0 | main | data | r0 | 0.000746 | 0.000746 | config | core.multipackindex:true 19:27:15.383397 pack-bitmap.c:525 | d0 | main | region_enter | r0 | 0.001105 | | pack-bitmap | label:open_bitmap 19:27:15.383408 pack-bitmap.c:386 | d0 | main | data | r0 | 0.001116 | 0.000011 | bitmap | ..path:/home/tenglong.tl/test/dyrone_bitmap/.git/objects/pack/pack-e9eb18e6a423057f4424a762069e13804a75d01e.bitmap 19:27:15.383419 pack-bitmap.c:530 | d0 | main | region_leave | r0 | 0.001128 | 0.000023 | pack-bitmap | label:open_bitmap Bitmap v1 test (1 entries loaded) Found bitmap for d864fefa87415d6cd289c72aa9ffd45b4a8ffd84. 64 bits / 11030517 checksum 19:27:15.383730 progress.c:268 | d0 | main | region_enter | r0 | 0.001439 | | progress | label:Verifying bitmap entries Verifying bitmap entries: 100% (3/3), done. 19:27:15.383822 progress.c:339 | d0 | main | data | r0 | 0.001531 | 0.000092 | progress | ..total_objects:3 19:27:15.383830 progress.c:346 | d0 | main | region_leave | r0 | 0.001539 | 0.000100 | progress | label:Verifying bitmap entries OK! 19:27:15.383848 git.c:718 | d0 | main | exit | | 0.001557 | | | code:0 19:27:15.383867 trace2/tr2_tgt_perf.c:215 | d0 | main | atexit | | 0.001576 | | | code:0 Scenario 5: core.multipackIndex [true], midx bitmap exists [Y] but corrupted, normal bitmap exists [Y] 19:29:25.888233 repo-settings.c:11 | d0 | main | data | r0 | 0.000794 | 0.000794 | config | core.multipackindex:true 19:29:25.888591 pack-bitmap.c:525 | d0 | main | region_enter | r0 | 0.001152 | | pack-bitmap | label:open_bitmap 19:29:25.888603 pack-bitmap.c:386 | d0 | main | data | r0 | 0.001163 | 0.000011 | bitmap | ..path:/home/tenglong.tl/test/dyrone_bitmap/.git/objects/pack/pack-e9eb18e6a423057f4424a762069e13804a75d01e.bitmap 19:29:25.888622 usage.c:79 | d0 | main | error | | | | | ..Corrupted bitmap index file (wrong header) error: Corrupted bitmap index file (wrong header) 19:29:25.888638 usage.c:79 | d0 | main | error | | | | | ..bitmap header is invalid error: bitmap header is invalid 19:29:25.888650 pack-bitmap.c:530 | d0 | main | region_leave | r0 | 0.001211 | 0.000059 | pack-bitmap | label:open_bitmap 19:29:25.888659 usage.c:60 | d0 | main | error | | | | | failed to load bitmap indexes fatal: failed to load bitmap indexes 19:29:25.888670 usage.c:74 | d0 | main | exit | | 0.001231 | | | code:128 19:29:25.888680 trace2/tr2_tgt_perf.c:215 | d0 | main | atexit | | 0.001241 | | | code:128 Signed-off-by: Teng Long <dyroneteng@gmail.com> --- pack-bitmap.c | 27 +++++++++++++++++++++------ repo-settings.c | 1 + 2 files changed, 22 insertions(+), 6 deletions(-)