{"thread":{"id":"61957","subject":"[PATCH 0/2] Add additional trace2 regions for fetch and push","startedAt":"2024-08-15T18:51:16Z","lastAt":"2024-08-22T22:10:31Z","messageCount":13,"participants":["Josh Steadmon","Junio C Hamano"],"isPatch":true,"patchVersion":1,"patchTotal":2},"messages":[{"id":"501035","messageId":"cover.1723747832.git.steadmon@google.com","threadId":"61957","inReplyTo":null,"subject":"[PATCH 0/2] Add additional trace2 regions for fetch and push","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2024-08-15T18:51:11Z","receivedAt":"2024-08-15T18:51:16Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"Last year at $DAYJOB we were having issues with slow\nfetches/pulls/pushes. We added some additional trace2 regions which\nhelped us narrow down the issue to some server-side negotiation\nproblems. We've been carrying these patches downstream ever since, but\nthey might be useful to others as well.\n\n\nCalvin Wan (1):\n  send-pack: add new tracing regions for push\n\nJosh Steadmon (1):\n  fetch: add top-level trace2 regions\n\n builtin/fetch.c | 27 +++++++++++++++++++++++----\n send-pack.c     | 16 +++++++++++++---\n 2 files changed, 36 insertions(+), 7 deletions(-)\n\n\nbase-commit: 25673b1c476756ec0587fb0596ab3c22b96dc52a\n-- \n2.46.0.184.g6999bdac58-goog\n\n"},{"id":"501036","messageId":"c0481f85f8166e520c387f9e9157b142b93d933c.1723747832.git.steadmon@google.com","threadId":"61957","inReplyTo":"cover.1723747832.git.steadmon@google.com","subject":"[PATCH 1/2] fetch: add top-level trace2 regions","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2024-08-15T18:51:12Z","receivedAt":"2024-08-15T18:51:17Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"At $DAYJOB we experienced some slow fetch operations and needed some\nadditional data to help diagnose the issue.\n\nAdd top-level trace2 regions for the various modes of operation of\n`git-fetch`. None of these regions are in recursive code, so any\nenclosed trace messages should only see their nesting level increase by\none.\n\nSigned-off-by: Josh Steadmon <steadmon@google.com>\n---\n builtin/fetch.c | 27 +++++++++++++++++++++++----\n 1 file changed, 23 insertions(+), 4 deletions(-)\n\ndiff --git a/builtin/fetch.c b/builtin/fetch.c\nindex 693f02b958..950cd79baa 100644\n--- a/builtin/fetch.c\n+++ b/builtin/fetch.c\n@@ -2353,9 +2353,14 @@ int cmd_fetch(int argc, const char **argv, const char *prefix)\n \tif (!max_jobs)\n \t\tmax_jobs = online_cpus();\n \n-\tif (!git_config_get_string_tmp(\"fetch.bundleuri\", &bundle_uri) &&\n-\t    fetch_bundle_uri(the_repository, bundle_uri, NULL))\n-\t\twarning(_(\"failed to fetch bundles from '%s'\"), bundle_uri);\n+\tif (!git_config_get_string_tmp(\"fetch.bundleuri\", &bundle_uri)) {\n+\t\tint result = 0;\n+\t\ttrace2_region_enter(\"fetch\", \"fetch-bundle-uri\", the_repository);\n+\t\tresult = fetch_bundle_uri(the_repository, bundle_uri, NULL);\n+\t\ttrace2_region_leave(\"fetch\", \"fetch-bundle-uri\", the_repository);\n+\t\tif (result)\n+\t\t\twarning(_(\"failed to fetch bundles from '%s'\"), bundle_uri);\n+\t}\n \n \tif (all < 0) {\n \t\t/*\n@@ -2407,6 +2412,7 @@ int cmd_fetch(int argc, const char **argv, const char *prefix)\n \t\tstruct oidset_iter iter;\n \t\tconst struct object_id *oid;\n \n+\t\ttrace2_region_enter(\"fetch\", \"negotiate-only\", the_repository);\n \t\tif (!remote)\n \t\t\tdie(_(\"must supply remote when using --negotiate-only\"));\n \t\tgtransport = prepare_transport(remote, 1);\n@@ -2415,6 +2421,7 @@ int cmd_fetch(int argc, const char **argv, const char *prefix)\n \t\t} else {\n \t\t\twarning(_(\"protocol does not support --negotiate-only, exiting\"));\n \t\t\tresult = 1;\n+\t\t\ttrace2_region_leave(\"fetch\", \"negotiate-only\", the_repository);\n \t\t\tgoto cleanup;\n \t\t}\n \t\tif (server_options.nr)\n@@ -2425,11 +2432,17 @@ int cmd_fetch(int argc, const char **argv, const char *prefix)\n \t\twhile ((oid = oidset_iter_next(&iter)))\n \t\t\tprintf(\"%s\\n\", oid_to_hex(oid));\n \t\toidset_clear(&acked_commits);\n+\t\ttrace2_region_leave(\"fetch\", \"negotiate-only\", the_repository);\n \t} else if (remote) {\n-\t\tif (filter_options.choice || repo_has_promisor_remote(the_repository))\n+\t\tif (filter_options.choice || repo_has_promisor_remote(the_repository)) {\n+\t\t\ttrace2_region_enter(\"fetch\", \"setup-partial\", the_repository);\n \t\t\tfetch_one_setup_partial(remote);\n+\t\t\ttrace2_region_leave(\"fetch\", \"setup-partial\", the_repository);\n+\t\t}\n+\t\ttrace2_region_enter(\"fetch\", \"fetch-one\", the_repository);\n \t\tresult = fetch_one(remote, argc, argv, prune_tags_ok, stdin_refspecs,\n \t\t\t\t   &config);\n+\t\ttrace2_region_leave(\"fetch\", \"fetch-one\", the_repository);\n \t} else {\n \t\tint max_children = max_jobs;\n \n@@ -2449,7 +2462,9 @@ int cmd_fetch(int argc, const char **argv, const char *prefix)\n \t\t\tmax_children = config.parallel;\n \n \t\t/* TODO should this also die if we have a previous partial-clone? */\n+\t\ttrace2_region_enter(\"fetch\", \"fetch-multiple\", the_repository);\n \t\tresult = fetch_multiple(&list, max_children, &config);\n+\t\ttrace2_region_leave(\"fetch\", \"fetch-multiple\", the_repository);\n \t}\n \n \t/*\n@@ -2471,6 +2486,7 @@ int cmd_fetch(int argc, const char **argv, const char *prefix)\n \t\t\tmax_children = config.parallel;\n \n \t\tadd_options_to_argv(&options, &config);\n+\t\ttrace2_region_enter_printf(\"fetch\", \"recurse-submodule\", the_repository, \"%s\", submodule_prefix);\n \t\tresult = fetch_submodules(the_repository,\n \t\t\t\t\t  &options,\n \t\t\t\t\t  submodule_prefix,\n@@ -2478,6 +2494,7 @@ int cmd_fetch(int argc, const char **argv, const char *prefix)\n \t\t\t\t\t  recurse_submodules_default,\n \t\t\t\t\t  verbosity < 0,\n \t\t\t\t\t  max_children);\n+\t\ttrace2_region_leave_printf(\"fetch\", \"recurse-submodule\", the_repository, \"%s\", submodule_prefix);\n \t\tstrvec_clear(&options);\n \t}\n \n@@ -2501,9 +2518,11 @@ int cmd_fetch(int argc, const char **argv, const char *prefix)\n \t\tif (progress)\n \t\t\tcommit_graph_flags |= COMMIT_GRAPH_WRITE_PROGRESS;\n \n+\t\ttrace2_region_enter(\"fetch\", \"write-commit-graph\", the_repository);\n \t\twrite_commit_graph_reachable(the_repository->objects->odb,\n \t\t\t\t\t     commit_graph_flags,\n \t\t\t\t\t     NULL);\n+\t\ttrace2_region_leave(\"fetch\", \"write-commit-graph\", the_repository);\n \t}\n \n \tif (enable_auto_gc) {\n-- \n2.46.0.184.g6999bdac58-goog\n\n"},{"id":"501037","messageId":"d57f258026f941e7bc05de8dac359fc1e2e42bee.1723747832.git.steadmon@google.com","threadId":"61957","inReplyTo":"cover.1723747832.git.steadmon@google.com","subject":"[PATCH 2/2] send-pack: add new tracing regions for push","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2024-08-15T18:51:13Z","receivedAt":"2024-08-15T18:51:19Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"From: Calvin Wan <calvinwan@google.com>\n\nAt $DAYJOB we experienced some slow pushes and needed additional trace\ndata to diagnose them.\n\nAdd trace2 regions for various sections of send_pack().\n\nSigned-off-by: Josh Steadmon <steadmon@google.com>\n---\n send-pack.c | 16 +++++++++++++---\n 1 file changed, 13 insertions(+), 3 deletions(-)\n\ndiff --git a/send-pack.c b/send-pack.c\nindex fa2f5eec17..de8ba46ad5 100644\n--- a/send-pack.c\n+++ b/send-pack.c\n@@ -512,8 +512,11 @@ int send_pack(struct send_pack_args *args,\n \t}\n \n \tgit_config_get_bool(\"push.negotiate\", &push_negotiate);\n-\tif (push_negotiate)\n+\tif (push_negotiate) {\n+\t\ttrace2_region_enter(\"send_pack\", \"push_negotiate\", the_repository);\n \t\tget_commons_through_negotiation(args->url, remote_refs, &commons);\n+\t\ttrace2_region_leave(\"send_pack\", \"push_negotiate\", the_repository);\n+\t}\n \n \tif (!git_config_get_bool(\"push.usebitmaps\", &use_bitmaps))\n \t\targs->disable_bitmaps = !use_bitmaps;\n@@ -641,10 +644,12 @@ int send_pack(struct send_pack_args *args,\n \t/*\n \t * Finally, tell the other end!\n \t */\n-\tif (!args->dry_run && push_cert_nonce)\n+\tif (!args->dry_run && push_cert_nonce) {\n+\t\ttrace2_region_enter(\"send_pack\", \"push_cert\", the_repository);\n \t\tcmds_sent = generate_push_cert(&req_buf, remote_refs, args,\n \t\t\t\t\t       cap_buf.buf, push_cert_nonce);\n-\telse if (!args->dry_run)\n+\t\ttrace2_region_leave(\"send_pack\", \"push_cert\", the_repository);\n+\t} else if (!args->dry_run) {\n \t\tfor (ref = remote_refs; ref; ref = ref->next) {\n \t\t\tchar *old_hex, *new_hex;\n \n@@ -664,6 +669,7 @@ int send_pack(struct send_pack_args *args,\n \t\t\t\t\t\t old_hex, new_hex, ref->name);\n \t\t\t}\n \t\t}\n+\t}\n \n \tif (use_push_options) {\n \t\tstruct string_list_item *item;\n@@ -686,6 +692,7 @@ int send_pack(struct send_pack_args *args,\n \tstrbuf_release(&cap_buf);\n \n \tif (use_sideband && cmds_sent) {\n+\t\ttrace2_region_enter(\"send_pack\", \"sideband_demux\", the_repository);\n \t\tmemset(&demux, 0, sizeof(demux));\n \t\tdemux.proc = sideband_demux;\n \t\tdemux.data = fd;\n@@ -719,6 +726,8 @@ int send_pack(struct send_pack_args *args,\n \t\t\tif (use_sideband) {\n \t\t\t\tclose(demux.out);\n \t\t\t\tfinish_async(&demux);\n+\t\t\t\tif (cmds_sent)\n+\t\t\t\t\ttrace2_region_leave(\"send_pack\", \"sideband_demux\", the_repository);\n \t\t\t}\n \t\t\tfd[1] = -1;\n \t\t\treturn -1;\n@@ -743,6 +752,7 @@ int send_pack(struct send_pack_args *args,\n \t\t\terror(\"error in sideband demultiplexer\");\n \t\t\tret = -1;\n \t\t}\n+\t\ttrace2_region_leave(\"send_pack\", \"sideband_demux\", the_repository);\n \t}\n \n \tif (ret < 0)\n-- \n2.46.0.184.g6999bdac58-goog\n\n"},{"id":"501041","messageId":"xmqqh6blsh43.fsf@gitster.g","threadId":"61957","inReplyTo":"c0481f85f8166e520c387f9e9157b142b93d933c.1723747832.git.steadmon@google.com","subject":"Re: [PATCH 1/2] fetch: add top-level trace2 regions","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2024-08-15T19:47:40Z","receivedAt":"2024-08-15T19:47:43Z","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> -\tif (!git_config_get_string_tmp(\"fetch.bundleuri\", &bundle_uri) &&\n> -\t    fetch_bundle_uri(the_repository, bundle_uri, NULL))\n> -\t\twarning(_(\"failed to fetch bundles from '%s'\"), bundle_uri);\n> +\tif (!git_config_get_string_tmp(\"fetch.bundleuri\", &bundle_uri)) {\n> +\t\tint result = 0;\n\nThis needs no initialization.\n\n> +\t\ttrace2_region_enter(\"fetch\", \"fetch-bundle-uri\", the_repository);\n> +\t\tresult = fetch_bundle_uri(the_repository, bundle_uri, NULL);\n> +\t\ttrace2_region_leave(\"fetch\", \"fetch-bundle-uri\", the_repository);\n> +\t\tif (result)\n> +\t\t\twarning(_(\"failed to fetch bundles from '%s'\"), bundle_uri);\n> +\t}\n\nIt is a bit sad that the concise original with straight-forward\ncontrol flow had to be butchered like this to sprinkle tracing code\nin it, but I guess that cannot be helped?  I wonder if it becomes\nmuch less invasive and more future proof to define the trace region\nin the fetch_bundle_uri() function itself.  Has it been considered?\n\n> @@ -2407,6 +2412,7 @@ int cmd_fetch(int argc, const char **argv, const char *prefix)\n>  \t\tstruct oidset_iter iter;\n>  \t\tconst struct object_id *oid;\n>  \n> +\t\ttrace2_region_enter(\"fetch\", \"negotiate-only\", the_repository);\n>  \t\tif (!remote)\n>  \t\t\tdie(_(\"must supply remote when using --negotiate-only\"));\n>  \t\tgtransport = prepare_transport(remote, 1);\n> @@ -2415,6 +2421,7 @@ int cmd_fetch(int argc, const char **argv, const char *prefix)\n>  \t\t} else {\n>  \t\t\twarning(_(\"protocol does not support --negotiate-only, exiting\"));\n>  \t\t\tresult = 1;\n> +\t\t\ttrace2_region_leave(\"fetch\", \"negotiate-only\", the_repository);\n>  \t\t\tgoto cleanup;\n>  \t\t}\n>  \t\tif (server_options.nr)\n> @@ -2425,11 +2432,17 @@ int cmd_fetch(int argc, const char **argv, const char *prefix)\n>  \t\twhile ((oid = oidset_iter_next(&iter)))\n>  \t\t\tprintf(\"%s\\n\", oid_to_hex(oid));\n>  \t\toidset_clear(&acked_commits);\n> +\t\ttrace2_region_leave(\"fetch\", \"negotiate-only\", the_repository);\n\nOK.  Both error path and normal path we leave the region we entered.\n\nA complete tangent, but do we have an automated test or code\nanalysis that catches us if we forget to leave an entered region\n(i.e., imagine we didn't leave in the else clause after issuing the\nwarning---we remain in the region in such an error case, even though\nnormally we leave the region correctly)?\n\n>  \t} else if (remote) {\n> -\t\tif (filter_options.choice || repo_has_promisor_remote(the_repository))\n> +\t\tif (filter_options.choice || repo_has_promisor_remote(the_repository)) {\n> +\t\t\ttrace2_region_enter(\"fetch\", \"setup-partial\", the_repository);\n>  \t\t\tfetch_one_setup_partial(remote);\n> +\t\t\ttrace2_region_leave(\"fetch\", \"setup-partial\", the_repository);\n> +\t\t}\n\nOK.  That's nice and straight-forward.\n\n> +\t\ttrace2_region_enter(\"fetch\", \"fetch-one\", the_repository);\n>  \t\tresult = fetch_one(remote, argc, argv, prune_tags_ok, stdin_refspecs,\n>  \t\t\t\t   &config);\n> +\t\ttrace2_region_leave(\"fetch\", \"fetch-one\", the_repository);\n\nThis one, too.\n> @@ -2449,7 +2462,9 @@ int cmd_fetch(int argc, const char **argv, const char *prefix)\n>  \t\t\tmax_children = config.parallel;\n>  \n>  \t\t/* TODO should this also die if we have a previous partial-clone? */\n> +\t\ttrace2_region_enter(\"fetch\", \"fetch-multiple\", the_repository);\n>  \t\tresult = fetch_multiple(&list, max_children, &config);\n> +\t\ttrace2_region_leave(\"fetch\", \"fetch-multiple\", the_repository);\n\nSo is this.\n\n> @@ -2471,6 +2486,7 @@ int cmd_fetch(int argc, const char **argv, const char *prefix)\n>  \t\t\tmax_children = config.parallel;\n>  \n>  \t\tadd_options_to_argv(&options, &config);\n> +\t\ttrace2_region_enter_printf(\"fetch\", \"recurse-submodule\", the_repository, \"%s\", submodule_prefix);\n>  \t\tresult = fetch_submodules(the_repository,\n>  \t\t\t\t\t  &options,\n>  \t\t\t\t\t  submodule_prefix,\n> @@ -2478,6 +2494,7 @@ int cmd_fetch(int argc, const char **argv, const char *prefix)\n>  \t\t\t\t\t  recurse_submodules_default,\n>  \t\t\t\t\t  verbosity < 0,\n>  \t\t\t\t\t  max_children);\n> +\t\ttrace2_region_leave_printf(\"fetch\", \"recurse-submodule\", the_repository, \"%s\", submodule_prefix);\n>  \t\tstrvec_clear(&options);\n>  \t}\n\nDitto.\n\n> @@ -2501,9 +2518,11 @@ int cmd_fetch(int argc, const char **argv, const char *prefix)\n>  \t\tif (progress)\n>  \t\t\tcommit_graph_flags |= COMMIT_GRAPH_WRITE_PROGRESS;\n>  \n> +\t\ttrace2_region_enter(\"fetch\", \"write-commit-graph\", the_repository);\n>  \t\twrite_commit_graph_reachable(the_repository->objects->odb,\n>  \t\t\t\t\t     commit_graph_flags,\n>  \t\t\t\t\t     NULL);\n> +\t\ttrace2_region_leave(\"fetch\", \"write-commit-graph\", the_repository);\n\nOK.\n"},{"id":"501043","messageId":"xmqq8qwxsg8w.fsf@gitster.g","threadId":"61957","inReplyTo":"d57f258026f941e7bc05de8dac359fc1e2e42bee.1723747832.git.steadmon@google.com","subject":"Re: [PATCH 2/2] send-pack: add new tracing regions for push","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2024-08-15T20:06:23Z","receivedAt":"2024-08-15T20:06:28Z","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> From: Calvin Wan <calvinwan@google.com>\n>\n> At $DAYJOB we experienced some slow pushes and needed additional trace\n> data to diagnose them.\n>\n> Add trace2 regions for various sections of send_pack().\n>\n> Signed-off-by: Josh Steadmon <steadmon@google.com>\n> ---\n>  send-pack.c | 16 +++++++++++++---\n>  1 file changed, 13 insertions(+), 3 deletions(-)\n>\n> diff --git a/send-pack.c b/send-pack.c\n> index fa2f5eec17..de8ba46ad5 100644\n> --- a/send-pack.c\n> +++ b/send-pack.c\n> @@ -512,8 +512,11 @@ int send_pack(struct send_pack_args *args,\n>  \t}\n>  \n>  \tgit_config_get_bool(\"push.negotiate\", &push_negotiate);\n> -\tif (push_negotiate)\n> +\tif (push_negotiate) {\n> +\t\ttrace2_region_enter(\"send_pack\", \"push_negotiate\", the_repository);\n>  \t\tget_commons_through_negotiation(args->url, remote_refs, &commons);\n> +\t\ttrace2_region_leave(\"send_pack\", \"push_negotiate\", the_repository);\n> +\t}\n\n> @@ -641,10 +644,12 @@ int send_pack(struct send_pack_args *args,\n>  \t/*\n>  \t * Finally, tell the other end!\n>  \t */\n> -\tif (!args->dry_run && push_cert_nonce)\n> +\tif (!args->dry_run && push_cert_nonce) {\n> +\t\ttrace2_region_enter(\"send_pack\", \"push_cert\", the_repository);\n>  \t\tcmds_sent = generate_push_cert(&req_buf, remote_refs, args,\n>  \t\t\t\t\t       cap_buf.buf, push_cert_nonce);\n> -\telse if (!args->dry_run)\n> +\t\ttrace2_region_leave(\"send_pack\", \"push_cert\", the_repository);\n> +\t} else if (!args->dry_run) {\n\nMisleading \"diff\" but this is correct.\n\nBut makes me wonder if we really want to express these (and other\nevents we saw in [PATCH 1/2]) as regions we enter and leave.\nPresumably we would generate a certificate instantly, compared to\nall the other things happening in this process, like talking over\nthe network, waiting for the other end, and packing the payload, and\nI suspect that the single bit the debuggers would want to learn from\nthe trace is \"did we get asked to give a certificate?\".\nSandwitching a rather expensive operation inside a pair of\nenter/leave would give us a way to measure how long that operation\ntook in exchanges for one extra trace log entry, and \"ah, we need to\nfirst fetch the bundle and process it\" we saw in [PATCH 1/2] is\nsomething that is worth timing, but I am finding a bit hard to\nbelieve it is worth doing for push cert generation.  It is\nunderstandable if there weren't any suitable mechanism to simply log\n\"the control passed at this spot at this time\" kind of event in the\ntrace2 subsystem, but I do not think it is the case.\n\n> @@ -686,6 +692,7 @@ int send_pack(struct send_pack_args *args,\n>  \tstrbuf_release(&cap_buf);\n>  \n>  \tif (use_sideband && cmds_sent) {\n> +\t\ttrace2_region_enter(\"send_pack\", \"sideband_demux\", the_repository);\n>  \t\tmemset(&demux, 0, sizeof(demux));\n>  \t\tdemux.proc = sideband_demux;\n>  \t\tdemux.data = fd;\n> @@ -719,6 +726,8 @@ int send_pack(struct send_pack_args *args,\n>  \t\t\tif (use_sideband) {\n>  \t\t\t\tclose(demux.out);\n>  \t\t\t\tfinish_async(&demux);\n> +\t\t\t\tif (cmds_sent)\n> +\t\t\t\t\ttrace2_region_leave(\"send_pack\", \"sideband_demux\", the_repository);\n>  \t\t\t}\n>  \t\t\tfd[1] = -1;\n>  \t\t\treturn -1;\n> @@ -743,6 +752,7 @@ int send_pack(struct send_pack_args *args,\n>  \t\t\terror(\"error in sideband demultiplexer\");\n>  \t\t\tret = -1;\n>  \t\t}\n> +\t\ttrace2_region_leave(\"send_pack\", \"sideband_demux\", the_repository);\n>  \t}\n\nThis is also dubious.  When sideband is in effect, this records the\nfact that we did ran pack-objects and allows as to measure how much\ntime it was spent.  But on a connection without sideband enabled, it\ndoes not record anything.  But if we start the region a line sooner,\nand finish the region a line later, we should be able to record the\nsame facts even for a connection without sideband enabled.  I also\nfind the name given to this region ultra-iffy.  Is it so important\nthat sideband_demux was used to communicate with the other end that\nreceived the data our pack_objects() produced that the word\n\"sideband_demux\" deserves to be in the name of the region, more than\nthe fact that this is the crux of sending pack data from us to them\n(i.e. the main part of the \"send-pack\")?\n\n"},{"id":"501295","messageId":"erfaq73yp2w2kblymuuohxuj535j5dixdildwhnomv7sfcd2z2@gbtrvnztgkgj","threadId":"61957","inReplyTo":"xmqqh6blsh43.fsf@gitster.g","subject":"Re: [PATCH 1/2] fetch: add top-level trace2 regions","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2024-08-19T18:26:13Z","receivedAt":"2024-08-19T18:26:20Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"On 2024.08.15 12:47, Junio C Hamano wrote:\n> Josh Steadmon <steadmon@google.com> writes:\n> \n> > -\tif (!git_config_get_string_tmp(\"fetch.bundleuri\", &bundle_uri) &&\n> > -\t    fetch_bundle_uri(the_repository, bundle_uri, NULL))\n> > -\t\twarning(_(\"failed to fetch bundles from '%s'\"), bundle_uri);\n> > +\tif (!git_config_get_string_tmp(\"fetch.bundleuri\", &bundle_uri)) {\n> > +\t\tint result = 0;\n> \n> This needs no initialization.\n> \n> > +\t\ttrace2_region_enter(\"fetch\", \"fetch-bundle-uri\", the_repository);\n> > +\t\tresult = fetch_bundle_uri(the_repository, bundle_uri, NULL);\n> > +\t\ttrace2_region_leave(\"fetch\", \"fetch-bundle-uri\", the_repository);\n> > +\t\tif (result)\n> > +\t\t\twarning(_(\"failed to fetch bundles from '%s'\"), bundle_uri);\n> > +\t}\n> \n> It is a bit sad that the concise original with straight-forward\n> control flow had to be butchered like this to sprinkle tracing code\n> in it, but I guess that cannot be helped?  I wonder if it becomes\n> much less invasive and more future proof to define the trace region\n> in the fetch_bundle_uri() function itself.  Has it been considered?\n\nMoved to fetch_bundle_uri() in v2.\n\n\n> > @@ -2407,6 +2412,7 @@ int cmd_fetch(int argc, const char **argv, const char *prefix)\n> >  \t\tstruct oidset_iter iter;\n> >  \t\tconst struct object_id *oid;\n> >  \n> > +\t\ttrace2_region_enter(\"fetch\", \"negotiate-only\", the_repository);\n> >  \t\tif (!remote)\n> >  \t\t\tdie(_(\"must supply remote when using --negotiate-only\"));\n> >  \t\tgtransport = prepare_transport(remote, 1);\n> > @@ -2415,6 +2421,7 @@ int cmd_fetch(int argc, const char **argv, const char *prefix)\n> >  \t\t} else {\n> >  \t\t\twarning(_(\"protocol does not support --negotiate-only, exiting\"));\n> >  \t\t\tresult = 1;\n> > +\t\t\ttrace2_region_leave(\"fetch\", \"negotiate-only\", the_repository);\n> >  \t\t\tgoto cleanup;\n> >  \t\t}\n> >  \t\tif (server_options.nr)\n> > @@ -2425,11 +2432,17 @@ int cmd_fetch(int argc, const char **argv, const char *prefix)\n> >  \t\twhile ((oid = oidset_iter_next(&iter)))\n> >  \t\t\tprintf(\"%s\\n\", oid_to_hex(oid));\n> >  \t\toidset_clear(&acked_commits);\n> > +\t\ttrace2_region_leave(\"fetch\", \"negotiate-only\", the_repository);\n> \n> OK.  Both error path and normal path we leave the region we entered.\n> \n> A complete tangent, but do we have an automated test or code\n> analysis that catches us if we forget to leave an entered region\n> (i.e., imagine we didn't leave in the else clause after issuing the\n> warning---we remain in the region in such an error case, even though\n> normally we leave the region correctly)?\n\nIt's been discussed before [1], but the general feeling seems to be that\nit's not worth the effort / test runtime.\n\n[1] https://lore.kernel.org/git/xmqqbka27zu9.fsf@gitster.g/\n"},{"id":"501561","messageId":"jjnfnxuozlsguonviswt23simi4gwqjaetcm7b7wn7kndk6o4t@7p4dedarn6xt","threadId":"61957","inReplyTo":"xmqq8qwxsg8w.fsf@gitster.g","subject":"Re: [PATCH 2/2] send-pack: add new tracing regions for push","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2024-08-22T20:20:46Z","receivedAt":"2024-08-22T20:20:53Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"On 2024.08.15 13:06, Junio C Hamano wrote:\n> Josh Steadmon <steadmon@google.com> writes:\n> \n> > From: Calvin Wan <calvinwan@google.com>\n> >\n> > At $DAYJOB we experienced some slow pushes and needed additional trace\n> > data to diagnose them.\n> >\n> > Add trace2 regions for various sections of send_pack().\n> >\n> > Signed-off-by: Josh Steadmon <steadmon@google.com>\n> > ---\n> >  send-pack.c | 16 +++++++++++++---\n> >  1 file changed, 13 insertions(+), 3 deletions(-)\n> >\n> > diff --git a/send-pack.c b/send-pack.c\n> > index fa2f5eec17..de8ba46ad5 100644\n> > --- a/send-pack.c\n> > +++ b/send-pack.c\n> > @@ -512,8 +512,11 @@ int send_pack(struct send_pack_args *args,\n> >  \t}\n> >  \n> >  \tgit_config_get_bool(\"push.negotiate\", &push_negotiate);\n> > -\tif (push_negotiate)\n> > +\tif (push_negotiate) {\n> > +\t\ttrace2_region_enter(\"send_pack\", \"push_negotiate\", the_repository);\n> >  \t\tget_commons_through_negotiation(args->url, remote_refs, &commons);\n> > +\t\ttrace2_region_leave(\"send_pack\", \"push_negotiate\", the_repository);\n> > +\t}\n> \n> > @@ -641,10 +644,12 @@ int send_pack(struct send_pack_args *args,\n> >  \t/*\n> >  \t * Finally, tell the other end!\n> >  \t */\n> > -\tif (!args->dry_run && push_cert_nonce)\n> > +\tif (!args->dry_run && push_cert_nonce) {\n> > +\t\ttrace2_region_enter(\"send_pack\", \"push_cert\", the_repository);\n> >  \t\tcmds_sent = generate_push_cert(&req_buf, remote_refs, args,\n> >  \t\t\t\t\t       cap_buf.buf, push_cert_nonce);\n> > -\telse if (!args->dry_run)\n> > +\t\ttrace2_region_leave(\"send_pack\", \"push_cert\", the_repository);\n> > +\t} else if (!args->dry_run) {\n> \n> Misleading \"diff\" but this is correct.\n> \n> But makes me wonder if we really want to express these (and other\n> events we saw in [PATCH 1/2]) as regions we enter and leave.\n> Presumably we would generate a certificate instantly, compared to\n> all the other things happening in this process, like talking over\n> the network, waiting for the other end, and packing the payload, and\n> I suspect that the single bit the debuggers would want to learn from\n> the trace is \"did we get asked to give a certificate?\".\n> Sandwitching a rather expensive operation inside a pair of\n> enter/leave would give us a way to measure how long that operation\n> took in exchanges for one extra trace log entry, and \"ah, we need to\n> first fetch the bundle and process it\" we saw in [PATCH 1/2] is\n> something that is worth timing, but I am finding a bit hard to\n> believe it is worth doing for push cert generation.  It is\n> understandable if there weren't any suitable mechanism to simply log\n> \"the control passed at this spot at this time\" kind of event in the\n> trace2 subsystem, but I do not think it is the case.\n\nAck, changed this to a \"trace2_printf()\" instead. Annoyingly the JSON\nEvent trace2 target that we use at $DAYJOB doesn't log these events, but\nI can add another patch to enable that.\n\n\n> > @@ -686,6 +692,7 @@ int send_pack(struct send_pack_args *args,\n> >  \tstrbuf_release(&cap_buf);\n> >  \n> >  \tif (use_sideband && cmds_sent) {\n> > +\t\ttrace2_region_enter(\"send_pack\", \"sideband_demux\", the_repository);\n> >  \t\tmemset(&demux, 0, sizeof(demux));\n> >  \t\tdemux.proc = sideband_demux;\n> >  \t\tdemux.data = fd;\n> > @@ -719,6 +726,8 @@ int send_pack(struct send_pack_args *args,\n> >  \t\t\tif (use_sideband) {\n> >  \t\t\t\tclose(demux.out);\n> >  \t\t\t\tfinish_async(&demux);\n> > +\t\t\t\tif (cmds_sent)\n> > +\t\t\t\t\ttrace2_region_leave(\"send_pack\", \"sideband_demux\", the_repository);\n> >  \t\t\t}\n> >  \t\t\tfd[1] = -1;\n> >  \t\t\treturn -1;\n> > @@ -743,6 +752,7 @@ int send_pack(struct send_pack_args *args,\n> >  \t\t\terror(\"error in sideband demultiplexer\");\n> >  \t\t\tret = -1;\n> >  \t\t}\n> > +\t\ttrace2_region_leave(\"send_pack\", \"sideband_demux\", the_repository);\n> >  \t}\n> \n> This is also dubious.  When sideband is in effect, this records the\n> fact that we did ran pack-objects and allows as to measure how much\n> time it was spent.  But on a connection without sideband enabled, it\n> does not record anything.  But if we start the region a line sooner,\n> and finish the region a line later, we should be able to record the\n> same facts even for a connection without sideband enabled.  I also\n> find the name given to this region ultra-iffy.  Is it so important\n> that sideband_demux was used to communicate with the other end that\n> received the data our pack_objects() produced that the word\n> \"sideband_demux\" deserves to be in the name of the region, more than\n> the fact that this is the crux of sending pack data from us to them\n> (i.e. the main part of the \"send-pack\")?\n\nYeah, thanks, this did need to be reworked. I pushed the regions down\ninto pack_objects() and receive_status(), which look like the only two\nplaces we might spend much time.\n"},{"id":"501562","messageId":"xmqq5xrsqozg.fsf@gitster.g","threadId":"61957","inReplyTo":"jjnfnxuozlsguonviswt23simi4gwqjaetcm7b7wn7kndk6o4t@7p4dedarn6xt","subject":"Re: [PATCH 2/2] send-pack: add new tracing regions for push","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2024-08-22T20:30:59Z","receivedAt":"2024-08-22T20:31:02Z","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>> ... understandable if there weren't any suitable mechanism to simply log\n>> \"the control passed at this spot at this time\" kind of event in the\n>> trace2 subsystem, but I do not think it is the case.\n>\n> Ack, changed this to a \"trace2_printf()\" instead. Annoyingly the JSON\n> Event trace2 target that we use at $DAYJOB doesn't log these events, but\n> I can add another patch to enable that.\n\nAhh, OK, I was concentrating solely on the producing side, and\nforgot to consider that the consuming side may not be prepared for\nnon enter/leave pair of events.  That's understandable, but if you\nare updating the consuming side to be able to do so, that would be\neven better.\n\n> Yeah, thanks, this did need to be reworked. I pushed the regions down\n> into pack_objects() and receive_status(), which look like the only two\n> places we might spend much time.\n\nSounds good.\n\nThis is a tangent, but I doubt we have many users without sideband\nsupport.  In the longer term we may be able to drop the non-sideband\ncodepath, which would automatically simplify the flow quite a bit\naround here.  But that is totally outside of this topic.\n\nThanks.\n"},{"id":"501564","messageId":"cover.1724363615.git.steadmon@google.com","threadId":"61957","inReplyTo":"cover.1723747832.git.steadmon@google.com","subject":"[PATCH v2 0/3] Add additional trace2 regions for fetch and push","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2024-08-22T21:57:44Z","receivedAt":"2024-08-22T21:57:50Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"Last year at $DAYJOB we were having issues with slow\nfetches/pulls/pushes. We added some additional trace2 regions which\nhelped us narrow down the issue to some server-side negotiation\nproblems. We've been carrying these patches downstream ever since, but\nthey might be useful to others as well.\n\nChanges in V2:\n\n* Added a new patch to implement trace2_printf() for event targets.\n\n* Move some fetch trace regions deeper in the call stack to simplify\n  control flow.\n\n* Move some push trace regions deeper in the call stack to target the\n  actual slow functions, and to not tie tracing to whether or not\n  sideband communication is used.\n\n\nCalvin Wan (1):\n  send-pack: add new tracing regions for push\n\nJosh Steadmon (2):\n  trace2: implement trace2_printf() for event target\n  fetch: add top-level trace2 regions\n\n Documentation/technical/api-trace2.txt | 17 +++++++++++++++--\n builtin/fetch.c                        | 16 +++++++++++++++-\n bundle-uri.c                           |  4 ++++\n send-pack.c                            | 16 +++++++++++++---\n trace2/tr2_tgt_event.c                 | 22 ++++++++++++++++++++--\n 5 files changed, 67 insertions(+), 8 deletions(-)\n\nbase-commit: 25673b1c476756ec0587fb0596ab3c22b96dc52a\n-- \n2.46.0.295.g3b9ea8a38a-goog\n\n"},{"id":"501565","messageId":"de27f45401f32bc43de2db42384b2dfa5c651b25.1724363615.git.steadmon@google.com","threadId":"61957","inReplyTo":"cover.1724363615.git.steadmon@google.com","subject":"[PATCH v2 1/3] trace2: implement trace2_printf() for event target","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2024-08-22T21:57:45Z","receivedAt":"2024-08-22T21:57:52Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"The trace2 event target does not have an implementation for\ntrace2_printf(). While the event target is for structured events, and\ntrace2_printf() is for unstructured, human-readable messages, it may\nstill be useful to wrap these unstructured messages in a structured JSON\nobject. Among other things, it may reduce confusion when manually\ndebugging using event trace data.\n\nAdd a simple implementation for the event target that wraps\ntrace2_printf() messages in a minimal JSON object. Document this in\nDocumentation/technical/api-trace2.txt, and bump the event format\nversion since we're adding a new event type.\n\nSigned-off-by: Josh Steadmon <steadmon@google.com>\n---\n Documentation/technical/api-trace2.txt | 17 +++++++++++++++--\n trace2/tr2_tgt_event.c                 | 22 ++++++++++++++++++++--\n 2 files changed, 35 insertions(+), 4 deletions(-)\n\ndiff --git a/Documentation/technical/api-trace2.txt b/Documentation/technical/api-trace2.txt\nindex de5fc25059..5817b18310 100644\n--- a/Documentation/technical/api-trace2.txt\n+++ b/Documentation/technical/api-trace2.txt\n@@ -128,7 +128,7 @@ yields\n \n ------------\n $ cat ~/log.event\n-{\"event\":\"version\",\"sid\":\"20190408T191610.507018Z-H9b68c35f-P000059a8\",\"thread\":\"main\",\"time\":\"2019-01-16T17:28:42.620713Z\",\"file\":\"common-main.c\",\"line\":38,\"evt\":\"3\",\"exe\":\"2.20.1.155.g426c96fcdb\"}\n+{\"event\":\"version\",\"sid\":\"20190408T191610.507018Z-H9b68c35f-P000059a8\",\"thread\":\"main\",\"time\":\"2019-01-16T17:28:42.620713Z\",\"file\":\"common-main.c\",\"line\":38,\"evt\":\"4\",\"exe\":\"2.20.1.155.g426c96fcdb\"}\n {\"event\":\"start\",\"sid\":\"20190408T191610.507018Z-H9b68c35f-P000059a8\",\"thread\":\"main\",\"time\":\"2019-01-16T17:28:42.621027Z\",\"file\":\"common-main.c\",\"line\":39,\"t_abs\":0.001173,\"argv\":[\"git\",\"version\"]}\n {\"event\":\"cmd_name\",\"sid\":\"20190408T191610.507018Z-H9b68c35f-P000059a8\",\"thread\":\"main\",\"time\":\"2019-01-16T17:28:42.621122Z\",\"file\":\"git.c\",\"line\":432,\"name\":\"version\",\"hierarchy\":\"version\"}\n {\"event\":\"exit\",\"sid\":\"20190408T191610.507018Z-H9b68c35f-P000059a8\",\"thread\":\"main\",\"time\":\"2019-01-16T17:28:42.621236Z\",\"file\":\"git.c\",\"line\":662,\"t_abs\":0.001227,\"code\":0}\n@@ -344,7 +344,7 @@ only present on the \"start\" and \"atexit\" events.\n {\n \t\"event\":\"version\",\n \t...\n-\t\"evt\":\"3\",\t\t       # EVENT format version\n+\t\"evt\":\"4\",\t\t       # EVENT format version\n \t\"exe\":\"2.20.1.155.g426c96fcdb\" # git version\n }\n ------------\n@@ -835,6 +835,19 @@ The \"value\" field may be an integer or a string.\n }\n ------------\n \n+`\"printf\"`::\n+\tThis event logs a human-readable message with no particular formatting\n+\tguidelines.\n++\n+------------\n+{\n+\t\"event\":\"printf\",\n+\t...\n+\t\"t_abs\":0.015905,      # elapsed time in seconds\n+\t\"msg\":\"Hello world\"    # optional\n+}\n+------------\n+\n \n == Example Trace2 API Usage\n \ndiff --git a/trace2/tr2_tgt_event.c b/trace2/tr2_tgt_event.c\nindex 59910a1a4f..45b0850a5e 100644\n--- a/trace2/tr2_tgt_event.c\n+++ b/trace2/tr2_tgt_event.c\n@@ -24,7 +24,7 @@ static struct tr2_dst tr2dst_event = {\n  * a new field to an existing event, do not require an increment to the EVENT\n  * format version.\n  */\n-#define TR2_EVENT_VERSION \"3\"\n+#define TR2_EVENT_VERSION \"4\"\n \n /*\n  * Region nesting limit for messages written to the event target.\n@@ -622,6 +622,24 @@ static void fn_data_json_fl(const char *file, int line,\n \t}\n }\n \n+static void fn_printf_va_fl(const char *file, int line,\n+\t\t\t    uint64_t us_elapsed_absolute,\n+\t\t\t    const char *fmt, va_list ap)\n+{\n+\tconst char *event_name = \"printf\";\n+\tstruct json_writer jw = JSON_WRITER_INIT;\n+\tdouble t_abs = (double)us_elapsed_absolute / 1000000.0;\n+\n+\tjw_object_begin(&jw, 0);\n+\tevent_fmt_prepare(event_name, file, line, NULL, &jw);\n+\tjw_object_double(&jw, \"t_abs\", 6, t_abs);\n+\tmaybe_add_string_va(&jw, \"msg\", fmt, ap);\n+\tjw_end(&jw);\n+\n+\ttr2_dst_write_line(&tr2dst_event, &jw.json);\n+\tjw_release(&jw);\n+}\n+\n static void fn_timer(const struct tr2_timer_metadata *meta,\n \t\t     const struct tr2_timer *timer,\n \t\t     int is_final_data)\n@@ -694,7 +712,7 @@ struct tr2_tgt tr2_tgt_event = {\n \t.pfn_region_leave_printf_va_fl = fn_region_leave_printf_va_fl,\n \t.pfn_data_fl = fn_data_fl,\n \t.pfn_data_json_fl = fn_data_json_fl,\n-\t.pfn_printf_va_fl = NULL,\n+\t.pfn_printf_va_fl = fn_printf_va_fl,\n \t.pfn_timer = fn_timer,\n \t.pfn_counter = fn_counter,\n };\n-- \n2.46.0.295.g3b9ea8a38a-goog\n\n"},{"id":"501566","messageId":"acaa72cad30172f707a8706a7e0fd0131ea4b6fc.1724363615.git.steadmon@google.com","threadId":"61957","inReplyTo":"cover.1724363615.git.steadmon@google.com","subject":"[PATCH v2 2/3] fetch: add top-level trace2 regions","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2024-08-22T21:57:46Z","receivedAt":"2024-08-22T21:57:53Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"At $DAYJOB we experienced some slow fetch operations and needed some\nadditional data to help diagnose the issue.\n\nAdd top-level trace2 regions for the various modes of operation of\n`git-fetch`. None of these regions are in recursive code, so any\nenclosed trace messages should only see their nesting level increase by\none.\n\nSigned-off-by: Josh Steadmon <steadmon@google.com>\n---\n builtin/fetch.c | 16 +++++++++++++++-\n bundle-uri.c    |  4 ++++\n 2 files changed, 19 insertions(+), 1 deletion(-)\n\ndiff --git a/builtin/fetch.c b/builtin/fetch.c\nindex 693f02b958..9e20a41d2a 100644\n--- a/builtin/fetch.c\n+++ b/builtin/fetch.c\n@@ -2407,6 +2407,7 @@ int cmd_fetch(int argc, const char **argv, const char *prefix)\n \t\tstruct oidset_iter iter;\n \t\tconst struct object_id *oid;\n \n+\t\ttrace2_region_enter(\"fetch\", \"negotiate-only\", the_repository);\n \t\tif (!remote)\n \t\t\tdie(_(\"must supply remote when using --negotiate-only\"));\n \t\tgtransport = prepare_transport(remote, 1);\n@@ -2415,6 +2416,7 @@ int cmd_fetch(int argc, const char **argv, const char *prefix)\n \t\t} else {\n \t\t\twarning(_(\"protocol does not support --negotiate-only, exiting\"));\n \t\t\tresult = 1;\n+\t\t\ttrace2_region_leave(\"fetch\", \"negotiate-only\", the_repository);\n \t\t\tgoto cleanup;\n \t\t}\n \t\tif (server_options.nr)\n@@ -2425,11 +2427,17 @@ int cmd_fetch(int argc, const char **argv, const char *prefix)\n \t\twhile ((oid = oidset_iter_next(&iter)))\n \t\t\tprintf(\"%s\\n\", oid_to_hex(oid));\n \t\toidset_clear(&acked_commits);\n+\t\ttrace2_region_leave(\"fetch\", \"negotiate-only\", the_repository);\n \t} else if (remote) {\n-\t\tif (filter_options.choice || repo_has_promisor_remote(the_repository))\n+\t\tif (filter_options.choice || repo_has_promisor_remote(the_repository)) {\n+\t\t\ttrace2_region_enter(\"fetch\", \"setup-partial\", the_repository);\n \t\t\tfetch_one_setup_partial(remote);\n+\t\t\ttrace2_region_leave(\"fetch\", \"setup-partial\", the_repository);\n+\t\t}\n+\t\ttrace2_region_enter(\"fetch\", \"fetch-one\", the_repository);\n \t\tresult = fetch_one(remote, argc, argv, prune_tags_ok, stdin_refspecs,\n \t\t\t\t   &config);\n+\t\ttrace2_region_leave(\"fetch\", \"fetch-one\", the_repository);\n \t} else {\n \t\tint max_children = max_jobs;\n \n@@ -2449,7 +2457,9 @@ int cmd_fetch(int argc, const char **argv, const char *prefix)\n \t\t\tmax_children = config.parallel;\n \n \t\t/* TODO should this also die if we have a previous partial-clone? */\n+\t\ttrace2_region_enter(\"fetch\", \"fetch-multiple\", the_repository);\n \t\tresult = fetch_multiple(&list, max_children, &config);\n+\t\ttrace2_region_leave(\"fetch\", \"fetch-multiple\", the_repository);\n \t}\n \n \t/*\n@@ -2471,6 +2481,7 @@ int cmd_fetch(int argc, const char **argv, const char *prefix)\n \t\t\tmax_children = config.parallel;\n \n \t\tadd_options_to_argv(&options, &config);\n+\t\ttrace2_region_enter_printf(\"fetch\", \"recurse-submodule\", the_repository, \"%s\", submodule_prefix);\n \t\tresult = fetch_submodules(the_repository,\n \t\t\t\t\t  &options,\n \t\t\t\t\t  submodule_prefix,\n@@ -2478,6 +2489,7 @@ int cmd_fetch(int argc, const char **argv, const char *prefix)\n \t\t\t\t\t  recurse_submodules_default,\n \t\t\t\t\t  verbosity < 0,\n \t\t\t\t\t  max_children);\n+\t\ttrace2_region_leave_printf(\"fetch\", \"recurse-submodule\", the_repository, \"%s\", submodule_prefix);\n \t\tstrvec_clear(&options);\n \t}\n \n@@ -2501,9 +2513,11 @@ int cmd_fetch(int argc, const char **argv, const char *prefix)\n \t\tif (progress)\n \t\t\tcommit_graph_flags |= COMMIT_GRAPH_WRITE_PROGRESS;\n \n+\t\ttrace2_region_enter(\"fetch\", \"write-commit-graph\", the_repository);\n \t\twrite_commit_graph_reachable(the_repository->objects->odb,\n \t\t\t\t\t     commit_graph_flags,\n \t\t\t\t\t     NULL);\n+\t\ttrace2_region_leave(\"fetch\", \"write-commit-graph\", the_repository);\n \t}\n \n \tif (enable_auto_gc) {\ndiff --git a/bundle-uri.c b/bundle-uri.c\nindex 1e0ee156ba..dc0c96955b 100644\n--- a/bundle-uri.c\n+++ b/bundle-uri.c\n@@ -13,6 +13,7 @@\n #include \"config.h\"\n #include \"fetch-pack.h\"\n #include \"remote.h\"\n+#include \"trace2.h\"\n \n static struct {\n \tenum bundle_list_heuristic heuristic;\n@@ -799,6 +800,8 @@ int fetch_bundle_uri(struct repository *r, const char *uri,\n \t\t.id = xstrdup(\"\"),\n \t};\n \n+\ttrace2_region_enter(\"fetch\", \"fetch-bundle-uri\", the_repository);\n+\n \tinit_bundle_list(&list);\n \n \t/*\n@@ -824,6 +827,7 @@ int fetch_bundle_uri(struct repository *r, const char *uri,\n \tfor_all_bundles_in_list(&list, unlink_bundle, NULL);\n \tclear_bundle_list(&list);\n \tclear_remote_bundle_info(&bundle, NULL);\n+\ttrace2_region_leave(\"fetch\", \"fetch-bundle-uri\", the_repository);\n \treturn result;\n }\n \n-- \n2.46.0.295.g3b9ea8a38a-goog\n\n"},{"id":"501567","messageId":"1927bb5b1f8c6486d49013fb216c4cd672fcfbc5.1724363615.git.steadmon@google.com","threadId":"61957","inReplyTo":"cover.1724363615.git.steadmon@google.com","subject":"[PATCH v2 3/3] send-pack: add new tracing regions for push","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2024-08-22T21:57:47Z","receivedAt":"2024-08-22T21:57:55Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"From: Calvin Wan <calvinwan@google.com>\n\nAt $DAYJOB we experienced some slow pushes and needed additional trace\ndata to diagnose them.\n\nAdd trace2 regions for various sections of send_pack().\n\nSigned-off-by: Josh Steadmon <steadmon@google.com>\n---\n send-pack.c | 16 +++++++++++++---\n 1 file changed, 13 insertions(+), 3 deletions(-)\n\ndiff --git a/send-pack.c b/send-pack.c\nindex fa2f5eec17..9666b2c995 100644\n--- a/send-pack.c\n+++ b/send-pack.c\n@@ -75,6 +75,7 @@ static int pack_objects(int fd, struct ref *refs, struct oid_array *advertised,\n \tint i;\n \tint rc;\n \n+\ttrace2_region_enter(\"send_pack\", \"pack_objects\", the_repository);\n \tstrvec_push(&po.args, \"pack-objects\");\n \tstrvec_push(&po.args, \"--all-progress-implied\");\n \tstrvec_push(&po.args, \"--revs\");\n@@ -146,8 +147,10 @@ static int pack_objects(int fd, struct ref *refs, struct oid_array *advertised,\n \t\t */\n \t\tif (rc > 128 && rc != 141)\n \t\t\terror(\"pack-objects died of signal %d\", rc - 128);\n+\t\ttrace2_region_leave(\"send_pack\", \"pack_objects\", the_repository);\n \t\treturn -1;\n \t}\n+\ttrace2_region_leave(\"send_pack\", \"pack_objects\", the_repository);\n \treturn 0;\n }\n \n@@ -170,6 +173,7 @@ static int receive_status(struct packet_reader *reader, struct ref *refs)\n \tint new_report = 0;\n \tint once = 0;\n \n+\ttrace2_region_enter(\"send_pack\", \"receive_status\", the_repository);\n \thint = NULL;\n \tret = receive_unpack_status(reader);\n \twhile (1) {\n@@ -268,6 +272,7 @@ static int receive_status(struct packet_reader *reader, struct ref *refs)\n \t\t\tnew_report = 1;\n \t\t}\n \t}\n+\ttrace2_region_leave(\"send_pack\", \"receive_status\", the_repository);\n \treturn ret;\n }\n \n@@ -512,8 +517,11 @@ int send_pack(struct send_pack_args *args,\n \t}\n \n \tgit_config_get_bool(\"push.negotiate\", &push_negotiate);\n-\tif (push_negotiate)\n+\tif (push_negotiate) {\n+\t\ttrace2_region_enter(\"send_pack\", \"push_negotiate\", the_repository);\n \t\tget_commons_through_negotiation(args->url, remote_refs, &commons);\n+\t\ttrace2_region_leave(\"send_pack\", \"push_negotiate\", the_repository);\n+\t}\n \n \tif (!git_config_get_bool(\"push.usebitmaps\", &use_bitmaps))\n \t\targs->disable_bitmaps = !use_bitmaps;\n@@ -641,10 +649,11 @@ int send_pack(struct send_pack_args *args,\n \t/*\n \t * Finally, tell the other end!\n \t */\n-\tif (!args->dry_run && push_cert_nonce)\n+\tif (!args->dry_run && push_cert_nonce) {\n \t\tcmds_sent = generate_push_cert(&req_buf, remote_refs, args,\n \t\t\t\t\t       cap_buf.buf, push_cert_nonce);\n-\telse if (!args->dry_run)\n+\t\ttrace2_printf(\"Generated push certificate\");\n+\t} else if (!args->dry_run) {\n \t\tfor (ref = remote_refs; ref; ref = ref->next) {\n \t\t\tchar *old_hex, *new_hex;\n \n@@ -664,6 +673,7 @@ int send_pack(struct send_pack_args *args,\n \t\t\t\t\t\t old_hex, new_hex, ref->name);\n \t\t\t}\n \t\t}\n+\t}\n \n \tif (use_push_options) {\n \t\tstruct string_list_item *item;\n-- \n2.46.0.295.g3b9ea8a38a-goog\n\n"},{"id":"501568","messageId":"xmqq1q2gqkdn.fsf@gitster.g","threadId":"61957","inReplyTo":"cover.1724363615.git.steadmon@google.com","subject":"Re: [PATCH v2 0/3] Add additional trace2 regions for fetch and push","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2024-08-22T22:10:28Z","receivedAt":"2024-08-22T22:10:31Z","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> Last year at $DAYJOB we were having issues with slow\n> fetches/pulls/pushes. We added some additional trace2 regions which\n> helped us narrow down the issue to some server-side negotiation\n> problems. We've been carrying these patches downstream ever since, but\n> they might be useful to others as well.\n\nThanks, will queue.\n\n"}]}