From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from mail-ed1-f52.google.com (mail-ed1-f52.google.com [209.85.208.52]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (No client certificate requested) by smtp.subspace.kernel.org (Postfix) with ESMTPS id 5BD211845 for ; Fri, 5 Jan 2024 01:12:29 +0000 (UTC) Authentication-Results: smtp.subspace.kernel.org; dmarc=pass (p=reject dis=none) header.from=google.com Authentication-Results: smtp.subspace.kernel.org; spf=pass smtp.mailfrom=google.com Authentication-Results: smtp.subspace.kernel.org; dkim=pass (2048-bit key) header.d=google.com header.i=@google.com header.b="FvtRQEyp" Received: by mail-ed1-f52.google.com with SMTP id 4fb4d7f45d1cf-55679552710so2842a12.1 for ; Thu, 04 Jan 2024 17:12:29 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=20230601; t=1704417147; x=1705021947; darn=vger.kernel.org; h=content-transfer-encoding:cc:to:subject:message-id:date:from :in-reply-to:references:mime-version:from:to:cc:subject:date :message-id:reply-to; bh=6lzJh/UyWyKzeYppavfAmy+S0tDLSRUye6zVxW7eiCA=; b=FvtRQEyp/hR52FG+9IbUBgjt9mUc9dZZhj6+NlSTSXkS5jC4j45Q0cJ4yQLJx4G78r KKFW04x3aYoYvafc6T4mfNJ+zLmFG0gJ9FfockSGqJKSveEBeeiNw/ozRIbCk3E78icM 0OWD7dX3MPK/YTUmtoCgBxM//e61/Rmja1tsfOrwca8b2iX+cTrYVPaE4D87I4V+Gbgd PVz3gba43VYArorB2TUIw7D9pfzpfp12+uq57oi32jbrvEBdw97G+38/IZzSqIcuJKtP D6YP1xBcvPbFxo/AUkcFEmXWwWshb021bfIiTy7fuHGkIwO8KurZmOa16RaehZLjQpr3 pFng== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1704417147; x=1705021947; h=content-transfer-encoding:cc:to:subject:message-id:date:from :in-reply-to:references:mime-version:x-gm-message-state:from:to:cc :subject:date:message-id:reply-to; bh=6lzJh/UyWyKzeYppavfAmy+S0tDLSRUye6zVxW7eiCA=; b=eUbTN0xuTzyz6LKDrUlrThu0maIzzDVwe+3OTK+6z7B81VUQtIMdHB3tML/fhF8Cwh q7HvNnKLd3FheUnMgDgorYhtsO2w7OBjQ/4SHzQUCaA/0cPLvrpRHP94/dnCZHluDt3I yXwhv2GsBadnqcgMlHo/jDGCxoRnvd54qfW3DMhUo5cyoKtA9M1G6+f1ZJeXgboSQ3f8 B1gZugrQCU/7/tDi36sdB+jlJ7Zswh9ojfa+0gbxEpn9MWVRCbEoh5C1zsxeHZwn4016 OIE0N5xFP/bl9/n/+IHTKU71oGmNrJVsptJb+R/Tu54l/VcD1jxHvacep3MELGoJsIDX 0C1w== X-Gm-Message-State: AOJu0YxsRI8aEy3QyQIGqY7nfQNVzJSymobdC0qzzxOeQ17u8p5Vc9AV SiFzJ+qiZ7CTwqGDtZtLTyhSLpIO8gbQ3wCgYE+8GIX5upy1 X-Google-Smtp-Source: AGHT+IExyTC2d8jpwtne6qIDv8gpPRnim2msjC2yEa3Lv7wJEbiaJS4pxIajiwNs63KxHlVu9U1MRG8FIc6ew0ifxRw= X-Received: by 2002:a50:8743:0:b0:553:5578:2fc9 with SMTP id 3-20020a508743000000b0055355782fc9mr42374edv.5.1704417147438; Thu, 04 Jan 2024 17:12:27 -0800 (PST) Precedence: bulk X-Mailing-List: git@vger.kernel.org List-Id: List-Subscribe: List-Unsubscribe: MIME-Version: 1.0 References: <20240103224054.1940209-1-delmerico@google.com> In-Reply-To: From: Sam Delmerico Date: Thu, 4 Jan 2024 17:12:15 -0800 Message-ID: Subject: Re: [PATCH] push: region_leave trace for negotiate_using_fetch To: Junio C Hamano Cc: git@vger.kernel.org, steadmon@google.com Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable * I don't exactly remember how I noticed it. I was doing some debugging around the push negotiation code and either 1) saw this region get entered twice in the trace output, or 2) I was just reading the code around here and saw two enters. * Perhaps there could be a check before the last git process ends that checks that all opened trace regions have been closed? I'm not sure how much work this would involve. It's probably also not a very proactive way to catch these bugs since it would only get triggered when a *user* hits a code path with a trace region that never exits. * There could also be a test that checks that every region_enter trace log has a corresponding region_leave. But I'm not sure how to ensure that every code path is checked. Overall, I'm not sure how much benefit there is from checking for this. I'm not sure that it would have a large impact if it were to happen again. For example, I think that it could be noticed relatively quickly by a person/system looking at metrics like I was (e.g. if the time spent in a region is infinite or zero). FWIW I didn't see any other examples of this when going through logs. Sam
On Wed= , Jan 3, 2024 at 3:37=E2=80=AFPM Junio C Hamano <gitster@pobox.com> wrote:
Sam Delmerico <delmerico@google.com> writes:

> There were two region_enter events for negotiate_using_fetch instead o= f
> one enter and one leave. This commit replaces the second region_enter<= br> > event with a region_leave.
>
> Signed-off-by: Sam Delmerico <delmerico@google.com>
> ---
>  fetch-pack.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)

Looks right, after skimming a29263cf (fetch-pack: add tracing for
negotiation rounds, 2022-08-02).  Two questions and a half.

 * How did you find it?  Code inspection?  While writing a script to
   parse the output from around this area, your script noticed th= e
   ever-increasing nesting level?  Something else?

 * Would it be feasible to write some tests or tools that find
   similar problems (semi-)automatically?

 * Is the breakage (before this patch) something easily demonstrated    in a new test in t/ somewhere?  And if so, would it be worth
   doing?

Thanks.  Will queue.


>
> diff --git a/fetch-pack.c b/fetch-pack.c
> index 31a72d43de..dba6d79944 100644
> --- a/fetch-pack.c
> +++ b/fetch-pack.c
> @@ -2218,7 +2218,7 @@ void negotiate_using_fetch(const struct oid_array *negotiation_tips,
>                                          the_repository, "%d",
>                                          negotiation_round);
>       }
> -     trace2_region_enter("fetch-pack", "negotiate_using_fetch", the_repository);
> +     trace2_region_leave("fetch-pack", "negotiate_using_fetch", the_repository);
>       trace2_data_intmax("negotiate_using_fetch", the_repository,
>                          "total_rounds", negotiation_round);
>       clear_common_flag(acked_commits);
>
> base-commit: a26002b62827b89a19b1084bd75d9371d565d03c