| Message ID | d57f258026f941e7bc05de8dac359fc1e2e42bee.1723747832.git.steadmon@google.com (mailing list archive) |
|---|---|
| State | Superseded |
| Headers | show |
| Series | Add additional trace2 regions for fetch and push | expand |
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")?
On 2024.08.15 13:06, Junio C Hamano wrote: > 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. 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.
Josh Steadmon <steadmon@google.com> writes: >> ... 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. Ahh, OK, I was concentrating solely on the producing side, and forgot to consider that the consuming side may not be prepared for non enter/leave pair of events. That's understandable, but if you are updating the consuming side to be able to do so, that would be even better. > 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. Sounds good. This is a tangent, but I doubt we have many users without sideband support. In the longer term we may be able to drop the non-sideband codepath, which would automatically simplify the flow quite a bit around here. But that is totally outside of this topic. Thanks.
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); + } if (!git_config_get_bool("push.usebitmaps", &use_bitmaps)) args->disable_bitmaps = !use_bitmaps; @@ -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) { for (ref = remote_refs; ref; ref = ref->next) { char *old_hex, *new_hex; @@ -664,6 +669,7 @@ int send_pack(struct send_pack_args *args, old_hex, new_hex, ref->name); } } + } if (use_push_options) { struct string_list_item *item; @@ -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); } if (ret < 0)