diff mbox series

[v3,1/8,RFC] dir: convert trace calls to trace2 equivalents

Message ID 9f1c0d78d739cc1da8517eea92e81a7bd162578f.1620503945.git.gitgitgadget@gmail.com (mailing list archive)
State Superseded
Headers show
Series Directory traversal fixes | expand

Commit Message

Elijah Newren May 8, 2021, 7:58 p.m. UTC
From: Elijah Newren <newren@gmail.com>

Signed-off-by: Elijah Newren <newren@gmail.com>
---
 dir.c                             |  34 ++++--
 t/t7063-status-untracked-cache.sh | 193 +++++++++++++++++-------------
 t/t7519-status-fsmonitor.sh       |   8 +-
 3 files changed, 135 insertions(+), 100 deletions(-)

Comments

Junio C Hamano May 10, 2021, 4:49 a.m. UTC | #1
"Elijah Newren via GitGitGadget" <gitgitgadget@gmail.com> writes:

> +static void trace2_read_directory_statistics(struct dir_struct *dir,
> +					     struct repository *repo)
> +{
> +	if (!dir->untracked)
> +		return;
> +	trace2_data_intmax("read_directory", repo,
> +			   "node-creation", dir->untracked->dir_created);
> +	trace2_data_intmax("read_directory", repo,
> +			   "gitignore-invalidation",
> +			   dir->untracked->gitignore_invalidated);
> +	trace2_data_intmax("read_directory", repo,
> +			   "directory-invalidation",
> +			   dir->untracked->dir_invalidated);
> +	trace2_data_intmax("read_directory", repo,
> +			   "opendir", dir->untracked->dir_opened);
> +}
> +

This obviously looks like an equivalent to what happens in the
original inside the "if (dir->untracked)" block.

And we have a performance_{enter,leave} pair replaced with
a region_[enter,leave} pair. 

> -	trace_performance_enter();
> +	trace2_region_enter("dir", "read_directory", istate->repo);
>   ...
> -	trace_performance_leave("read directory %.*s", len, path);
> +	trace2_region_leave("dir", "read_directory", istate->repo);

