Re: [PATCH 2/2] send-pack: add new tracing regions for push

[Junio C Hamano <gitster@pobox.com>]

Josh Steadmon <steadmon@google.com> writes:

> 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);
> +	}

> @@ -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.

> @@ -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")?