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

[Junio C Hamano <gitster@pobox.com>]

Josh Steadmon <steadmon@google.com> writes:

> 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.

Quite sensibly argued.  I do not necessarily see the current code as
"broken", and "fix" at the beginning of the next line may not be an
appropriate word to describe this enhancement, but I think it would
be nice to have such numbers.

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

Not an objection, but all the hits to existing calls to this
function show the data in a format as vanilla as possible without
frills (presumably to make it easier to mechanically parse the value
out when needed???), and the "round-" prefix we see here somehow
looks out of place.  Doesn't the fact that the record is in the
"negotiation_v0_v1" category and has label "round" clear enough sign
that the value presented is the negotiation_round?

> +			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;
>  			packet_buf_flush(&req_buf);
>  			send_request(args, fd[1], &req_buf);
>  			strbuf_setlen(&req_buf, state_len);
> @@ -465,6 +476,9 @@ static int find_common(struct fetch_negotiator *negotiator,
>  						      ack, oid_to_hex(result_oid));
>  				switch (ack) {
>  				case ACK:
> +					trace2_region_leave_printf("negotiation_v0_v1", "round",
> +								   the_repository, "round-%d",
> +								   negotiation_round);
>  					flushes = 0;
>  					multi_ack = 0;
>  					retval = 0;
> @@ -490,6 +504,7 @@ static int find_common(struct fetch_negotiator *negotiator,
>  						const char *hex = oid_to_hex(result_oid);
>  						packet_buf_write(&req_buf, "have %s\n", hex);
>  						state_len = req_buf.len;
> +						haves++;
>  						/*
>  						 * Reset in_vain because an ack
>  						 * for this commit has not been
> @@ -510,14 +525,26 @@ static int find_common(struct fetch_negotiator *negotiator,
>  			flushes--;
>  			if (got_continue && MAX_IN_VAIN < in_vain) {
>  				print_verbose(args, _("giving up"));
> +				trace2_region_leave_printf("negotiation_v0_v1", "round",
> +							   the_repository, "round-%d",
> +							   negotiation_round);
>  				break; /* give up */
>  			}
> -			if (got_ready)
> +			if (got_ready) {
> +				trace2_region_leave_printf("negotiation_v0_v1", "round",
> +							   the_repository, "round-%d",
> +							   negotiation_round);
>  				break;
> +			}
> +			trace2_region_leave_printf("negotiation_v0_v1", "round",
> +						   the_repository, "round-%d",
> +						   negotiation_round);
>  		}

Having many duplicated calls to "leave" makes the whole thing look
somewhat confused.  Is this primarily because we have too many
"break" that breaks out of the loop?

> @@ -1603,6 +1632,7 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,
>  	struct oidset common = OIDSET_INIT;
>  	struct packet_reader reader;
>  	int in_vain = 0, negotiation_started = 0;
> +	int negotiation_round = 0;
>  	int haves_to_send = INITIAL_FLUSH;
>  	struct fetch_negotiator negotiator_alloc;
>  	struct fetch_negotiator *negotiator;
> @@ -1659,6 +1689,10 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,
>  						    "negotiation_v2",
>  						    the_repository);
>  			}
> +			negotiation_round++;
> +			trace2_region_enter_printf("negotiation_v2", "round",
> +						   the_repository, "round-%d",
> +						   negotiation_round);
>  			if (send_fetch_request(negotiator, fd[1], args, ref,
>  					       &common,
>  					       &haves_to_send, &in_vain,
> @@ -1686,12 +1720,20 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,
>  			} else {
>  				do_check_stateless_delimiter(args->stateless_rpc, &reader);
>  				state = FETCH_SEND_REQUEST;
> +				trace2_region_leave_printf("negotiation_v2", "round",
> +							   the_repository, "round-%d",
> +							   negotiation_round);
>  			}
>  			break;
>  		case FETCH_GET_PACK:
> +			trace2_region_leave_printf("negotiation_v2", "round",
> +						   the_repository, "round-%d",
> +						   negotiation_round);

Hmph.  Doesn't this logically belong to the "FETCH_PROCESS_ACKS"
case arm?  We "leave" the current round when we did not get "ready"
and "enter" the next round by moving to "FETCH_SEND_REQUEST" state,
but at the same location when we did get "ready", we can "leave" the
current (and final) round and move to "FETCH_GET_PACK" state.  I
suspect the code structure and control flow becomes easier to see
when expressed that way.

>  			trace2_region_leave("fetch-pack",
>  					    "negotiation_v2",
>  					    the_repository);
> +			trace2_data_intmax("negotiation_v2", the_repository,
> +					   "total_rounds", negotiation_round);
>  			/* Check for shallow-info section */
>  			if (process_section_header(&reader, "shallow-info", 1))
>  				receive_shallow_info(args, &reader, shallows, si);