Re: [PATCH] fetch-pack: add tracing for negotiation rounds
- From
Junio C Hamano <gitster@pobox.com>
- Date
- Jul 25, 2022, 23:07 UTC
- Message-ID
- <xmqqilnkyeom.fsf@gitster.g>
- In-Reply-To
- <a16d86e1ced104bb331bb9e7055037a3a2821352.1658787182.git.steadmon@google.com>
Josh Steadmon <steadmon@google.com> writes:
Show 7 quoted lines
> 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.
Show 24 quoted lines
> 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?
Show 46 quoted lines
> + 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?
Show 32 quoted lines
> @@ -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.
Show 8 quoted lines
> 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);