fetch-pack: add tracing for negotiation rounds
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. Add 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. Signed-off-by: Josh Steadmon <steadmon@google.com> Acked-by: Jeff Hostetler <jeffhost@microsoft.com> Signed-off-by: Junio C Hamano <gitster@pobox.com>
Josh Steadmon committed
Aug 2, 2022 at 15:04 UTC
a29263cf5f419fb3095d01bcf8e806d12dd7ec71
5 files changed
+75
-7
fetch-pack.c
+55
-1
@@ -323,6 +323,7 @@ static int find_common(struct fetch_negotiator *negotiator,
323
{
324
int fetching;
325
int count = 0, flushes = 0, flush_at = INITIAL_FLUSH, retval;
326
+ int negotiation_round = 0, haves = 0;
327
const struct object_id *oid;
328
unsigned in_vain = 0;
329
int got_continue = 0;
@@ -461,9 +462,19 @@ static int find_common(struct fetch_negotiator *negotiator,
462
packet_buf_write(&req_buf, "have %s\n", oid_to_hex(oid));
463
print_verbose(args, "have %s", oid_to_hex(oid));
464
in_vain++;
465
+ haves++;
466
if (flush_at <= ++count) {
467
int ack;
468
469
+ negotiation_round++;
470
+ trace2_region_enter_printf("negotiation_v0_v1", "round",
471
+ the_repository, "%d",
472
+ negotiation_round);
473
+ trace2_data_intmax("negotiation_v0_v1", the_repository,
474
+ "haves_added", haves);
475
+ trace2_data_intmax("negotiation_v0_v1", the_repository,
476
+ "in_vain", in_vain);
477
+ haves = 0;
478
packet_buf_flush(&req_buf);
479
send_request(args, fd[1], &req_buf);
480
strbuf_setlen(&req_buf, state_len);
@@ -485,6 +496,9 @@ static int find_common(struct fetch_negotiator *negotiator,
496
ack, oid_to_hex(result_oid));
497
switch (ack) {
498
case ACK:
499
+ trace2_region_leave_printf("negotiation_v0_v1", "round",
500
+ the_repository, "%d",
501
+ negotiation_round);
502
flushes = 0;
503
multi_ack = 0;
504
retval = 0;
@@ -510,6 +524,7 @@ static int find_common(struct fetch_negotiator *negotiator,
524
const char *hex = oid_to_hex(result_oid);
525
packet_buf_write(&req_buf, "have %s\n", hex);
526
state_len = req_buf.len;
527
+ haves++;
528
/*
529
* Reset in_vain because an ack
530
* for this commit has not been
@@ -528,6 +543,9 @@ static int find_common(struct fetch_negotiator *negotiator,
543
}
544
} while (ack);
545
flushes--;
546
+ trace2_region_leave_printf("negotiation_v0_v1", "round",
547
+ the_repository, "%d",
548
+ negotiation_round);
549
if (got_continue && MAX_IN_VAIN < in_vain) {
550
print_verbose(args, _("giving up"));
551
break; /* give up */
@@ -538,6 +556,8 @@ static int find_common(struct fetch_negotiator *negotiator,
556
}
557
done:
558
trace2_region_leave("fetch-pack", "negotiation_v0_v1", the_repository);
559
+ trace2_data_intmax("negotiation_v0_v1", the_repository, "total_rounds",
560
+ negotiation_round);
561
if (!got_ready || !no_done) {
562
packet_buf_write(&req_buf, "done\n");
563
send_request(args, fd[1], &req_buf);
@@ -1381,6 +1401,8 @@ static int send_fetch_request(struct fetch_negotiator *negotiator, int fd_out,
1401
1402
haves_added = add_haves(negotiator, &req_buf, haves_to_send);
1403
*in_vain += haves_added;
1404
+ trace2_data_intmax("negotiation_v2", the_repository, "haves_added", haves_added);
1405
+ trace2_data_intmax("negotiation_v2", the_repository, "in_vain", *in_vain);
1406
if (!haves_added || (seen_ack && *in_vain >= MAX_IN_VAIN)) {
1407
/* Send Done */
1408
packet_buf_write(&req_buf, "done\n");
@@ -1623,6 +1645,7 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,
1645
struct oidset common = OIDSET_INIT;
1646
struct packet_reader reader;
1647
int in_vain = 0, negotiation_started = 0;
1648
+ int negotiation_round = 0;
1649
int haves_to_send = INITIAL_FLUSH;
1650
struct fetch_negotiator negotiator_alloc;
1651
struct fetch_negotiator *negotiator;
@@ -1679,12 +1702,20 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,
1702
"negotiation_v2",
1703
the_repository);
1704
}
1705
+ negotiation_round++;
1706
+ trace2_region_enter_printf("negotiation_v2", "round",
1707
+ the_repository, "%d",
1708
+ negotiation_round);
1709
if (send_fetch_request(negotiator, fd[1], args, ref,
1710
&common,
1711
&haves_to_send, &in_vain,
1712
reader.use_sideband,
1686
- seen_ack))
1713
+ seen_ack)) {
1714
+ trace2_region_leave_printf("negotiation_v2", "round",
1715
+ the_repository, "%d",
1716
+ negotiation_round);
1717
state = FETCH_GET_PACK;
1718
+ }
1719
else
1720
state = FETCH_PROCESS_ACKS;
1721
break;
@@ -1697,6 +1728,9 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,
1728
seen_ack = 1;
1729
oidset_insert(&common, &common_oid);
1730
}
1731
+ trace2_region_leave_printf("negotiation_v2", "round",
1732
+ the_repository, "%d",
1733
+ negotiation_round);
1734
if (received_ready) {
1735
/*
1736
* Don't check for response delimiter; get_pack() will
@@ -1712,6 +1746,8 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,
1746
trace2_region_leave("fetch-pack",
1747
"negotiation_v2",
1748
the_repository);
1749
+ trace2_data_intmax("negotiation_v2", the_repository,
1750
+ "total_rounds", negotiation_round);
1751
/* Check for shallow-info section */
1752
if (process_section_header(&reader, "shallow-info", 1))
1753
receive_shallow_info(args, &reader, shallows, si);
@@ -2091,6 +2127,7 @@ void negotiate_using_fetch(const struct oid_array *negotiation_tips,
2127
int in_vain = 0;
2128
int seen_ack = 0;
2129
int last_iteration = 0;
2130
+ int negotiation_round = 0;
2131
timestamp_t min_generation = GENERATION_NUMBER_INFINITY;
2132
2133
fetch_negotiator_init(the_repository, &negotiator);
@@ -2104,11 +2141,17 @@ void negotiate_using_fetch(const struct oid_array *negotiation_tips,
2141
add_to_object_array,
2142
&nt_object_array);
2143
2144
+ trace2_region_enter("fetch-pack", "negotiate_using_fetch", the_repository);
2145
while (!last_iteration) {
2146
int haves_added;
2147
struct object_id common_oid;
2148
int received_ready = 0;
2149
2150
+ negotiation_round++;
2151
+
2152
+ trace2_region_enter_printf("negotiate_using_fetch", "round",
2153
+ the_repository, "%d",
2154
+ negotiation_round);
2155
strbuf_reset(&req_buf);
2156
write_fetch_command_and_capabilities(&req_buf, server_options);
2157
@@ -2119,6 +2162,11 @@ void negotiate_using_fetch(const struct oid_array *negotiation_tips,
2162
if (!haves_added || (seen_ack && in_vain >= MAX_IN_VAIN))
2163
last_iteration = 1;
2164
2165
+ trace2_data_intmax("negotiate_using_fetch", the_repository,
2166
+ "haves_added", haves_added);
2167
+ trace2_data_intmax("negotiate_using_fetch", the_repository,
2168
+ "in_vain", in_vain);
2169
+
2170
/* Send request */
2171
packet_buf_flush(&req_buf);
2172
if (write_in_full(fd[1], req_buf.buf, req_buf.len) < 0)
@@ -2151,7 +2199,13 @@ void negotiate_using_fetch(const struct oid_array *negotiation_tips,
2199
REACH_SCRATCH, 0,
2200
min_generation))
2201
last_iteration = 1;
2202
+ trace2_region_leave_printf("negotiation", "round",
2203
+ the_repository, "%d",
2204
+ negotiation_round);
2205
}
2206
+ trace2_region_enter("fetch-pack", "negotiate_using_fetch", the_repository);
2207
+ trace2_data_intmax("negotiate_using_fetch", the_repository,
2208
+ "total_rounds", negotiation_round);
2209
clear_common_flag(acked_commits);
2210
strbuf_release(&req_buf);
2211
}
t/t5500-fetch-pack.sh
+3
-1
@@ -407,6 +407,7 @@ test_expect_success 'in_vain not triggered before first ACK' '
407
'
408
409
test_expect_success 'in_vain resetted upon ACK' '
410
+ test_when_finished rm -f log trace2 &&
411
rm -rf myserver myclient &&
412
git init myserver &&
413
@@ -432,7 +433,8 @@ test_expect_success 'in_vain resetted upon ACK' '
433
# first. The 256th commit is common between the client and the server,
434
# and should reset in_vain. This allows negotiation to continue until
435
# the client reports that first_anotherbranch_commit is common.
435
- git -C myclient fetch --progress origin main 2>log &&
436
+ GIT_TRACE2_EVENT="$(pwd)/trace2" git -C myclient fetch --progress origin main 2>log &&
437
+ grep \"key\":\"total_rounds\",\"value\":\"6\" trace2 &&
438
test_i18ngrep "Total 3 " log
439
'
440
t/t5516-fetch-push.sh
+8
-2
@@ -200,7 +200,10 @@ test_expect_success 'push with negotiation' '
200
test_commit -C testrepo unrelated_commit &&
201
git -C testrepo config receive.hideRefs refs/remotes/origin/first_commit &&
202
test_when_finished "rm event" &&
203
- GIT_TRACE2_EVENT="$(pwd)/event" git -c protocol.version=2 -c push.negotiate=1 push testrepo refs/heads/main:refs/remotes/origin/main &&
203
+ GIT_TRACE2_EVENT="$(pwd)/event" \
204
+ git -c protocol.version=2 -c push.negotiate=1 \
205
+ push testrepo refs/heads/main:refs/remotes/origin/main &&
206
+ grep \"key\":\"total_rounds\",\"value\":\"1\" event &&
207
grep_wrote 2 event # 1 commit, 1 tree
208
'
209
@@ -224,7 +227,10 @@ test_expect_success 'push with negotiation does not attempt to fetch submodules'
227
git push testrepo $the_first_commit:refs/remotes/origin/first_commit &&
228
test_commit -C testrepo unrelated_commit &&
229
git -C testrepo config receive.hideRefs refs/remotes/origin/first_commit &&
227
- git -c submodule.recurse=true -c protocol.version=2 -c push.negotiate=1 push testrepo refs/heads/main:refs/remotes/origin/main 2>err &&
230
+ GIT_TRACE2_EVENT="$(pwd)/event" git -c submodule.recurse=true \
231
+ -c protocol.version=2 -c push.negotiate=1 \
232
+ push testrepo refs/heads/main:refs/remotes/origin/main 2>err &&
233
+ grep \"key\":\"total_rounds\",\"value\":\"1\" event &&
234
! grep "Fetching submodule" err
235
'
236
t/t5601-clone.sh
+5
-1
@@ -743,7 +743,11 @@ test_expect_success 'batch missing blob request during checkout' '
743
744
# Ensure that there is only one negotiation by checking that there is
745
# only "done" line sent. ("done" marks the end of negotiation.)
746
- GIT_TRACE_PACKET="$(pwd)/trace" git -C client checkout HEAD^ &&
746
+ GIT_TRACE_PACKET="$(pwd)/trace" \
747
+ GIT_TRACE2_EVENT="$(pwd)/trace2_event" \
748
+ git -C client -c trace2.eventNesting=5 checkout HEAD^ &&
749
+ grep \"key\":\"total_rounds\",\"value\":\"1\" trace2_event >trace_lines &&
750
+ test_line_count = 1 trace_lines &&
751
grep "fetch> done" trace >done_lines &&
752
test_line_count = 1 done_lines
753
'
t/t5703-upload-pack-ref-in-want.sh
+4
-2
@@ -229,14 +229,16 @@ test_expect_success 'setup repos for fetching with ref-in-want tests' '
229
'
230
231
test_expect_success 'fetching with exact OID' '
232
- test_when_finished "rm -f log" &&
232
+ test_when_finished "rm -f log trace2" &&
233
234
rm -rf local &&
235
cp -r "$LOCAL_PRISTINE" local &&
236
oid=$(git -C "$REPO" rev-parse d) &&
237
- GIT_TRACE_PACKET="$(pwd)/log" git -C local fetch origin \
237
+ GIT_TRACE_PACKET="$(pwd)/log" GIT_TRACE2_EVENT="$(pwd)/trace2" \
238
+ git -C local fetch origin \
239
"$oid":refs/heads/actual &&
240
241
+ grep \"key\":\"total_rounds\",\"value\":\"2\" trace2 &&
242
git -C "$REPO" rev-parse "d" >expected &&
243
git -C local rev-parse refs/heads/actual >actual &&
244
test_cmp expected actual &&