>  	if (dir->untracked) {
>  		static int force_untracked_cache = -1;
> -		static struct trace_key trace_untracked_stats = TRACE_KEY_INIT(UNTRACKED_STATS);
>  
>  		if (force_untracked_cache < 0)
>  			force_untracked_cache =
>  				git_env_bool("GIT_FORCE_UNTRACKED_CACHE", 0);
> -		trace_printf_key(&trace_untracked_stats,
> -				 "node creation: %u\n"
> -				 "gitignore invalidation: %u\n"
> -				 "directory invalidation: %u\n"
> -				 "opendir: %u\n",
> -				 dir->untracked->dir_created,
> -				 dir->untracked->gitignore_invalidated,
> -				 dir->untracked->dir_invalidated,
> -				 dir->untracked->dir_opened);
>  		if (force_untracked_cache &&
>  			dir->untracked == istate->untracked &&
>  		    (dir->untracked->dir_opened ||

Removal of the trace_printf() in the middle made the body of this
if() statement much less distracting, which is good.

> @@ -2811,6 +2818,9 @@ int read_directory(struct dir_struct *dir, struct index_state *istate,
>  			FREE_AND_NULL(dir->untracked);
>  		}
>  	}
> +
> +	if (trace2_is_enabled())
> +		trace2_read_directory_statistics(dir, istate->repo);

This slightly changes the semantics in that the original did an
equivalent emitting from inside the "if (dir->untracked)" block, but
this call is hoisted outside, and the new helper knows how to be
silent when untracked thing is not in effect, so the net effect at
this step is the same.  And if we ever add tracing statics that is
relevant when !dir->untracked is true, the new code organization is
easier to work with.

The only curious thing is the guard "if (trace2_is_enabled())";
correctness-wise, are there bad things going to happen if it is not
here, or is this a performance hack, or is it more for its
documentation value (meaning, it would be a bug if we later added
things that are irrelevant when trace is not enabled to the helper)?

> @@ -57,6 +57,19 @@ iuc () {
>  	return $ret
>  }
>  
> +get_relevant_traces() {

Style.  SP on both sides of "()".

> +	# From the GIT_TRACE2_PERF data of the form
> +	#    $TIME $FILE:$LINE | d0 | main | data | r1 | ? | ? | read_directo | $RELEVANT_STAT
> +	# extract the $RELEVANT_STAT fields.  We don't care about region_enter
> +	# or region_leave, or stats for things outside read_directory.
> +	INPUT_FILE=$1
> +	OUTPUT_FILE=$2
> +	grep data.*read_directo $INPUT_FILE \
> +	    | cut -d "|" -f 9 \
> +	    >$OUTPUT_FILE

Style.  Wrapping the line after pipe '|' will allow you to omit the
backslash.  Also quote the redirection target, i.e. >"$OUTPUT_FILE",
to help certain vintage of bash.

Those who are more familiar with the trace2 infrastructure may want
to further comment, but it looked obvious and straightforward to me.

Thanks.
Jeff Hostetler May 11, 2021, 4:17 p.m. UTC | #2
On 5/8/21 3:58 PM, Elijah Newren via GitGitGadget wrote:
> From: Elijah Newren <newren@gmail.com>
> 
> Signed-off-by: Elijah Newren <newren@gmail.com>
> ---
>   dir.c                             |  34 ++++--
>   t/t7063-status-untracked-cache.sh | 193 +++++++++++++++++-------------
>   t/t7519-status-fsmonitor.sh       |   8 +-
>   3 files changed, 135 insertions(+), 100 deletions(-)
> 
> diff --git a/dir.c b/dir.c
> index 3474e67e8f3c..9f7c8debeab3 100644
> --- a/dir.c
> +++ b/dir.c
> @@ -2760,12 +2760,29 @@ static struct untracked_cache_dir *validate_untracked_cache(struct dir_struct *d
>   	return root;
>   }
>   
> +static void trace2_read_directory_statistics(struct dir_struct *dir,
> +					     struct repository *repo)
> +{
> +	if (!dir->untracked)
> +		return;

Is there value to also printing the path?
The existing `trace_performance_leave()` calls were, but
I'm familiar enough with this code to say if the output
wasn't always something like ".".

> +	trace2_data_intmax("read_directory", repo,
> +			   "node-creation", dir->untracked->dir_created);
> +	trace2_data_intmax("read_directory", repo,
> +			   "gitignore-invalidation",
> +			   dir->untracked->gitignore_invalidated);
> +	trace2_data_intmax("read_directory", repo,
> +			   "directory-invalidation",
> +			   dir->untracked->dir_invalidated);
> +	trace2_data_intmax("read_directory", repo,
> +			   "opendir", dir->untracked->dir_opened);
> +}
> +

The existing code was quite tangled and I think this helps
make things more clear.


>   int read_directory(struct dir_struct *dir, struct index_state *istate,
>   		   const char *path, int len, const struct pathspec *pathspec)
>   {
>   	struct untracked_cache_dir *untracked;
>   
> -	trace_performance_enter();
> +	trace2_region_enter("dir", "read_directory", istate->repo);
>   
>   	if (has_symlink_leading_path(path, len)) {
>   		trace_performance_leave("read directory %.*s", len, path);

This `trace_performance_leave()` inside the `if` needs to be
converted too.


> @@ -2784,23 +2801,13 @@ int read_directory(struct dir_struct *dir, struct index_state *istate,
>   	QSORT(dir->entries, dir->nr, cmp_dir_entry);
>   	QSORT(dir->ignored, dir->ignored_nr, cmp_dir_entry);
>   
> -	trace_performance_leave("read directory %.*s", len, path);
> +	trace2_region_leave("dir", "read_directory", istate->repo);

Can we put the call to `trace2_read_directory_statistics()` before
the above `trace2_region_leave()` call?   Then those stats will
appear indented between the begin- and end-region events in the output.

That way, the following `if (dir-untracked) {...}` is only
concerned with the untracked cache and/or freeing that data.

>   	if (dir->untracked) {
>   		static int force_untracked_cache = -1;
> -		static struct trace_key trace_untracked_stats = TRACE_KEY_INIT(UNTRACKED_STATS);
>   
>   		if (force_untracked_cache < 0)
>   			force_untracked_cache =
>   				git_env_bool("GIT_FORCE_UNTRACKED_CACHE", 0);
> -		trace_printf_key(&trace_untracked_stats,
> -				 "node creation: %u\n"
> -				 "gitignore invalidation: %u\n"
> -				 "directory invalidation: %u\n"
> -				 "opendir: %u\n",
> -				 dir->untracked->dir_created,
> -				 dir->untracked->gitignore_invalidated,
> -				 dir->untracked->dir_invalidated,
> -				 dir->untracked->dir_opened);
>   		if (force_untracked_cache &&
>   			dir->untracked == istate->untracked &&
>   		    (dir->untracked->dir_opened ||
> @@ -2811,6 +2818,9 @@ int read_directory(struct dir_struct *dir, struct index_state *istate,
>   			FREE_AND_NULL(dir->untracked);
>   		}
>   	}
> +
> +	if (trace2_is_enabled())
> +		trace2_read_directory_statistics(dir, istate->repo);

Also, I think it'd be ok to move the `trace2_is_enabled()` call
inside the function.  Since we're also testing `!dir->untracked`
inside the function.

The more that I look at the before and after versions, the
more I think the `trace2_read_directory_statistics()` call
should be up before the `trace2_region_leave()`.  Here at the
bottom of the function, we may have already freed `dir->untracked`.
I'm not familiar enough with this code to know if that is a
good or bad thing.


>   	return dir->nr;
>   }
>   
...


Thanks,
Jeff
Elijah Newren May 11, 2021, 5:23 p.m. UTC | #3
On Sun, May 9, 2021 at 9:49 PM Junio C Hamano <gitster@pobox.com> wrote:
>
> "Elijah Newren via GitGitGadget" <gitgitgadget@gmail.com> writes:
>
> > +static void trace2_read_directory_statistics(struct dir_struct *dir,
> > +                                          struct repository *repo)
> > +{
> > +     if (!dir->untracked)
> > +             return;
> > +     trace2_data_intmax("read_directory", repo,
> > +                        "node-creation", dir->untracked->dir_created);
> > +     trace2_data_intmax("read_directory", repo,
> > +                        "gitignore-invalidation",
> > +                        dir->untracked->gitignore_invalidated);
> > +     trace2_data_intmax("read_directory", repo,
> > +                        "directory-invalidation",
> > +                        dir->untracked->dir_invalidated);
> > +     trace2_data_intmax("read_directory", repo,
> > +                        "opendir", dir->untracked->dir_opened);
> > +}
> > +
>
> This obviously looks like an equivalent to what happens in the
> original inside the "if (dir->untracked)" block.
>
> And we have a performance_{enter,leave} pair replaced with
> a region_[enter,leave} pair.
>
> > -     trace_performance_enter();
> > +     trace2_region_enter("dir", "read_directory", istate->repo);
> >   ...
> > -     trace_performance_leave("read directory %.*s", len, path);
> > +     trace2_region_leave("dir", "read_directory", istate->repo);
>
> >       if (dir->untracked) {
> >               static int force_untracked_cache = -1;
> > -             static struct trace_key trace_untracked_stats = TRACE_KEY_INIT(UNTRACKED_STATS);
> >
> >               if (force_untracked_cache < 0)
> >                       force_untracked_cache =
> >                               git_env_bool("GIT_FORCE_UNTRACKED_CACHE", 0);
> > -             trace_printf_key(&trace_untracked_stats,
> > -                              "node creation: %u\n"
> > -                              "gitignore invalidation: %u\n"
> > -                              "directory invalidation: %u\n"
> > -                              "opendir: %u\n",
> > -                              dir->untracked->dir_created,
> > -                              dir->untracked->gitignore_invalidated,
> > -                              dir->untracked->dir_invalidated,
> > -                              dir->untracked->dir_opened);
> >               if (force_untracked_cache &&
> >                       dir->untracked == istate->untracked &&
> >                   (dir->untracked->dir_opened ||
>
> Removal of the trace_printf() in the middle made the body of this
> if() statement much less distracting, which is good.
>
> > @@ -2811,6 +2818,9 @@ int read_directory(struct dir_struct *dir, struct index_state *istate,
> >                       FREE_AND_NULL(dir->untracked);
> >               }
> >       }
> > +
> > +     if (trace2_is_enabled())
> > +             trace2_read_directory_statistics(dir, istate->repo);
>
> This slightly changes the semantics in that the original did an
> equivalent emitting from inside the "if (dir->untracked)" block, but
> this call is hoisted outside, and the new helper knows how to be
> silent when untracked thing is not in effect, so the net effect at
> this step is the same.  And if we ever add tracing statics that is
> relevant when !dir->untracked is true, the new code organization is
> easier to work with.
>
> The only curious thing is the guard "if (trace2_is_enabled())";
> correctness-wise, are there bad things going to happen if it is not
> here, or is this a performance hack, or is it more for its
> documentation value (meaning, it would be a bug if we later added
> things that are irrelevant when trace is not enabled to the helper)?

No, there's nothing bad that would happen here.  It was a combination
of a performance hack and documentation in case
trace2_read_directory_statistics() started gaining other code besides
trace2_*() calls, but which code was only relevant when trace2 was
enabled.

Turns out, though, that Jeff's suggestion to also print the path in
the statistics is going to require me creating a temporary strbuf so
that I can get a NUL-terminated string.  We only want to do that when
trace2_is_enabled(), so that will make the introduction of that check
a bit more natural.

> > @@ -57,6 +57,19 @@ iuc () {
> >       return $ret
> >  }
> >
> > +get_relevant_traces() {
>
> Style.  SP on both sides of "()".

Will fix.

>
> > +     # From the GIT_TRACE2_PERF data of the form
> > +     #    $TIME $FILE:$LINE | d0 | main | data | r1 | ? | ? | read_directo | $RELEVANT_STAT
> > +     # extract the $RELEVANT_STAT fields.  We don't care about region_enter
> > +     # or region_leave, or stats for things outside read_directory.
> > +     INPUT_FILE=$1
> > +     OUTPUT_FILE=$2
> > +     grep data.*read_directo $INPUT_FILE \
> > +         | cut -d "|" -f 9 \
> > +         >$OUTPUT_FILE
>
> Style.  Wrapping the line after pipe '|' will allow you to omit the
> backslash.  Also quote the redirection target, i.e. >"$OUTPUT_FILE",
> to help certain vintage of bash.

Will fix.
Elijah Newren May 11, 2021, 5:29 p.m. UTC | #4
On Tue, May 11, 2021 at 9:17 AM Jeff Hostetler <git@jeffhostetler.com> wrote:
>
> On 5/8/21 3:58 PM, Elijah Newren via GitGitGadget wrote:
> > From: Elijah Newren <newren@gmail.com>
> >
> > Signed-off-by: Elijah Newren <newren@gmail.com>
> > ---
> >   dir.c                             |  34 ++++--
> >   t/t7063-status-untracked-cache.sh | 193 +++++++++++++++++-------------
> >   t/t7519-status-fsmonitor.sh       |   8 +-
> >   3 files changed, 135 insertions(+), 100 deletions(-)
> >
> > diff --git a/dir.c b/dir.c
> > index 3474e67e8f3c..9f7c8debeab3 100644
> > --- a/dir.c
> > +++ b/dir.c
> > @@ -2760,12 +2760,29 @@ static struct untracked_cache_dir *validate_untracked_cache(struct dir_struct *d
> >       return root;
> >   }
> >
> > +static void trace2_read_directory_statistics(struct dir_struct *dir,
> > +                                          struct repository *repo)
> > +{
> > +     if (!dir->untracked)
> > +             return;
>
> Is there value to also printing the path?
> The existing `trace_performance_leave()` calls were, but
> I'm familiar enough with this code to say if the output
> wasn't always something like ".".

The path will most likely just be "" (i.e. the empty string) for the
toplevel directory, but not always so it may be useful to print it.
I'll add it.

> > +     trace2_data_intmax("read_directory", repo,
> > +                        "node-creation", dir->untracked->dir_created);
> > +     trace2_data_intmax("read_directory", repo,
> > +                        "gitignore-invalidation",
> > +                        dir->untracked->gitignore_invalidated);
> > +     trace2_data_intmax("read_directory", repo,
> > +                        "directory-invalidation",
> > +                        dir->untracked->dir_invalidated);
> > +     trace2_data_intmax("read_directory", repo,
> > +                        "opendir", dir->untracked->dir_opened);
> > +}
> > +
>
> The existing code was quite tangled and I think this helps
> make things more clear.
>
>
> >   int read_directory(struct dir_struct *dir, struct index_state *istate,
> >                  const char *path, int len, const struct pathspec *pathspec)
> >   {
> >       struct untracked_cache_dir *untracked;
> >
> > -     trace_performance_enter();
> > +     trace2_region_enter("dir", "read_directory", istate->repo);
> >
> >       if (has_symlink_leading_path(path, len)) {
> >               trace_performance_leave("read directory %.*s", len, path);
>
> This `trace_performance_leave()` inside the `if` needs to be
> converted too.

Ooh, good catch.  Will fix.

> > @@ -2784,23 +2801,13 @@ int read_directory(struct dir_struct *dir, struct index_state *istate,
> >       QSORT(dir->entries, dir->nr, cmp_dir_entry);
> >       QSORT(dir->ignored, dir->ignored_nr, cmp_dir_entry);
> >
> > -     trace_performance_leave("read directory %.*s", len, path);
> > +     trace2_region_leave("dir", "read_directory", istate->repo);
>
> Can we put the call to `trace2_read_directory_statistics()` before
> the above `trace2_region_leave()` call?   Then those stats will
> appear indented between the begin- and end-region events in the output.
>
> That way, the following `if (dir-untracked) {...}` is only
> concerned with the untracked cache and/or freeing that data.

Makes sense, I'll move it.

> >       if (dir->untracked) {
> >               static int force_untracked_cache = -1;
> > -             static struct trace_key trace_untracked_stats = TRACE_KEY_INIT(UNTRACKED_STATS);
> >
> >               if (force_untracked_cache < 0)
> >                       force_untracked_cache =
> >                               git_env_bool("GIT_FORCE_UNTRACKED_CACHE", 0);
> > -             trace_printf_key(&trace_untracked_stats,
> > -                              "node creation: %u\n"
> > -                              "gitignore invalidation: %u\n"
> > -                              "directory invalidation: %u\n"
> > -                              "opendir: %u\n",
> > -                              dir->untracked->dir_created,
> > -                              dir->untracked->gitignore_invalidated,
> > -                              dir->untracked->dir_invalidated,
> > -                              dir->untracked->dir_opened);
> >               if (force_untracked_cache &&
> >                       dir->untracked == istate->untracked &&
> >                   (dir->untracked->dir_opened ||
> > @@ -2811,6 +2818,9 @@ int read_directory(struct dir_struct *dir, struct index_state *istate,
> >                       FREE_AND_NULL(dir->untracked);
> >               }
> >       }
> > +
> > +     if (trace2_is_enabled())
> > +             trace2_read_directory_statistics(dir, istate->repo);
>
> Also, I think it'd be ok to move the `trace2_is_enabled()` call
> inside the function.  Since we're also testing `!dir->untracked`
> inside the function.

Actually, I can't do that.  The path passed to this function is not
going to always be (and will often not be) NUL-terminated, but
trace2_data_string() expects a NUL-terminated string.  So, I'm going
to make a temporary strbuf and copy the path into it, but of course I
only want to spend time doing that if trace2_is_enabled().

> The more that I look at the before and after versions, the
> more I think the `trace2_read_directory_statistics()` call
> should be up before the `trace2_region_leave()`.  Here at the
> bottom of the function, we may have already freed `dir->untracked`.
> I'm not familiar enough with this code to know if that is a
> good or bad thing.

Yeah, the statistics really need to be moved earlier, both for the
nesting reasons you point out and because otherwise the statistics
won't print whenever dir->untracked != istate->untracked.  I'll move
them.
diff mbox series

Patch

diff --git a/dir.c b/dir.c
index 3474e67e8f3c..9f7c8debeab3 100644
--- a/dir.c
+++ b/dir.c
@@ -2760,12 +2760,29 @@  static struct untracked_cache_dir *validate_untracked_cache(struct dir_struct *d
 	return root;
 }
 
+static void trace2_read_directory_statistics(struct dir_struct *dir,
+					     struct repository *repo)
+{
+	if (!dir->untracked)
+		return;
+	trace2_data_intmax("read_directory", repo,
+			   "node-creation", dir->untracked->dir_created);
+	trace2_data_intmax("read_directory", repo,
+			   "gitignore-invalidation",
+			   dir->untracked->gitignore_invalidated);
+	trace2_data_intmax("read_directory", repo,
+			   "directory-invalidation",
+			   dir->untracked->dir_invalidated);
+	trace2_data_intmax("read_directory", repo,
+			   "opendir", dir->untracked->dir_opened);
+}
+
 int read_directory(struct dir_struct *dir, struct index_state *istate,
 		   const char *path, int len, const struct pathspec *pathspec)
 {
 	struct untracked_cache_dir *untracked;
 
-	trace_performance_enter();
+	trace2_region_enter("dir", "read_directory", istate->repo);
 
 	if (has_symlink_leading_path(path, len)) {
 		trace_performance_leave("read directory %.*s", len, path);
@@ -2784,23 +2801,13 @@  int read_directory(struct dir_struct *dir, struct index_state *istate,
 	QSORT(dir->entries, dir->nr, cmp_dir_entry);
 	QSORT(dir->ignored, dir->ignored_nr, cmp_dir_entry);
 
-	trace_performance_leave("read directory %.*s", len, path);
+	trace2_region_leave("dir", "read_directory", istate->repo);
 	if (dir->untracked) {
 		static int force_untracked_cache = -1;
-		static struct trace_key trace_untracked_stats = TRACE_KEY_INIT(UNTRACKED_STATS);
 
 		if (force_untracked_cache < 0)
 			force_untracked_cache =
 				git_env_bool("GIT_FORCE_UNTRACKED_CACHE", 0);
-		trace_printf_key(&trace_untracked_stats,
-				 "node creation: %u\n"
-				 "gitignore invalidation: %u\n"
-				 "directory invalidation: %u\n"
-				 "opendir: %u\n",
-				 dir->untracked->dir_created,
-				 dir->untracked->gitignore_invalidated,
-				 dir->untracked->dir_invalidated,
-				 dir->untracked->dir_opened);
 		if (force_untracked_cache &&
 			dir->untracked == istate->untracked &&
 		    (dir->untracked->dir_opened ||
@@ -2811,6 +2818,9 @@  int read_directory(struct dir_struct *dir, struct index_state *istate,
 			FREE_AND_NULL(dir->untracked);
 		}
 	}
+
+	if (trace2_is_enabled())
+		trace2_read_directory_statistics(dir, istate->repo);
 	return dir->nr;
 }
 
diff --git a/t/t7063-status-untracked-cache.sh b/t/t7063-status-untracked-cache.sh
index accefde72fb1..6bce65b439e3 100755
--- a/t/t7063-status-untracked-cache.sh
+++ b/t/t7063-status-untracked-cache.sh
@@ -57,6 +57,19 @@  iuc () {
 	return $ret
 }
 
+get_relevant_traces() {
+	# From the GIT_TRACE2_PERF data of the form
+	#    $TIME $FILE:$LINE | d0 | main | data | r1 | ? | ? | read_directo | $RELEVANT_STAT
+	# extract the $RELEVANT_STAT fields.  We don't care about region_enter
+	# or region_leave, or stats for things outside read_directory.
+	INPUT_FILE=$1
+	OUTPUT_FILE=$2
+	grep data.*read_directo $INPUT_FILE \
+	    | cut -d "|" -f 9 \
+	    >$OUTPUT_FILE
+}
+
+
 test_lazy_prereq UNTRACKED_CACHE '
 	{ git update-index --test-untracked-cache; ret=$?; } &&
 	test $ret -ne 1
@@ -129,19 +142,20 @@  EOF
 
 test_expect_success 'status first time (empty cache)' '
 	avoid_racy &&
-	: >../trace &&
-	GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace" \
+	: >../trace.output &&
+	GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace.output" \
 	git status --porcelain >../actual &&
 	iuc status --porcelain >../status.iuc &&
 	test_cmp ../status.expect ../status.iuc &&
 	test_cmp ../status.expect ../actual &&
+	get_relevant_traces ../trace.output ../trace.relevant &&
 	cat >../trace.expect <<EOF &&
-node creation: 3
-gitignore invalidation: 1
-directory invalidation: 0
-opendir: 4
+ ..node-creation:3
+ ..gitignore-invalidation:1
+ ..directory-invalidation:0
+ ..opendir:4
 EOF
-	test_cmp ../trace.expect ../trace
+	test_cmp ../trace.expect ../trace.relevant
 '
 
 test_expect_success 'untracked cache after first status' '
@@ -151,19 +165,20 @@  test_expect_success 'untracked cache after first status' '
 
 test_expect_success 'status second time (fully populated cache)' '
 	avoid_racy &&
-	: >../trace &&
-	GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace" \
+	: >../trace.output &&
+	GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace.output" \
 	git status --porcelain >../actual &&
 	iuc status --porcelain >../status.iuc &&
 	test_cmp ../status.expect ../status.iuc &&
 	test_cmp ../status.expect ../actual &&
+	get_relevant_traces ../trace.output ../trace.relevant &&
 	cat >../trace.expect <<EOF &&
-node creation: 0
-gitignore invalidation: 0
-directory invalidation: 0
-opendir: 0
+ ..node-creation:0
+ ..gitignore-invalidation:0
+ ..directory-invalidation:0
+ ..opendir:0
 EOF
-	test_cmp ../trace.expect ../trace
+	test_cmp ../trace.expect ../trace.relevant
 '
 
 test_expect_success 'untracked cache after second status' '
@@ -174,8 +189,8 @@  test_expect_success 'untracked cache after second status' '
 test_expect_success 'modify in root directory, one dir invalidation' '
 	avoid_racy &&
 	: >four &&
-	: >../trace &&
-	GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace" \
+	: >../trace.output &&
+	GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace.output" \
 	git status --porcelain >../actual &&
 	iuc status --porcelain >../status.iuc &&
 	cat >../status.expect <<EOF &&
@@ -189,13 +204,14 @@  A  two
 EOF
 	test_cmp ../status.expect ../status.iuc &&
 	test_cmp ../status.expect ../actual &&
+	get_relevant_traces ../trace.output ../trace.relevant &&
 	cat >../trace.expect <<EOF &&
-node creation: 0
-gitignore invalidation: 0
-directory invalidation: 1
-opendir: 1
+ ..node-creation:0
+ ..gitignore-invalidation:0
+ ..directory-invalidation:1
+ ..opendir:1
 EOF
-	test_cmp ../trace.expect ../trace
+	test_cmp ../trace.expect ../trace.relevant
 
 '
 
@@ -223,8 +239,8 @@  EOF
 test_expect_success 'new .gitignore invalidates recursively' '
 	avoid_racy &&
 	echo four >.gitignore &&
-	: >../trace &&
-	GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace" \
+	: >../trace.output &&
+	GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace.output" \
 	git status --porcelain >../actual &&
 	iuc status --porcelain >../status.iuc &&
 	cat >../status.expect <<EOF &&
@@ -238,13 +254,14 @@  A  two
 EOF
 	test_cmp ../status.expect ../status.iuc &&
 	test_cmp ../status.expect ../actual &&
+	get_relevant_traces ../trace.output ../trace.relevant &&
 	cat >../trace.expect <<EOF &&
-node creation: 0
-gitignore invalidation: 1
-directory invalidation: 1
-opendir: 4
+ ..node-creation:0
+ ..gitignore-invalidation:1
+ ..directory-invalidation:1
+ ..opendir:4
 EOF
-	test_cmp ../trace.expect ../trace
+	test_cmp ../trace.expect ../trace.relevant
 
 '
 
@@ -272,8 +289,8 @@  EOF
 test_expect_success 'new info/exclude invalidates everything' '
 	avoid_racy &&
 	echo three >>.git/info/exclude &&
-	: >../trace &&
-	GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace" \
+	: >../trace.output &&
+	GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace.output" \
 	git status --porcelain >../actual &&
 	iuc status --porcelain >../status.iuc &&
 	cat >../status.expect <<EOF &&
@@ -285,13 +302,14 @@  A  two
 EOF
 	test_cmp ../status.expect ../status.iuc &&
 	test_cmp ../status.expect ../actual &&
+	get_relevant_traces ../trace.output ../trace.relevant &&
 	cat >../trace.expect <<EOF &&
-node creation: 0
-gitignore invalidation: 1
-directory invalidation: 0
-opendir: 4
+ ..node-creation:0
+ ..gitignore-invalidation:1
+ ..directory-invalidation:0
+ ..opendir:4
 EOF
-	test_cmp ../trace.expect ../trace
+	test_cmp ../trace.expect ../trace.relevant
 '
 
 test_expect_success 'verify untracked cache dump' '
@@ -330,8 +348,8 @@  EOF
 '
 
 test_expect_success 'status after the move' '
-	: >../trace &&
-	GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace" \
+	: >../trace.output &&
+	GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace.output" \
 	git status --porcelain >../actual &&
 	iuc status --porcelain >../status.iuc &&
 	cat >../status.expect <<EOF &&
@@ -343,13 +361,14 @@  A  one
 EOF
 	test_cmp ../status.expect ../status.iuc &&
 	test_cmp ../status.expect ../actual &&
+	get_relevant_traces ../trace.output ../trace.relevant &&
 	cat >../trace.expect <<EOF &&
-node creation: 0
-gitignore invalidation: 0
-directory invalidation: 0
-opendir: 1
+ ..node-creation:0
+ ..gitignore-invalidation:0
+ ..directory-invalidation:0
+ ..opendir:1
 EOF
-	test_cmp ../trace.expect ../trace
+	test_cmp ../trace.expect ../trace.relevant
 '
 
 test_expect_success 'verify untracked cache dump' '
@@ -389,8 +408,8 @@  EOF
 '
 
 test_expect_success 'status after the move' '
-	: >../trace &&
-	GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace" \
+	: >../trace.output &&
+	GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace.output" \
 	git status --porcelain >../actual &&
 	iuc status --porcelain >../status.iuc &&
 	cat >../status.expect <<EOF &&
@@ -402,13 +421,14 @@  A  two
 EOF
 	test_cmp ../status.expect ../status.iuc &&
 	test_cmp ../status.expect ../actual &&
+	get_relevant_traces ../trace.output ../trace.relevant &&
 	cat >../trace.expect <<EOF &&
-node creation: 0
-gitignore invalidation: 0
-directory invalidation: 0
-opendir: 1
+ ..node-creation:0
+ ..gitignore-invalidation:0
+ ..directory-invalidation:0
+ ..opendir:1
 EOF
-	test_cmp ../trace.expect ../trace
+	test_cmp ../trace.expect ../trace.relevant
 '
 
 test_expect_success 'verify untracked cache dump' '
@@ -438,8 +458,8 @@  test_expect_success 'set up for sparse checkout testing' '
 '
 
 test_expect_success 'status after commit' '
-	: >../trace &&
-	GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace" \
+	: >../trace.output &&
+	GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace.output" \
 	git status --porcelain >../actual &&
 	iuc status --porcelain >../status.iuc &&
 	cat >../status.expect <<EOF &&
@@ -448,13 +468,14 @@  test_expect_success 'status after commit' '
 EOF
 	test_cmp ../status.expect ../status.iuc &&
 	test_cmp ../status.expect ../actual &&
+	get_relevant_traces ../trace.output ../trace.relevant &&
 	cat >../trace.expect <<EOF &&
-node creation: 0
-gitignore invalidation: 0
-directory invalidation: 0
-opendir: 2
+ ..node-creation:0
+ ..gitignore-invalidation:0
+ ..directory-invalidation:0
+ ..opendir:2
 EOF
-	test_cmp ../trace.expect ../trace
+	test_cmp ../trace.expect ../trace.relevant
 '
 
 test_expect_success 'untracked cache correct after commit' '
@@ -496,9 +517,9 @@  test_expect_success 'create/modify files, some of which are gitignored' '
 '
 
 test_expect_success 'test sparse status with untracked cache' '
-	: >../trace &&
+	: >../trace.output &&
 	avoid_racy &&
-	GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace" \
+	GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace.output" \
 	git status --porcelain >../status.actual &&
 	iuc status --porcelain >../status.iuc &&
 	cat >../status.expect <<EOF &&
@@ -509,13 +530,14 @@  test_expect_success 'test sparse status with untracked cache' '
 EOF
 	test_cmp ../status.expect ../status.iuc &&
 	test_cmp ../status.expect ../status.actual &&
+	get_relevant_traces ../trace.output ../trace.relevant &&
 	cat >../trace.expect <<EOF &&
-node creation: 0
-gitignore invalidation: 1
-directory invalidation: 2
-opendir: 2
+ ..node-creation:0
+ ..gitignore-invalidation:1
+ ..directory-invalidation:2
+ ..opendir:2
 EOF
-	test_cmp ../trace.expect ../trace
+	test_cmp ../trace.expect ../trace.relevant
 '
 
 test_expect_success 'untracked cache correct after status' '
@@ -539,8 +561,8 @@  EOF
 
 test_expect_success 'test sparse status again with untracked cache' '
 	avoid_racy &&
-	: >../trace &&
-	GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace" \
+	: >../trace.output &&
+	GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace.output" \
 	git status --porcelain >../status.actual &&
 	iuc status --porcelain >../status.iuc &&
 	cat >../status.expect <<EOF &&
@@ -551,13 +573,14 @@  test_expect_success 'test sparse status again with untracked cache' '
 EOF
 	test_cmp ../status.expect ../status.iuc &&
 	test_cmp ../status.expect ../status.actual &&
+	get_relevant_traces ../trace.output ../trace.relevant &&
 	cat >../trace.expect <<EOF &&
-node creation: 0
-gitignore invalidation: 0
-directory invalidation: 0
-opendir: 0
+ ..node-creation:0
+ ..gitignore-invalidation:0
+ ..directory-invalidation:0
+ ..opendir:0
 EOF
-	test_cmp ../trace.expect ../trace
+	test_cmp ../trace.expect ../trace.relevant
 '
 
 test_expect_success 'set up for test of subdir and sparse checkouts' '
@@ -568,8 +591,8 @@  test_expect_success 'set up for test of subdir and sparse checkouts' '
 
 test_expect_success 'test sparse status with untracked cache and subdir' '
 	avoid_racy &&
-	: >../trace &&
-	GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace" \
+	: >../trace.output &&
+	GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace.output" \
 	git status --porcelain >../status.actual &&
 	iuc status --porcelain >../status.iuc &&
 	cat >../status.expect <<EOF &&
@@ -581,13 +604,14 @@  test_expect_success 'test sparse status with untracked cache and subdir' '
 EOF
 	test_cmp ../status.expect ../status.iuc &&
 	test_cmp ../status.expect ../status.actual &&
+	get_relevant_traces ../trace.output ../trace.relevant &&
 	cat >../trace.expect <<EOF &&
-node creation: 2
-gitignore invalidation: 0
-directory invalidation: 1
-opendir: 3
+ ..node-creation:2
+ ..gitignore-invalidation:0
+ ..directory-invalidation:1
+ ..opendir:3
 EOF
-	test_cmp ../trace.expect ../trace
+	test_cmp ../trace.expect ../trace.relevant
 '
 
 test_expect_success 'verify untracked cache dump (sparse/subdirs)' '
@@ -616,19 +640,20 @@  EOF
 
 test_expect_success 'test sparse status again with untracked cache and subdir' '
 	avoid_racy &&
-	: >../trace &&
-	GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace" \
+	: >../trace.output &&
+	GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace.output" \
 	git status --porcelain >../status.actual &&
 	iuc status --porcelain >../status.iuc &&
 	test_cmp ../status.expect ../status.iuc &&
 	test_cmp ../status.expect ../status.actual &&
+	get_relevant_traces ../trace.output ../trace.relevant &&
 	cat >../trace.expect <<EOF &&
-node creation: 0
-gitignore invalidation: 0
-directory invalidation: 0
-opendir: 0
+ ..node-creation:0
+ ..gitignore-invalidation:0
+ ..directory-invalidation:0
+ ..opendir:0
 EOF
-	test_cmp ../trace.expect ../trace
+	test_cmp ../trace.expect ../trace.relevant
 '
 
 test_expect_success 'move entry in subdir from untracked to cached' '
diff --git a/t/t7519-status-fsmonitor.sh b/t/t7519-status-fsmonitor.sh
index 45d025f96010..637391c6ce46 100755
--- a/t/t7519-status-fsmonitor.sh
+++ b/t/t7519-status-fsmonitor.sh
@@ -334,7 +334,7 @@  test_expect_success UNTRACKED_CACHE 'ignore .git changes when invalidating UNTR'
 		git config core.fsmonitor .git/hooks/fsmonitor-test &&
 		git update-index --untracked-cache &&
 		git update-index --fsmonitor &&
-		GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace-before" \
+		GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace-before" \
 		git status &&
 		test-tool dump-untracked-cache >../before
 	) &&
@@ -346,12 +346,12 @@  test_expect_success UNTRACKED_CACHE 'ignore .git changes when invalidating UNTR'
 	EOF
 	(
 		cd dot-git &&
-		GIT_TRACE_UNTRACKED_STATS="$TRASH_DIRECTORY/trace-after" \
+		GIT_TRACE2_PERF="$TRASH_DIRECTORY/trace-after" \
 		git status &&
 		test-tool dump-untracked-cache >../after
 	) &&
-	grep "directory invalidation" trace-before >>before &&
-	grep "directory invalidation" trace-after >>after &&
+	grep "directory-invalidation" trace-before | cut -d"|" -f 9 >>before &&
+	grep "directory-invalidation" trace-after  | cut -d"|" -f 9 >>after &&
 	# UNTR extension unchanged, dir invalidation count unchanged
 	test_cmp before after
 '