merge-ort: begin performance work; instrument with trace2_region_* calls

Add some timing instrumentation for both merge-ort and diffcore-rename; I used these to measure and optimize performance in both, and several future patch series will build on these to reduce the timings of some select testcases. === Setup === The primary testcase I used involved rebasing a random topic in the linux kernel (consisting of 35 patches) against an older version. I added two variants, one where I rename a toplevel directory, and another where I only rebase one patch instead of the whole topic. The setup is as follows: $ git clone git://git.kernel.org/pub/scm/linux/kernel/git/stable/linux-stable.git $ git branch hwmon-updates fd8bdb23b91876ac1e624337bb88dc1dcc21d67e $ git branch hwmon-just-one fd8bdb23b91876ac1e624337bb88dc1dcc21d67e~34 $ git branch base 4703d9119972bf586d2cca76ec6438f819ffa30e $ git switch -c 5.4-renames v5.4 $ git mv drivers pilots # Introduce over 26,000 renames $ git commit -m "Rename drivers/ to pilots/" $ git config merge.renameLimit 30000 $ git config merge.directoryRenames true === Testcases === Now with REBASE standing for either "git rebase [--merge]" (using merge-recursive) or "test-tool fast-rebase" (using merge-ort), the testcases are: Testcase #1: no-renames $ git checkout v5.4^0 $ REBASE --onto HEAD base hwmon-updates Note: technically the name is misleading; there are some renames, but very few. Rename detection only takes about half the overall time. Testcase #2: mega-renames $ git checkout 5.4-renames^0 $ REBASE --onto HEAD base hwmon-updates Testcase #3: just-one-mega $ git checkout 5.4-renames^0 $ REBASE --onto HEAD base hwmon-just-one === Timing results === Overall timings, using hyperfine (1 warmup run, 3 runs for mega-renames, 10 runs for the other two cases): merge-recursive merge-ort no-renames: 18.912 s ± 0.174 s 14.263 s ± 0.053 s mega-renames: 5964.031 s ± 10.459 s 5504.231 s ± 5.150 s just-one-mega: 149.583 s ± 0.751 s 158.534 s ± 0.498 s A single re-run of each with some breakdowns: --- no-renames --- merge-recursive merge-ort overall runtime: 19.302 s 14.257 s inexact rename detection: 7.603 s 7.906 s everything else: 11.699 s 6.351 s --- mega-renames --- merge-recursive merge-ort overall runtime: 5950.195 s 5499.672 s inexact rename detection: 5746.309 s 5487.120 s everything else: 203.886 s 17.552 s --- just-one-mega --- merge-recursive merge-ort overall runtime: 151.001 s 158.582 s inexact rename detection: 143.448 s 157.835 s everything else: 7.553 s 0.747 s === Timing observations === 0) Maximum speedup The "everything else" row represents the maximum speedup we could achieve if we were to somehow infinitely parallelize inexact rename detection, but leave everything else alone. The fact that this is so much smaller than the real runtime (even in the case with virtually no renames) makes it clear just how overwhelmingly large the time spent on rename detection can be. 1) no-renames 1a) merge-ort is faster than merge-recursive, which is nice. However, this still should not be considered good enough. Although the "merge" backend to rebase (merge-recursive) is sometimes faster than the "apply" backend, this is one of those cases where it is not. In fact, even merge-ort is slower. The "apply" backend can complete this testcase in 6.940 s ± 0.485 s which is about 2x faster than merge-ort and 3x faster than merge-recursive. One goal of the merge-ort performance work will be to make it faster than git-am on this (and similar) testcases. 2) mega-renames 2a) Obviously rename detection is a huge cost; it's where most the time is spent. We need to cut that down. If we could somehow infinitely parallelize it and drive its time to 0, the merge-recursive time would drop to about 204s, and the merge-ort time would drop to about 17s. I think this particular stat shows I've subtly baked a couple performance improvements into merge-ort and into fast-rebase already. 3) just-one-mega 3a) not much to say here, it just gives some flavor for how rebasing only one patch compares to rebasing 35. === Goals === This patch is obviously just the beginning. Here are some of my goals that this measurement will help us achieve: * Drive the cost of rename detection down considerably for merges * After the above has been achieved, see if there are other slowness factors (which would have previously been overshadowed by rename detection costs) which we can then focus on and also optimize. * Ensure our rebase testcase that requires little rename detection is noticeably faster with merge-ort than with apply-based rebase. Signed-off-by: Elijah Newren <newren@gmail.com> Acked-by: Taylor Blau <ttaylorr@github.com> Signed-off-by: Junio C Hamano <gitster@pobox.com>

