Re: [PATCH] trace2: add stats for fsync operations

["Ævar Arnfjörð Bjarmason" <avarab@gmail.com>]

On Wed, Mar 30 2022, Neeraj K. Singh via GitGitGadget wrote:

> From: Neeraj Singh <neerajsi@microsoft.com>
>
> Add some global trace2 statistics for the number of fsyncs performed
> during the lifetime of a Git process.

This make sense.

> These stats are printed as part of trace2_cmd_exit_fl, which is
> presumably where we might want to print any other cross-cutting
> statistics.

[...]

> diff --git a/t/t0211/scrub_perf.perl b/t/t0211/scrub_perf.perl
> index d164b750ff7..299999f0f89 100644
> --- a/t/t0211/scrub_perf.perl
> +++ b/t/t0211/scrub_perf.perl
> @@ -59,6 +59,10 @@ while (<>) {
>  	    # and highly variable.  Just omit them.
>  	    goto SKIP_LINE;
>  	}
> +	if ($tokens[$col_category] =~ m/fsync/) {
> +	    # fsync events aren't interesting for the test
> +	    goto SKIP_LINE;
> +	}
>      }
>  
>      # t_abs and t_rel are either blank or a float.  Replace the float

This part doesn't, per the comment at the top of t/t0211/scrub_perf.perl
and the rest of the code the reason we scrub trace2 output is to get rid
of variable output, i.e. startup times and the like.

If I omit this and run the tests only t0211-trace2-perf.sh fails, and in
exactly the tests it seems we should be updating instead of sweeping
this new data under the rug.

Maybe I'm missing something, but your comment/commit message doesn't
discuss the interesing "why", we can see that the author of the code
doesn't think "fsync events [are] interesting for the test".

But why? Unlike the platform-specific APIs fsync() is something we'll
call everywhere, and surely any platform-specific API calls will be
guarded by the relevant options, and we could skip this there for those
tests.

Here I'm eliding that git_fsync() we are calling the platform-specific
APIs, but that's something this logging is explicitly hiding, e.g. if we
call it in a loop this will log once, so this shouldn't be variable
based on the OS, we're logging our own git_fsync() and
FSYNC_WRITEOUT_ONLY v.s. FSYNC_HARDWARE_FLUSH.

> diff --git a/wrapper.c b/wrapper.c
> index 354d784c034..f512994690b 100644
> --- a/wrapper.c
> +++ b/wrapper.c
> @@ -4,6 +4,9 @@
>  #include "cache.h"
>  #include "config.h"
>  
> +static intmax_t count_fsync_writeout_only;
> +static intmax_t count_fsync_hardware_flush;
> +

nit: stray whitespace change.

>  #ifdef HAVE_RTLGENRANDOM
>  /* This is required to get access to RtlGenRandom. */
>  #define SystemFunction036 NTAPI SystemFunction036
> @@ -564,6 +567,7 @@ int git_fsync(int fd, enum fsync_action action)
>  {
>  	switch (action) {
>  	case FSYNC_WRITEOUT_ONLY:
> +		count_fsync_writeout_only += 1;
>  
>  #ifdef __APPLE__
>  		/*
> @@ -595,6 +599,8 @@ int git_fsync(int fd, enum fsync_action action)
>  		return -1;
>  
>  	case FSYNC_HARDWARE_FLUSH:
> +		count_fsync_hardware_flush += 1;
> +
>  		/*
>  		 * On macOS, a special fcntl is required to really flush the
>  		 * caches within the storage controller. As of this writing,

Isn't this making this very low-level API thread-unsafe?

I.e. shouldn't you be using something like the tr2tls_locked_increment()
API to keep track of this instead?

> @@ -610,6 +616,12 @@ int git_fsync(int fd, enum fsync_action action)
>  	}
>  }
>  
> +void trace_git_fsync_stats(void)
> +{
> +	trace2_data_intmax("fsync", the_repository, "fsync/writeout-only", count_fsync_writeout_only);
> +	trace2_data_intmax("fsync", the_repository, "fsync/hardware-flush", count_fsync_hardware_flush);
> +}
> +

Is this logging really all that useful in this form? I.e. if we were to
log these as they happen they'd be attributed to whatever the open
region is, and you'd see them "as they happen".

But these sorts of aggregate statistics just seem no give us pretty much
the same thing that strace and similar tools would give us, i.e. we
don't log the number of open(), write() and close() calls.

It *does* abstract away the OS-specific syscall though, but for anyone
looking at the level of detail of "number of fsync's" is that going to
be that useful (and the same goes for logging this v.s. open() on
e.g. mingw).