[PATCH] trace2: add stats for fsync operations

[PATCH] trace2: add stats for fsync operations

[Neeraj K. Singh via GitGitGadget]

From: Neeraj Singh <neerajsi@microsoft.com>

Add some global trace2 statistics for the number of fsyncs performed
during the lifetime of a Git process.

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.

Signed-off-by: Neeraj Singh <neerajsi@microsoft.com>
---
    trace2: add stats for fsync operations
    
    Add some global trace2 statistics for the number of fsyncs performed
    during the lifetime of a Git process.
    
    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.
    
    Signed-off-by: Neeraj Singh neerajsi@microsoft.com

Published-As: https://github.com/gitgitgadget/git/releases/tag/pr-1192%2Fneerajsi-msft%2Fns%2Ftrace2-fsync-stats-v1
Fetch-It-Via: git fetch https://github.com/gitgitgadget/git pr-1192/neerajsi-msft/ns/trace2-fsync-stats-v1
Pull-Request: https://github.com/gitgitgadget/git/pull/1192

 git-compat-util.h       |  5 +++++
 t/t0211/scrub_perf.perl |  4 ++++
 trace2.c                |  1 +
 wrapper.c               | 12 ++++++++++++
 4 files changed, 22 insertions(+)

diff --git a/git-compat-util.h b/git-compat-util.h
index 0892e209a2f..4d444dca274 100644
--- a/git-compat-util.h
+++ b/git-compat-util.h
@@ -1281,6 +1281,11 @@ enum fsync_action {
  */
 int git_fsync(int fd, enum fsync_action action);
 
+/*
+ * Writes out trace statistics for fsync using the trace2 API.
+ */
+void trace_git_fsync_stats(void);
+
 /*
  * Preserves errno, prints a message, but gives no warning for ENOENT.
  * Returns 0 on success, which includes trying to unlink an object that does
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
diff --git a/trace2.c b/trace2.c
index 179caa72cfe..e01cf77f1a8 100644
--- a/trace2.c
+++ b/trace2.c
@@ -214,6 +214,7 @@ int trace2_cmd_exit_fl(const char *file, int line, int code)
 	if (!trace2_enabled)
 		return code;
 
+	trace_git_fsync_stats();
 	trace2_collect_process_info(TRACE2_PROCESS_INFO_EXIT);
 
 	tr2main_exit_code = code;
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;
+
 #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,
@@ -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);
+}
+
 static int warn_if_unremovable(const char *op, const char *file, int rc)
 {
 	int err;

base-commit: c54b8eb302ffb72f31e73a26044c8a864e2cb307
-- 
gitgitgadget

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

[Ævar Arnfjörð Bjarmason]

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).

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

[Neeraj Singh]

On Wed, Mar 30, 2022 at 03:29:10PM +0200, Ævar Arnfjörð Bjarmason wrote:
> 
> 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).

The overall question about the benefit of this patch is a good one.
The idea here is that there might be some 'countable' things that
affect the performance of Git, such as peak memory usage, fs operations,
etc.  Fsync is the one I happen to care about at the moment, but certainly
number of write calls, opens, or other such stats would be interesting.

I've got to switch gears to some non-Git work, so I'm not going to push
too hard on this patch in the near future. I'll be focusing my efforts on
the batch patches. This might be worth reviving later if people want to add
global stats of this nature.