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

[Elijah Newren <newren@gmail.com>]

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.