From: Jeff Hostetler Date: Fri, 15 May 2020 19:44:58 GMT Subject: Re: [PATCH] trace2: log progress time and throughput Message-ID: <369ab235-e23a-712a-d2bf-82735194ceff@jeffhostetler.com> In-Reply-To: <90f800d5-c647-6750-52d1-da973f036bd0@jeffhostetler.com> On 5/15/20 3:37 PM, Jeff Hostetler wrote: > > > On 5/12/20 5:44 PM, Emily Shaffer wrote: >> Rather than teaching only one operation, like 'git fetch', how to write >> down throughput to traces, we can learn about a wide range of user >> operations that may seem slow by adding tooling to the progress library >> itself. Operations which display progress are likely to be slow-running >> and the kind of thing we want to monitor for performance anyways. By >> showing object counts and data transfer size, we should be able to >> make some derived measurements to ensure operations are scaling the way >> we expect. >> >> Signed-off-by: Emily Shaffer > > We need to be careful here.  The region_enter and _leave calls need > to always be properly nested.  Having an implicit region within the > progress code means the code path between all of the different start_ > and stop_progress calls need to not interleave with explicit regions. > > How about putting something like this in stop_progress: > >     struct json_writer jw = JSON_WRITER_INIT; >     jw_object_begin(&jw, 0); >     jw_object_intmax(&jw, "total", p->total); >     if (p->throughput) >         jw_object_intmax(&jw, "throughput", p->throughput->curr_total); >     /* >      * and so on... >      * and maybe include the elapsed time in since the start_progress. >      */ >     jw_end(&jw); >     trace2_data_json("progress", NULL, p->title, &jw); >     jw_release(&jw); > > That will give you a single record summary of the progress meter > and you won't have to worry about any interleaving. > > You could also add a bit to `struct progress` to let you opt-in > or opt-out of the message on a case-by-case basis. > > Jeff Hit send too quickly... One of the advantages of a "data_json" event is that it will keep the multiple values together in one event. This makes it easier to correlate them during post processing. For example, you could grep for "\"data_json\".*\"progress\".*" and easily parse and see the total and time and etc in one record.