Re: [PATCH 2/2] send-pack: add new tracing regions for push
- From
Junio C Hamano <gitster@pobox.com>
- Date
- Aug 15, 2024, 20:06 UTC
- Message-ID
- <xmqq8qwxsg8w.fsf@gitster.g>
- In-Reply-To
- <d57f258026f941e7bc05de8dac359fc1e2e42bee.1723747832.git.steadmon@google.com>
Josh Steadmon <steadmon@google.com> writes:
Show 26 quoted lines
> From: Calvin Wan <calvinwan@google.com>
>
> At $DAYJOB we experienced some slow pushes and needed additional trace
> data to diagnose them.
>
> Add trace2 regions for various sections of send_pack().
>
> Signed-off-by: Josh Steadmon <steadmon@google.com>
> ---
> send-pack.c | 16 +++++++++++++---
> 1 file changed, 13 insertions(+), 3 deletions(-)
>
> diff --git a/send-pack.c b/send-pack.c
> index fa2f5eec17..de8ba46ad5 100644
> --- a/send-pack.c
> +++ b/send-pack.c
> @@ -512,8 +512,11 @@ int send_pack(struct send_pack_args *args,
> }
>
> git_config_get_bool("push.negotiate", &push_negotiate);
> - if (push_negotiate)
> + if (push_negotiate) {
> + trace2_region_enter("send_pack", "push_negotiate", the_repository);
> get_commons_through_negotiation(args->url, remote_refs, &commons);
> + trace2_region_leave("send_pack", "push_negotiate", the_repository);
> + }Show 12 quoted lines
> @@ -641,10 +644,12 @@ int send_pack(struct send_pack_args *args,
> /*
> * Finally, tell the other end!
> */
> - if (!args->dry_run && push_cert_nonce)
> + if (!args->dry_run && push_cert_nonce) {
> + trace2_region_enter("send_pack", "push_cert", the_repository);
> cmds_sent = generate_push_cert(&req_buf, remote_refs, args,
> cap_buf.buf, push_cert_nonce);
> - else if (!args->dry_run)
> + trace2_region_leave("send_pack", "push_cert", the_repository);
> + } else if (!args->dry_run) {Misleading "diff" but this is correct.
But makes me wonder if we really want to express these (and other events we saw in [PATCH 1/2]) as regions we enter and leave. Presumably we would generate a certificate instantly, compared to all the other things happening in this process, like talking over the network, waiting for the other end, and packing the payload, and I suspect that the single bit the debuggers would want to learn from the trace is "did we get asked to give a certificate?". Sandwitching a rather expensive operation inside a pair of enter/leave would give us a way to measure how long that operation took in exchanges for one extra trace log entry, and "ah, we need to first fetch the bundle and process it" we saw in [PATCH 1/2] is something that is worth timing, but I am finding a bit hard to believe it is worth doing for push cert generation. It is understandable if there weren't any suitable mechanism to simply log "the control passed at this spot at this time" kind of event in the trace2 subsystem, but I do not think it is the case.
Show 23 quoted lines
> @@ -686,6 +692,7 @@ int send_pack(struct send_pack_args *args,
> strbuf_release(&cap_buf);
>
> if (use_sideband && cmds_sent) {
> + trace2_region_enter("send_pack", "sideband_demux", the_repository);
> memset(&demux, 0, sizeof(demux));
> demux.proc = sideband_demux;
> demux.data = fd;
> @@ -719,6 +726,8 @@ int send_pack(struct send_pack_args *args,
> if (use_sideband) {
> close(demux.out);
> finish_async(&demux);
> + if (cmds_sent)
> + trace2_region_leave("send_pack", "sideband_demux", the_repository);
> }
> fd[1] = -1;
> return -1;
> @@ -743,6 +752,7 @@ int send_pack(struct send_pack_args *args,
> error("error in sideband demultiplexer");
> ret = -1;
> }
> + trace2_region_leave("send_pack", "sideband_demux", the_repository);
> }This is also dubious. When sideband is in effect, this records the fact that we did ran pack-objects and allows as to measure how much time it was spent. But on a connection without sideband enabled, it does not record anything. But if we start the region a line sooner, and finish the region a line later, we should be able to record the same facts even for a connection without sideband enabled. I also find the name given to this region ultra-iffy. Is it so important that sideband_demux was used to communicate with the other end that received the data our pack_objects() produced that the word "sideband_demux" deserves to be in the name of the region, more than the fact that this is the crux of sending pack data from us to them (i.e. the main part of the "send-pack")?