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