Re: [PATCH] fetch-pack: add tracing for negotiation rounds

[Jeff Hostetler <git@jeffhostetler.com>]

On 7/25/22 6:13 PM, Josh Steadmon wrote:
> Currently, negotiation for V0/V1/V2 fetch have trace2 regions covering
> the entire negotiation process. However, we'd like additional data, such
> as timing for each round of negotiation or the number of "haves" in each
> round. Additionally, "independent negotiation" (AKA push negotiation)
> has no tracing at all. Having this data would allow us to compare the
> performance of the various negotation implementations, and to debug
> unexpectedly slow fetch & push sessions.
> 
> Fix this by adding per-round trace2 regions for all negotiation
> implementations (V0+V1, V2, and independent negotiation), as well as an
> overall region for independent negotiation. Add trace2 data logging for
> the number of haves and "in vain" objects for each round, and for the
> total number of rounds once negotiation completes.  Finally, add a few
> checks into various tests to verify that the number of rounds is logged
> as expected.

I've been wanting to add data like this around the negotiation
code for a while now.  Thanks!

> 
> Signed-off-by: Josh Steadmon <steadmon@google.com>
> ---
>   fetch-pack.c                       | 62 +++++++++++++++++++++++++++++-
>   t/t5500-fetch-pack.sh              |  4 +-
>   t/t5516-fetch-push.sh              | 10 ++++-
>   t/t5601-clone.sh                   |  6 ++-
>   t/t5703-upload-pack-ref-in-want.sh |  6 ++-
>   5 files changed, 81 insertions(+), 7 deletions(-)
> 
> diff --git a/fetch-pack.c b/fetch-pack.c
> index cb6647d657..01a451e456 100644
> --- a/fetch-pack.c
> +++ b/fetch-pack.c
> @@ -299,6 +299,7 @@ static int find_common(struct fetch_negotiator *negotiator,
>   {
>   	int fetching;
>   	int count = 0, flushes = 0, flush_at = INITIAL_FLUSH, retval;
> +	int negotiation_round = 0, haves = 0;
>   	const struct object_id *oid;
>   	unsigned in_vain = 0;
>   	int got_continue = 0;
> @@ -441,9 +442,19 @@ static int find_common(struct fetch_negotiator *negotiator,
>   		packet_buf_write(&req_buf, "have %s\n", oid_to_hex(oid));
>   		print_verbose(args, "have %s", oid_to_hex(oid));
>   		in_vain++;
> +		haves++;
>   		if (flush_at <= ++count) {
>   			int ack;
>   
> +			negotiation_round++;
> +			trace2_region_enter_printf("negotiation_v0_v1", "round",
> +						   the_repository, "round-%d",
> +						   negotiation_round);

I'm wondering here if the "round-%d" should have some number
of leading zeros so that multiple rounds will sort correctly
when you have a bunch of them.

I'm also wondering (and this is more of a style thing, so feel
free to ignore) if we could just use trace2_region_enter()
and make the "label" field be the "round/%04d" and not need
the extra args.


> +			trace2_data_intmax("negotiation_v0_v1", the_repository,
> +					   "haves_added", haves);
> +			trace2_data_intmax("negotiation_v0_v1", the_repository,
> +					   "in_vain", in_vain);
> +			haves = 0;

Thanks,
Jeff