On 2024.08.15 13:06, Junio C Hamano wrote:
> Josh Steadmon <steadmon@xxxxxxxxxx> writes:
>
> > From: Calvin Wan <calvinwan@xxxxxxxxxx>
> >
> > 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@xxxxxxxxxx>
> > ---
> > 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.
Ack, changed this to a "trace2_printf()" instead. Annoyingly the JSON
Event trace2 target that we use at $DAYJOB doesn't log these events, but
I can add another patch to enable that.
> > @@ -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")?
Yeah, thanks, this did need to be reworked. I pushed the regions down
into pack_objects() and receive_status(), which look like the only two
places we might spend much time.