Elijah Newren committed Jan 23, 2021 at 22:01 UTC 557ac0350d9efa1f59c708779ca3fb3aee121131
2 files changed +65
diffcore-rename.c
+8
@@ -465,6 +465,7 @@ void diffcore_rename(struct diff_options *options)
465 int num_destinations, dst_cnt;
466 struct progress *progress = NULL;
467
468 + trace2_region_enter("diff", "setup", options->repo);
469 if (!minimum_score)
470 minimum_score = DEFAULT_RENAME_SCORE;
471
@@ -510,14 +511,17 @@ void diffcore_rename(struct diff_options *options)
511 register_rename_src(p);
512 }
513 }
514 + trace2_region_leave("diff", "setup", options->repo);
515 if (rename_dst_nr == 0 || rename_src_nr == 0)
516 goto cleanup; /* nothing to do */
517
518 + trace2_region_enter("diff", "exact renames", options->repo);
519 /*
520 * We really want to cull the candidates list early
521 * with cheap tests in order to avoid doing deltas.
522 */
523 rename_count = find_exact_renames(options);
524 + trace2_region_leave("diff", "exact renames", options->repo);
525
526 /* Did we only want exact renames? */
527 if (minimum_score == MAX_SCORE)
@@ -545,6 +549,7 @@ void diffcore_rename(struct diff_options *options)
549 break;
550 }
551
552 + trace2_region_enter("diff", "inexact renames", options->repo);
553 if (options->show_rename_progress) {
554 progress = start_delayed_progress(
555 _("Performing inexact rename detection"),
@@ -600,11 +605,13 @@ void diffcore_rename(struct diff_options *options)
605 if (detect_rename == DIFF_DETECT_COPY)
606 rename_count += find_renames(mx, dst_cnt, minimum_score, 1);
607 free(mx);
608 + trace2_region_leave("diff", "inexact renames", options->repo);
609
610 cleanup:
611 /* At this point, we have found some renames and copies and they
612 * are recorded in rename_dst. The original list is still in *q.
613 */
614 + trace2_region_enter("diff", "write back to queue", options->repo);
615 DIFF_QUEUE_CLEAR(&outq);
616 for (i = 0; i < q->nr; i++) {
617 struct diff_filepair *p = q->queue[i];
@@ -680,5 +687,6 @@ void diffcore_rename(struct diff_options *options)
687 strintmap_clear(break_idx);
688 FREE_AND_NULL(break_idx);
689 }
690 + trace2_region_leave("diff", "write back to queue", options->repo);
691 return;
692 }
merge-ort.c
+57
@@ -752,7 +752,9 @@ static int collect_merge_info(struct merge_options *opt,
752 init_tree_desc(t + 1, side1->buffer, side1->size);
753 init_tree_desc(t + 2, side2->buffer, side2->size);
754
755 + trace2_region_enter("merge", "traverse_trees", opt->repo);
756 ret = traverse_trees(NULL, 3, t, &info);
757 + trace2_region_leave("merge", "traverse_trees", opt->repo);
758
759 return ret;
760 }
@@ -2105,9 +2107,12 @@ static void detect_regular_renames(struct merge_options *opt,
2107 diff_opts.show_rename_progress = opt->show_rename_progress;
2108 diff_opts.output_format = DIFF_FORMAT_NO_OUTPUT;
2109 diff_setup_done(&diff_opts);
2110 +
2111 + trace2_region_enter("diff", "diffcore_rename", opt->repo);
2112 diff_tree_oid(&merge_base->object.oid, &side->object.oid, "",
2113 &diff_opts);
2114 diffcore_std(&diff_opts);
2115 + trace2_region_leave("diff", "diffcore_rename", opt->repo);
2116
2117 if (diff_opts.needed_rename_limit > renames->needed_limit)
2118 renames->needed_limit = diff_opts.needed_rename_limit;
@@ -2206,9 +2211,12 @@ static int detect_and_process_renames(struct merge_options *opt,
2211
2212 memset(&combined, 0, sizeof(combined));
2213
2214 + trace2_region_enter("merge", "regular renames", opt->repo);
2215 detect_regular_renames(opt, merge_base, side1, MERGE_SIDE1);
2216 detect_regular_renames(opt, merge_base, side2, MERGE_SIDE2);
2217 + trace2_region_leave("merge", "regular renames", opt->repo);
2218
2219 + trace2_region_enter("merge", "directory renames", opt->repo);
2220 need_dir_renames =
2221 !opt->priv->call_depth &&
2222 (opt->detect_directory_renames == MERGE_DIRECTORY_RENAMES_TRUE ||
@@ -2230,8 +2238,11 @@ static int detect_and_process_renames(struct merge_options *opt,
2238 &renames->dir_renames[1],
2239 &renames->dir_renames[2]);
2240 QSORT(combined.queue, combined.nr, compare_pairs);
2241 + trace2_region_leave("merge", "directory renames", opt->repo);
2242
2243 + trace2_region_enter("merge", "process renames", opt->repo);
2244 clean &= process_renames(opt, &combined);
2245 + trace2_region_leave("merge", "process renames", opt->repo);
2246
2247 /* Free memory for renames->pairs[] and combined */
2248 for (s = MERGE_SIDE1; s <= MERGE_SIDE2; s++) {
@@ -2913,20 +2924,30 @@ static void process_entries(struct merge_options *opt,
2924 STRING_LIST_INIT_NODUP,
2925 NULL, 0 };
2926
2927 + trace2_region_enter("merge", "process_entries setup", opt->repo);
2928 if (strmap_empty(&opt->priv->paths)) {
2929 oidcpy(result_oid, opt->repo->hash_algo->empty_tree);
2930 return;
2931 }
2932
2933 /* Hack to pre-allocate plist to the desired size */
2934 + trace2_region_enter("merge", "plist grow", opt->repo);
2935 ALLOC_GROW(plist.items, strmap_get_size(&opt->priv->paths), plist.alloc);
2936 + trace2_region_leave("merge", "plist grow", opt->repo);
2937
2938 /* Put every entry from paths into plist, then sort */
2939 + trace2_region_enter("merge", "plist copy", opt->repo);
2940 strmap_for_each_entry(&opt->priv->paths, &iter, e) {
2941 string_list_append(&plist, e->key)->util = e->value;
2942 }
2943 + trace2_region_leave("merge", "plist copy", opt->repo);
2944 +
2945 + trace2_region_enter("merge", "plist special sort", opt->repo);
2946 plist.cmp = string_list_df_name_compare;
2947 string_list_sort(&plist);
2948 + trace2_region_leave("merge", "plist special sort", opt->repo);
2949 +
2950 + trace2_region_leave("merge", "process_entries setup", opt->repo);
2951
2952 /*
2953 * Iterate over the items in reverse order, so we can handle paths
@@ -2937,6 +2958,7 @@ static void process_entries(struct merge_options *opt,
2958 * (because it allows us to know whether the directory is still in
2959 * the way when it is time to process the file at the same path).
2960 */
2961 + trace2_region_enter("merge", "processing", opt->repo);
2962 for (entry = &plist.items[plist.nr-1]; entry >= plist.items; --entry) {
2963 char *path = entry->string;
2964 /*
@@ -2955,7 +2977,9 @@ static void process_entries(struct merge_options *opt,
2977 process_entry(opt, path, ci, &dir_metadata);
2978 }
2979 }
2980 + trace2_region_leave("merge", "processing", opt->repo);
2981
2982 + trace2_region_enter("merge", "process_entries cleanup", opt->repo);
2983 if (dir_metadata.offsets.nr != 1 ||
2984 (uintptr_t)dir_metadata.offsets.items[0].util != 0) {
2985 printf("dir_metadata.offsets.nr = %d (should be 1)\n",
@@ -2970,6 +2994,7 @@ static void process_entries(struct merge_options *opt,
2994 string_list_clear(&plist, 0);
2995 string_list_clear(&dir_metadata.versions, 0);
2996 string_list_clear(&dir_metadata.offsets, 0);
2997 + trace2_region_leave("merge", "process_entries cleanup", opt->repo);
2998 }
2999
3000 /*** Function Grouping: functions related to merge_switch_to_result() ***/
@@ -3128,12 +3153,15 @@ void merge_switch_to_result(struct merge_options *opt,
3153 if (result->clean >= 0 && update_worktree_and_index) {
3154 struct merge_options_internal *opti = result->priv;
3155
3156 + trace2_region_enter("merge", "checkout", opt->repo);
3157 if (checkout(opt, head, result->tree)) {
3158 /* failure to function */
3159 result->clean = -1;
3160 return;
3161 }
3162 + trace2_region_leave("merge", "checkout", opt->repo);
3163
3164 + trace2_region_enter("merge", "record_conflicted", opt->repo);
3165 if (record_conflicted_index_entries(opt, opt->repo->index,
3166 &opti->paths,
3167 &opti->conflicted)) {
@@ -3141,6 +3169,7 @@ void merge_switch_to_result(struct merge_options *opt,
3169 result->clean = -1;
3170 return;
3171 }
3172 + trace2_region_leave("merge", "record_conflicted", opt->repo);
3173 }
3174
3175 if (display_update_msgs) {
@@ -3150,6 +3179,8 @@ void merge_switch_to_result(struct merge_options *opt,
3179 struct string_list olist = STRING_LIST_INIT_NODUP;
3180 int i;
3181
3182 + trace2_region_enter("merge", "display messages", opt->repo);
3183 +
3184 /* Hack to pre-allocate olist to the desired size */
3185 ALLOC_GROW(olist.items, strmap_get_size(&opti->output),
3186 olist.alloc);
@@ -3171,6 +3202,8 @@ void merge_switch_to_result(struct merge_options *opt,
3202 /* Also include needed rename limit adjustment now */
3203 diff_warn_rename_limit("merge.renamelimit",
3204 opti->renames.needed_limit, 0);
3205 +
3206 + trace2_region_leave("merge", "display messages", opt->repo);
3207 }
3208
3209 merge_finalize(opt, result);
@@ -3212,6 +3245,7 @@ static void merge_start(struct merge_options *opt, struct merge_result *result)
3245 int i;
3246
3247 /* Sanity checks on opt */
3248 + trace2_region_enter("merge", "sanity checks", opt->repo);
3249 assert(opt->repo);
3250
3251 assert(opt->branch1 && opt->branch2);
@@ -3250,11 +3284,13 @@ static void merge_start(struct merge_options *opt, struct merge_result *result)
3284 assert(!opt->priv->toplevel_dir ||
3285 0 == strlen(opt->priv->toplevel_dir));
3286 }
3287 + trace2_region_leave("merge", "sanity checks", opt->repo);
3288
3289 /* Default to histogram diff. Actually, just hardcode it...for now. */
3290 opt->xdl_opts = DIFF_WITH_ALG(opt, HISTOGRAM_DIFF);
3291
3292 /* Initialization of opt->priv, our internal merge data */
3293 + trace2_region_enter("merge", "allocate/init", opt->repo);
3294 if (opt->priv) {
3295 clear_or_reinit_internal_opts(opt->priv, 1);
3296 trace2_region_leave("merge", "allocate/init", opt->repo);
@@ -3292,6 +3328,8 @@ static void merge_start(struct merge_options *opt, struct merge_result *result)
3328 * subset of the overall paths that have special output.
3329 */
3330 strmap_init(&opt->priv->output);
3331 +
3332 + trace2_region_leave("merge", "allocate/init", opt->repo);
3333 }
3334
3335 /*** Function Grouping: merge_incore_*() and their internal variants ***/
@@ -3307,6 +3345,7 @@ static void merge_ort_nonrecursive_internal(struct merge_options *opt,
3345 {
3346 struct object_id working_tree_oid;
3347
3348 + trace2_region_enter("merge", "collect_merge_info", opt->repo);
3349 if (collect_merge_info(opt, merge_base, side1, side2) != 0) {
3350 /*
3351 * TRANSLATORS: The %s arguments are: 1) tree hash of a merge
@@ -3319,10 +3358,16 @@ static void merge_ort_nonrecursive_internal(struct merge_options *opt,
3358 result->clean = -1;
3359 return;
3360 }
3361 + trace2_region_leave("merge", "collect_merge_info", opt->repo);
3362
3363 + trace2_region_enter("merge", "renames", opt->repo);
3364 result->clean = detect_and_process_renames(opt, merge_base,
3365 side1, side2);
3366 + trace2_region_leave("merge", "renames", opt->repo);
3367 +
3368 + trace2_region_enter("merge", "process_entries", opt->repo);
3369 process_entries(opt, &working_tree_oid);
3370 + trace2_region_leave("merge", "process_entries", opt->repo);
3371
3372 /* Set return values */
3373 result->tree = parse_tree_indirect(&working_tree_oid);
@@ -3423,9 +3468,15 @@ void merge_incore_nonrecursive(struct merge_options *opt,
3468 struct tree *side2,
3469 struct merge_result *result)
3470 {
3471 + trace2_region_enter("merge", "incore_nonrecursive", opt->repo);
3472 +
3473 + trace2_region_enter("merge", "merge_start", opt->repo);
3474 assert(opt->ancestor != NULL);
3475 merge_start(opt, result);
3476 + trace2_region_leave("merge", "merge_start", opt->repo);
3477 +
3478 merge_ort_nonrecursive_internal(opt, merge_base, side1, side2, result);
3479 + trace2_region_leave("merge", "incore_nonrecursive", opt->repo);
3480 }
3481
3482 void merge_incore_recursive(struct merge_options *opt,
@@ -3434,9 +3485,15 @@ void merge_incore_recursive(struct merge_options *opt,
3485 struct commit *side2,
3486 struct merge_result *result)
3487 {
3488 + trace2_region_enter("merge", "incore_recursive", opt->repo);
3489 +
3490 /* We set the ancestor label based on the merge_bases */
3491 assert(opt->ancestor == NULL);
3492
3493 + trace2_region_enter("merge", "merge_start", opt->repo);
3494 merge_start(opt, result);
3495 + trace2_region_leave("merge", "merge_start", opt->repo);
3496 +
3497 merge_ort_internal(opt, merge_bases, side1, side2, result);
3498 + trace2_region_leave("merge", "incore_recursive", opt->repo);
3499 }