git@vger.kernel.org list mirror (unofficial, one of many)
 help / color / mirror / code / Atom feed
* [PATCH] trace2: don't include "fsync" events in all trace2 logs
@ 2022-06-23 15:51 Ævar Arnfjörð Bjarmason
  2022-06-23 18:21 ` [EXTERNAL] " Neeraj Singh (WINDOWS-SFS)
  2022-06-23 19:34 ` Junio C Hamano
  0 siblings, 2 replies; 3+ messages in thread
From: Ævar Arnfjörð Bjarmason @ 2022-06-23 15:51 UTC (permalink / raw)
  To: git; +Cc: Junio C Hamano, Neeraj Singh, Ævar Arnfjörð Bjarmason

Fix the overly verbose trace2 logging added in 9a4987677d3 (trace2:
add stats for fsync operations, 2022-03-30) (first released with
v2.36.0).

Since that change every single "git" command invocation has included
these "data" events, even though we'll only make use of these with
core.fsyncMethod=batch, and even then only have non-zero values if
we're writing object data to disk. See c0f4752ed2f (core.fsyncmethod:
batched disk flushes for loose-objects, 2022-04-04) for that feature.

The result was that e.g. "git version" would previously emit a total
of 6 trace2 events with the GIT_TRACE2_EVENT target (version, start,
cmd_ancestry, cmd_name, exit, atexit), but afterwards would emit
8. We'd emit 2 "data" events before the "exit" event.

The reason we didn't catch this was that the trace2 unit tests added
in a15860dca3f (trace2: t/helper/test-trace2, t0210.sh, t0211.sh,
t0212.sh, 2019-02-22) would omit any "data" events that weren't the
ones it cared about. Before this change to the C code 6/7 of our
"t/t0212-trace2-event.sh" tests would fail if this change was applied
to "t/t0212/parse_events.perl".

Let's make the trace2 testing more strict, and further append any new
events types we don't know about in "t/t0212/parse_events.perl". Since
we only invoke the "test-tool trace2" there's no guarantee that we'll
catch other overly verbose events in the future, but we'll at least
notice if we start emitting new events that are issues every time we
log anything with trace2's JSON target.

We exclude the "data_json" event type, we'd otherwise would fail on
both "win test" and "win+VS test" CI due to the logging added in
353d3d77f4f (trace2: collect Windows-specific process information,
2019-02-22). It looks like that logging should really be using
trace2_cmd_ancestry() instead, which was introduced later in
2f732bf15e6 (tr2: log parent process name, 2021-07-21), but let's
leave it for now.

Signed-off-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>
---

This is a fix for a v2.36.0 regression/change, so perhaps it's
categorically out for v2.37.0, but given how isolated the fix is & how
verbose the new trace2 data is perhaps it's worth including anyway.

Passing CI at: https://github.com/avar/git/actions/runs/2548732003

 t/t0212/parse_events.perl | 17 +++++++++++------
 wrapper.c                 |  3 +++
 2 files changed, 14 insertions(+), 6 deletions(-)

diff --git a/t/t0212/parse_events.perl b/t/t0212/parse_events.perl
index b6408560c0c..389cf6f61c4 100644
--- a/t/t0212/parse_events.perl
+++ b/t/t0212/parse_events.perl
@@ -216,12 +216,17 @@
 
     elsif ($event eq 'data') {
 	my $cat = $line->{'category'};
-	if ($cat eq 'test_category') {
-	    
-	    my $key = $line->{'key'};
-	    my $value = $line->{'value'};
-	    $processes->{$sid}->{'data'}->{$cat}->{$key} = $value;
-	}
+	my $key = $line->{'key'};
+	my $value = $line->{'value'};
+	$processes->{$sid}->{'data'}->{$cat}->{$key} = $value;
+    }
+
+    elsif ($event eq 'data_json') {
+	# Ignore due to compat/win32/trace2_win32_process_info.c
+    }
+
+    else {
+	push @{$processes->{$sid}->{$event}} => $line->{value};
     }
 
     # This trace2 target does not emit 'printf' events.
diff --git a/wrapper.c b/wrapper.c
index 1c3c970080b..eebd764131f 100644
--- a/wrapper.c
+++ b/wrapper.c
@@ -618,6 +618,9 @@ int git_fsync(int fd, enum fsync_action action)
 
 void trace_git_fsync_stats(void)
 {
+	if (!count_fsync_writeout_only && !count_fsync_hardware_flush)
+		return;
+
 	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);
 }
-- 
2.37.0.rc2.867.gbe8216e3e5c


^ permalink raw reply	[flat|nested] 3+ messages in thread

* RE: [EXTERNAL] [PATCH] trace2: don't include "fsync" events in all trace2 logs
  2022-06-23 15:51 [PATCH] trace2: don't include "fsync" events in all trace2 logs Ævar Arnfjörð Bjarmason
@ 2022-06-23 18:21 ` Neeraj Singh (WINDOWS-SFS)
  2022-06-23 19:34 ` Junio C Hamano
  1 sibling, 0 replies; 3+ messages in thread
From: Neeraj Singh (WINDOWS-SFS) @ 2022-06-23 18:21 UTC (permalink / raw)
  To: Ævar Arnfjörð Bjarmason, git; +Cc: Junio C Hamano

This patch looks good to me. 

Thanks,
Neeraj

^ permalink raw reply	[flat|nested] 3+ messages in thread

