{"thread":{"id":"60682","subject":"[PATCH] push: region_leave trace for negotiate_using_fetch","startedAt":"2024-01-03T22:41:07Z","lastAt":"2024-01-05T16:19:02Z","messageCount":4,"participants":["Sam Delmerico","Junio C Hamano"],"isPatch":true,"patchVersion":1,"patchTotal":null},"messages":[{"id":"486279","messageId":"20240103224054.1940209-1-delmerico@google.com","threadId":"60682","inReplyTo":null,"subject":"[PATCH] push: region_leave trace for negotiate_using_fetch","fromName":"Sam Delmerico","fromEmail":"delmerico@google.com","sentAt":"2024-01-03T22:40:54Z","receivedAt":"2024-01-03T22:41:07Z","isPatch":true,"sender":{"key":"delmerico@google.com","avatar":null},"body":"There were two region_enter events for negotiate_using_fetch instead of\none enter and one leave. This commit replaces the second region_enter\nevent with a region_leave.\n\nSigned-off-by: Sam Delmerico \n---\n fetch-pack.c | 2 +-\n 1 file changed, 1 insertion(+), 1 deletion(-)\n\ndiff --git a/fetch-pack.c b/fetch-pack.c\nindex 31a72d43de..dba6d79944 100644\n--- a/fetch-pack.c\n+++ b/fetch-pack.c\n@@ -2218,7 +2218,7 @@ void negotiate_using_fetch(const struct oid_array *negotiation_tips,\n \t\t\t\t\t the_repository, \"%d\",\n \t\t\t\t\t negotiation_round);\n \t}\n-\ttrace2_region_enter(\"fetch-pack\", \"negotiate_using_fetch\", the_repository);\n+\ttrace2_region_leave(\"fetch-pack\", \"negotiate_using_fetch\", the_repository);\n \ttrace2_data_intmax(\"negotiate_using_fetch\", the_repository,\n \t\t\t \"total_rounds\", negotiation_round);\n \tclear_common_flag(acked_commits);\n\nbase-commit: a26002b62827b89a19b1084bd75d9371d565d03c\n-- \n2.43.0.472.g3155946c3a-goog\n\n"},{"id":"486280","messageId":"xmqqbka27zu9.fsf@gitster.g","threadId":"60682","inReplyTo":"20240103224054.1940209-1-delmerico@google.com","subject":"Re: [PATCH] push: region_leave trace for negotiate_using_fetch","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2024-01-03T23:37:50Z","receivedAt":"2024-01-03T23:37:55Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Sam Delmerico writes:\n\n> There were two region_enter events for negotiate_using_fetch instead of\n> one enter and one leave. This commit replaces the second region_enter\n> event with a region_leave.\n>\n> Signed-off-by: Sam Delmerico \n> ---\n> fetch-pack.c | 2 +-\n> 1 file changed, 1 insertion(+), 1 deletion(-)\n\nLooks right, after skimming a29263cf (fetch-pack: add tracing for\nnegotiation rounds, 2022-08-02). Two questions and a half.\n\n * How did you find it? Code inspection? While writing a script to\n parse the output from around this area, your script noticed the\n ever-increasing nesting level? Something else?\n\n * Would it be feasible to write some tests or tools that find\n similar problems (semi-)automatically?\n\n * Is the breakage (before this patch) something easily demonstrated\n in a new test in t/ somewhere? And if so, would it be worth\n doing?\n\nThanks. Will queue.\n\n\n>\n> diff --git a/fetch-pack.c b/fetch-pack.c\n> index 31a72d43de..dba6d79944 100644\n> --- a/fetch-pack.c\n> +++ b/fetch-pack.c\n> @@ -2218,7 +2218,7 @@ void negotiate_using_fetch(const struct oid_array *negotiation_tips,\n> \t\t\t\t\t the_repository, \"%d\",\n> \t\t\t\t\t negotiation_round);\n> \t}\n> -\ttrace2_region_enter(\"fetch-pack\", \"negotiate_using_fetch\", the_repository);\n> +\ttrace2_region_leave(\"fetch-pack\", \"negotiate_using_fetch\", the_repository);\n> \ttrace2_data_intmax(\"negotiate_using_fetch\", the_repository,\n> \t\t\t \"total_rounds\", negotiation_round);\n> \tclear_common_flag(acked_commits);\n>\n> base-commit: a26002b62827b89a19b1084bd75d9371d565d03c\n"},{"id":"486330","messageId":"CAHVcGPSSJr7L_NyFSKEkEywBap6hUrucga98RLpa6xuZ0k4CzA@mail.gmail.com","threadId":"60682","inReplyTo":"xmqqbka27zu9.fsf@gitster.g","subject":"Re: [PATCH] push: region_leave trace for negotiate_using_fetch","fromName":"Sam Delmerico","fromEmail":"delmerico@google.com","sentAt":"2024-01-05T01:12:15Z","receivedAt":"2024-01-05T01:12:29Z","isPatch":true,"sender":{"key":"delmerico@google.com","avatar":null},"body":"* I don't exactly remember how I noticed it. I was doing some\ndebugging around the push negotiation code and either 1) saw this\nregion get entered twice in the trace output, or 2) I was just reading\nthe code around here and saw two enters.\n\n* Perhaps there could be a check before the last git process ends that\nchecks that all opened trace regions have been closed? I'm not sure\nhow much work this would involve. It's probably also not a very\nproactive way to catch these bugs since it would only get triggered\nwhen a *user* hits a code path with a trace region that never exits.\n\n* There could also be a test that checks that every region_enter trace\nlog has a corresponding region_leave. But I'm not sure how to ensure\nthat every code path is checked.\n\nOverall, I'm not sure how much benefit there is from checking for\nthis. I'm not sure that it would have a large impact if it were to\nhappen again. For example, I think that it could be noticed relatively\nquickly by a person/system looking at metrics like I was (e.g. if the\ntime spent in a region is infinite or zero).\n\nFWIW I didn't see any other examples of this when going through logs.\n\nSam\n
On Wed,\nJan 3, 2024 at 3:37 PM Junio C Hamano <gitster@pobox.com>\nwrote:
Sam Delmerico <delmerico@google.com> writes:
\n
\n> There were two region_enter events for negotiate_using_fetch instead of
\n> one enter and one leave. This commit replaces the second region_enter
\n> event with a region_leave.
\n>
\n> Signed-off-by: Sam Delmerico <delmerico@google.com>
\n> ---
\n>  fetch-pack.c | 2 +-
\n>  1 file changed, 1 insertion(+), 1 deletion(-)
\n
\nLooks right, after skimming a29263cf (fetch-pack: add tracing for
\nnegotiation rounds, 2022-08-02).  Two questions and a half.
\n
\n * How did you find it?  Code inspection?  While\nwriting a script to
\n   parse the output from around this area, your script noticed the
\n   ever-increasing nesting level?  Something else?
\n
\n * Would it be feasible to write some tests or tools that find
\n   similar problems (semi-)automatically?
\n
\n * Is the breakage (before this patch) something easily demonstrated
\n   in a new test in t/ somewhere?  And if so, would it\nbe worth
\n   doing?
\n
\nThanks.  Will queue.
\n
\n
\n>
\n> diff --git a/fetch-pack.c b/fetch-pack.c
\n> index 31a72d43de..dba6d79944 100644
\n> --- a/fetch-pack.c
\n> +++ b/fetch-pack.c
\n> @@ -2218,7 +2218,7 @@ void negotiate_using_fetch(const struct\noid_array *negotiation_tips,
\n>                 \n                   \n    the_repository, \"%d\",
\n>                 \n                   \n    negotiation_round);
\n>       }
\n> -     trace2_region_enter(\"fetch-pack\",\n\"negotiate_using_fetch\", the_repository);
\n> +     trace2_region_leave(\"fetch-pack\",\n\"negotiate_using_fetch\", the_repository);
\n>     \n trace2_data_intmax(\"negotiate_using_fetch\",\nthe_repository,
\n>                 \n        \"total_rounds\", negotiation_round);
\n>       clear_common_flag(acked_commits);
\n>
\n> base-commit: a26002b62827b89a19b1084bd75d9371d565d03c
\n
\n"},{"id":"486344","messageId":"xmqq4jfrpxce.fsf@gitster.g","threadId":"60682","inReplyTo":"CAHVcGPSSJr7L_NyFSKEkEywBap6hUrucga98RLpa6xuZ0k4CzA@mail.gmail.com","subject":"Re: [PATCH] push: region_leave trace for negotiate_using_fetch","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2024-01-05T16:18:57Z","receivedAt":"2024-01-05T16:19:02Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Sam Delmerico writes:\n\n> * I don't exactly remember how I noticed it. I was doing some\n> debugging around the push negotiation code and either 1) saw this\n> region get entered twice in the trace output, or 2) I was just reading\n> the code around here and saw two enters.\n>\n> * Perhaps there could be a check before the last git process ends that\n> checks that all opened trace regions have been closed? I'm not sure\n> how much work this would involve. It's probably also not a very\n> proactive way to catch these bugs since it would only get triggered\n> when a *user* hits a code path with a trace region that never exits.\n>\n> * There could also be a test that checks that every region_enter trace\n> log has a corresponding region_leave. But I'm not sure how to ensure\n> that every code path is checked.\n>\n> Overall, I'm not sure how much benefit there is from checking for\n> this. I'm not sure that it would have a large impact if it were to\n> happen again. For example, I think that it could be noticed relatively\n> quickly by a person/system looking at metrics like I was (e.g. if the\n> time spent in a region is infinite or zero).\n>\n> FWIW I didn't see any other examples of this when going through logs.\n\nThe above matches my intuition. A test that covers this specific\ncase would likely be of low value as it is unlikely for us to\nregress this specific one. A CI job that runs all the tests under\ntracing and inspects the log may catch some but its finding would be\nlimited to the code paths that are covered (but increasing the test\ncoverage would help here, not just for finding unbalanced region\nmarkers, but for finding bugs in general).\n\nThanks.\n"}]}