On 2022.07.25 16:07, Junio C Hamano wrote: > Josh Steadmon <steadmon@xxxxxxxxxx> 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. Reworded that sentence. > > 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? True, fixed in V2. > > + 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? Yes, although now that I look at it again, I believe as soon as we finish the do-while, we know that the round is over, so I believe we can just put a single region_leave there. Fixed in V2. > > @@ -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. That works, but then we also need an additional region_leave in the FETCH_SEND_REQUEST case where we jump directly to FETCH_GET_PACK. I'm not sure which way is more intuitive, but I've gone with your suggestion for V2. > > 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);