* Re: [PATCH] trace2: don't include "fsync" events in all trace2 logs
  2022-06-23 15:51 [PATCH] trace2: don't include "fsync" events in all trace2 logs Ævar Arnfjörð Bjarmason
  2022-06-23 18:21 ` [EXTERNAL] " Neeraj Singh (WINDOWS-SFS)
@ 2022-06-23 19:34 ` Junio C Hamano
  1 sibling, 0 replies; 3+ messages in thread
From: Junio C Hamano @ 2022-06-23 19:34 UTC (permalink / raw)
  To: Ævar Arnfjörð Bjarmason; +Cc: git, Neeraj Singh

Ævar Arnfjörð Bjarmason  <avarab@gmail.com> writes:

> Fix the overly verbose trace2 logging added in 9a4987677d3 (trace2:
> add stats for fsync operations, 2022-03-30) (first released with
> v2.36.0).
>
> Since that change every single "git" command invocation has included
> these "data" events, even though we'll only make use of these with
> core.fsyncMethod=batch, and even then only have non-zero values if
> we're writing object data to disk. See c0f4752ed2f (core.fsyncmethod:
> batched disk flushes for loose-objects, 2022-04-04) for that feature.
>
> The result was that e.g. "git version" would previously emit a total
> of 6 trace2 events with the GIT_TRACE2_EVENT target (version, start,
> cmd_ancestry, cmd_name, exit, atexit), but afterwards would emit
> 8. We'd emit 2 "data" events before the "exit" event.
>
> The reason we didn't catch this was that the trace2 unit tests added
> in a15860dca3f (trace2: t/helper/test-trace2, t0210.sh, t0211.sh,
> t0212.sh, 2019-02-22) would omit any "data" events that weren't the
> ones it cared about. Before this change to the C code 6/7 of our
> "t/t0212-trace2-event.sh" tests would fail if this change was applied
> to "t/t0212/parse_events.perl".
>
> Let's make the trace2 testing more strict, and further append any new
> events types we don't know about in "t/t0212/parse_events.perl". Since
> we only invoke the "test-tool trace2" there's no guarantee that we'll
> catch other overly verbose events in the future, but we'll at least
> notice if we start emitting new events that are issues every time we
> log anything with trace2's JSON target.
>
> We exclude the "data_json" event type, we'd otherwise would fail on
> both "win test" and "win+VS test" CI due to the logging added in
> 353d3d77f4f (trace2: collect Windows-specific process information,
> 2019-02-22). It looks like that logging should really be using
> trace2_cmd_ancestry() instead, which was introduced later in
> 2f732bf15e6 (tr2: log parent process name, 2021-07-21), but let's
> leave it for now.
>
> Signed-off-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>
> ---
>
> This is a fix for a v2.36.0 regression/change, so perhaps it's
> categorically out for v2.37.0, but given how isolated the fix is & how
> verbose the new trace2 data is perhaps it's worth including anyway.
>
> Passing CI at: https://github.com/avar/git/actions/runs/2548732003
>
>  t/t0212/parse_events.perl | 17 +++++++++++------
>  wrapper.c                 |  3 +++
>  2 files changed, 14 insertions(+), 6 deletions(-)
>
> diff --git a/t/t0212/parse_events.perl b/t/t0212/parse_events.perl
> index b6408560c0c..389cf6f61c4 100644
> --- a/t/t0212/parse_events.perl
> +++ b/t/t0212/parse_events.perl
> @@ -216,12 +216,17 @@
>  
>      elsif ($event eq 'data') {
>  	my $cat = $line->{'category'};
> +	my $key = $line->{'key'};
> +	my $value = $line->{'value'};
> +	$processes->{$sid}->{'data'}->{$cat}->{$key} = $value;
> +    }
> +
> +    elsif ($event eq 'data_json') {
> +	# Ignore due to compat/win32/trace2_win32_process_info.c
> +    }
> +
> +    else {
> +	push @{$processes->{$sid}->{$event}} => $line->{value};
>      }

The special casing is unfortunate, but if it is "let's leave it for
now", probably we should leave a NEEDSWORK comment here to remind
us, instead of giving a false impresion that abusing data_json is
OK?

> diff --git a/wrapper.c b/wrapper.c
> index 1c3c970080b..eebd764131f 100644
> --- a/wrapper.c
> +++ b/wrapper.c
> @@ -618,6 +618,9 @@ int git_fsync(int fd, enum fsync_action action)
>  
>  void trace_git_fsync_stats(void)
>  {
> +	if (!count_fsync_writeout_only && !count_fsync_hardware_flush)
> +		return;
> +

OK, both counters are unconditionally incremented whenever the
corresponding action triggers, so this implementation is probably OK
for now, but I suspect that it would become a maintenance burden if
we were to add more fsync actions later.

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

If each of these is guarded with "show only when non-zero", that
would become less problematic, though.

A bigger issue is when somebody is debugging the callers of
git_fsync() wondering why they do not trigger.  Getting log entries
that say "no git_fsync() call with these actions have been made"
may be useful (i.e. explicitly negative answer).

I am not sure if it is a good solution in the longer term, but this
implementation may be a good-enough way to squelch the immediate
loudness issue.

Thanks.


^ permalink raw reply	[flat|nested] 3+ messages in thread

end of thread, other threads:[~2022-06-23 19:43 UTC | newest]

Thread overview: 3+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2022-06-23 15:51 [PATCH] trace2: don't include "fsync" events in all trace2 logs Ævar Arnfjörð Bjarmason
2022-06-23 18:21 ` [EXTERNAL] " Neeraj Singh (WINDOWS-SFS)
2022-06-23 19:34 ` Junio C Hamano

Code repositories for project(s) associated with this inbox:

	https://80x24.org/mirrors/git.git

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).