{"thread":{"id":"58060","subject":"[PATCH] trace2: don't include \"fsync\" events in all trace2 logs","startedAt":"2022-06-23T15:51:59Z","lastAt":"2022-07-18T19:02:04Z","messageCount":8,"participants":["Ævar Arnfjörð Bjarmason","Neeraj Singh (WINDOWS-SFS)","Junio C Hamano"],"isPatch":true,"patchVersion":1,"patchTotal":null},"messages":[{"id":"457797","messageId":"patch-1.1-df87e515efd-20220623T154943Z-avarab@gmail.com","threadId":"58060","inReplyTo":null,"subject":"[PATCH] trace2: don't include \"fsync\" events in all trace2 logs","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2022-06-23T15:51:46Z","receivedAt":"2022-06-23T15:51:59Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"Fix the overly verbose trace2 logging added in 9a4987677d3 (trace2:\nadd stats for fsync operations, 2022-03-30) (first released with\nv2.36.0).\n\nSince that change every single \"git\" command invocation has included\nthese \"data\" events, even though we'll only make use of these with\ncore.fsyncMethod=batch, and even then only have non-zero values if\nwe're writing object data to disk. See c0f4752ed2f (core.fsyncmethod:\nbatched disk flushes for loose-objects, 2022-04-04) for that feature.\n\nThe result was that e.g. \"git version\" would previously emit a total\nof 6 trace2 events with the GIT_TRACE2_EVENT target (version, start,\ncmd_ancestry, cmd_name, exit, atexit), but afterwards would emit\n8. We'd emit 2 \"data\" events before the \"exit\" event.\n\nThe reason we didn't catch this was that the trace2 unit tests added\nin a15860dca3f (trace2: t/helper/test-trace2, t0210.sh, t0211.sh,\nt0212.sh, 2019-02-22) would omit any \"data\" events that weren't the\nones it cared about. Before this change to the C code 6/7 of our\n\"t/t0212-trace2-event.sh\" tests would fail if this change was applied\nto \"t/t0212/parse_events.perl\".\n\nLet's make the trace2 testing more strict, and further append any new\nevents types we don't know about in \"t/t0212/parse_events.perl\". Since\nwe only invoke the \"test-tool trace2\" there's no guarantee that we'll\ncatch other overly verbose events in the future, but we'll at least\nnotice if we start emitting new events that are issues every time we\nlog anything with trace2's JSON target.\n\nWe exclude the \"data_json\" event type, we'd otherwise would fail on\nboth \"win test\" and \"win+VS test\" CI due to the logging added in\n353d3d77f4f (trace2: collect Windows-specific process information,\n2019-02-22). It looks like that logging should really be using\ntrace2_cmd_ancestry() instead, which was introduced later in\n2f732bf15e6 (tr2: log parent process name, 2021-07-21), but let's\nleave it for now.\n\nSigned-off-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>\n---\n\nThis is a fix for a v2.36.0 regression/change, so perhaps it's\ncategorically out for v2.37.0, but given how isolated the fix is & how\nverbose the new trace2 data is perhaps it's worth including anyway.\n\nPassing CI at: https://github.com/avar/git/actions/runs/2548732003\n\n t/t0212/parse_events.perl | 17 +++++++++++------\n wrapper.c                 |  3 +++\n 2 files changed, 14 insertions(+), 6 deletions(-)\n\ndiff --git a/t/t0212/parse_events.perl b/t/t0212/parse_events.perl\nindex b6408560c0c..389cf6f61c4 100644\n--- a/t/t0212/parse_events.perl\n+++ b/t/t0212/parse_events.perl\n@@ -216,12 +216,17 @@\n \n     elsif ($event eq 'data') {\n \tmy $cat = $line->{'category'};\n-\tif ($cat eq 'test_category') {\n-\t    \n-\t    my $key = $line->{'key'};\n-\t    my $value = $line->{'value'};\n-\t    $processes->{$sid}->{'data'}->{$cat}->{$key} = $value;\n-\t}\n+\tmy $key = $line->{'key'};\n+\tmy $value = $line->{'value'};\n+\t$processes->{$sid}->{'data'}->{$cat}->{$key} = $value;\n+    }\n+\n+    elsif ($event eq 'data_json') {\n+\t# Ignore due to compat/win32/trace2_win32_process_info.c\n+    }\n+\n+    else {\n+\tpush @{$processes->{$sid}->{$event}} => $line->{value};\n     }\n \n     # This trace2 target does not emit 'printf' events.\ndiff --git a/wrapper.c b/wrapper.c\nindex 1c3c970080b..eebd764131f 100644\n--- a/wrapper.c\n+++ b/wrapper.c\n@@ -618,6 +618,9 @@ int git_fsync(int fd, enum fsync_action action)\n \n void trace_git_fsync_stats(void)\n {\n+\tif (!count_fsync_writeout_only && !count_fsync_hardware_flush)\n+\t\treturn;\n+\n \ttrace2_data_intmax(\"fsync\", the_repository, \"fsync/writeout-only\", count_fsync_writeout_only);\n \ttrace2_data_intmax(\"fsync\", the_repository, \"fsync/hardware-flush\", count_fsync_hardware_flush);\n }\n-- \n2.37.0.rc2.867.gbe8216e3e5c\n\n"},{"id":"457808","messageId":"DM5PR21MB15422C4A9D82BEF301262F10CCB59@DM5PR21MB1542.namprd21.prod.outlook.com","threadId":"58060","inReplyTo":"patch-1.1-df87e515efd-20220623T154943Z-avarab@gmail.com","subject":"RE: [EXTERNAL] [PATCH] trace2: don't include \"fsync\" events in all trace2 logs","fromName":"Neeraj Singh (WINDOWS-SFS)","fromEmail":"neerajsi@microsoft.com","sentAt":"2022-06-23T18:21:12Z","receivedAt":"2022-06-23T19:17:09Z","isPatch":true,"sender":{"key":"neerajsi@microsoft.com","avatar":"https://avatars.githubusercontent.com/u/78932899?v=4"},"body":"This patch looks good to me. \n\nThanks,\nNeeraj\n"},{"id":"457812","messageId":"xmqqh74byy19.fsf@gitster.g","threadId":"58060","inReplyTo":"patch-1.1-df87e515efd-20220623T154943Z-avarab@gmail.com","subject":"Re: [PATCH] trace2: don't include \"fsync\" events in all trace2 logs","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2022-06-23T19:34:10Z","receivedAt":"2022-06-23T19:43:20Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Ævar Arnfjörð Bjarmason  <avarab@gmail.com> writes:\n\n> Fix the overly verbose trace2 logging added in 9a4987677d3 (trace2:\n> add stats for fsync operations, 2022-03-30) (first released with\n> v2.36.0).\n>\n> Since that change every single \"git\" command invocation has included\n> these \"data\" events, even though we'll only make use of these with\n> core.fsyncMethod=batch, and even then only have non-zero values if\n> we're writing object data to disk. See c0f4752ed2f (core.fsyncmethod:\n> batched disk flushes for loose-objects, 2022-04-04) for that feature.\n>\n> The result was that e.g. \"git version\" would previously emit a total\n> of 6 trace2 events with the GIT_TRACE2_EVENT target (version, start,\n> cmd_ancestry, cmd_name, exit, atexit), but afterwards would emit\n> 8. We'd emit 2 \"data\" events before the \"exit\" event.\n>\n> The reason we didn't catch this was that the trace2 unit tests added\n> in a15860dca3f (trace2: t/helper/test-trace2, t0210.sh, t0211.sh,\n> t0212.sh, 2019-02-22) would omit any \"data\" events that weren't the\n> ones it cared about. Before this change to the C code 6/7 of our\n> \"t/t0212-trace2-event.sh\" tests would fail if this change was applied\n> to \"t/t0212/parse_events.perl\".\n>\n> Let's make the trace2 testing more strict, and further append any new\n> events types we don't know about in \"t/t0212/parse_events.perl\". Since\n> we only invoke the \"test-tool trace2\" there's no guarantee that we'll\n> catch other overly verbose events in the future, but we'll at least\n> notice if we start emitting new events that are issues every time we\n> log anything with trace2's JSON target.\n>\n> We exclude the \"data_json\" event type, we'd otherwise would fail on\n> both \"win test\" and \"win+VS test\" CI due to the logging added in\n> 353d3d77f4f (trace2: collect Windows-specific process information,\n> 2019-02-22). It looks like that logging should really be using\n> trace2_cmd_ancestry() instead, which was introduced later in\n> 2f732bf15e6 (tr2: log parent process name, 2021-07-21), but let's\n> leave it for now.\n>\n> Signed-off-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>\n> ---\n>\n> This is a fix for a v2.36.0 regression/change, so perhaps it's\n> categorically out for v2.37.0, but given how isolated the fix is & how\n> verbose the new trace2 data is perhaps it's worth including anyway.\n>\n> Passing CI at: https://github.com/avar/git/actions/runs/2548732003\n>\n>  t/t0212/parse_events.perl | 17 +++++++++++------\n>  wrapper.c                 |  3 +++\n>  2 files changed, 14 insertions(+), 6 deletions(-)\n>\n> diff --git a/t/t0212/parse_events.perl b/t/t0212/parse_events.perl\n> index b6408560c0c..389cf6f61c4 100644\n> --- a/t/t0212/parse_events.perl\n> +++ b/t/t0212/parse_events.perl\n> @@ -216,12 +216,17 @@\n>  \n>      elsif ($event eq 'data') {\n>  \tmy $cat = $line->{'category'};\n> +\tmy $key = $line->{'key'};\n> +\tmy $value = $line->{'value'};\n> +\t$processes->{$sid}->{'data'}->{$cat}->{$key} = $value;\n> +    }\n> +\n> +    elsif ($event eq 'data_json') {\n> +\t# Ignore due to compat/win32/trace2_win32_process_info.c\n> +    }\n> +\n> +    else {\n> +\tpush @{$processes->{$sid}->{$event}} => $line->{value};\n>      }\n\nThe special casing is unfortunate, but if it is \"let's leave it for\nnow\", probably we should leave a NEEDSWORK comment here to remind\nus, instead of giving a false impresion that abusing data_json is\nOK?\n\n> diff --git a/wrapper.c b/wrapper.c\n> index 1c3c970080b..eebd764131f 100644\n> --- a/wrapper.c\n> +++ b/wrapper.c\n> @@ -618,6 +618,9 @@ int git_fsync(int fd, enum fsync_action action)\n>  \n>  void trace_git_fsync_stats(void)\n>  {\n> +\tif (!count_fsync_writeout_only && !count_fsync_hardware_flush)\n> +\t\treturn;\n> +\n\nOK, both counters are unconditionally incremented whenever the\ncorresponding action triggers, so this implementation is probably OK\nfor now, but I suspect that it would become a maintenance burden if\nwe were to add more fsync actions later.\n\n>  \ttrace2_data_intmax(\"fsync\", the_repository, \"fsync/writeout-only\", count_fsync_writeout_only);\n>  \ttrace2_data_intmax(\"fsync\", the_repository, \"fsync/hardware-flush\", count_fsync_hardware_flush);\n\nIf each of these is guarded with \"show only when non-zero\", that\nwould become less problematic, though.\n\nA bigger issue is when somebody is debugging the callers of\ngit_fsync() wondering why they do not trigger.  Getting log entries\nthat say \"no git_fsync() call with these actions have been made\"\nmay be useful (i.e. explicitly negative answer).\n\nI am not sure if it is a good solution in the longer term, but this\nimplementation may be a good-enough way to squelch the immediate\nloudness issue.\n\nThanks.\n\n"},{"id":"458168","messageId":"patch-v2-1.1-a1fc37de947-20220630T084607Z-avarab@gmail.com","threadId":"58060","inReplyTo":"patch-1.1-df87e515efd-20220623T154943Z-avarab@gmail.com","subject":"[PATCH v2] trace2: don't include \"fsync\" events in all trace2 logs","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2022-06-30T08:56:47Z","receivedAt":"2022-06-30T08:56:56Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"Fix the overly verbose trace2 logging added in 9a4987677d3 (trace2:\nadd stats for fsync operations, 2022-03-30) (first released with\nv2.36.0).\n\nSince that change every single \"git\" command invocation has included\nthese \"data\" events, even though we'll only make use of these with\ncore.fsyncMethod=batch, and even then only have non-zero values if\nwe're writing object data to disk. See c0f4752ed2f (core.fsyncmethod:\nbatched disk flushes for loose-objects, 2022-04-04) for that feature.\n\nAs we're needing to indent the trace2_data_intmax() lines let's\nintroduce helper variables to ensure that our resulting lines (which\nwere already too) don't exceed the recommendations of the\nCodingGuidelines. Doing that requires either wrapping them twice, or\nintroducing short throwaway variable names, let's do the latter.\n\nThe result was that e.g. \"git version\" would previously emit a total\nof 6 trace2 events with the GIT_TRACE2_EVENT target (version, start,\ncmd_ancestry, cmd_name, exit, atexit), but afterwards would emit\n8. We'd emit 2 \"data\" events before the \"exit\" event.\n\nThe reason we didn't catch this was that the trace2 unit tests added\nin a15860dca3f (trace2: t/helper/test-trace2, t0210.sh, t0211.sh,\nt0212.sh, 2019-02-22) would omit any \"data\" events that weren't the\nones it cared about. Before this change to the C code 6/7 of our\n\"t/t0212-trace2-event.sh\" tests would fail if this change was applied\nto \"t/t0212/parse_events.perl\".\n\nLet's make the trace2 testing more strict, and further append any new\nevents types we don't know about in \"t/t0212/parse_events.perl\". Since\nwe only invoke the \"test-tool trace2\" there's no guarantee that we'll\ncatch other overly verbose events in the future, but we'll at least\nnotice if we start emitting new events that are issues every time we\nlog anything with trace2's JSON target.\n\nWe exclude the \"data_json\" event type, we'd otherwise would fail on\nboth \"win test\" and \"win+VS test\" CI due to the logging added in\n353d3d77f4f (trace2: collect Windows-specific process information,\n2019-02-22). It looks like that logging should really be using\ntrace2_cmd_ancestry() instead, which was introduced later in\n2f732bf15e6 (tr2: log parent process name, 2021-07-21), but let's\nleave it for now.\n\nSigned-off-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>\n---\n\nI think this re-roll addresses the concerns Junio brought up in:\nhttps://lore.kernel.org/git/xmqqh74byy19.fsf@gitster.g/; As to the\nlarger question of:\n\nOn Thu, Jun 23 2022, Junio C Hamano wrote:\n\n> I am not sure if it is a good solution in the longer term, but this\n> implementation may be a good-enough way to squelch the immediate\n> loudness issue.\n\nI think a better long-term solution in this case, per the initial\nfeedback on the patch would be to have a generic facility to trace2\nlog how often we call a given syscall:\n\n\thttps://lore.kernel.org/git/220330.86zgl7o8l8.gmgdl@evledraar.gmail.com/\n\nI.e. in most (all?) other cases our trace2 logging is logging git's\n\"business logic\", but in this case the logging is functionally the\nsame as a more dumb interception of an arbitrary system call, and then\nhaving some generic \"syscall stats\" trace2 event.\n\nIn this case such a generic logger would need to be a bit smarter than\njust a dumb wrapper, i.e. we'd need:\n\n    fsync() != EINTR /* due to fsync_loop() */\n    sync_file_range()\n\nThat still wouldn't be the same as the current logging if implemented\ncorrectly, but I think in a good way. E.g. now we'll log a failed\nfsync() the same as a successful one, as we increment the counter\nbefore seeing what the return value was.\n\nBut anyway, as noted in the original thread Neeraj didn't have time to\nlook into that, neither do I, and the patch is now a part of git. So\nlet's solve the immediate issue of verbose logging, and leave any\nother improvements for the future.\n\nRange-diff against v1:\n1:  df87e515efd ! 1:  a1fc37de947 trace2: don't include \"fsync\" events in all trace2 logs\n    @@ Commit message\n         we're writing object data to disk. See c0f4752ed2f (core.fsyncmethod:\n         batched disk flushes for loose-objects, 2022-04-04) for that feature.\n     \n    +    As we're needing to indent the trace2_data_intmax() lines let's\n    +    introduce helper variables to ensure that our resulting lines (which\n    +    were already too) don't exceed the recommendations of the\n    +    CodingGuidelines. Doing that requires either wrapping them twice, or\n    +    introducing short throwaway variable names, let's do the latter.\n    +\n         The result was that e.g. \"git version\" would previously emit a total\n         of 6 trace2 events with the GIT_TRACE2_EVENT target (version, start,\n         cmd_ancestry, cmd_name, exit, atexit), but afterwards would emit\n    @@ t/t0212/parse_events.perl\n     +    }\n     +\n     +    elsif ($event eq 'data_json') {\n    -+\t# Ignore due to compat/win32/trace2_win32_process_info.c\n    ++\t# NEEDSWORK: Ignore due to\n    ++\t# compat/win32/trace2_win32_process_info.c, which should log a\n    ++\t# \"cmd_ancestry\" event instead.\n     +    }\n     +\n     +    else {\n    @@ wrapper.c: int git_fsync(int fd, enum fsync_action action)\n      \n      void trace_git_fsync_stats(void)\n      {\n    -+\tif (!count_fsync_writeout_only && !count_fsync_hardware_flush)\n    -+\t\treturn;\n    +-\ttrace2_data_intmax(\"fsync\", the_repository, \"fsync/writeout-only\", count_fsync_writeout_only);\n    +-\ttrace2_data_intmax(\"fsync\", the_repository, \"fsync/hardware-flush\", count_fsync_hardware_flush);\n    ++\tconst struct repository *r = the_repository;\n    ++\tconst intmax_t cfwo = count_fsync_writeout_only;\n    ++\tconst intmax_t cfhf = count_fsync_hardware_flush;\n     +\n    - \ttrace2_data_intmax(\"fsync\", the_repository, \"fsync/writeout-only\", count_fsync_writeout_only);\n    - \ttrace2_data_intmax(\"fsync\", the_repository, \"fsync/hardware-flush\", count_fsync_hardware_flush);\n    ++\tif (cfwo)\n    ++\t\ttrace2_data_intmax(\"fsync\", r, \"fsync/writeout-only\", cfwo);\n    ++\tif (cfhf)\n    ++\t\ttrace2_data_intmax(\"fsync\", r, \"fsync/hardware-flush\", cfhf);\n      }\n    + \n    + static int warn_if_unremovable(const char *op, const char *file, int rc)\n\n t/t0212/parse_events.perl | 19 +++++++++++++------\n wrapper.c                 | 10 ++++++++--\n 2 files changed, 21 insertions(+), 8 deletions(-)\n\ndiff --git a/t/t0212/parse_events.perl b/t/t0212/parse_events.perl\nindex b6408560c0c..30a9f51e9f1 100644\n--- a/t/t0212/parse_events.perl\n+++ b/t/t0212/parse_events.perl\n@@ -216,12 +216,19 @@\n \n     elsif ($event eq 'data') {\n \tmy $cat = $line->{'category'};\n-\tif ($cat eq 'test_category') {\n-\t    \n-\t    my $key = $line->{'key'};\n-\t    my $value = $line->{'value'};\n-\t    $processes->{$sid}->{'data'}->{$cat}->{$key} = $value;\n-\t}\n+\tmy $key = $line->{'key'};\n+\tmy $value = $line->{'value'};\n+\t$processes->{$sid}->{'data'}->{$cat}->{$key} = $value;\n+    }\n+\n+    elsif ($event eq 'data_json') {\n+\t# NEEDSWORK: Ignore due to\n+\t# compat/win32/trace2_win32_process_info.c, which should log a\n+\t# \"cmd_ancestry\" event instead.\n+    }\n+\n+    else {\n+\tpush @{$processes->{$sid}->{$event}} => $line->{value};\n     }\n \n     # This trace2 target does not emit 'printf' events.\ndiff --git a/wrapper.c b/wrapper.c\nindex 1c3c970080b..67727f95411 100644\n--- a/wrapper.c\n+++ b/wrapper.c\n@@ -618,8 +618,14 @@ int git_fsync(int fd, enum fsync_action action)\n \n void trace_git_fsync_stats(void)\n {\n-\ttrace2_data_intmax(\"fsync\", the_repository, \"fsync/writeout-only\", count_fsync_writeout_only);\n-\ttrace2_data_intmax(\"fsync\", the_repository, \"fsync/hardware-flush\", count_fsync_hardware_flush);\n+\tconst struct repository *r = the_repository;\n+\tconst intmax_t cfwo = count_fsync_writeout_only;\n+\tconst intmax_t cfhf = count_fsync_hardware_flush;\n+\n+\tif (cfwo)\n+\t\ttrace2_data_intmax(\"fsync\", r, \"fsync/writeout-only\", cfwo);\n+\tif (cfhf)\n+\t\ttrace2_data_intmax(\"fsync\", r, \"fsync/hardware-flush\", cfhf);\n }\n \n static int warn_if_unremovable(const char *op, const char *file, int rc)\n-- \n2.37.0.880.gf07d56b18ba\n\n"},{"id":"458246","messageId":"xmqqczepev8e.fsf@gitster.g","threadId":"58060","inReplyTo":"patch-v2-1.1-a1fc37de947-20220630T084607Z-avarab@gmail.com","subject":"Re: [PATCH v2] trace2: don't include \"fsync\" events in all trace2 logs","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2022-06-30T20:45:21Z","receivedAt":"2022-06-30T20:45:32Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Ævar Arnfjörð Bjarmason  <avarab@gmail.com> writes:\n\n> As we're needing to indent the trace2_data_intmax() lines let's\n> introduce helper variables to ensure that our resulting lines (which\n> were already too) don't exceed the recommendations of the\n\ntoo -> too something\n\n> +    elsif ($event eq 'data_json') {\n> +\t# NEEDSWORK: Ignore due to\n> +\t# compat/win32/trace2_win32_process_info.c, which should log a\n> +\t# \"cmd_ancestry\" event instead.\n> +    }\n\nThis does read better.\n\n>  void trace_git_fsync_stats(void)\n>  {\n> -\ttrace2_data_intmax(\"fsync\", the_repository, \"fsync/writeout-only\", count_fsync_writeout_only);\n> -\ttrace2_data_intmax(\"fsync\", the_repository, \"fsync/hardware-flush\", count_fsync_hardware_flush);\n> +\tconst struct repository *r = the_repository;\n> +\tconst intmax_t cfwo = count_fsync_writeout_only;\n> +\tconst intmax_t cfhf = count_fsync_hardware_flush;\n> +\n> +\tif (cfwo)\n> +\t\ttrace2_data_intmax(\"fsync\", r, \"fsync/writeout-only\", cfwo);\n> +\tif (cfhf)\n> +\t\ttrace2_data_intmax(\"fsync\", r, \"fsync/hardware-flush\", cfhf);\n\nI would have wrapped the lines instead of introducing these extra\nvariables; the key observation is that it would make a much easier\npattern to follow for a future developer who needs to add the third\nkind of \"fsync\" on top of the existing wo and hf.\n\nBut we can address that when somebody actually adds the third one,\nso let's take the patch as-is.\n\nThanks.\n"},{"id":"459252","messageId":"patch-v3-1.1-979dea5956a-20220718T102747Z-avarab@gmail.com","threadId":"58060","inReplyTo":"patch-v2-1.1-a1fc37de947-20220630T084607Z-avarab@gmail.com","subject":"[PATCH v3] trace2: only include \"fsync\" events if we git_fsync()","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2022-07-18T10:31:52Z","receivedAt":"2022-07-18T10:32:04Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"Fix the overly verbose trace2 logging added in 9a4987677d3 (trace2:\nadd stats for fsync operations, 2022-03-30) (first released with\nv2.36.0).\n\nSince that change every single \"git\" command invocation has included\nthese \"data\" events, even though we'll only make use of these with\ncore.fsyncMethod=batch, and even then only have non-zero values if\nwe're writing object data to disk. See c0f4752ed2f (core.fsyncmethod:\nbatched disk flushes for loose-objects, 2022-04-04) for that feature.\n\nAs we're needing to indent the trace2_data_intmax() lines let's\nintroduce helper variables to ensure that our resulting lines (which\nwere already too) don't exceed the recommendations of the\nCodingGuidelines. Doing that requires either wrapping them twice, or\nintroducing short throwaway variable names, let's do the latter.\n\nThe result was that e.g. \"git version\" would previously emit a total\nof 6 trace2 events with the GIT_TRACE2_EVENT target (version, start,\ncmd_ancestry, cmd_name, exit, atexit), but afterwards would emit\n8. We'd emit 2 \"data\" events before the \"exit\" event.\n\nThe reason we didn't catch this was that the trace2 unit tests added\nin a15860dca3f (trace2: t/helper/test-trace2, t0210.sh, t0211.sh,\nt0212.sh, 2019-02-22) would omit any \"data\" events that weren't the\nones it cared about. Before this change to the C code 6/7 of our\n\"t/t0212-trace2-event.sh\" tests would fail if this change was applied\nto \"t/t0212/parse_events.perl\".\n\nLet's make the trace2 testing more strict, and further append any new\nevents types we don't know about in \"t/t0212/parse_events.perl\". Since\nwe only invoke the \"test-tool trace2\" there's no guarantee that we'll\ncatch other overly verbose events in the future, but we'll at least\nnotice if we start emitting new events that are issues every time we\nlog anything with trace2's JSON target.\n\nWe exclude the \"data_json\" event type, we'd otherwise would fail on\nboth \"win test\" and \"win+VS test\" CI due to the logging added in\n353d3d77f4f (trace2: collect Windows-specific process information,\n2019-02-22). It looks like that logging should really be using\ntrace2_cmd_ancestry() instead, which was introduced later in\n2f732bf15e6 (tr2: log parent process name, 2021-07-21), but let's\nleave it for now.\n\nThe fix-up to aaf81223f48 (unpack-objects: use stream_loose_object()\nto unpack large objects, 2022-06-11) is needed because we're changing\nthe behavior of these events as discussed above. Since we'd always\nemit a \"hardware-flush\" event the test added in aaf81223f48 wasn't\ntesting anything except that this trace2 data was unconditionally\nlogged. Even if \"core.fsyncMethod\" wasn't set to \"batch\" we'd pass the\ntest.\n\nNow we'll check the expected number of \"writeout\" v.s. \"flush\" calls\nunder \"core.fsyncMethod=batch\", but note that this doesn't actually\ntest if we carried out the sync using that method, on a platform where\nwe'd have to fall back to fsync() each of those \"writeout\" would\nreally be a \"flush\" (i.e. a full fsync()).\n\nBut in this case what we're testing is that the logic in\n\"unpack-objects\" behaves as expected, not the OS-specific question of\nwhether we actually were able to use the \"bulk\" method.\n\nSigned-off-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>\n---\n\nThis v3:\n\n * Fixes the failing tests, due to a merge with\n   hx/unpack-streaming. See details at:\n   https://lore.kernel.org/git/220715.86bktqzdb8.gmgdl@evledraar.gmail.com/\n\n   We now test how many \"writeout\" and \"flush\" sync events we emit,\n   rather than the (meaningless) previous behavior (see above)>\n\n * Creates a log_trace_fsync_if() helper in wrapper.c, to avoid both\n   the duplication and line-wrapping issues previous rounds tried to\n   address more verbosely.\n\nRange-diff against v2:\n1:  a1fc37de947 ! 1:  979dea5956a trace2: don't include \"fsync\" events in all trace2 logs\n    @@ Metadata\n     Author: Ævar Arnfjörð Bjarmason <avarab@gmail.com>\n     \n      ## Commit message ##\n    -    trace2: don't include \"fsync\" events in all trace2 logs\n    +    trace2: only include \"fsync\" events if we git_fsync()\n     \n         Fix the overly verbose trace2 logging added in 9a4987677d3 (trace2:\n         add stats for fsync operations, 2022-03-30) (first released with\n    @@ Commit message\n         2f732bf15e6 (tr2: log parent process name, 2021-07-21), but let's\n         leave it for now.\n     \n    +    The fix-up to aaf81223f48 (unpack-objects: use stream_loose_object()\n    +    to unpack large objects, 2022-06-11) is needed because we're changing\n    +    the behavior of these events as discussed above. Since we'd always\n    +    emit a \"hardware-flush\" event the test added in aaf81223f48 wasn't\n    +    testing anything except that this trace2 data was unconditionally\n    +    logged. Even if \"core.fsyncMethod\" wasn't set to \"batch\" we'd pass the\n    +    test.\n    +\n    +    Now we'll check the expected number of \"writeout\" v.s. \"flush\" calls\n    +    under \"core.fsyncMethod=batch\", but note that this doesn't actually\n    +    test if we carried out the sync using that method, on a platform where\n    +    we'd have to fall back to fsync() each of those \"writeout\" would\n    +    really be a \"flush\" (i.e. a full fsync()).\n    +\n    +    But in this case what we're testing is that the logic in\n    +    \"unpack-objects\" behaves as expected, not the OS-specific question of\n    +    whether we actually were able to use the \"bulk\" method.\n    +\n         Signed-off-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>\n     \n      ## t/t0212/parse_events.perl ##\n    @@ t/t0212/parse_events.perl\n      \n          # This trace2 target does not emit 'printf' events.\n     \n    + ## t/t5351-unpack-large-objects.sh ##\n    +@@ t/t5351-unpack-large-objects.sh: test_expect_success 'unpack big object in stream' '\n    + \ttest_dir_is_empty dest.git/objects/pack\n    + '\n    + \n    ++check_fsync_events () {\n    ++\tlocal trace=\"$1\" &&\n    ++\tshift &&\n    ++\n    ++\tcat >expect &&\n    ++\tsed -n \\\n    ++\t\t-e '/^{\"event\":\"data\",.*\"category\":\"fsync\",/ {\n    ++\t\t\ts/.*\"category\":\"fsync\",//;\n    ++\t\t\ts/}$//;\n    ++\t\t\tp;\n    ++\t\t}' \\\n    ++\t\t<\"$trace\" >actual &&\n    ++\ttest_cmp expect actual\n    ++}\n    ++\n    + BATCH_CONFIGURATION='-c core.fsync=loose-object -c core.fsyncmethod=batch'\n    + \n    + test_expect_success 'unpack big object in stream (core.fsyncmethod=batch)' '\n    + \tprepare_dest 1m &&\n    + \tGIT_TRACE2_EVENT=\"$(pwd)/trace2.txt\" \\\n    ++\tGIT_TEST_FSYNC=true \\\n    + \t\tgit -C dest.git $BATCH_CONFIGURATION unpack-objects <pack-$PACK.pack &&\n    +-\tgrep fsync/hardware-flush trace2.txt &&\n    ++\tcheck_fsync_events trace2.txt <<-\\EOF &&\n    ++\t\"key\":\"fsync/writeout-only\",\"value\":\"6\"\n    ++\t\"key\":\"fsync/hardware-flush\",\"value\":\"1\"\n    ++\tEOF\n    ++\n    + \ttest_dir_is_empty dest.git/objects/pack &&\n    + \tgit -C dest.git cat-file --batch-check=\"%(objectname)\" <obj-list >current &&\n    + \tcmp obj-list current\n    +\n      ## wrapper.c ##\n     @@ wrapper.c: int git_fsync(int fd, enum fsync_action action)\n    + \t}\n    + }\n      \n    ++static void log_trace_fsync_if(const char *key, intmax_t value)\n    ++{\n    ++\tif (value)\n    ++\t\ttrace2_data_intmax(\"fsync\", the_repository, key, value);\n    ++}\n    ++\n      void trace_git_fsync_stats(void)\n      {\n     -\ttrace2_data_intmax(\"fsync\", the_repository, \"fsync/writeout-only\", count_fsync_writeout_only);\n     -\ttrace2_data_intmax(\"fsync\", the_repository, \"fsync/hardware-flush\", count_fsync_hardware_flush);\n    -+\tconst struct repository *r = the_repository;\n    -+\tconst intmax_t cfwo = count_fsync_writeout_only;\n    -+\tconst intmax_t cfhf = count_fsync_hardware_flush;\n    -+\n    -+\tif (cfwo)\n    -+\t\ttrace2_data_intmax(\"fsync\", r, \"fsync/writeout-only\", cfwo);\n    -+\tif (cfhf)\n    -+\t\ttrace2_data_intmax(\"fsync\", r, \"fsync/hardware-flush\", cfhf);\n    ++\tlog_trace_fsync_if(\"fsync/writeout-only\", count_fsync_writeout_only);\n    ++\tlog_trace_fsync_if(\"fsync/hardware-flush\", count_fsync_hardware_flush);\n      }\n      \n      static int warn_if_unremovable(const char *op, const char *file, int rc)\n\n t/t0212/parse_events.perl       | 19 +++++++++++++------\n t/t5351-unpack-large-objects.sh | 22 +++++++++++++++++++++-\n wrapper.c                       | 10 ++++++++--\n 3 files changed, 42 insertions(+), 9 deletions(-)\n\ndiff --git a/t/t0212/parse_events.perl b/t/t0212/parse_events.perl\nindex b6408560c0c..30a9f51e9f1 100644\n--- a/t/t0212/parse_events.perl\n+++ b/t/t0212/parse_events.perl\n@@ -216,12 +216,19 @@\n \n     elsif ($event eq 'data') {\n \tmy $cat = $line->{'category'};\n-\tif ($cat eq 'test_category') {\n-\t    \n-\t    my $key = $line->{'key'};\n-\t    my $value = $line->{'value'};\n-\t    $processes->{$sid}->{'data'}->{$cat}->{$key} = $value;\n-\t}\n+\tmy $key = $line->{'key'};\n+\tmy $value = $line->{'value'};\n+\t$processes->{$sid}->{'data'}->{$cat}->{$key} = $value;\n+    }\n+\n+    elsif ($event eq 'data_json') {\n+\t# NEEDSWORK: Ignore due to\n+\t# compat/win32/trace2_win32_process_info.c, which should log a\n+\t# \"cmd_ancestry\" event instead.\n+    }\n+\n+    else {\n+\tpush @{$processes->{$sid}->{$event}} => $line->{value};\n     }\n \n     # This trace2 target does not emit 'printf' events.\ndiff --git a/t/t5351-unpack-large-objects.sh b/t/t5351-unpack-large-objects.sh\nindex 8ce8aa3b147..f785cb06173 100755\n--- a/t/t5351-unpack-large-objects.sh\n+++ b/t/t5351-unpack-large-objects.sh\n@@ -48,13 +48,33 @@ test_expect_success 'unpack big object in stream' '\n \ttest_dir_is_empty dest.git/objects/pack\n '\n \n+check_fsync_events () {\n+\tlocal trace=\"$1\" &&\n+\tshift &&\n+\n+\tcat >expect &&\n+\tsed -n \\\n+\t\t-e '/^{\"event\":\"data\",.*\"category\":\"fsync\",/ {\n+\t\t\ts/.*\"category\":\"fsync\",//;\n+\t\t\ts/}$//;\n+\t\t\tp;\n+\t\t}' \\\n+\t\t<\"$trace\" >actual &&\n+\ttest_cmp expect actual\n+}\n+\n BATCH_CONFIGURATION='-c core.fsync=loose-object -c core.fsyncmethod=batch'\n \n test_expect_success 'unpack big object in stream (core.fsyncmethod=batch)' '\n \tprepare_dest 1m &&\n \tGIT_TRACE2_EVENT=\"$(pwd)/trace2.txt\" \\\n+\tGIT_TEST_FSYNC=true \\\n \t\tgit -C dest.git $BATCH_CONFIGURATION unpack-objects <pack-$PACK.pack &&\n-\tgrep fsync/hardware-flush trace2.txt &&\n+\tcheck_fsync_events trace2.txt <<-\\EOF &&\n+\t\"key\":\"fsync/writeout-only\",\"value\":\"6\"\n+\t\"key\":\"fsync/hardware-flush\",\"value\":\"1\"\n+\tEOF\n+\n \ttest_dir_is_empty dest.git/objects/pack &&\n \tgit -C dest.git cat-file --batch-check=\"%(objectname)\" <obj-list >current &&\n \tcmp obj-list current\ndiff --git a/wrapper.c b/wrapper.c\nindex 1c3c970080b..cfe79bd081f 100644\n--- a/wrapper.c\n+++ b/wrapper.c\n@@ -616,10 +616,16 @@ int git_fsync(int fd, enum fsync_action action)\n \t}\n }\n \n+static void log_trace_fsync_if(const char *key, intmax_t value)\n+{\n+\tif (value)\n+\t\ttrace2_data_intmax(\"fsync\", the_repository, key, value);\n+}\n+\n void trace_git_fsync_stats(void)\n {\n-\ttrace2_data_intmax(\"fsync\", the_repository, \"fsync/writeout-only\", count_fsync_writeout_only);\n-\ttrace2_data_intmax(\"fsync\", the_repository, \"fsync/hardware-flush\", count_fsync_hardware_flush);\n+\tlog_trace_fsync_if(\"fsync/writeout-only\", count_fsync_writeout_only);\n+\tlog_trace_fsync_if(\"fsync/hardware-flush\", count_fsync_hardware_flush);\n }\n \n static int warn_if_unremovable(const char *op, const char *file, int rc)\n-- \n2.37.1.1032.gb00b5447790\n\n"},{"id":"459296","messageId":"xmqq5yjus6u2.fsf@gitster.g","threadId":"58060","inReplyTo":"patch-v3-1.1-979dea5956a-20220718T102747Z-avarab@gmail.com","subject":"Re: [PATCH v3] trace2: only include \"fsync\" events if we git_fsync()","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2022-07-18T16:50:45Z","receivedAt":"2022-07-18T16:50:57Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Ævar Arnfjörð Bjarmason  <avarab@gmail.com> writes:\n\n> As we're needing to indent the trace2_data_intmax() lines let's\n> introduce helper variables to ensure that our resulting lines (which\n> were already too) don't exceed the recommendations of the\n> CodingGuidelines. Doing that requires either wrapping them twice, or\n> introducing short throwaway variable names, let's do the latter.\n\nOr a macro that can be used like\n\n\tlog_trace_fsync_nonzero(writeout_only);\n\tlog_trace_fsync_nonzero(hardware_flush);\n\nsomething along the lines of\n\n#define log_trace_fsync_nonzero(var) \\\n\tif (count_fsync_ #var) \\\n\t\ttrace2_data_intmax(\"fsync\", the_repository, \\\n\t\t\t\"fsync/\" ##var, count_fsync_ #var)\n\nusing token pasting and token stringification ;-)\n\nThe macro itself I am not serious at all.  s/_if/_nonzero/ may be\nworth pondering, though.\n\n>    We now test how many \"writeout\" and \"flush\" sync events we emit,\n>    rather than the (meaningless) previous behavior (see above)>\n\nMakes sense.\n\nNeeraj, Ack, as the author of 9a498767 (trace2: add stats for fsync\noperations, 2022-03-30)?\n\nThanks all.\n"},{"id":"459312","messageId":"LV2PR21MB3157899077CD86F1949024D1CC8C9@LV2PR21MB3157.namprd21.prod.outlook.com","threadId":"58060","inReplyTo":"xmqq5yjus6u2.fsf@gitster.g","subject":"RE: [EXTERNAL] Re: [PATCH v3] trace2: only include \"fsync\" events if we git_fsync()","fromName":"Neeraj Singh (WINDOWS-SFS)","fromEmail":"neerajsi@microsoft.com","sentAt":"2022-07-18T19:01:22Z","receivedAt":"2022-07-18T19:02:04Z","isPatch":true,"sender":{"key":"neerajsi@microsoft.com","avatar":"https://avatars.githubusercontent.com/u/78932899?v=4"},"body":"Yes, ACK.  Looks fine to me.  This is still enough info to diagnose if the configuration is being parsed properly and if we're going down the right codepaths.\n\nThanks,\nNeeraj\n"}]}