{"thread":{"id":"51961","subject":"[PATCH 0/2] add trace2 regions to fetch & push","startedAt":"2019-10-02T23:49:33Z","lastAt":"2019-10-08T04:18:29Z","messageCount":11,"participants":["Josh Steadmon","Jonathan Tan","Junio C Hamano"],"isPatch":true,"patchVersion":1,"patchTotal":2},"messages":[{"id":"383312","messageId":"cover.1570059953.git.steadmon@google.com","threadId":"51961","inReplyTo":null,"subject":"[PATCH 0/2] add trace2 regions to fetch & push","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2019-10-02T23:49:27Z","receivedAt":"2019-10-02T23:49:33Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"We'd like to collect better statistics about where the time is spent in\nfetches and pushes so that we can hopefully identify some areas for\nfuture optimization. So let's add some trace2 regions around some of the\nfetch/push phases so we can break down their timing.\n\nJosh Steadmon (2):\n fetch: add trace2 instrumentation\n push: add trace2 instrumentation\n\n builtin/fetch.c | 22 +++++++++++++++-------\n builtin/push.c | 2 ++\n fetch-pack.c | 13 ++++++++++++-\n transport.c | 14 ++++++++++++--\n 4 files changed, 41 insertions(+), 10 deletions(-)\n\n-- \n2.23.0.444.g18eeb5a265-goog\n\n"},{"id":"383313","messageId":"348b99edf3e736f11ea13793610f2e0433875fab.1570059953.git.steadmon@google.com","threadId":"51961","inReplyTo":"cover.1570059953.git.steadmon@google.com","subject":"[PATCH 1/2] fetch: add trace2 instrumentation","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2019-10-02T23:49:28Z","receivedAt":"2019-10-02T23:49:38Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"Add trace2 regions to fetch-pack.c and builtins/fetch.c to better track\ntime spent in the various phases of a fetch:\n\n* listing refs\n* negotiation for protocol versions v0-v2\n* fetching refs\n* consuming refs\n\nSigned-off-by: Josh Steadmon \n---\n builtin/fetch.c | 22 +++++++++++++++-------\n fetch-pack.c | 13 ++++++++++++-\n 2 files changed, 27 insertions(+), 8 deletions(-)\n\ndiff --git a/builtin/fetch.c b/builtin/fetch.c\nindex 67c0eb88c6..ee3dc085bb 100644\n--- a/builtin/fetch.c\n+++ b/builtin/fetch.c\n@@ -1071,8 +1071,11 @@ static int check_exist_and_connected(struct ref *ref_map)\n static int fetch_refs(struct transport *transport, struct ref *ref_map)\n {\n \tint ret = check_exist_and_connected(ref_map);\n-\tif (ret)\n+\tif (ret) {\n+\t\ttrace2_region_enter(\"fetch\", \"fetch_refs\", the_repository);\n \t\tret = transport_fetch_refs(transport, ref_map);\n+\t\ttrace2_region_leave(\"fetch\", \"fetch_refs\", the_repository);\n+\t}\n \tif (!ret)\n \t\t/*\n \t\t * Keep the new pack's \".keep\" file around to allow the caller\n@@ -1088,11 +1091,14 @@ static int consume_refs(struct transport *transport, struct ref *ref_map)\n {\n \tint connectivity_checked = transport->smart_options\n \t\t? transport->smart_options->connectivity_checked : 0;\n-\tint ret = store_updated_refs(transport->url,\n-\t\t\t\t transport->remote->name,\n-\t\t\t\t connectivity_checked,\n-\t\t\t\t ref_map);\n+\tint ret;\n+\ttrace2_region_enter(\"fetch\", \"consume_refs\", the_repository);\n+\tret = store_updated_refs(transport->url,\n+\t\t\t\t transport->remote->name,\n+\t\t\t\t connectivity_checked,\n+\t\t\t\t ref_map);\n \ttransport_unlock_pack(transport);\n+\ttrace2_region_leave(\"fetch\", \"consume_refs\", the_repository);\n \treturn ret;\n }\n \n@@ -1337,9 +1343,11 @@ static int do_fetch(struct transport *transport,\n \t\t\targv_array_push(&ref_prefixes, \"refs/tags/\");\n \t}\n \n-\tif (must_list_refs)\n+\tif (must_list_refs) {\n+\t\ttrace2_region_enter(\"fetch\", \"remote_refs\", the_repository);\n \t\tremote_refs = transport_get_remote_refs(transport, &ref_prefixes);\n-\telse\n+\t\ttrace2_region_leave(\"fetch\", \"remote_refs\", the_repository);\n+\t} else\n \t\tremote_refs = NULL;\n \n \targv_array_clear(&ref_prefixes);\ndiff --git a/fetch-pack.c b/fetch-pack.c\nindex 6ccc6294ea..c016eeab1d 100644\n--- a/fetch-pack.c\n+++ b/fetch-pack.c\n@@ -382,6 +382,7 @@ static int find_common(struct fetch_negotiator *negotiator,\n \t\tstate_len = 0;\n \t}\n \n+\ttrace2_region_enter(\"fetch-pack\", \"negotiation_v0_v1\", the_repository);\n \tflushes = 0;\n \tretval = -1;\n \tif (args->no_dependents)\n@@ -466,6 +467,7 @@ static int find_common(struct fetch_negotiator *negotiator,\n \t\t}\n \t}\n done:\n+\ttrace2_region_leave(\"fetch-pack\", \"negotiation_v0_v1\", the_repository);\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@@ -1378,7 +1380,7 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,\n \tenum fetch_state state = FETCH_CHECK_LOCAL;\n \tstruct oidset common = OIDSET_INIT;\n \tstruct packet_reader reader;\n-\tint in_vain = 0;\n+\tint in_vain = 0, negotiation_started = 0;\n \tint haves_to_send = INITIAL_FLUSH;\n \tstruct fetch_negotiator negotiator;\n \tfetch_negotiator_init(r, &negotiator);\n@@ -1421,6 +1423,12 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,\n \t\t\t}\n \t\t\tbreak;\n \t\tcase FETCH_SEND_REQUEST:\n+\t\t\tif (!negotiation_started) {\n+\t\t\t\tnegotiation_started = 1;\n+\t\t\t\ttrace2_region_enter(\"fetch-pack\",\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\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@@ -1444,6 +1452,9 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,\n \t\t\t}\n \t\t\tbreak;\n \t\tcase FETCH_GET_PACK:\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\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-- \n2.23.0.444.g18eeb5a265-goog\n\n"},{"id":"383314","messageId":"054936f40b8232516763ec90bf44ad50d86d7b65.1570059953.git.steadmon@google.com","threadId":"51961","inReplyTo":"cover.1570059953.git.steadmon@google.com","subject":"[PATCH 2/2] push: add trace2 instrumentation","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2019-10-02T23:49:29Z","receivedAt":"2019-10-02T23:49:40Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"Add trace2 regions in transport.c and builtin/push.c to better track\ntime spent in various phases of pushing:\n\n* Listing refs\n* Checking submodules\n* Pushing submodules\n* Pushing refs\n\nSigned-off-by: Josh Steadmon \n---\n builtin/push.c | 2 ++\n transport.c | 14 ++++++++++++--\n 2 files changed, 14 insertions(+), 2 deletions(-)\n\ndiff --git a/builtin/push.c b/builtin/push.c\nindex 3742daf7b0..cc1292a566 100644\n--- a/builtin/push.c\n+++ b/builtin/push.c\n@@ -357,8 +357,10 @@ static int push_with_options(struct transport *transport, struct refspec *rs,\n \n \tif (verbosity > 0)\n \t\tfprintf(stderr, _(\"Pushing to %s\\n\"), transport->url);\n+\ttrace2_region_enter(\"push\", \"transport_push\", the_repository);\n \terr = transport_push(the_repository, transport,\n \t\t\t rs, flags, &reject_reasons);\n+\ttrace2_region_leave(\"push\", \"transport_push\", the_repository);\n \tif (err != 0) {\n \t\tfprintf(stderr, \"%s\", push_get_color(PUSH_COLOR_ERROR));\n \t\terror(_(\"failed to push some refs to '%s'\"), transport->url);\ndiff --git a/transport.c b/transport.c\nindex ae558af944..f313f288de 100644\n--- a/transport.c\n+++ b/transport.c\n@@ -1145,8 +1145,10 @@ int transport_push(struct repository *r,\n \n \t\trefspec_ref_prefixes(rs, &ref_prefixes);\n \n+\t\ttrace2_region_enter(\"transport_push\", \"get_refs_list\", the_repository);\n \t\tremote_refs = transport->vtable->get_refs_list(transport, 1,\n \t\t\t\t\t\t\t &ref_prefixes);\n+\t\ttrace2_region_leave(\"transport_push\", \"get_refs_list\", the_repository);\n \n \t\targv_array_clear(&ref_prefixes);\n \n@@ -1182,6 +1184,7 @@ int transport_push(struct repository *r,\n \t\t\tstruct ref *ref = remote_refs;\n \t\t\tstruct oid_array commits = OID_ARRAY_INIT;\n \n+\t\t\ttrace2_region_enter(\"transport_push\", \"push_submodules\", the_repository);\n \t\t\tfor (; ref; ref = ref->next)\n \t\t\t\tif (!is_null_oid(&ref->new_oid))\n \t\t\t\t\toid_array_append(&commits,\n@@ -1194,9 +1197,11 @@ int transport_push(struct repository *r,\n \t\t\t\t\t\t transport->push_options,\n \t\t\t\t\t\t pretend)) {\n \t\t\t\toid_array_clear(&commits);\n+\t\t\t\ttrace2_region_leave(\"transport_push\", \"push_submodules\", the_repository);\n \t\t\t\tdie(_(\"failed to push all needed submodules\"));\n \t\t\t}\n \t\t\toid_array_clear(&commits);\n+\t\t\ttrace2_region_leave(\"transport_push\", \"push_submodules\", the_repository);\n \t\t}\n \n \t\tif (((flags & TRANSPORT_RECURSE_SUBMODULES_CHECK) ||\n@@ -1207,6 +1212,7 @@ int transport_push(struct repository *r,\n \t\t\tstruct string_list needs_pushing = STRING_LIST_INIT_DUP;\n \t\t\tstruct oid_array commits = OID_ARRAY_INIT;\n \n+\t\t\ttrace2_region_enter(\"transport_push\", \"check_submodules\", the_repository);\n \t\t\tfor (; ref; ref = ref->next)\n \t\t\t\tif (!is_null_oid(&ref->new_oid))\n \t\t\t\t\toid_array_append(&commits,\n@@ -1217,15 +1223,19 @@ int transport_push(struct repository *r,\n \t\t\t\t\t\t transport->remote->name,\n \t\t\t\t\t\t &needs_pushing)) {\n \t\t\t\toid_array_clear(&commits);\n+\t\t\t\ttrace2_region_leave(\"transport_push\", \"check_submodules\", the_repository);\n \t\t\t\tdie_with_unpushed_submodules(&needs_pushing);\n \t\t\t}\n \t\t\tstring_list_clear(&needs_pushing, 0);\n \t\t\toid_array_clear(&commits);\n+\t\t\ttrace2_region_leave(\"transport_push\", \"check_submodules\", the_repository);\n \t\t}\n \n-\t\tif (!(flags & TRANSPORT_RECURSE_SUBMODULES_ONLY))\n+\t\tif (!(flags & TRANSPORT_RECURSE_SUBMODULES_ONLY)) {\n+\t\t\ttrace2_region_enter(\"transport_push\", \"push_refs\", the_repository);\n \t\t\tpush_ret = transport->vtable->push_refs(transport, remote_refs, flags);\n-\t\telse\n+\t\t\ttrace2_region_leave(\"transport_push\", \"push_refs\", the_repository);\n+\t\t} else\n \t\t\tpush_ret = 0;\n \t\terr = push_had_errors(remote_refs);\n \t\tret = push_ret | err;\n-- \n2.23.0.444.g18eeb5a265-goog\n\n"},{"id":"383628","messageId":"20191007214644.236055-1-jonathantanmy@google.com","threadId":"51961","inReplyTo":"cover.1570059953.git.steadmon@google.com","subject":"Re: [PATCH 0/2] add trace2 regions to fetch & push","fromName":"Jonathan Tan","fromEmail":"jonathantanmy@google.com","sentAt":"2019-10-07T21:46:44Z","receivedAt":"2019-10-07T21:46:51Z","isPatch":true,"sender":{"key":"jonathantanmy@fastmail.com","avatar":null},"body":"> We'd like to collect better statistics about where the time is spent in\n> fetches and pushes so that we can hopefully identify some areas for\n> future optimization. So let's add some trace2 regions around some of the\n> fetch/push phases so we can break down their timing.\n\nThanks.\n\nPatch 1 looks good to me - different regions at the same level\n(builtin/fetch.c, so it will be just for \"git fetch\") and one specific\none just for negotiation, which has to be in fetch-pack.c because only\nthat file operates at that level.\n\nPatch 2 mostly looks good to me too - unlike fetch, a lot happens in\ntransport.c, so it's reasonable to put most of the regions there. One\ncomment: in transport_push(), should trace2_region_{enter,leave} take\n\"r\" instead of \"the_repository\"?\n"},{"id":"383632","messageId":"cover.1570487473.git.steadmon@google.com","threadId":"51961","inReplyTo":"cover.1570059953.git.steadmon@google.com","subject":"[PATCH v2 0/2] add trace2 regions to fetch & push","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2019-10-07T22:35:14Z","receivedAt":"2019-10-07T22:35:21Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"We'd like to collect better statistics about where the time is spent in\nfetches and pushes so that we can hopefully identify some areas for\nfuture optimization. So let's add some trace2 regions around some of the\nfetch/push phases so we can break down their timing.\n\nChanges since V1:\n* Use the repository struct argument in transport_push(), rather than\n the global the_repository.\n\nJosh Steadmon (2):\n fetch: add trace2 instrumentation\n push: add trace2 instrumentation\n\n builtin/fetch.c | 22 +++++++++++++++-------\n builtin/push.c | 2 ++\n fetch-pack.c | 13 ++++++++++++-\n transport.c | 14 ++++++++++++--\n 4 files changed, 41 insertions(+), 10 deletions(-)\n\nRange-diff against v1:\n1: 054936f40b ! 1: fe6108b6f9 push: add trace2 instrumentation\n @@ transport.c: int transport_push(struct repository *r,\n \n \t\trefspec_ref_prefixes(rs, &ref_prefixes);\n \n -+\t\ttrace2_region_enter(\"transport_push\", \"get_refs_list\", the_repository);\n ++\t\ttrace2_region_enter(\"transport_push\", \"get_refs_list\", r);\n \t\tremote_refs = transport->vtable->get_refs_list(transport, 1,\n \t\t\t\t\t\t\t &ref_prefixes);\n -+\t\ttrace2_region_leave(\"transport_push\", \"get_refs_list\", the_repository);\n ++\t\ttrace2_region_leave(\"transport_push\", \"get_refs_list\", r);\n \n \t\targv_array_clear(&ref_prefixes);\n \n @@ transport.c: int transport_push(struct repository *r,\n \t\t\tstruct ref *ref = remote_refs;\n \t\t\tstruct oid_array commits = OID_ARRAY_INIT;\n \n -+\t\t\ttrace2_region_enter(\"transport_push\", \"push_submodules\", the_repository);\n ++\t\t\ttrace2_region_enter(\"transport_push\", \"push_submodules\", r);\n \t\t\tfor (; ref; ref = ref->next)\n \t\t\t\tif (!is_null_oid(&ref->new_oid))\n \t\t\t\t\toid_array_append(&commits,\n @@ transport.c: int transport_push(struct repository *r,\n \t\t\t\t\t\t transport->push_options,\n \t\t\t\t\t\t pretend)) {\n \t\t\t\toid_array_clear(&commits);\n -+\t\t\t\ttrace2_region_leave(\"transport_push\", \"push_submodules\", the_repository);\n ++\t\t\t\ttrace2_region_leave(\"transport_push\", \"push_submodules\", r);\n \t\t\t\tdie(_(\"failed to push all needed submodules\"));\n \t\t\t}\n \t\t\toid_array_clear(&commits);\n -+\t\t\ttrace2_region_leave(\"transport_push\", \"push_submodules\", the_repository);\n ++\t\t\ttrace2_region_leave(\"transport_push\", \"push_submodules\", r);\n \t\t}\n \n \t\tif (((flags & TRANSPORT_RECURSE_SUBMODULES_CHECK) ||\n @@ transport.c: int transport_push(struct repository *r,\n \t\t\tstruct string_list needs_pushing = STRING_LIST_INIT_DUP;\n \t\t\tstruct oid_array commits = OID_ARRAY_INIT;\n \n -+\t\t\ttrace2_region_enter(\"transport_push\", \"check_submodules\", the_repository);\n ++\t\t\ttrace2_region_enter(\"transport_push\", \"check_submodules\", r);\n \t\t\tfor (; ref; ref = ref->next)\n \t\t\t\tif (!is_null_oid(&ref->new_oid))\n \t\t\t\t\toid_array_append(&commits,\n @@ transport.c: int transport_push(struct repository *r,\n \t\t\t\t\t\t transport->remote->name,\n \t\t\t\t\t\t &needs_pushing)) {\n \t\t\t\toid_array_clear(&commits);\n -+\t\t\t\ttrace2_region_leave(\"transport_push\", \"check_submodules\", the_repository);\n ++\t\t\t\ttrace2_region_leave(\"transport_push\", \"check_submodules\", r);\n \t\t\t\tdie_with_unpushed_submodules(&needs_pushing);\n \t\t\t}\n \t\t\tstring_list_clear(&needs_pushing, 0);\n \t\t\toid_array_clear(&commits);\n -+\t\t\ttrace2_region_leave(\"transport_push\", \"check_submodules\", the_repository);\n ++\t\t\ttrace2_region_leave(\"transport_push\", \"check_submodules\", r);\n \t\t}\n \n -\t\tif (!(flags & TRANSPORT_RECURSE_SUBMODULES_ONLY))\n +\t\tif (!(flags & TRANSPORT_RECURSE_SUBMODULES_ONLY)) {\n -+\t\t\ttrace2_region_enter(\"transport_push\", \"push_refs\", the_repository);\n ++\t\t\ttrace2_region_enter(\"transport_push\", \"push_refs\", r);\n \t\t\tpush_ret = transport->vtable->push_refs(transport, remote_refs, flags);\n -\t\telse\n -+\t\t\ttrace2_region_leave(\"transport_push\", \"push_refs\", the_repository);\n ++\t\t\ttrace2_region_leave(\"transport_push\", \"push_refs\", r);\n +\t\t} else\n \t\t\tpush_ret = 0;\n \t\terr = push_had_errors(remote_refs);\n-- \n2.23.0.581.g78d2f28ef7-goog\n\n"},{"id":"383633","messageId":"348b99edf3e736f11ea13793610f2e0433875fab.1570487473.git.steadmon@google.com","threadId":"51961","inReplyTo":"cover.1570487473.git.steadmon@google.com","subject":"[PATCH v2 1/2] fetch: add trace2 instrumentation","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2019-10-07T22:35:15Z","receivedAt":"2019-10-07T22:35:24Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"Add trace2 regions to fetch-pack.c and builtins/fetch.c to better track\ntime spent in the various phases of a fetch:\n\n* listing refs\n* negotiation for protocol versions v0-v2\n* fetching refs\n* consuming refs\n\nSigned-off-by: Josh Steadmon \n---\n builtin/fetch.c | 22 +++++++++++++++-------\n fetch-pack.c | 13 ++++++++++++-\n 2 files changed, 27 insertions(+), 8 deletions(-)\n\ndiff --git a/builtin/fetch.c b/builtin/fetch.c\nindex 67c0eb88c6..ee3dc085bb 100644\n--- a/builtin/fetch.c\n+++ b/builtin/fetch.c\n@@ -1071,8 +1071,11 @@ static int check_exist_and_connected(struct ref *ref_map)\n static int fetch_refs(struct transport *transport, struct ref *ref_map)\n {\n \tint ret = check_exist_and_connected(ref_map);\n-\tif (ret)\n+\tif (ret) {\n+\t\ttrace2_region_enter(\"fetch\", \"fetch_refs\", the_repository);\n \t\tret = transport_fetch_refs(transport, ref_map);\n+\t\ttrace2_region_leave(\"fetch\", \"fetch_refs\", the_repository);\n+\t}\n \tif (!ret)\n \t\t/*\n \t\t * Keep the new pack's \".keep\" file around to allow the caller\n@@ -1088,11 +1091,14 @@ static int consume_refs(struct transport *transport, struct ref *ref_map)\n {\n \tint connectivity_checked = transport->smart_options\n \t\t? transport->smart_options->connectivity_checked : 0;\n-\tint ret = store_updated_refs(transport->url,\n-\t\t\t\t transport->remote->name,\n-\t\t\t\t connectivity_checked,\n-\t\t\t\t ref_map);\n+\tint ret;\n+\ttrace2_region_enter(\"fetch\", \"consume_refs\", the_repository);\n+\tret = store_updated_refs(transport->url,\n+\t\t\t\t transport->remote->name,\n+\t\t\t\t connectivity_checked,\n+\t\t\t\t ref_map);\n \ttransport_unlock_pack(transport);\n+\ttrace2_region_leave(\"fetch\", \"consume_refs\", the_repository);\n \treturn ret;\n }\n \n@@ -1337,9 +1343,11 @@ static int do_fetch(struct transport *transport,\n \t\t\targv_array_push(&ref_prefixes, \"refs/tags/\");\n \t}\n \n-\tif (must_list_refs)\n+\tif (must_list_refs) {\n+\t\ttrace2_region_enter(\"fetch\", \"remote_refs\", the_repository);\n \t\tremote_refs = transport_get_remote_refs(transport, &ref_prefixes);\n-\telse\n+\t\ttrace2_region_leave(\"fetch\", \"remote_refs\", the_repository);\n+\t} else\n \t\tremote_refs = NULL;\n \n \targv_array_clear(&ref_prefixes);\ndiff --git a/fetch-pack.c b/fetch-pack.c\nindex 6ccc6294ea..c016eeab1d 100644\n--- a/fetch-pack.c\n+++ b/fetch-pack.c\n@@ -382,6 +382,7 @@ static int find_common(struct fetch_negotiator *negotiator,\n \t\tstate_len = 0;\n \t}\n \n+\ttrace2_region_enter(\"fetch-pack\", \"negotiation_v0_v1\", the_repository);\n \tflushes = 0;\n \tretval = -1;\n \tif (args->no_dependents)\n@@ -466,6 +467,7 @@ static int find_common(struct fetch_negotiator *negotiator,\n \t\t}\n \t}\n done:\n+\ttrace2_region_leave(\"fetch-pack\", \"negotiation_v0_v1\", the_repository);\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@@ -1378,7 +1380,7 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,\n \tenum fetch_state state = FETCH_CHECK_LOCAL;\n \tstruct oidset common = OIDSET_INIT;\n \tstruct packet_reader reader;\n-\tint in_vain = 0;\n+\tint in_vain = 0, negotiation_started = 0;\n \tint haves_to_send = INITIAL_FLUSH;\n \tstruct fetch_negotiator negotiator;\n \tfetch_negotiator_init(r, &negotiator);\n@@ -1421,6 +1423,12 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,\n \t\t\t}\n \t\t\tbreak;\n \t\tcase FETCH_SEND_REQUEST:\n+\t\t\tif (!negotiation_started) {\n+\t\t\t\tnegotiation_started = 1;\n+\t\t\t\ttrace2_region_enter(\"fetch-pack\",\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\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@@ -1444,6 +1452,9 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,\n \t\t\t}\n \t\t\tbreak;\n \t\tcase FETCH_GET_PACK:\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\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-- \n2.23.0.581.g78d2f28ef7-goog\n\n"},{"id":"383634","messageId":"fe6108b6f98247582f8819c89a76249d477c2df3.1570487473.git.steadmon@google.com","threadId":"51961","inReplyTo":"cover.1570487473.git.steadmon@google.com","subject":"[PATCH v2 2/2] push: add trace2 instrumentation","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2019-10-07T22:35:16Z","receivedAt":"2019-10-07T22:35:27Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"Add trace2 regions in transport.c and builtin/push.c to better track\ntime spent in various phases of pushing:\n\n* Listing refs\n* Checking submodules\n* Pushing submodules\n* Pushing refs\n\nSigned-off-by: Josh Steadmon \n---\n builtin/push.c | 2 ++\n transport.c | 14 ++++++++++++--\n 2 files changed, 14 insertions(+), 2 deletions(-)\n\ndiff --git a/builtin/push.c b/builtin/push.c\nindex 3742daf7b0..cc1292a566 100644\n--- a/builtin/push.c\n+++ b/builtin/push.c\n@@ -357,8 +357,10 @@ static int push_with_options(struct transport *transport, struct refspec *rs,\n \n \tif (verbosity > 0)\n \t\tfprintf(stderr, _(\"Pushing to %s\\n\"), transport->url);\n+\ttrace2_region_enter(\"push\", \"transport_push\", the_repository);\n \terr = transport_push(the_repository, transport,\n \t\t\t rs, flags, &reject_reasons);\n+\ttrace2_region_leave(\"push\", \"transport_push\", the_repository);\n \tif (err != 0) {\n \t\tfprintf(stderr, \"%s\", push_get_color(PUSH_COLOR_ERROR));\n \t\terror(_(\"failed to push some refs to '%s'\"), transport->url);\ndiff --git a/transport.c b/transport.c\nindex ae558af944..83379a037d 100644\n--- a/transport.c\n+++ b/transport.c\n@@ -1145,8 +1145,10 @@ int transport_push(struct repository *r,\n \n \t\trefspec_ref_prefixes(rs, &ref_prefixes);\n \n+\t\ttrace2_region_enter(\"transport_push\", \"get_refs_list\", r);\n \t\tremote_refs = transport->vtable->get_refs_list(transport, 1,\n \t\t\t\t\t\t\t &ref_prefixes);\n+\t\ttrace2_region_leave(\"transport_push\", \"get_refs_list\", r);\n \n \t\targv_array_clear(&ref_prefixes);\n \n@@ -1182,6 +1184,7 @@ int transport_push(struct repository *r,\n \t\t\tstruct ref *ref = remote_refs;\n \t\t\tstruct oid_array commits = OID_ARRAY_INIT;\n \n+\t\t\ttrace2_region_enter(\"transport_push\", \"push_submodules\", r);\n \t\t\tfor (; ref; ref = ref->next)\n \t\t\t\tif (!is_null_oid(&ref->new_oid))\n \t\t\t\t\toid_array_append(&commits,\n@@ -1194,9 +1197,11 @@ int transport_push(struct repository *r,\n \t\t\t\t\t\t transport->push_options,\n \t\t\t\t\t\t pretend)) {\n \t\t\t\toid_array_clear(&commits);\n+\t\t\t\ttrace2_region_leave(\"transport_push\", \"push_submodules\", r);\n \t\t\t\tdie(_(\"failed to push all needed submodules\"));\n \t\t\t}\n \t\t\toid_array_clear(&commits);\n+\t\t\ttrace2_region_leave(\"transport_push\", \"push_submodules\", r);\n \t\t}\n \n \t\tif (((flags & TRANSPORT_RECURSE_SUBMODULES_CHECK) ||\n@@ -1207,6 +1212,7 @@ int transport_push(struct repository *r,\n \t\t\tstruct string_list needs_pushing = STRING_LIST_INIT_DUP;\n \t\t\tstruct oid_array commits = OID_ARRAY_INIT;\n \n+\t\t\ttrace2_region_enter(\"transport_push\", \"check_submodules\", r);\n \t\t\tfor (; ref; ref = ref->next)\n \t\t\t\tif (!is_null_oid(&ref->new_oid))\n \t\t\t\t\toid_array_append(&commits,\n@@ -1217,15 +1223,19 @@ int transport_push(struct repository *r,\n \t\t\t\t\t\t transport->remote->name,\n \t\t\t\t\t\t &needs_pushing)) {\n \t\t\t\toid_array_clear(&commits);\n+\t\t\t\ttrace2_region_leave(\"transport_push\", \"check_submodules\", r);\n \t\t\t\tdie_with_unpushed_submodules(&needs_pushing);\n \t\t\t}\n \t\t\tstring_list_clear(&needs_pushing, 0);\n \t\t\toid_array_clear(&commits);\n+\t\t\ttrace2_region_leave(\"transport_push\", \"check_submodules\", r);\n \t\t}\n \n-\t\tif (!(flags & TRANSPORT_RECURSE_SUBMODULES_ONLY))\n+\t\tif (!(flags & TRANSPORT_RECURSE_SUBMODULES_ONLY)) {\n+\t\t\ttrace2_region_enter(\"transport_push\", \"push_refs\", r);\n \t\t\tpush_ret = transport->vtable->push_refs(transport, remote_refs, flags);\n-\t\telse\n+\t\t\ttrace2_region_leave(\"transport_push\", \"push_refs\", r);\n+\t\t} else\n \t\t\tpush_ret = 0;\n \t\terr = push_had_errors(remote_refs);\n \t\tret = push_ret | err;\n-- \n2.23.0.581.g78d2f28ef7-goog\n\n"},{"id":"383635","messageId":"20191007223644.GA8397@google.com","threadId":"51961","inReplyTo":"20191007214644.236055-1-jonathantanmy@google.com","subject":"Re: [PATCH 0/2] add trace2 regions to fetch & push","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2019-10-07T22:36:44Z","receivedAt":"2019-10-07T22:36:54Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"On 2019.10.07 14:46, Jonathan Tan wrote:\n> > We'd like to collect better statistics about where the time is spent in\n> > fetches and pushes so that we can hopefully identify some areas for\n> > future optimization. So let's add some trace2 regions around some of the\n> > fetch/push phases so we can break down their timing.\n> \n> Thanks.\n> \n> Patch 1 looks good to me - different regions at the same level\n> (builtin/fetch.c, so it will be just for \"git fetch\") and one specific\n> one just for negotiation, which has to be in fetch-pack.c because only\n> that file operates at that level.\n> \n> Patch 2 mostly looks good to me too - unlike fetch, a lot happens in\n> transport.c, so it's reasonable to put most of the regions there. One\n> comment: in transport_push(), should trace2_region_{enter,leave} take\n> \"r\" instead of \"the_repository\"?\n\nAh yeah, thanks for the catch. Fixed in V2.\n"},{"id":"383637","messageId":"20191007235532.9320-1-jonathantanmy@google.com","threadId":"51961","inReplyTo":"cover.1570487473.git.steadmon@google.com","subject":"Re: [PATCH v2 0/2] add trace2 regions to fetch & push","fromName":"Jonathan Tan","fromEmail":"jonathantanmy@google.com","sentAt":"2019-10-07T23:55:32Z","receivedAt":"2019-10-07T23:55:38Z","isPatch":true,"sender":{"key":"jonathantanmy@fastmail.com","avatar":null},"body":"> Changes since V1:\n> * Use the repository struct argument in transport_push(), rather than\n> the global the_repository.\n\nThanks, the patches now look good to me. I verified that the repository\nargument to the trace functions just cause a different repo ID to be\nprinted, which is what we want (e.g. fn_region_enter_printf_va_fl() in\ntr2_tgt_event.c, which appears in the vtable defined at the bottom of\nthe file).\n"},{"id":"383649","messageId":"xmqq4l0jopu6.fsf@gitster-ct.c.googlers.com","threadId":"51961","inReplyTo":"20191007223644.GA8397@google.com","subject":"Re: [PATCH 0/2] add trace2 regions to fetch & push","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2019-10-08T03:53:21Z","receivedAt":"2019-10-08T03:54:06Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Josh Steadmon writes:\n\n> On 2019.10.07 14:46, Jonathan Tan wrote:\n>> > We'd like to collect better statistics about where the time is spent in\n>> > fetches and pushes so that we can hopefully identify some areas for\n>> > future optimization. So let's add some trace2 regions around some of the\n>> > fetch/push phases so we can break down their timing.\n>> \n>> Thanks.\n>> \n>> Patch 1 looks good to me - different regions at the same level\n>> (builtin/fetch.c, so it will be just for \"git fetch\") and one specific\n>> one just for negotiation, which has to be in fetch-pack.c because only\n>> that file operates at that level.\n>> \n>> Patch 2 mostly looks good to me too - unlike fetch, a lot happens in\n>> transport.c, so it's reasonable to put most of the regions there. One\n>> comment: in transport_push(), should trace2_region_{enter,leave} take\n>> \"r\" instead of \"the_repository\"?\n>\n> Ah yeah, thanks for the catch. Fixed in V2.\n\nYuck. It's already in 'next', isn't it?\n\n"},{"id":"383651","messageId":"xmqqr23nna3z.fsf@gitster-ct.c.googlers.com","threadId":"51961","inReplyTo":"xmqq4l0jopu6.fsf@gitster-ct.c.googlers.com","subject":"Re: [PATCH 0/2] add trace2 regions to fetch & push","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2019-10-08T04:18:24Z","receivedAt":"2019-10-08T04:18:29Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Junio C Hamano writes:\n\n> Yuck. It's already in 'next', isn't it?\n\nYuck, indeed. Here is your v2 in an incremental form to be queued\non top.\n\nThanks.\n\n-- >8 --\nSubject: [PATCH 3/2] transport: push codepath can take arbitrary repository\n\nThe previous step added annotations with \"the_repository\" to various\nfunctions in the push codepath in the transport layer, but they all\ncan take arbitrary repository pointer, and may be working on a\nrepository that is not the_repository. Fix them.\n\nSigned-off-by: Josh Steadmon \nSigned-off-by: Junio C Hamano \n---\n transport.c | 20 ++++++++++----------\n 1 file changed, 10 insertions(+), 10 deletions(-)\n\ndiff --git a/transport.c b/transport.c\nindex f313f288de..83379a037d 100644\n--- a/transport.c\n+++ b/transport.c\n@@ -1145,10 +1145,10 @@ int transport_push(struct repository *r,\n \n \t\trefspec_ref_prefixes(rs, &ref_prefixes);\n \n-\t\ttrace2_region_enter(\"transport_push\", \"get_refs_list\", the_repository);\n+\t\ttrace2_region_enter(\"transport_push\", \"get_refs_list\", r);\n \t\tremote_refs = transport->vtable->get_refs_list(transport, 1,\n \t\t\t\t\t\t\t &ref_prefixes);\n-\t\ttrace2_region_leave(\"transport_push\", \"get_refs_list\", the_repository);\n+\t\ttrace2_region_leave(\"transport_push\", \"get_refs_list\", r);\n \n \t\targv_array_clear(&ref_prefixes);\n \n@@ -1184,7 +1184,7 @@ int transport_push(struct repository *r,\n \t\t\tstruct ref *ref = remote_refs;\n \t\t\tstruct oid_array commits = OID_ARRAY_INIT;\n \n-\t\t\ttrace2_region_enter(\"transport_push\", \"push_submodules\", the_repository);\n+\t\t\ttrace2_region_enter(\"transport_push\", \"push_submodules\", r);\n \t\t\tfor (; ref; ref = ref->next)\n \t\t\t\tif (!is_null_oid(&ref->new_oid))\n \t\t\t\t\toid_array_append(&commits,\n@@ -1197,11 +1197,11 @@ int transport_push(struct repository *r,\n \t\t\t\t\t\t transport->push_options,\n \t\t\t\t\t\t pretend)) {\n \t\t\t\toid_array_clear(&commits);\n-\t\t\t\ttrace2_region_leave(\"transport_push\", \"push_submodules\", the_repository);\n+\t\t\t\ttrace2_region_leave(\"transport_push\", \"push_submodules\", r);\n \t\t\t\tdie(_(\"failed to push all needed submodules\"));\n \t\t\t}\n \t\t\toid_array_clear(&commits);\n-\t\t\ttrace2_region_leave(\"transport_push\", \"push_submodules\", the_repository);\n+\t\t\ttrace2_region_leave(\"transport_push\", \"push_submodules\", r);\n \t\t}\n \n \t\tif (((flags & TRANSPORT_RECURSE_SUBMODULES_CHECK) ||\n@@ -1212,7 +1212,7 @@ int transport_push(struct repository *r,\n \t\t\tstruct string_list needs_pushing = STRING_LIST_INIT_DUP;\n \t\t\tstruct oid_array commits = OID_ARRAY_INIT;\n \n-\t\t\ttrace2_region_enter(\"transport_push\", \"check_submodules\", the_repository);\n+\t\t\ttrace2_region_enter(\"transport_push\", \"check_submodules\", r);\n \t\t\tfor (; ref; ref = ref->next)\n \t\t\t\tif (!is_null_oid(&ref->new_oid))\n \t\t\t\t\toid_array_append(&commits,\n@@ -1223,18 +1223,18 @@ int transport_push(struct repository *r,\n \t\t\t\t\t\t transport->remote->name,\n \t\t\t\t\t\t &needs_pushing)) {\n \t\t\t\toid_array_clear(&commits);\n-\t\t\t\ttrace2_region_leave(\"transport_push\", \"check_submodules\", the_repository);\n+\t\t\t\ttrace2_region_leave(\"transport_push\", \"check_submodules\", r);\n \t\t\t\tdie_with_unpushed_submodules(&needs_pushing);\n \t\t\t}\n \t\t\tstring_list_clear(&needs_pushing, 0);\n \t\t\toid_array_clear(&commits);\n-\t\t\ttrace2_region_leave(\"transport_push\", \"check_submodules\", the_repository);\n+\t\t\ttrace2_region_leave(\"transport_push\", \"check_submodules\", r);\n \t\t}\n \n \t\tif (!(flags & TRANSPORT_RECURSE_SUBMODULES_ONLY)) {\n-\t\t\ttrace2_region_enter(\"transport_push\", \"push_refs\", the_repository);\n+\t\t\ttrace2_region_enter(\"transport_push\", \"push_refs\", r);\n \t\t\tpush_ret = transport->vtable->push_refs(transport, remote_refs, flags);\n-\t\t\ttrace2_region_leave(\"transport_push\", \"push_refs\", the_repository);\n+\t\t\ttrace2_region_leave(\"transport_push\", \"push_refs\", r);\n \t\t} else\n \t\t\tpush_ret = 0;\n \t\terr = push_had_errors(remote_refs);\n"}]}