dir: convert trace calls to trace2 equivalents

Signed-off-by: Elijah Newren <newren@gmail.com> Signed-off-by: Junio C Hamano <gitster@pobox.com>

Elijah Newren committed May 12, 2021 at 17:28 UTC 7f9dd87922c9065c8adcea1469c3caf3b3af2afa
3 files changed +162 -101
dir.c
+37 -13
@@ -2751,15 +2751,46 @@ static struct untracked_cache_dir *validate_untracked_cache(struct dir_struct *d
2751 return root;
2752 }
2753
2754 +static void emit_traversal_statistics(struct dir_struct *dir,
2755 + struct repository *repo,
2756 + const char *path,
2757 + int path_len)
2758 +{
2759 + if (!trace2_is_enabled())
2760 + return;
2761 +
2762 + if (!path_len) {
2763 + trace2_data_string("read_directory", repo, "path", "");
2764 + } else {
2765 + struct strbuf tmp = STRBUF_INIT;
2766 + strbuf_add(&tmp, path, path_len);
2767 + trace2_data_string("read_directory", repo, "path", tmp.buf);
2768 + strbuf_release(&tmp);
2769 + }
2770 +
2771 + if (!dir->untracked)
2772 + return;
2773 + trace2_data_intmax("read_directory", repo,
2774 + "node-creation", dir->untracked->dir_created);
2775 + trace2_data_intmax("read_directory", repo,
2776 + "gitignore-invalidation",
2777 + dir->untracked->gitignore_invalidated);
2778 + trace2_data_intmax("read_directory", repo,
2779 + "directory-invalidation",
2780 + dir->untracked->dir_invalidated);
2781 + trace2_data_intmax("read_directory", repo,
2782 + "opendir", dir->untracked->dir_opened);
2783 +}
2784 +
2785 int read_directory(struct dir_struct *dir, struct index_state *istate,
2786 const char *path, int len, const struct pathspec *pathspec)
2787 {
2788 struct untracked_cache_dir *untracked;
2789
2759 - trace_performance_enter();
2790 + trace2_region_enter("dir", "read_directory", istate->repo);
2791
2792 if (has_symlink_leading_path(path, len)) {
2762 - trace_performance_leave("read directory %.*s", len, path);
2793 + trace2_region_leave("dir", "read_directory", istate->repo);
2794 return dir->nr;
2795 }
2796
@@ -2775,23 +2806,15 @@ int read_directory(struct dir_struct *dir, struct index_state *istate,
2806 QSORT(dir->entries, dir->nr, cmp_dir_entry);
2807 QSORT(dir->ignored, dir->ignored_nr, cmp_dir_entry);
2808
2778 - trace_performance_leave("read directory %.*s", len, path);
2809 + emit_traversal_statistics(dir, istate->repo, path, len);
2810 +
2811 + trace2_region_leave("dir", "read_directory", istate->repo);
2812 if (dir->untracked) {
2813 static int force_untracked_cache = -1;
2781 - static struct trace_key trace_untracked_stats = TRACE_KEY_INIT(UNTRACKED_STATS);
2814
2815 if (force_untracked_cache < 0)
2816 force_untracked_cache =
2817 git_env_bool("GIT_FORCE_UNTRACKED_CACHE", 0);
2786 - trace_printf_key(&trace_untracked_stats,
2787 - "node creation: %u\n"
2788 - "gitignore invalidation: %u\n"
2789 - "directory invalidation: %u\n"
2790 - "opendir: %u\n",
2791 - dir->untracked->dir_created,
2792 - dir->untracked->gitignore_invalidated,
2793 - dir->untracked->dir_invalidated,
2794 - dir->untracked->dir_opened);
2818 if (force_untracked_cache &&
2819 dir->untracked == istate->untracked &&
2820 (dir->untracked->dir_opened ||
@@ -2802,6 +2825,7 @@ int read_directory(struct dir_struct *dir, struct index_state *istate,
2825 FREE_AND_NULL(dir->untracked);
2826 }
2827 }
2828 +
2829 return dir->nr;
2830 }
2831
t/t7063-status-untracked-cache.sh
+121 -84
@@ -57,6 +57,19 @@ iuc () {
57 return $ret
58 }
59
60 +get_relevant_traces () {
61 + # From the GIT_TRACE2_PERF data of the form
62 + # $TIME $FILE:$LINE | d0 | main | data | r1 | ? | ? | read_directo | $RELEVANT_STAT
63 + # extract the $RELEVANT_STAT fields. We don't care about region_enter
64 + # or region_leave, or stats for things outside read_directory.
65 + INPUT_FILE=$1
66 + OUTPUT_FILE=$2
67 + grep data.*read_directo $INPUT_FILE |
68 + cut -d "|" -f 9 \
69 + >"$OUTPUT_FILE"
70 +}
71 +
72 +
73 test_lazy_prereq UNTRACKED_CACHE '
74 { git update-index --test-untracked-cache; ret=$?; } &&
75 test $ret -ne 1
@@ -129,19 +142,21 @@ EOF
142
143 test_expect_success 'status first time (empty cache)' '
144 avoid_racy &&
132 - : >../trace &&
133 - GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace" \
145 + : >../trace.output &&
146 + GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace.output" \
147 git status --porcelain >../actual &&
148 iuc status --porcelain >../status.iuc &&
149 test_cmp ../status.expect ../status.iuc &&
150 test_cmp ../status.expect ../actual &&
151 + get_relevant_traces ../trace.output ../trace.relevant &&
152 cat >../trace.expect <<EOF &&
139 -node creation: 3
140 -gitignore invalidation: 1
141 -directory invalidation: 0
142 -opendir: 4
153 + ....path:
154 + ....node-creation:3
155 + ....gitignore-invalidation:1
156 + ....directory-invalidation:0
157 + ....opendir:4
158 EOF
144 - test_cmp ../trace.expect ../trace
159 + test_cmp ../trace.expect ../trace.relevant
160 '
161
162 test_expect_success 'untracked cache after first status' '
@@ -151,19 +166,21 @@ test_expect_success 'untracked cache after first status' '
166
167 test_expect_success 'status second time (fully populated cache)' '
168 avoid_racy &&
154 - : >../trace &&
155 - GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace" \
169 + : >../trace.output &&
170 + GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace.output" \
171 git status --porcelain >../actual &&
172 iuc status --porcelain >../status.iuc &&
173 test_cmp ../status.expect ../status.iuc &&
174 test_cmp ../status.expect ../actual &&
175 + get_relevant_traces ../trace.output ../trace.relevant &&
176 cat >../trace.expect <<EOF &&
161 -node creation: 0
162 -gitignore invalidation: 0
163 -directory invalidation: 0
164 -opendir: 0
177 + ....path:
178 + ....node-creation:0
179 + ....gitignore-invalidation:0
180 + ....directory-invalidation:0
181 + ....opendir:0
182 EOF
166 - test_cmp ../trace.expect ../trace
183 + test_cmp ../trace.expect ../trace.relevant
184 '
185
186 test_expect_success 'untracked cache after second status' '
@@ -174,8 +191,8 @@ test_expect_success 'untracked cache after second status' '
191 test_expect_success 'modify in root directory, one dir invalidation' '
192 avoid_racy &&
193 : >four &&
177 - : >../trace &&
178 - GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace" \
194 + : >../trace.output &&
195 + GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace.output" \
196 git status --porcelain >../actual &&
197 iuc status --porcelain >../status.iuc &&
198 cat >../status.expect <<EOF &&
@@ -189,13 +206,15 @@ A two
206 EOF
207 test_cmp ../status.expect ../status.iuc &&
208 test_cmp ../status.expect ../actual &&
209 + get_relevant_traces ../trace.output ../trace.relevant &&
210 cat >../trace.expect <<EOF &&
193 -node creation: 0
194 -gitignore invalidation: 0
195 -directory invalidation: 1
196 -opendir: 1
211 + ....path:
212 + ....node-creation:0
213 + ....gitignore-invalidation:0
214 + ....directory-invalidation:1
215 + ....opendir:1
216 EOF
198 - test_cmp ../trace.expect ../trace
217 + test_cmp ../trace.expect ../trace.relevant
218
219 '
220
@@ -223,8 +242,8 @@ EOF
242 test_expect_success 'new .gitignore invalidates recursively' '
243 avoid_racy &&
244 echo four >.gitignore &&
226 - : >../trace &&
227 - GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace" \
245 + : >../trace.output &&
246 + GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace.output" \
247 git status --porcelain >../actual &&
248 iuc status --porcelain >../status.iuc &&
249 cat >../status.expect <<EOF &&
@@ -238,13 +257,15 @@ A two
257 EOF
258 test_cmp ../status.expect ../status.iuc &&
259 test_cmp ../status.expect ../actual &&
260 + get_relevant_traces ../trace.output ../trace.relevant &&
261 cat >../trace.expect <<EOF &&
242 -node creation: 0
243 -gitignore invalidation: 1
244 -directory invalidation: 1
245 -opendir: 4
262 + ....path:
263 + ....node-creation:0
264 + ....gitignore-invalidation:1
265 + ....directory-invalidation:1
266 + ....opendir:4
267 EOF
247 - test_cmp ../trace.expect ../trace
268 + test_cmp ../trace.expect ../trace.relevant
269
270 '
271
@@ -272,8 +293,8 @@ EOF
293 test_expect_success 'new info/exclude invalidates everything' '
294 avoid_racy &&
295 echo three >>.git/info/exclude &&
275 - : >../trace &&
276 - GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace" \
296 + : >../trace.output &&
297 + GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace.output" \
298 git status --porcelain >../actual &&
299 iuc status --porcelain >../status.iuc &&
300 cat >../status.expect <<EOF &&
@@ -285,13 +306,15 @@ A two
306 EOF
307 test_cmp ../status.expect ../status.iuc &&
308 test_cmp ../status.expect ../actual &&
309 + get_relevant_traces ../trace.output ../trace.relevant &&
310 cat >../trace.expect <<EOF &&
289 -node creation: 0
290 -gitignore invalidation: 1
291 -directory invalidation: 0
292 -opendir: 4
311 + ....path:
312 + ....node-creation:0
313 + ....gitignore-invalidation:1
314 + ....directory-invalidation:0
315 + ....opendir:4
316 EOF
294 - test_cmp ../trace.expect ../trace
317 + test_cmp ../trace.expect ../trace.relevant
318 '
319
320 test_expect_success 'verify untracked cache dump' '
@@ -330,8 +353,8 @@ EOF
353 '
354
355 test_expect_success 'status after the move' '
333 - : >../trace &&
334 - GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace" \
356 + : >../trace.output &&
357 + GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace.output" \
358 git status --porcelain >../actual &&
359 iuc status --porcelain >../status.iuc &&
360 cat >../status.expect <<EOF &&
@@ -343,13 +366,15 @@ A one
366 EOF
367 test_cmp ../status.expect ../status.iuc &&
368 test_cmp ../status.expect ../actual &&
369 + get_relevant_traces ../trace.output ../trace.relevant &&
370 cat >../trace.expect <<EOF &&
347 -node creation: 0
348 -gitignore invalidation: 0
349 -directory invalidation: 0
350 -opendir: 1
371 + ....path:
372 + ....node-creation:0
373 + ....gitignore-invalidation:0
374 + ....directory-invalidation:0
375 + ....opendir:1
376 EOF
352 - test_cmp ../trace.expect ../trace
377 + test_cmp ../trace.expect ../trace.relevant
378 '
379
380 test_expect_success 'verify untracked cache dump' '
@@ -389,8 +414,8 @@ EOF
414 '
415
416 test_expect_success 'status after the move' '
392 - : >../trace &&
393 - GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace" \
417 + : >../trace.output &&
418 + GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace.output" \
419 git status --porcelain >../actual &&
420 iuc status --porcelain >../status.iuc &&
421 cat >../status.expect <<EOF &&
@@ -402,13 +427,15 @@ A two
427 EOF
428 test_cmp ../status.expect ../status.iuc &&
429 test_cmp ../status.expect ../actual &&
430 + get_relevant_traces ../trace.output ../trace.relevant &&
431 cat >../trace.expect <<EOF &&
406 -node creation: 0
407 -gitignore invalidation: 0
408 -directory invalidation: 0
409 -opendir: 1
432 + ....path:
433 + ....node-creation:0
434 + ....gitignore-invalidation:0
435 + ....directory-invalidation:0
436 + ....opendir:1
437 EOF
411 - test_cmp ../trace.expect ../trace
438 + test_cmp ../trace.expect ../trace.relevant
439 '
440
441 test_expect_success 'verify untracked cache dump' '
@@ -438,8 +465,8 @@ test_expect_success 'set up for sparse checkout testing' '
465 '
466
467 test_expect_success 'status after commit' '
441 - : >../trace &&
442 - GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace" \
468 + : >../trace.output &&
469 + GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace.output" \
470 git status --porcelain >../actual &&
471 iuc status --porcelain >../status.iuc &&
472 cat >../status.expect <<EOF &&
@@ -448,13 +475,15 @@ test_expect_success 'status after commit' '
475 EOF
476 test_cmp ../status.expect ../status.iuc &&
477 test_cmp ../status.expect ../actual &&
478 + get_relevant_traces ../trace.output ../trace.relevant &&
479 cat >../trace.expect <<EOF &&
452 -node creation: 0
453 -gitignore invalidation: 0
454 -directory invalidation: 0
455 -opendir: 2
480 + ....path:
481 + ....node-creation:0
482 + ....gitignore-invalidation:0
483 + ....directory-invalidation:0
484 + ....opendir:2
485 EOF
457 - test_cmp ../trace.expect ../trace
486 + test_cmp ../trace.expect ../trace.relevant
487 '
488
489 test_expect_success 'untracked cache correct after commit' '
@@ -496,9 +525,9 @@ test_expect_success 'create/modify files, some of which are gitignored' '
525 '
526
527 test_expect_success 'test sparse status with untracked cache' '
499 - : >../trace &&
528 + : >../trace.output &&
529 avoid_racy &&
501 - GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace" \
530 + GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace.output" \
531 git status --porcelain >../status.actual &&
532 iuc status --porcelain >../status.iuc &&
533 cat >../status.expect <<EOF &&
@@ -509,13 +538,15 @@ test_expect_success 'test sparse status with untracked cache' '
538 EOF
539 test_cmp ../status.expect ../status.iuc &&
540 test_cmp ../status.expect ../status.actual &&
541 + get_relevant_traces ../trace.output ../trace.relevant &&
542 cat >../trace.expect <<EOF &&
513 -node creation: 0
514 -gitignore invalidation: 1
515 -directory invalidation: 2
516 -opendir: 2
543 + ....path:
544 + ....node-creation:0
545 + ....gitignore-invalidation:1
546 + ....directory-invalidation:2
547 + ....opendir:2
548 EOF
518 - test_cmp ../trace.expect ../trace
549 + test_cmp ../trace.expect ../trace.relevant
550 '
551
552 test_expect_success 'untracked cache correct after status' '
@@ -539,8 +570,8 @@ EOF
570
571 test_expect_success 'test sparse status again with untracked cache' '
572 avoid_racy &&
542 - : >../trace &&
543 - GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace" \
573 + : >../trace.output &&
574 + GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace.output" \
575 git status --porcelain >../status.actual &&
576 iuc status --porcelain >../status.iuc &&
577 cat >../status.expect <<EOF &&
@@ -551,13 +582,15 @@ test_expect_success 'test sparse status again with untracked cache' '
582 EOF
583 test_cmp ../status.expect ../status.iuc &&
584 test_cmp ../status.expect ../status.actual &&
585 + get_relevant_traces ../trace.output ../trace.relevant &&
586 cat >../trace.expect <<EOF &&
555 -node creation: 0
556 -gitignore invalidation: 0
557 -directory invalidation: 0
558 -opendir: 0
587 + ....path:
588 + ....node-creation:0
589 + ....gitignore-invalidation:0
590 + ....directory-invalidation:0
591 + ....opendir:0
592 EOF
560 - test_cmp ../trace.expect ../trace
593 + test_cmp ../trace.expect ../trace.relevant
594 '
595
596 test_expect_success 'set up for test of subdir and sparse checkouts' '
@@ -568,8 +601,8 @@ test_expect_success 'set up for test of subdir and sparse checkouts' '
601
602 test_expect_success 'test sparse status with untracked cache and subdir' '
603 avoid_racy &&
571 - : >../trace &&
572 - GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace" \
604 + : >../trace.output &&
605 + GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace.output" \
606 git status --porcelain >../status.actual &&
607 iuc status --porcelain >../status.iuc &&
608 cat >../status.expect <<EOF &&
@@ -581,13 +614,15 @@ test_expect_success 'test sparse status with untracked cache and subdir' '
614 EOF
615 test_cmp ../status.expect ../status.iuc &&
616 test_cmp ../status.expect ../status.actual &&
617 + get_relevant_traces ../trace.output ../trace.relevant &&
618 cat >../trace.expect <<EOF &&
585 -node creation: 2
586 -gitignore invalidation: 0
587 -directory invalidation: 1
588 -opendir: 3
619 + ....path:
620 + ....node-creation:2
621 + ....gitignore-invalidation:0
622 + ....directory-invalidation:1
623 + ....opendir:3
624 EOF
590 - test_cmp ../trace.expect ../trace
625 + test_cmp ../trace.expect ../trace.relevant
626 '
627
628 test_expect_success 'verify untracked cache dump (sparse/subdirs)' '
@@ -616,19 +651,21 @@ EOF
651
652 test_expect_success 'test sparse status again with untracked cache and subdir' '
653 avoid_racy &&
619 - : >../trace &&
620 - GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace" \
654 + : >../trace.output &&
655 + GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace.output" \
656 git status --porcelain >../status.actual &&
657 iuc status --porcelain >../status.iuc &&
658 test_cmp ../status.expect ../status.iuc &&
659 test_cmp ../status.expect ../status.actual &&
660 + get_relevant_traces ../trace.output ../trace.relevant &&
661 cat >../trace.expect <<EOF &&
626 -node creation: 0
627 -gitignore invalidation: 0
628 -directory invalidation: 0
629 -opendir: 0
662 + ....path:
663 + ....node-creation:0
664 + ....gitignore-invalidation:0
665 + ....directory-invalidation:0
666 + ....opendir:0
667 EOF
631 - test_cmp ../trace.expect ../trace
668 + test_cmp ../trace.expect ../trace.relevant
669 '
670
671 test_expect_success 'move entry in subdir from untracked to cached' '
t/t7519-status-fsmonitor.sh
+4 -4
@@ -334,7 +334,7 @@ test_expect_success UNTRACKED_CACHE 'ignore .git changes when invalidating UNTR'
334 git config core.fsmonitor .git/hooks/fsmonitor-test &&
335 git update-index --untracked-cache &&
336 git update-index --fsmonitor &&
337 - GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace-before" \
337 + GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace-before" \
338 git status &&
339 test-tool dump-untracked-cache >../before
340 ) &&
@@ -346,12 +346,12 @@ test_expect_success UNTRACKED_CACHE 'ignore .git changes when invalidating UNTR'
346 EOF
347 (
348 cd dot-git &&
349 - GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace-after" \
349 + GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace-after" \
350 git status &&
351 test-tool dump-untracked-cache >../after
352 ) &&
353 - grep "directory invalidation" trace-before >>before &&
354 - grep "directory invalidation" trace-after >>after &&
353 + grep "directory-invalidation" trace-before | cut -d"|" -f 9 >>before &&
354 + grep "directory-invalidation" trace-after | cut -d"|" -f 9 >>after &&
355 # UNTR extension unchanged, dir invalidation count unchanged
356 test_cmp before after
357 '