Re: [PATCH] fetch-pack: add tracing for negotiation rounds
From: Jeff Hostetler <hidden>
Date: 2022-07-26 00:04:58
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!
quoted hunk ↗ jump to hunk
Signed-off-by: Josh Steadmon <redacted> --- 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