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

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