{"thread":{"id":"58222","subject":"[PATCH] fetch-pack: add tracing for negotiation rounds","startedAt":"2022-07-25T22:13:40Z","lastAt":"2022-08-15T15:08:30Z","messageCount":7,"participants":["Josh Steadmon","Junio C Hamano","Jeff Hostetler"],"isPatch":true,"patchVersion":1,"patchTotal":null},"messages":[{"id":"459934","messageId":"a16d86e1ced104bb331bb9e7055037a3a2821352.1658787182.git.steadmon@google.com","threadId":"58222","inReplyTo":null,"subject":"[PATCH] fetch-pack: add tracing for negotiation rounds","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2022-07-25T22:13:32Z","receivedAt":"2022-07-25T22:13:40Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"Currently, negotiation for V0/V1/V2 fetch have trace2 regions covering\nthe entire negotiation process. However, we'd like additional data, such\nas timing for each round of negotiation or the number of \"haves\" in each\nround. Additionally, \"independent negotiation\" (AKA push negotiation)\nhas no tracing at all. Having this data would allow us to compare the\nperformance of the various negotation implementations, and to debug\nunexpectedly slow fetch & push sessions.\n\nFix this by adding per-round trace2 regions for all negotiation\nimplementations (V0+V1, V2, and independent negotiation), as well as an\noverall region for independent negotiation. Add trace2 data logging for\nthe number of haves and \"in vain\" objects for each round, and for the\ntotal number of rounds once negotiation completes.  Finally, add a few\nchecks into various tests to verify that the number of rounds is logged\nas expected.\n\nSigned-off-by: Josh Steadmon <steadmon@google.com>\n---\n fetch-pack.c                       | 62 +++++++++++++++++++++++++++++-\n t/t5500-fetch-pack.sh              |  4 +-\n t/t5516-fetch-push.sh              | 10 ++++-\n t/t5601-clone.sh                   |  6 ++-\n t/t5703-upload-pack-ref-in-want.sh |  6 ++-\n 5 files changed, 81 insertions(+), 7 deletions(-)\n\ndiff --git a/fetch-pack.c b/fetch-pack.c\nindex cb6647d657..01a451e456 100644\n--- a/fetch-pack.c\n+++ b/fetch-pack.c\n@@ -299,6 +299,7 @@ static int find_common(struct fetch_negotiator *negotiator,\n {\n \tint fetching;\n \tint count = 0, flushes = 0, flush_at = INITIAL_FLUSH, retval;\n+\tint negotiation_round = 0, haves = 0;\n \tconst struct object_id *oid;\n \tunsigned in_vain = 0;\n \tint got_continue = 0;\n@@ -441,9 +442,19 @@ static int find_common(struct fetch_negotiator *negotiator,\n \t\tpacket_buf_write(&req_buf, \"have %s\\n\", oid_to_hex(oid));\n \t\tprint_verbose(args, \"have %s\", oid_to_hex(oid));\n \t\tin_vain++;\n+\t\thaves++;\n \t\tif (flush_at <= ++count) {\n \t\t\tint ack;\n \n+\t\t\tnegotiation_round++;\n+\t\t\ttrace2_region_enter_printf(\"negotiation_v0_v1\", \"round\",\n+\t\t\t\t\t\t   the_repository, \"round-%d\",\n+\t\t\t\t\t\t   negotiation_round);\n+\t\t\ttrace2_data_intmax(\"negotiation_v0_v1\", the_repository,\n+\t\t\t\t\t   \"haves_added\", haves);\n+\t\t\ttrace2_data_intmax(\"negotiation_v0_v1\", the_repository,\n+\t\t\t\t\t   \"in_vain\", in_vain);\n+\t\t\thaves = 0;\n \t\t\tpacket_buf_flush(&req_buf);\n \t\t\tsend_request(args, fd[1], &req_buf);\n \t\t\tstrbuf_setlen(&req_buf, state_len);\n@@ -465,6 +476,9 @@ static int find_common(struct fetch_negotiator *negotiator,\n \t\t\t\t\t\t      ack, oid_to_hex(result_oid));\n \t\t\t\tswitch (ack) {\n \t\t\t\tcase ACK:\n+\t\t\t\t\ttrace2_region_leave_printf(\"negotiation_v0_v1\", \"round\",\n+\t\t\t\t\t\t\t\t   the_repository, \"round-%d\",\n+\t\t\t\t\t\t\t\t   negotiation_round);\n \t\t\t\t\tflushes = 0;\n \t\t\t\t\tmulti_ack = 0;\n \t\t\t\t\tretval = 0;\n@@ -490,6 +504,7 @@ static int find_common(struct fetch_negotiator *negotiator,\n \t\t\t\t\t\tconst char *hex = oid_to_hex(result_oid);\n \t\t\t\t\t\tpacket_buf_write(&req_buf, \"have %s\\n\", hex);\n \t\t\t\t\t\tstate_len = req_buf.len;\n+\t\t\t\t\t\thaves++;\n \t\t\t\t\t\t/*\n \t\t\t\t\t\t * Reset in_vain because an ack\n \t\t\t\t\t\t * for this commit has not been\n@@ -510,14 +525,26 @@ static int find_common(struct fetch_negotiator *negotiator,\n \t\t\tflushes--;\n \t\t\tif (got_continue && MAX_IN_VAIN < in_vain) {\n \t\t\t\tprint_verbose(args, _(\"giving up\"));\n+\t\t\t\ttrace2_region_leave_printf(\"negotiation_v0_v1\", \"round\",\n+\t\t\t\t\t\t\t   the_repository, \"round-%d\",\n+\t\t\t\t\t\t\t   negotiation_round);\n \t\t\t\tbreak; /* give up */\n \t\t\t}\n-\t\t\tif (got_ready)\n+\t\t\tif (got_ready) {\n+\t\t\t\ttrace2_region_leave_printf(\"negotiation_v0_v1\", \"round\",\n+\t\t\t\t\t\t\t   the_repository, \"round-%d\",\n+\t\t\t\t\t\t\t   negotiation_round);\n \t\t\t\tbreak;\n+\t\t\t}\n+\t\t\ttrace2_region_leave_printf(\"negotiation_v0_v1\", \"round\",\n+\t\t\t\t\t\t   the_repository, \"round-%d\",\n+\t\t\t\t\t\t   negotiation_round);\n \t\t}\n \t}\n done:\n \ttrace2_region_leave(\"fetch-pack\", \"negotiation_v0_v1\", the_repository);\n+\ttrace2_data_intmax(\"negotiation_v0_v1\", the_repository, \"total_rounds\",\n+\t\t\t   negotiation_round);\n \tif (!got_ready || !no_done) {\n \t\tpacket_buf_write(&req_buf, \"done\\n\");\n \t\tsend_request(args, fd[1], &req_buf);\n@@ -1361,6 +1388,8 @@ static int send_fetch_request(struct fetch_negotiator *negotiator, int fd_out,\n \n \thaves_added = add_haves(negotiator, &req_buf, haves_to_send);\n \t*in_vain += haves_added;\n+\ttrace2_data_intmax(\"negotiation_v2\", the_repository, \"haves_added\", haves_added);\n+\ttrace2_data_intmax(\"negotiation_v2\", the_repository, \"in_vain\", *in_vain);\n \tif (!haves_added || (seen_ack && *in_vain >= MAX_IN_VAIN)) {\n \t\t/* Send Done */\n \t\tpacket_buf_write(&req_buf, \"done\\n\");\n@@ -1603,6 +1632,7 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,\n \tstruct oidset common = OIDSET_INIT;\n \tstruct packet_reader reader;\n \tint in_vain = 0, negotiation_started = 0;\n+\tint negotiation_round = 0;\n \tint haves_to_send = INITIAL_FLUSH;\n \tstruct fetch_negotiator negotiator_alloc;\n \tstruct fetch_negotiator *negotiator;\n@@ -1659,6 +1689,10 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,\n \t\t\t\t\t\t    \"negotiation_v2\",\n \t\t\t\t\t\t    the_repository);\n \t\t\t}\n+\t\t\tnegotiation_round++;\n+\t\t\ttrace2_region_enter_printf(\"negotiation_v2\", \"round\",\n+\t\t\t\t\t\t   the_repository, \"round-%d\",\n+\t\t\t\t\t\t   negotiation_round);\n \t\t\tif (send_fetch_request(negotiator, fd[1], args, ref,\n \t\t\t\t\t       &common,\n \t\t\t\t\t       &haves_to_send, &in_vain,\n@@ -1686,12 +1720,20 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,\n \t\t\t} else {\n \t\t\t\tdo_check_stateless_delimiter(args->stateless_rpc, &reader);\n \t\t\t\tstate = FETCH_SEND_REQUEST;\n+\t\t\t\ttrace2_region_leave_printf(\"negotiation_v2\", \"round\",\n+\t\t\t\t\t\t\t   the_repository, \"round-%d\",\n+\t\t\t\t\t\t\t   negotiation_round);\n \t\t\t}\n \t\t\tbreak;\n \t\tcase FETCH_GET_PACK:\n+\t\t\ttrace2_region_leave_printf(\"negotiation_v2\", \"round\",\n+\t\t\t\t\t\t   the_repository, \"round-%d\",\n+\t\t\t\t\t\t   negotiation_round);\n \t\t\ttrace2_region_leave(\"fetch-pack\",\n \t\t\t\t\t    \"negotiation_v2\",\n \t\t\t\t\t    the_repository);\n+\t\t\ttrace2_data_intmax(\"negotiation_v2\", the_repository,\n+\t\t\t\t\t   \"total_rounds\", negotiation_round);\n \t\t\t/* Check for shallow-info section */\n \t\t\tif (process_section_header(&reader, \"shallow-info\", 1))\n \t\t\t\treceive_shallow_info(args, &reader, shallows, si);\n@@ -2071,6 +2113,7 @@ void negotiate_using_fetch(const struct oid_array *negotiation_tips,\n \tint in_vain = 0;\n \tint seen_ack = 0;\n \tint last_iteration = 0;\n+\tint negotiation_round = 0;\n \ttimestamp_t min_generation = GENERATION_NUMBER_INFINITY;\n \n \tfetch_negotiator_init(the_repository, &negotiator);\n@@ -2084,11 +2127,17 @@ void negotiate_using_fetch(const struct oid_array *negotiation_tips,\n \t\t\t   add_to_object_array,\n \t\t\t   &nt_object_array);\n \n+\ttrace2_region_enter(\"fetch-pack\", \"negotiate_using_fetch\", the_repository);\n \twhile (!last_iteration) {\n \t\tint haves_added;\n \t\tstruct object_id common_oid;\n \t\tint received_ready = 0;\n \n+\t\tnegotiation_round++;\n+\n+\t\ttrace2_region_enter_printf(\"negotiate_using_fetch\", \"round\",\n+\t\t\t\t\t   the_repository, \"round-%d\",\n+\t\t\t\t\t   negotiation_round);\n \t\tstrbuf_reset(&req_buf);\n \t\twrite_fetch_command_and_capabilities(&req_buf, server_options);\n \n@@ -2099,6 +2148,11 @@ void negotiate_using_fetch(const struct oid_array *negotiation_tips,\n \t\tif (!haves_added || (seen_ack && in_vain >= MAX_IN_VAIN))\n \t\t\tlast_iteration = 1;\n \n+\t\ttrace2_data_intmax(\"negotiate_using_fetch\", the_repository,\n+\t\t\t\t   \"haves_added\", haves_added);\n+\t\ttrace2_data_intmax(\"negotiate_using_fetch\", the_repository,\n+\t\t\t\t   \"in_vain\", in_vain);\n+\n \t\t/* Send request */\n \t\tpacket_buf_flush(&req_buf);\n \t\tif (write_in_full(fd[1], req_buf.buf, req_buf.len) < 0)\n@@ -2131,7 +2185,13 @@ void negotiate_using_fetch(const struct oid_array *negotiation_tips,\n \t\t\t\t\t\t REACH_SCRATCH, 0,\n \t\t\t\t\t\t min_generation))\n \t\t\tlast_iteration = 1;\n+\t\ttrace2_region_leave_printf(\"negotiation\", \"round\",\n+\t\t\t\t\t   the_repository, \"round-%d\",\n+\t\t\t\t\t   negotiation_round);\n \t}\n+\ttrace2_region_enter(\"fetch-pack\", \"negotiate_using_fetch\", the_repository);\n+\ttrace2_data_intmax(\"negotiate_using_fetch\", the_repository,\n+\t\t\t   \"total_rounds\", negotiation_round);\n \tclear_common_flag(acked_commits);\n \tstrbuf_release(&req_buf);\n }\ndiff --git a/t/t5500-fetch-pack.sh b/t/t5500-fetch-pack.sh\nindex ee6d2dde9f..d18f2823d8 100755\n--- a/t/t5500-fetch-pack.sh\n+++ b/t/t5500-fetch-pack.sh\n@@ -407,6 +407,7 @@ test_expect_success 'in_vain not triggered before first ACK' '\n '\n \n test_expect_success 'in_vain resetted upon ACK' '\n+\ttest_when_finished rm -f log trace2 &&\n \trm -rf myserver myclient &&\n \tgit init myserver &&\n \n@@ -432,7 +433,8 @@ test_expect_success 'in_vain resetted upon ACK' '\n \t# first. The 256th commit is common between the client and the server,\n \t# and should reset in_vain. This allows negotiation to continue until\n \t# the client reports that first_anotherbranch_commit is common.\n-\tgit -C myclient fetch --progress origin main 2>log &&\n+\tGIT_TRACE2_EVENT=\"$(pwd)/trace2\" git -C myclient fetch --progress origin main 2>log &&\n+\tgrep \\\"key\\\":\\\"total_rounds\\\",\\\"value\\\":\\\"6\\\" trace2 &&\n \ttest_i18ngrep \"Total 3 \" log\n '\n \ndiff --git a/t/t5516-fetch-push.sh b/t/t5516-fetch-push.sh\nindex 9ca0f8c144..f64cefa29a 100755\n--- a/t/t5516-fetch-push.sh\n+++ b/t/t5516-fetch-push.sh\n@@ -198,7 +198,10 @@ test_expect_success 'push with negotiation' '\n \ttest_commit -C testrepo unrelated_commit &&\n \tgit -C testrepo config receive.hideRefs refs/remotes/origin/first_commit &&\n \ttest_when_finished \"rm event\" &&\n-\tGIT_TRACE2_EVENT=\"$(pwd)/event\" git -c protocol.version=2 -c push.negotiate=1 push testrepo refs/heads/main:refs/remotes/origin/main &&\n+\tGIT_TRACE2_EVENT=\"$(pwd)/event\" \\\n+\t\tgit -c protocol.version=2 -c push.negotiate=1 \\\n+\t\tpush testrepo refs/heads/main:refs/remotes/origin/main &&\n+\tgrep \\\"key\\\":\\\"total_rounds\\\",\\\"value\\\":\\\"1\\\" event &&\n \tgrep_wrote 2 event # 1 commit, 1 tree\n '\n \n@@ -222,7 +225,10 @@ test_expect_success 'push with negotiation does not attempt to fetch submodules'\n \tgit push testrepo $the_first_commit:refs/remotes/origin/first_commit &&\n \ttest_commit -C testrepo unrelated_commit &&\n \tgit -C testrepo config receive.hideRefs refs/remotes/origin/first_commit &&\n-\tgit -c submodule.recurse=true -c protocol.version=2 -c push.negotiate=1 push testrepo refs/heads/main:refs/remotes/origin/main 2>err &&\n+\tGIT_TRACE2_EVENT=\"$(pwd)/event\"  git -c submodule.recurse=true \\\n+\t\t-c protocol.version=2 -c push.negotiate=1 \\\n+\t\tpush testrepo refs/heads/main:refs/remotes/origin/main 2>err &&\n+\tgrep \\\"key\\\":\\\"total_rounds\\\",\\\"value\\\":\\\"1\\\" event &&\n \t! grep \"Fetching submodule\" err\n '\n \ndiff --git a/t/t5601-clone.sh b/t/t5601-clone.sh\nindex cf3be0584f..2e57de9c12 100755\n--- a/t/t5601-clone.sh\n+++ b/t/t5601-clone.sh\n@@ -743,7 +743,11 @@ test_expect_success 'batch missing blob request during checkout' '\n \n \t# Ensure that there is only one negotiation by checking that there is\n \t# only \"done\" line sent. (\"done\" marks the end of negotiation.)\n-\tGIT_TRACE_PACKET=\"$(pwd)/trace\" git -C client checkout HEAD^ &&\n+\tGIT_TRACE_PACKET=\"$(pwd)/trace\" \\\n+\t\tGIT_TRACE2_EVENT=\"$(pwd)/trace2_event\" \\\n+\t\tgit -C client -c trace2.eventNesting=5 checkout HEAD^ &&\n+\tgrep \\\"key\\\":\\\"total_rounds\\\",\\\"value\\\":\\\"1\\\" trace2_event >trace_lines &&\n+\ttest_line_count = 1 trace_lines &&\n \tgrep \"fetch> done\" trace >done_lines &&\n \ttest_line_count = 1 done_lines\n '\ndiff --git a/t/t5703-upload-pack-ref-in-want.sh b/t/t5703-upload-pack-ref-in-want.sh\nindex 9d6cd7d986..df74f80061 100755\n--- a/t/t5703-upload-pack-ref-in-want.sh\n+++ b/t/t5703-upload-pack-ref-in-want.sh\n@@ -229,14 +229,16 @@ test_expect_success 'setup repos for fetching with ref-in-want tests' '\n '\n \n test_expect_success 'fetching with exact OID' '\n-\ttest_when_finished \"rm -f log\" &&\n+\ttest_when_finished \"rm -f log trace2\" &&\n \n \trm -rf local &&\n \tcp -r \"$LOCAL_PRISTINE\" local &&\n \toid=$(git -C \"$REPO\" rev-parse d) &&\n-\tGIT_TRACE_PACKET=\"$(pwd)/log\" git -C local fetch origin \\\n+\tGIT_TRACE_PACKET=\"$(pwd)/log\" GIT_TRACE2_EVENT=\"$(pwd)/trace2\" \\\n+\t\tgit -C local fetch origin \\\n \t\t\"$oid\":refs/heads/actual &&\n \n+\tgrep \\\"key\\\":\\\"total_rounds\\\",\\\"value\\\":\\\"2\\\" trace2 &&\n \tgit -C \"$REPO\" rev-parse \"d\" >expected &&\n \tgit -C local rev-parse refs/heads/actual >actual &&\n \ttest_cmp expected actual &&\n\nbase-commit: 4e2a4d1dd44367d7783f33b169698f2930ff13c0\n-- \n2.37.1.359.gd136c6c3e2-goog\n\n"},{"id":"459937","messageId":"xmqqilnkyeom.fsf@gitster.g","threadId":"58222","inReplyTo":"a16d86e1ced104bb331bb9e7055037a3a2821352.1658787182.git.steadmon@google.com","subject":"Re: [PATCH] fetch-pack: add tracing for negotiation rounds","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2022-07-25T23:07:21Z","receivedAt":"2022-07-25T23:07:30Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Josh Steadmon <steadmon@google.com> writes:\n\n> Currently, negotiation for V0/V1/V2 fetch have trace2 regions covering\n> the entire negotiation process. However, we'd like additional data, such\n> as timing for each round of negotiation or the number of \"haves\" in each\n> round. Additionally, \"independent negotiation\" (AKA push negotiation)\n> has no tracing at all. Having this data would allow us to compare the\n> performance of the various negotation implementations, and to debug\n> unexpectedly slow fetch & push sessions.\n\nQuite sensibly argued.  I do not necessarily see the current code as\n\"broken\", and \"fix\" at the beginning of the next line may not be an\nappropriate word to describe this enhancement, but I think it would\nbe nice to have such numbers.\n\n> diff --git a/fetch-pack.c b/fetch-pack.c\n> index cb6647d657..01a451e456 100644\n> --- a/fetch-pack.c\n> +++ b/fetch-pack.c\n> @@ -299,6 +299,7 @@ static int find_common(struct fetch_negotiator *negotiator,\n>  {\n>  \tint fetching;\n>  \tint count = 0, flushes = 0, flush_at = INITIAL_FLUSH, retval;\n> +\tint negotiation_round = 0, haves = 0;\n>  \tconst struct object_id *oid;\n>  \tunsigned in_vain = 0;\n>  \tint got_continue = 0;\n> @@ -441,9 +442,19 @@ static int find_common(struct fetch_negotiator *negotiator,\n>  \t\tpacket_buf_write(&req_buf, \"have %s\\n\", oid_to_hex(oid));\n>  \t\tprint_verbose(args, \"have %s\", oid_to_hex(oid));\n>  \t\tin_vain++;\n> +\t\thaves++;\n>  \t\tif (flush_at <= ++count) {\n>  \t\t\tint ack;\n>  \n> +\t\t\tnegotiation_round++;\n> +\t\t\ttrace2_region_enter_printf(\"negotiation_v0_v1\", \"round\",\n> +\t\t\t\t\t\t   the_repository, \"round-%d\",\n> +\t\t\t\t\t\t   negotiation_round);\n\nNot an objection, but all the hits to existing calls to this\nfunction show the data in a format as vanilla as possible without\nfrills (presumably to make it easier to mechanically parse the value\nout when needed???), and the \"round-\" prefix we see here somehow\nlooks out of place.  Doesn't the fact that the record is in the\n\"negotiation_v0_v1\" category and has label \"round\" clear enough sign\nthat the value presented is the negotiation_round?\n\n> +\t\t\ttrace2_data_intmax(\"negotiation_v0_v1\", the_repository,\n> +\t\t\t\t\t   \"haves_added\", haves);\n> +\t\t\ttrace2_data_intmax(\"negotiation_v0_v1\", the_repository,\n> +\t\t\t\t\t   \"in_vain\", in_vain);\n> +\t\t\thaves = 0;\n>  \t\t\tpacket_buf_flush(&req_buf);\n>  \t\t\tsend_request(args, fd[1], &req_buf);\n>  \t\t\tstrbuf_setlen(&req_buf, state_len);\n> @@ -465,6 +476,9 @@ static int find_common(struct fetch_negotiator *negotiator,\n>  \t\t\t\t\t\t      ack, oid_to_hex(result_oid));\n>  \t\t\t\tswitch (ack) {\n>  \t\t\t\tcase ACK:\n> +\t\t\t\t\ttrace2_region_leave_printf(\"negotiation_v0_v1\", \"round\",\n> +\t\t\t\t\t\t\t\t   the_repository, \"round-%d\",\n> +\t\t\t\t\t\t\t\t   negotiation_round);\n>  \t\t\t\t\tflushes = 0;\n>  \t\t\t\t\tmulti_ack = 0;\n>  \t\t\t\t\tretval = 0;\n> @@ -490,6 +504,7 @@ static int find_common(struct fetch_negotiator *negotiator,\n>  \t\t\t\t\t\tconst char *hex = oid_to_hex(result_oid);\n>  \t\t\t\t\t\tpacket_buf_write(&req_buf, \"have %s\\n\", hex);\n>  \t\t\t\t\t\tstate_len = req_buf.len;\n> +\t\t\t\t\t\thaves++;\n>  \t\t\t\t\t\t/*\n>  \t\t\t\t\t\t * Reset in_vain because an ack\n>  \t\t\t\t\t\t * for this commit has not been\n> @@ -510,14 +525,26 @@ static int find_common(struct fetch_negotiator *negotiator,\n>  \t\t\tflushes--;\n>  \t\t\tif (got_continue && MAX_IN_VAIN < in_vain) {\n>  \t\t\t\tprint_verbose(args, _(\"giving up\"));\n> +\t\t\t\ttrace2_region_leave_printf(\"negotiation_v0_v1\", \"round\",\n> +\t\t\t\t\t\t\t   the_repository, \"round-%d\",\n> +\t\t\t\t\t\t\t   negotiation_round);\n>  \t\t\t\tbreak; /* give up */\n>  \t\t\t}\n> -\t\t\tif (got_ready)\n> +\t\t\tif (got_ready) {\n> +\t\t\t\ttrace2_region_leave_printf(\"negotiation_v0_v1\", \"round\",\n> +\t\t\t\t\t\t\t   the_repository, \"round-%d\",\n> +\t\t\t\t\t\t\t   negotiation_round);\n>  \t\t\t\tbreak;\n> +\t\t\t}\n> +\t\t\ttrace2_region_leave_printf(\"negotiation_v0_v1\", \"round\",\n> +\t\t\t\t\t\t   the_repository, \"round-%d\",\n> +\t\t\t\t\t\t   negotiation_round);\n>  \t\t}\n\nHaving many duplicated calls to \"leave\" makes the whole thing look\nsomewhat confused.  Is this primarily because we have too many\n\"break\" that breaks out of the loop?\n\n> @@ -1603,6 +1632,7 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,\n>  \tstruct oidset common = OIDSET_INIT;\n>  \tstruct packet_reader reader;\n>  \tint in_vain = 0, negotiation_started = 0;\n> +\tint negotiation_round = 0;\n>  \tint haves_to_send = INITIAL_FLUSH;\n>  \tstruct fetch_negotiator negotiator_alloc;\n>  \tstruct fetch_negotiator *negotiator;\n> @@ -1659,6 +1689,10 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,\n>  \t\t\t\t\t\t    \"negotiation_v2\",\n>  \t\t\t\t\t\t    the_repository);\n>  \t\t\t}\n> +\t\t\tnegotiation_round++;\n> +\t\t\ttrace2_region_enter_printf(\"negotiation_v2\", \"round\",\n> +\t\t\t\t\t\t   the_repository, \"round-%d\",\n> +\t\t\t\t\t\t   negotiation_round);\n>  \t\t\tif (send_fetch_request(negotiator, fd[1], args, ref,\n>  \t\t\t\t\t       &common,\n>  \t\t\t\t\t       &haves_to_send, &in_vain,\n> @@ -1686,12 +1720,20 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,\n>  \t\t\t} else {\n>  \t\t\t\tdo_check_stateless_delimiter(args->stateless_rpc, &reader);\n>  \t\t\t\tstate = FETCH_SEND_REQUEST;\n> +\t\t\t\ttrace2_region_leave_printf(\"negotiation_v2\", \"round\",\n> +\t\t\t\t\t\t\t   the_repository, \"round-%d\",\n> +\t\t\t\t\t\t\t   negotiation_round);\n>  \t\t\t}\n>  \t\t\tbreak;\n>  \t\tcase FETCH_GET_PACK:\n> +\t\t\ttrace2_region_leave_printf(\"negotiation_v2\", \"round\",\n> +\t\t\t\t\t\t   the_repository, \"round-%d\",\n> +\t\t\t\t\t\t   negotiation_round);\n\nHmph.  Doesn't this logically belong to the \"FETCH_PROCESS_ACKS\"\ncase arm?  We \"leave\" the current round when we did not get \"ready\"\nand \"enter\" the next round by moving to \"FETCH_SEND_REQUEST\" state,\nbut at the same location when we did get \"ready\", we can \"leave\" the\ncurrent (and final) round and move to \"FETCH_GET_PACK\" state.  I\nsuspect the code structure and control flow becomes easier to see\nwhen expressed that way.\n\n>  \t\t\ttrace2_region_leave(\"fetch-pack\",\n>  \t\t\t\t\t    \"negotiation_v2\",\n>  \t\t\t\t\t    the_repository);\n> +\t\t\ttrace2_data_intmax(\"negotiation_v2\", the_repository,\n> +\t\t\t\t\t   \"total_rounds\", negotiation_round);\n>  \t\t\t/* Check for shallow-info section */\n>  \t\t\tif (process_section_header(&reader, \"shallow-info\", 1))\n>  \t\t\t\treceive_shallow_info(args, &reader, shallows, si);\n"},{"id":"459944","messageId":"16998c06-8394-1c8a-06d1-0f7ac4034cf4@jeffhostetler.com","threadId":"58222","inReplyTo":"a16d86e1ced104bb331bb9e7055037a3a2821352.1658787182.git.steadmon@google.com","subject":"Re: [PATCH] fetch-pack: add tracing for negotiation rounds","fromName":"Jeff Hostetler","fromEmail":"git@jeffhostetler.com","sentAt":"2022-07-26T00:04:50Z","receivedAt":"2022-07-26T00:04:58Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"\n\nOn 7/25/22 6:13 PM, Josh Steadmon wrote:\n> Currently, negotiation for V0/V1/V2 fetch have trace2 regions covering\n> the entire negotiation process. However, we'd like additional data, such\n> as timing for each round of negotiation or the number of \"haves\" in each\n> round. Additionally, \"independent negotiation\" (AKA push negotiation)\n> has no tracing at all. Having this data would allow us to compare the\n> performance of the various negotation implementations, and to debug\n> unexpectedly slow fetch & push sessions.\n> \n> Fix this by adding per-round trace2 regions for all negotiation\n> implementations (V0+V1, V2, and independent negotiation), as well as an\n> overall region for independent negotiation. Add trace2 data logging for\n> the number of haves and \"in vain\" objects for each round, and for the\n> total number of rounds once negotiation completes.  Finally, add a few\n> checks into various tests to verify that the number of rounds is logged\n> as expected.\n\nI've been wanting to add data like this around the negotiation\ncode for a while now.  Thanks!\n\n> \n> Signed-off-by: Josh Steadmon <steadmon@google.com>\n> ---\n>   fetch-pack.c                       | 62 +++++++++++++++++++++++++++++-\n>   t/t5500-fetch-pack.sh              |  4 +-\n>   t/t5516-fetch-push.sh              | 10 ++++-\n>   t/t5601-clone.sh                   |  6 ++-\n>   t/t5703-upload-pack-ref-in-want.sh |  6 ++-\n>   5 files changed, 81 insertions(+), 7 deletions(-)\n> \n> diff --git a/fetch-pack.c b/fetch-pack.c\n> index cb6647d657..01a451e456 100644\n> --- a/fetch-pack.c\n> +++ b/fetch-pack.c\n> @@ -299,6 +299,7 @@ static int find_common(struct fetch_negotiator *negotiator,\n>   {\n>   \tint fetching;\n>   \tint count = 0, flushes = 0, flush_at = INITIAL_FLUSH, retval;\n> +\tint negotiation_round = 0, haves = 0;\n>   \tconst struct object_id *oid;\n>   \tunsigned in_vain = 0;\n>   \tint got_continue = 0;\n> @@ -441,9 +442,19 @@ static int find_common(struct fetch_negotiator *negotiator,\n>   \t\tpacket_buf_write(&req_buf, \"have %s\\n\", oid_to_hex(oid));\n>   \t\tprint_verbose(args, \"have %s\", oid_to_hex(oid));\n>   \t\tin_vain++;\n> +\t\thaves++;\n>   \t\tif (flush_at <= ++count) {\n>   \t\t\tint ack;\n>   \n> +\t\t\tnegotiation_round++;\n> +\t\t\ttrace2_region_enter_printf(\"negotiation_v0_v1\", \"round\",\n> +\t\t\t\t\t\t   the_repository, \"round-%d\",\n> +\t\t\t\t\t\t   negotiation_round);\n\nI'm wondering here if the \"round-%d\" should have some number\nof leading zeros so that multiple rounds will sort correctly\nwhen you have a bunch of them.\n\nI'm also wondering (and this is more of a style thing, so feel\nfree to ignore) if we could just use trace2_region_enter()\nand make the \"label\" field be the \"round/%04d\" and not need\nthe extra args.\n\n\n> +\t\t\ttrace2_data_intmax(\"negotiation_v0_v1\", the_repository,\n> +\t\t\t\t\t   \"haves_added\", haves);\n> +\t\t\ttrace2_data_intmax(\"negotiation_v0_v1\", the_repository,\n> +\t\t\t\t\t   \"in_vain\", in_vain);\n> +\t\t\thaves = 0;\n\nThanks,\nJeff\n"},{"id":"460510","messageId":"YumceAg8txkKIuDf@google.com","threadId":"58222","inReplyTo":"xmqqilnkyeom.fsf@gitster.g","subject":"Re: [PATCH] fetch-pack: add tracing for negotiation rounds","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2022-08-02T21:51:52Z","receivedAt":"2022-08-02T21:52:03Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"On 2022.07.25 16:07, Junio C Hamano wrote:\n> Josh Steadmon <steadmon@google.com> writes:\n> \n> > Currently, negotiation for V0/V1/V2 fetch have trace2 regions covering\n> > the entire negotiation process. However, we'd like additional data, such\n> > as timing for each round of negotiation or the number of \"haves\" in each\n> > round. Additionally, \"independent negotiation\" (AKA push negotiation)\n> > has no tracing at all. Having this data would allow us to compare the\n> > performance of the various negotation implementations, and to debug\n> > unexpectedly slow fetch & push sessions.\n> \n> Quite sensibly argued.  I do not necessarily see the current code as\n> \"broken\", and \"fix\" at the beginning of the next line may not be an\n> appropriate word to describe this enhancement, but I think it would\n> be nice to have such numbers.\n\nReworded that sentence.\n\n\n> > diff --git a/fetch-pack.c b/fetch-pack.c\n> > index cb6647d657..01a451e456 100644\n> > --- a/fetch-pack.c\n> > +++ b/fetch-pack.c\n> > @@ -299,6 +299,7 @@ static int find_common(struct fetch_negotiator *negotiator,\n> >  {\n> >  \tint fetching;\n> >  \tint count = 0, flushes = 0, flush_at = INITIAL_FLUSH, retval;\n> > +\tint negotiation_round = 0, haves = 0;\n> >  \tconst struct object_id *oid;\n> >  \tunsigned in_vain = 0;\n> >  \tint got_continue = 0;\n> > @@ -441,9 +442,19 @@ static int find_common(struct fetch_negotiator *negotiator,\n> >  \t\tpacket_buf_write(&req_buf, \"have %s\\n\", oid_to_hex(oid));\n> >  \t\tprint_verbose(args, \"have %s\", oid_to_hex(oid));\n> >  \t\tin_vain++;\n> > +\t\thaves++;\n> >  \t\tif (flush_at <= ++count) {\n> >  \t\t\tint ack;\n> >  \n> > +\t\t\tnegotiation_round++;\n> > +\t\t\ttrace2_region_enter_printf(\"negotiation_v0_v1\", \"round\",\n> > +\t\t\t\t\t\t   the_repository, \"round-%d\",\n> > +\t\t\t\t\t\t   negotiation_round);\n> \n> Not an objection, but all the hits to existing calls to this\n> function show the data in a format as vanilla as possible without\n> frills (presumably to make it easier to mechanically parse the value\n> out when needed???), and the \"round-\" prefix we see here somehow\n> looks out of place.  Doesn't the fact that the record is in the\n> \"negotiation_v0_v1\" category and has label \"round\" clear enough sign\n> that the value presented is the negotiation_round?\n\nTrue, fixed in V2.\n\n\n> > +\t\t\ttrace2_data_intmax(\"negotiation_v0_v1\", the_repository,\n> > +\t\t\t\t\t   \"haves_added\", haves);\n> > +\t\t\ttrace2_data_intmax(\"negotiation_v0_v1\", the_repository,\n> > +\t\t\t\t\t   \"in_vain\", in_vain);\n> > +\t\t\thaves = 0;\n> >  \t\t\tpacket_buf_flush(&req_buf);\n> >  \t\t\tsend_request(args, fd[1], &req_buf);\n> >  \t\t\tstrbuf_setlen(&req_buf, state_len);\n> > @@ -465,6 +476,9 @@ static int find_common(struct fetch_negotiator *negotiator,\n> >  \t\t\t\t\t\t      ack, oid_to_hex(result_oid));\n> >  \t\t\t\tswitch (ack) {\n> >  \t\t\t\tcase ACK:\n> > +\t\t\t\t\ttrace2_region_leave_printf(\"negotiation_v0_v1\", \"round\",\n> > +\t\t\t\t\t\t\t\t   the_repository, \"round-%d\",\n> > +\t\t\t\t\t\t\t\t   negotiation_round);\n> >  \t\t\t\t\tflushes = 0;\n> >  \t\t\t\t\tmulti_ack = 0;\n> >  \t\t\t\t\tretval = 0;\n> > @@ -490,6 +504,7 @@ static int find_common(struct fetch_negotiator *negotiator,\n> >  \t\t\t\t\t\tconst char *hex = oid_to_hex(result_oid);\n> >  \t\t\t\t\t\tpacket_buf_write(&req_buf, \"have %s\\n\", hex);\n> >  \t\t\t\t\t\tstate_len = req_buf.len;\n> > +\t\t\t\t\t\thaves++;\n> >  \t\t\t\t\t\t/*\n> >  \t\t\t\t\t\t * Reset in_vain because an ack\n> >  \t\t\t\t\t\t * for this commit has not been\n> > @@ -510,14 +525,26 @@ static int find_common(struct fetch_negotiator *negotiator,\n> >  \t\t\tflushes--;\n> >  \t\t\tif (got_continue && MAX_IN_VAIN < in_vain) {\n> >  \t\t\t\tprint_verbose(args, _(\"giving up\"));\n> > +\t\t\t\ttrace2_region_leave_printf(\"negotiation_v0_v1\", \"round\",\n> > +\t\t\t\t\t\t\t   the_repository, \"round-%d\",\n> > +\t\t\t\t\t\t\t   negotiation_round);\n> >  \t\t\t\tbreak; /* give up */\n> >  \t\t\t}\n> > -\t\t\tif (got_ready)\n> > +\t\t\tif (got_ready) {\n> > +\t\t\t\ttrace2_region_leave_printf(\"negotiation_v0_v1\", \"round\",\n> > +\t\t\t\t\t\t\t   the_repository, \"round-%d\",\n> > +\t\t\t\t\t\t\t   negotiation_round);\n> >  \t\t\t\tbreak;\n> > +\t\t\t}\n> > +\t\t\ttrace2_region_leave_printf(\"negotiation_v0_v1\", \"round\",\n> > +\t\t\t\t\t\t   the_repository, \"round-%d\",\n> > +\t\t\t\t\t\t   negotiation_round);\n> >  \t\t}\n> \n> Having many duplicated calls to \"leave\" makes the whole thing look\n> somewhat confused.  Is this primarily because we have too many\n> \"break\" that breaks out of the loop?\n\nYes, although now that I look at it again, I believe as soon as we\nfinish the do-while, we know that the round is over, so I believe we can\njust put a single region_leave there. Fixed in V2.\n\n\n> > @@ -1603,6 +1632,7 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,\n> >  \tstruct oidset common = OIDSET_INIT;\n> >  \tstruct packet_reader reader;\n> >  \tint in_vain = 0, negotiation_started = 0;\n> > +\tint negotiation_round = 0;\n> >  \tint haves_to_send = INITIAL_FLUSH;\n> >  \tstruct fetch_negotiator negotiator_alloc;\n> >  \tstruct fetch_negotiator *negotiator;\n> > @@ -1659,6 +1689,10 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,\n> >  \t\t\t\t\t\t    \"negotiation_v2\",\n> >  \t\t\t\t\t\t    the_repository);\n> >  \t\t\t}\n> > +\t\t\tnegotiation_round++;\n> > +\t\t\ttrace2_region_enter_printf(\"negotiation_v2\", \"round\",\n> > +\t\t\t\t\t\t   the_repository, \"round-%d\",\n> > +\t\t\t\t\t\t   negotiation_round);\n> >  \t\t\tif (send_fetch_request(negotiator, fd[1], args, ref,\n> >  \t\t\t\t\t       &common,\n> >  \t\t\t\t\t       &haves_to_send, &in_vain,\n> > @@ -1686,12 +1720,20 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,\n> >  \t\t\t} else {\n> >  \t\t\t\tdo_check_stateless_delimiter(args->stateless_rpc, &reader);\n> >  \t\t\t\tstate = FETCH_SEND_REQUEST;\n> > +\t\t\t\ttrace2_region_leave_printf(\"negotiation_v2\", \"round\",\n> > +\t\t\t\t\t\t\t   the_repository, \"round-%d\",\n> > +\t\t\t\t\t\t\t   negotiation_round);\n> >  \t\t\t}\n> >  \t\t\tbreak;\n> >  \t\tcase FETCH_GET_PACK:\n> > +\t\t\ttrace2_region_leave_printf(\"negotiation_v2\", \"round\",\n> > +\t\t\t\t\t\t   the_repository, \"round-%d\",\n> > +\t\t\t\t\t\t   negotiation_round);\n> \n> Hmph.  Doesn't this logically belong to the \"FETCH_PROCESS_ACKS\"\n> case arm?  We \"leave\" the current round when we did not get \"ready\"\n> and \"enter\" the next round by moving to \"FETCH_SEND_REQUEST\" state,\n> but at the same location when we did get \"ready\", we can \"leave\" the\n> current (and final) round and move to \"FETCH_GET_PACK\" state.  I\n> suspect the code structure and control flow becomes easier to see\n> when expressed that way.\n\nThat works, but then we also need an additional region_leave in the\nFETCH_SEND_REQUEST case where we jump directly to FETCH_GET_PACK. I'm\nnot sure which way is more intuitive, but I've gone with your suggestion\nfor V2.\n\n\n> >  \t\t\ttrace2_region_leave(\"fetch-pack\",\n> >  \t\t\t\t\t    \"negotiation_v2\",\n> >  \t\t\t\t\t    the_repository);\n> > +\t\t\ttrace2_data_intmax(\"negotiation_v2\", the_repository,\n> > +\t\t\t\t\t   \"total_rounds\", negotiation_round);\n> >  \t\t\t/* Check for shallow-info section */\n> >  \t\t\tif (process_section_header(&reader, \"shallow-info\", 1))\n> >  \t\t\t\treceive_shallow_info(args, &reader, shallows, si);\n"},{"id":"460511","messageId":"Yumcj1oD9grwF7ZV@google.com","threadId":"58222","inReplyTo":"16998c06-8394-1c8a-06d1-0f7ac4034cf4@jeffhostetler.com","subject":"Re: [PATCH] fetch-pack: add tracing for negotiation rounds","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2022-08-02T21:52:15Z","receivedAt":"2022-08-02T21:52:26Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"On 2022.07.25 20:04, Jeff Hostetler wrote:\n> \n> \n> On 7/25/22 6:13 PM, Josh Steadmon wrote:\n> > Currently, negotiation for V0/V1/V2 fetch have trace2 regions covering\n> > the entire negotiation process. However, we'd like additional data, such\n> > as timing for each round of negotiation or the number of \"haves\" in each\n> > round. Additionally, \"independent negotiation\" (AKA push negotiation)\n> > has no tracing at all. Having this data would allow us to compare the\n> > performance of the various negotation implementations, and to debug\n> > unexpectedly slow fetch & push sessions.\n> > \n> > Fix this by adding per-round trace2 regions for all negotiation\n> > implementations (V0+V1, V2, and independent negotiation), as well as an\n> > overall region for independent negotiation. Add trace2 data logging for\n> > the number of haves and \"in vain\" objects for each round, and for the\n> > total number of rounds once negotiation completes.  Finally, add a few\n> > checks into various tests to verify that the number of rounds is logged\n> > as expected.\n> \n> I've been wanting to add data like this around the negotiation\n> code for a while now.  Thanks!\n> \n> > \n> > Signed-off-by: Josh Steadmon <steadmon@google.com>\n> > ---\n> >   fetch-pack.c                       | 62 +++++++++++++++++++++++++++++-\n> >   t/t5500-fetch-pack.sh              |  4 +-\n> >   t/t5516-fetch-push.sh              | 10 ++++-\n> >   t/t5601-clone.sh                   |  6 ++-\n> >   t/t5703-upload-pack-ref-in-want.sh |  6 ++-\n> >   5 files changed, 81 insertions(+), 7 deletions(-)\n> > \n> > diff --git a/fetch-pack.c b/fetch-pack.c\n> > index cb6647d657..01a451e456 100644\n> > --- a/fetch-pack.c\n> > +++ b/fetch-pack.c\n> > @@ -299,6 +299,7 @@ static int find_common(struct fetch_negotiator *negotiator,\n> >   {\n> >   \tint fetching;\n> >   \tint count = 0, flushes = 0, flush_at = INITIAL_FLUSH, retval;\n> > +\tint negotiation_round = 0, haves = 0;\n> >   \tconst struct object_id *oid;\n> >   \tunsigned in_vain = 0;\n> >   \tint got_continue = 0;\n> > @@ -441,9 +442,19 @@ static int find_common(struct fetch_negotiator *negotiator,\n> >   \t\tpacket_buf_write(&req_buf, \"have %s\\n\", oid_to_hex(oid));\n> >   \t\tprint_verbose(args, \"have %s\", oid_to_hex(oid));\n> >   \t\tin_vain++;\n> > +\t\thaves++;\n> >   \t\tif (flush_at <= ++count) {\n> >   \t\t\tint ack;\n> > +\t\t\tnegotiation_round++;\n> > +\t\t\ttrace2_region_enter_printf(\"negotiation_v0_v1\", \"round\",\n> > +\t\t\t\t\t\t   the_repository, \"round-%d\",\n> > +\t\t\t\t\t\t   negotiation_round);\n> \n> I'm wondering here if the \"round-%d\" should have some number\n> of leading zeros so that multiple rounds will sort correctly\n> when you have a bunch of them.\n> \n> I'm also wondering (and this is more of a style thing, so feel\n> free to ignore) if we could just use trace2_region_enter()\n> and make the \"label\" field be the \"round/%04d\" and not need\n> the extra args.\n\nJunio suggested just dropping the prefix altogether, so that's what I've\ndone for V2, but if you feel strongly about it we can discuss further\nfor V3.\n\n\n> > +\t\t\ttrace2_data_intmax(\"negotiation_v0_v1\", the_repository,\n> > +\t\t\t\t\t   \"haves_added\", haves);\n> > +\t\t\ttrace2_data_intmax(\"negotiation_v0_v1\", the_repository,\n> > +\t\t\t\t\t   \"in_vain\", in_vain);\n> > +\t\t\thaves = 0;\n> \n> Thanks,\n> Jeff\n"},{"id":"460513","messageId":"4390677ec75d51487142adf7c2ab821cbd24a53e.1659477669.git.steadmon@google.com","threadId":"58222","inReplyTo":"a16d86e1ced104bb331bb9e7055037a3a2821352.1658787182.git.steadmon@google.com","subject":"[PATCH v2] fetch-pack: add tracing for negotiation rounds","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2022-08-02T22:04:05Z","receivedAt":"2022-08-02T22:04:14Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"Currently, negotiation for V0/V1/V2 fetch have trace2 regions covering\nthe entire negotiation process. However, we'd like additional data, such\nas timing for each round of negotiation or the number of \"haves\" in each\nround. Additionally, \"independent negotiation\" (AKA push negotiation)\nhas no tracing at all. Having this data would allow us to compare the\nperformance of the various negotation implementations, and to debug\nunexpectedly slow fetch & push sessions.\n\nAdd per-round trace2 regions for all negotiation implementations (V0+V1,\nV2, and independent negotiation), as well as an overall region for\nindependent negotiation. Add trace2 data logging for the number of haves\nand \"in vain\" objects for each round, and for the total number of rounds\nonce negotiation completes.  Finally, add a few checks into various\ntests to verify that the number of rounds is logged as expected.\n\nSigned-off-by: Josh Steadmon <steadmon@google.com>\n---\nChanges since V1:\n* Removed \"round-\" prefix in per-round region messages.\n* Deduplicate some trace2_region_leave_printf() calls.\n* Clarified the commit message.\n\nRange-diff against v1:\n1:  a16d86e1ce ! 1:  4390677ec7 fetch-pack: add tracing for negotiation rounds\n    @@ Commit message\n         performance of the various negotation implementations, and to debug\n         unexpectedly slow fetch & push sessions.\n     \n    -    Fix this by adding per-round trace2 regions for all negotiation\n    -    implementations (V0+V1, V2, and independent negotiation), as well as an\n    -    overall region for independent negotiation. Add trace2 data logging for\n    -    the number of haves and \"in vain\" objects for each round, and for the\n    -    total number of rounds once negotiation completes.  Finally, add a few\n    -    checks into various tests to verify that the number of rounds is logged\n    -    as expected.\n    +    Add per-round trace2 regions for all negotiation implementations (V0+V1,\n    +    V2, and independent negotiation), as well as an overall region for\n    +    independent negotiation. Add trace2 data logging for the number of haves\n    +    and \"in vain\" objects for each round, and for the total number of rounds\n    +    once negotiation completes.  Finally, add a few checks into various\n    +    tests to verify that the number of rounds is logged as expected.\n     \n     \n    @@ fetch-pack.c: static int find_common(struct fetch_negotiator *negotiator,\n      \n     +\t\t\tnegotiation_round++;\n     +\t\t\ttrace2_region_enter_printf(\"negotiation_v0_v1\", \"round\",\n    -+\t\t\t\t\t\t   the_repository, \"round-%d\",\n    ++\t\t\t\t\t\t   the_repository, \"%d\",\n     +\t\t\t\t\t\t   negotiation_round);\n     +\t\t\ttrace2_data_intmax(\"negotiation_v0_v1\", the_repository,\n     +\t\t\t\t\t   \"haves_added\", haves);\n    @@ fetch-pack.c: static int find_common(struct fetch_negotiator *negotiator,\n      \t\t\t\tswitch (ack) {\n      \t\t\t\tcase ACK:\n     +\t\t\t\t\ttrace2_region_leave_printf(\"negotiation_v0_v1\", \"round\",\n    -+\t\t\t\t\t\t\t\t   the_repository, \"round-%d\",\n    ++\t\t\t\t\t\t\t\t   the_repository, \"%d\",\n     +\t\t\t\t\t\t\t\t   negotiation_round);\n      \t\t\t\t\tflushes = 0;\n      \t\t\t\t\tmulti_ack = 0;\n    @@ fetch-pack.c: static int find_common(struct fetch_negotiator *negotiator,\n      \t\t\t\t\t\t * Reset in_vain because an ack\n      \t\t\t\t\t\t * for this commit has not been\n     @@ fetch-pack.c: static int find_common(struct fetch_negotiator *negotiator,\n    + \t\t\t\t}\n    + \t\t\t} while (ack);\n      \t\t\tflushes--;\n    ++\t\t\ttrace2_region_leave_printf(\"negotiation_v0_v1\", \"round\",\n    ++\t\t\t\t\t\t   the_repository, \"%d\",\n    ++\t\t\t\t\t\t   negotiation_round);\n      \t\t\tif (got_continue && MAX_IN_VAIN < in_vain) {\n      \t\t\t\tprint_verbose(args, _(\"giving up\"));\n    -+\t\t\t\ttrace2_region_leave_printf(\"negotiation_v0_v1\", \"round\",\n    -+\t\t\t\t\t\t\t   the_repository, \"round-%d\",\n    -+\t\t\t\t\t\t\t   negotiation_round);\n      \t\t\t\tbreak; /* give up */\n    - \t\t\t}\n    --\t\t\tif (got_ready)\n    -+\t\t\tif (got_ready) {\n    -+\t\t\t\ttrace2_region_leave_printf(\"negotiation_v0_v1\", \"round\",\n    -+\t\t\t\t\t\t\t   the_repository, \"round-%d\",\n    -+\t\t\t\t\t\t\t   negotiation_round);\n    - \t\t\t\tbreak;\n    -+\t\t\t}\n    -+\t\t\ttrace2_region_leave_printf(\"negotiation_v0_v1\", \"round\",\n    -+\t\t\t\t\t\t   the_repository, \"round-%d\",\n    -+\t\t\t\t\t\t   negotiation_round);\n    - \t\t}\n    +@@ fetch-pack.c: static int find_common(struct fetch_negotiator *negotiator,\n      \t}\n      done:\n      \ttrace2_region_leave(\"fetch-pack\", \"negotiation_v0_v1\", the_repository);\n    @@ fetch-pack.c: static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,\n      \t\t\t}\n     +\t\t\tnegotiation_round++;\n     +\t\t\ttrace2_region_enter_printf(\"negotiation_v2\", \"round\",\n    -+\t\t\t\t\t\t   the_repository, \"round-%d\",\n    ++\t\t\t\t\t\t   the_repository, \"%d\",\n     +\t\t\t\t\t\t   negotiation_round);\n      \t\t\tif (send_fetch_request(negotiator, fd[1], args, ref,\n      \t\t\t\t\t       &common,\n      \t\t\t\t\t       &haves_to_send, &in_vain,\n    -@@ fetch-pack.c: static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,\n    - \t\t\t} else {\n    - \t\t\t\tdo_check_stateless_delimiter(args->stateless_rpc, &reader);\n    - \t\t\t\tstate = FETCH_SEND_REQUEST;\n    + \t\t\t\t\t       reader.use_sideband,\n    +-\t\t\t\t\t       seen_ack))\n    ++\t\t\t\t\t       seen_ack)) {\n     +\t\t\t\ttrace2_region_leave_printf(\"negotiation_v2\", \"round\",\n    -+\t\t\t\t\t\t\t   the_repository, \"round-%d\",\n    ++\t\t\t\t\t\t\t   the_repository, \"%d\",\n     +\t\t\t\t\t\t\t   negotiation_round);\n    - \t\t\t}\n    + \t\t\t\tstate = FETCH_GET_PACK;\n    ++\t\t\t}\n    + \t\t\telse\n    + \t\t\t\tstate = FETCH_PROCESS_ACKS;\n      \t\t\tbreak;\n    - \t\tcase FETCH_GET_PACK:\n    +@@ fetch-pack.c: static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,\n    + \t\t\t\tseen_ack = 1;\n    + \t\t\t\toidset_insert(&common, &common_oid);\n    + \t\t\t}\n     +\t\t\ttrace2_region_leave_printf(\"negotiation_v2\", \"round\",\n    -+\t\t\t\t\t\t   the_repository, \"round-%d\",\n    ++\t\t\t\t\t\t   the_repository, \"%d\",\n     +\t\t\t\t\t\t   negotiation_round);\n    + \t\t\tif (received_ready) {\n    + \t\t\t\t/*\n    + \t\t\t\t * Don't check for response delimiter; get_pack() will\n    +@@ fetch-pack.c: static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,\n      \t\t\ttrace2_region_leave(\"fetch-pack\",\n      \t\t\t\t\t    \"negotiation_v2\",\n      \t\t\t\t\t    the_repository);\n    @@ fetch-pack.c: void negotiate_using_fetch(const struct oid_array *negotiation_tip\n     +\t\tnegotiation_round++;\n     +\n     +\t\ttrace2_region_enter_printf(\"negotiate_using_fetch\", \"round\",\n    -+\t\t\t\t\t   the_repository, \"round-%d\",\n    ++\t\t\t\t\t   the_repository, \"%d\",\n     +\t\t\t\t\t   negotiation_round);\n      \t\tstrbuf_reset(&req_buf);\n      \t\twrite_fetch_command_and_capabilities(&req_buf, server_options);\n    @@ fetch-pack.c: void negotiate_using_fetch(const struct oid_array *negotiation_tip\n      \t\t\t\t\t\t min_generation))\n      \t\t\tlast_iteration = 1;\n     +\t\ttrace2_region_leave_printf(\"negotiation\", \"round\",\n    -+\t\t\t\t\t   the_repository, \"round-%d\",\n    ++\t\t\t\t\t   the_repository, \"%d\",\n     +\t\t\t\t\t   negotiation_round);\n      \t}\n     +\ttrace2_region_enter(\"fetch-pack\", \"negotiate_using_fetch\", the_repository);\n\n fetch-pack.c                       | 56 +++++++++++++++++++++++++++++-\n t/t5500-fetch-pack.sh              |  4 ++-\n t/t5516-fetch-push.sh              | 10 ++++--\n t/t5601-clone.sh                   |  6 +++-\n t/t5703-upload-pack-ref-in-want.sh |  6 ++--\n 5 files changed, 75 insertions(+), 7 deletions(-)\n\ndiff --git a/fetch-pack.c b/fetch-pack.c\nindex cb6647d657..666aaa9a89 100644\n--- a/fetch-pack.c\n+++ b/fetch-pack.c\n@@ -299,6 +299,7 @@ static int find_common(struct fetch_negotiator *negotiator,\n {\n \tint fetching;\n \tint count = 0, flushes = 0, flush_at = INITIAL_FLUSH, retval;\n+\tint negotiation_round = 0, haves = 0;\n \tconst struct object_id *oid;\n \tunsigned in_vain = 0;\n \tint got_continue = 0;\n@@ -441,9 +442,19 @@ static int find_common(struct fetch_negotiator *negotiator,\n \t\tpacket_buf_write(&req_buf, \"have %s\\n\", oid_to_hex(oid));\n \t\tprint_verbose(args, \"have %s\", oid_to_hex(oid));\n \t\tin_vain++;\n+\t\thaves++;\n \t\tif (flush_at <= ++count) {\n \t\t\tint ack;\n \n+\t\t\tnegotiation_round++;\n+\t\t\ttrace2_region_enter_printf(\"negotiation_v0_v1\", \"round\",\n+\t\t\t\t\t\t   the_repository, \"%d\",\n+\t\t\t\t\t\t   negotiation_round);\n+\t\t\ttrace2_data_intmax(\"negotiation_v0_v1\", the_repository,\n+\t\t\t\t\t   \"haves_added\", haves);\n+\t\t\ttrace2_data_intmax(\"negotiation_v0_v1\", the_repository,\n+\t\t\t\t\t   \"in_vain\", in_vain);\n+\t\t\thaves = 0;\n \t\t\tpacket_buf_flush(&req_buf);\n \t\t\tsend_request(args, fd[1], &req_buf);\n \t\t\tstrbuf_setlen(&req_buf, state_len);\n@@ -465,6 +476,9 @@ static int find_common(struct fetch_negotiator *negotiator,\n \t\t\t\t\t\t      ack, oid_to_hex(result_oid));\n \t\t\t\tswitch (ack) {\n \t\t\t\tcase ACK:\n+\t\t\t\t\ttrace2_region_leave_printf(\"negotiation_v0_v1\", \"round\",\n+\t\t\t\t\t\t\t\t   the_repository, \"%d\",\n+\t\t\t\t\t\t\t\t   negotiation_round);\n \t\t\t\t\tflushes = 0;\n \t\t\t\t\tmulti_ack = 0;\n \t\t\t\t\tretval = 0;\n@@ -490,6 +504,7 @@ static int find_common(struct fetch_negotiator *negotiator,\n \t\t\t\t\t\tconst char *hex = oid_to_hex(result_oid);\n \t\t\t\t\t\tpacket_buf_write(&req_buf, \"have %s\\n\", hex);\n \t\t\t\t\t\tstate_len = req_buf.len;\n+\t\t\t\t\t\thaves++;\n \t\t\t\t\t\t/*\n \t\t\t\t\t\t * Reset in_vain because an ack\n \t\t\t\t\t\t * for this commit has not been\n@@ -508,6 +523,9 @@ static int find_common(struct fetch_negotiator *negotiator,\n \t\t\t\t}\n \t\t\t} while (ack);\n \t\t\tflushes--;\n+\t\t\ttrace2_region_leave_printf(\"negotiation_v0_v1\", \"round\",\n+\t\t\t\t\t\t   the_repository, \"%d\",\n+\t\t\t\t\t\t   negotiation_round);\n \t\t\tif (got_continue && MAX_IN_VAIN < in_vain) {\n \t\t\t\tprint_verbose(args, _(\"giving up\"));\n \t\t\t\tbreak; /* give up */\n@@ -518,6 +536,8 @@ static int find_common(struct fetch_negotiator *negotiator,\n \t}\n done:\n \ttrace2_region_leave(\"fetch-pack\", \"negotiation_v0_v1\", the_repository);\n+\ttrace2_data_intmax(\"negotiation_v0_v1\", the_repository, \"total_rounds\",\n+\t\t\t   negotiation_round);\n \tif (!got_ready || !no_done) {\n \t\tpacket_buf_write(&req_buf, \"done\\n\");\n \t\tsend_request(args, fd[1], &req_buf);\n@@ -1361,6 +1381,8 @@ static int send_fetch_request(struct fetch_negotiator *negotiator, int fd_out,\n \n \thaves_added = add_haves(negotiator, &req_buf, haves_to_send);\n \t*in_vain += haves_added;\n+\ttrace2_data_intmax(\"negotiation_v2\", the_repository, \"haves_added\", haves_added);\n+\ttrace2_data_intmax(\"negotiation_v2\", the_repository, \"in_vain\", *in_vain);\n \tif (!haves_added || (seen_ack && *in_vain >= MAX_IN_VAIN)) {\n \t\t/* Send Done */\n \t\tpacket_buf_write(&req_buf, \"done\\n\");\n@@ -1603,6 +1625,7 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,\n \tstruct oidset common = OIDSET_INIT;\n \tstruct packet_reader reader;\n \tint in_vain = 0, negotiation_started = 0;\n+\tint negotiation_round = 0;\n \tint haves_to_send = INITIAL_FLUSH;\n \tstruct fetch_negotiator negotiator_alloc;\n \tstruct fetch_negotiator *negotiator;\n@@ -1659,12 +1682,20 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,\n \t\t\t\t\t\t    \"negotiation_v2\",\n \t\t\t\t\t\t    the_repository);\n \t\t\t}\n+\t\t\tnegotiation_round++;\n+\t\t\ttrace2_region_enter_printf(\"negotiation_v2\", \"round\",\n+\t\t\t\t\t\t   the_repository, \"%d\",\n+\t\t\t\t\t\t   negotiation_round);\n \t\t\tif (send_fetch_request(negotiator, fd[1], args, ref,\n \t\t\t\t\t       &common,\n \t\t\t\t\t       &haves_to_send, &in_vain,\n \t\t\t\t\t       reader.use_sideband,\n-\t\t\t\t\t       seen_ack))\n+\t\t\t\t\t       seen_ack)) {\n+\t\t\t\ttrace2_region_leave_printf(\"negotiation_v2\", \"round\",\n+\t\t\t\t\t\t\t   the_repository, \"%d\",\n+\t\t\t\t\t\t\t   negotiation_round);\n \t\t\t\tstate = FETCH_GET_PACK;\n+\t\t\t}\n \t\t\telse\n \t\t\t\tstate = FETCH_PROCESS_ACKS;\n \t\t\tbreak;\n@@ -1677,6 +1708,9 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,\n \t\t\t\tseen_ack = 1;\n \t\t\t\toidset_insert(&common, &common_oid);\n \t\t\t}\n+\t\t\ttrace2_region_leave_printf(\"negotiation_v2\", \"round\",\n+\t\t\t\t\t\t   the_repository, \"%d\",\n+\t\t\t\t\t\t   negotiation_round);\n \t\t\tif (received_ready) {\n \t\t\t\t/*\n \t\t\t\t * Don't check for response delimiter; get_pack() will\n@@ -1692,6 +1726,8 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,\n \t\t\ttrace2_region_leave(\"fetch-pack\",\n \t\t\t\t\t    \"negotiation_v2\",\n \t\t\t\t\t    the_repository);\n+\t\t\ttrace2_data_intmax(\"negotiation_v2\", the_repository,\n+\t\t\t\t\t   \"total_rounds\", negotiation_round);\n \t\t\t/* Check for shallow-info section */\n \t\t\tif (process_section_header(&reader, \"shallow-info\", 1))\n \t\t\t\treceive_shallow_info(args, &reader, shallows, si);\n@@ -2071,6 +2107,7 @@ void negotiate_using_fetch(const struct oid_array *negotiation_tips,\n \tint in_vain = 0;\n \tint seen_ack = 0;\n \tint last_iteration = 0;\n+\tint negotiation_round = 0;\n \ttimestamp_t min_generation = GENERATION_NUMBER_INFINITY;\n \n \tfetch_negotiator_init(the_repository, &negotiator);\n@@ -2084,11 +2121,17 @@ void negotiate_using_fetch(const struct oid_array *negotiation_tips,\n \t\t\t   add_to_object_array,\n \t\t\t   &nt_object_array);\n \n+\ttrace2_region_enter(\"fetch-pack\", \"negotiate_using_fetch\", the_repository);\n \twhile (!last_iteration) {\n \t\tint haves_added;\n \t\tstruct object_id common_oid;\n \t\tint received_ready = 0;\n \n+\t\tnegotiation_round++;\n+\n+\t\ttrace2_region_enter_printf(\"negotiate_using_fetch\", \"round\",\n+\t\t\t\t\t   the_repository, \"%d\",\n+\t\t\t\t\t   negotiation_round);\n \t\tstrbuf_reset(&req_buf);\n \t\twrite_fetch_command_and_capabilities(&req_buf, server_options);\n \n@@ -2099,6 +2142,11 @@ void negotiate_using_fetch(const struct oid_array *negotiation_tips,\n \t\tif (!haves_added || (seen_ack && in_vain >= MAX_IN_VAIN))\n \t\t\tlast_iteration = 1;\n \n+\t\ttrace2_data_intmax(\"negotiate_using_fetch\", the_repository,\n+\t\t\t\t   \"haves_added\", haves_added);\n+\t\ttrace2_data_intmax(\"negotiate_using_fetch\", the_repository,\n+\t\t\t\t   \"in_vain\", in_vain);\n+\n \t\t/* Send request */\n \t\tpacket_buf_flush(&req_buf);\n \t\tif (write_in_full(fd[1], req_buf.buf, req_buf.len) < 0)\n@@ -2131,7 +2179,13 @@ void negotiate_using_fetch(const struct oid_array *negotiation_tips,\n \t\t\t\t\t\t REACH_SCRATCH, 0,\n \t\t\t\t\t\t min_generation))\n \t\t\tlast_iteration = 1;\n+\t\ttrace2_region_leave_printf(\"negotiation\", \"round\",\n+\t\t\t\t\t   the_repository, \"%d\",\n+\t\t\t\t\t   negotiation_round);\n \t}\n+\ttrace2_region_enter(\"fetch-pack\", \"negotiate_using_fetch\", the_repository);\n+\ttrace2_data_intmax(\"negotiate_using_fetch\", the_repository,\n+\t\t\t   \"total_rounds\", negotiation_round);\n \tclear_common_flag(acked_commits);\n \tstrbuf_release(&req_buf);\n }\ndiff --git a/t/t5500-fetch-pack.sh b/t/t5500-fetch-pack.sh\nindex ee6d2dde9f..d18f2823d8 100755\n--- a/t/t5500-fetch-pack.sh\n+++ b/t/t5500-fetch-pack.sh\n@@ -407,6 +407,7 @@ test_expect_success 'in_vain not triggered before first ACK' '\n '\n \n test_expect_success 'in_vain resetted upon ACK' '\n+\ttest_when_finished rm -f log trace2 &&\n \trm -rf myserver myclient &&\n \tgit init myserver &&\n \n@@ -432,7 +433,8 @@ test_expect_success 'in_vain resetted upon ACK' '\n \t# first. The 256th commit is common between the client and the server,\n \t# and should reset in_vain. This allows negotiation to continue until\n \t# the client reports that first_anotherbranch_commit is common.\n-\tgit -C myclient fetch --progress origin main 2>log &&\n+\tGIT_TRACE2_EVENT=\"$(pwd)/trace2\" git -C myclient fetch --progress origin main 2>log &&\n+\tgrep \\\"key\\\":\\\"total_rounds\\\",\\\"value\\\":\\\"6\\\" trace2 &&\n \ttest_i18ngrep \"Total 3 \" log\n '\n \ndiff --git a/t/t5516-fetch-push.sh b/t/t5516-fetch-push.sh\nindex 9ca0f8c144..f64cefa29a 100755\n--- a/t/t5516-fetch-push.sh\n+++ b/t/t5516-fetch-push.sh\n@@ -198,7 +198,10 @@ test_expect_success 'push with negotiation' '\n \ttest_commit -C testrepo unrelated_commit &&\n \tgit -C testrepo config receive.hideRefs refs/remotes/origin/first_commit &&\n \ttest_when_finished \"rm event\" &&\n-\tGIT_TRACE2_EVENT=\"$(pwd)/event\" git -c protocol.version=2 -c push.negotiate=1 push testrepo refs/heads/main:refs/remotes/origin/main &&\n+\tGIT_TRACE2_EVENT=\"$(pwd)/event\" \\\n+\t\tgit -c protocol.version=2 -c push.negotiate=1 \\\n+\t\tpush testrepo refs/heads/main:refs/remotes/origin/main &&\n+\tgrep \\\"key\\\":\\\"total_rounds\\\",\\\"value\\\":\\\"1\\\" event &&\n \tgrep_wrote 2 event # 1 commit, 1 tree\n '\n \n@@ -222,7 +225,10 @@ test_expect_success 'push with negotiation does not attempt to fetch submodules'\n \tgit push testrepo $the_first_commit:refs/remotes/origin/first_commit &&\n \ttest_commit -C testrepo unrelated_commit &&\n \tgit -C testrepo config receive.hideRefs refs/remotes/origin/first_commit &&\n-\tgit -c submodule.recurse=true -c protocol.version=2 -c push.negotiate=1 push testrepo refs/heads/main:refs/remotes/origin/main 2>err &&\n+\tGIT_TRACE2_EVENT=\"$(pwd)/event\"  git -c submodule.recurse=true \\\n+\t\t-c protocol.version=2 -c push.negotiate=1 \\\n+\t\tpush testrepo refs/heads/main:refs/remotes/origin/main 2>err &&\n+\tgrep \\\"key\\\":\\\"total_rounds\\\",\\\"value\\\":\\\"1\\\" event &&\n \t! grep \"Fetching submodule\" err\n '\n \ndiff --git a/t/t5601-clone.sh b/t/t5601-clone.sh\nindex cf3be0584f..2e57de9c12 100755\n--- a/t/t5601-clone.sh\n+++ b/t/t5601-clone.sh\n@@ -743,7 +743,11 @@ test_expect_success 'batch missing blob request during checkout' '\n \n \t# Ensure that there is only one negotiation by checking that there is\n \t# only \"done\" line sent. (\"done\" marks the end of negotiation.)\n-\tGIT_TRACE_PACKET=\"$(pwd)/trace\" git -C client checkout HEAD^ &&\n+\tGIT_TRACE_PACKET=\"$(pwd)/trace\" \\\n+\t\tGIT_TRACE2_EVENT=\"$(pwd)/trace2_event\" \\\n+\t\tgit -C client -c trace2.eventNesting=5 checkout HEAD^ &&\n+\tgrep \\\"key\\\":\\\"total_rounds\\\",\\\"value\\\":\\\"1\\\" trace2_event >trace_lines &&\n+\ttest_line_count = 1 trace_lines &&\n \tgrep \"fetch> done\" trace >done_lines &&\n \ttest_line_count = 1 done_lines\n '\ndiff --git a/t/t5703-upload-pack-ref-in-want.sh b/t/t5703-upload-pack-ref-in-want.sh\nindex 9d6cd7d986..df74f80061 100755\n--- a/t/t5703-upload-pack-ref-in-want.sh\n+++ b/t/t5703-upload-pack-ref-in-want.sh\n@@ -229,14 +229,16 @@ test_expect_success 'setup repos for fetching with ref-in-want tests' '\n '\n \n test_expect_success 'fetching with exact OID' '\n-\ttest_when_finished \"rm -f log\" &&\n+\ttest_when_finished \"rm -f log trace2\" &&\n \n \trm -rf local &&\n \tcp -r \"$LOCAL_PRISTINE\" local &&\n \toid=$(git -C \"$REPO\" rev-parse d) &&\n-\tGIT_TRACE_PACKET=\"$(pwd)/log\" git -C local fetch origin \\\n+\tGIT_TRACE_PACKET=\"$(pwd)/log\" GIT_TRACE2_EVENT=\"$(pwd)/trace2\" \\\n+\t\tgit -C local fetch origin \\\n \t\t\"$oid\":refs/heads/actual &&\n \n+\tgrep \\\"key\\\":\\\"total_rounds\\\",\\\"value\\\":\\\"2\\\" trace2 &&\n \tgit -C \"$REPO\" rev-parse \"d\" >expected &&\n \tgit -C local rev-parse refs/heads/actual >actual &&\n \ttest_cmp expected actual &&\n\nbase-commit: 4e2a4d1dd44367d7783f33b169698f2930ff13c0\n-- \n2.37.1.455.g008518b4e5-goog\n\n"},{"id":"461237","messageId":"7dae2e8b-1168-3738-8efb-7ecfdfae796a@jeffhostetler.com","threadId":"58222","inReplyTo":"4390677ec75d51487142adf7c2ab821cbd24a53e.1659477669.git.steadmon@google.com","subject":"Re: [PATCH v2] fetch-pack: add tracing for negotiation rounds","fromName":"Jeff Hostetler","fromEmail":"git@jeffhostetler.com","sentAt":"2022-08-15T15:08:24Z","receivedAt":"2022-08-15T15:08:30Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"\n\n\nOn 8/2/22 6:04 PM, Josh Steadmon wrote:\n> Currently, negotiation for V0/V1/V2 fetch have trace2 regions covering\n> the entire negotiation process. However, we'd like additional data, such\n> as timing for each round of negotiation or the number of \"haves\" in each\n> round. Additionally, \"independent negotiation\" (AKA push negotiation)\n> has no tracing at all. Having this data would allow us to compare the\n> performance of the various negotation implementations, and to debug\n> unexpectedly slow fetch & push sessions.\n> \n> Add per-round trace2 regions for all negotiation implementations (V0+V1,\n> V2, and independent negotiation), as well as an overall region for\n> independent negotiation. Add trace2 data logging for the number of haves\n> and \"in vain\" objects for each round, and for the total number of rounds\n> once negotiation completes.  Finally, add a few checks into various\n> tests to verify that the number of rounds is logged as expected.\n> \n> Signed-off-by: Josh Steadmon <steadmon@google.com>\n\nSorry for the delay in responding. Just got back from a much\nneeded vacation.\n\nThis version LGTM.\n\nThanks\nJeff\n"}]}