trace2: add trace2_child_ready() to report on background children
Create "child_ready" event to capture the state of a child process created in the background. When a child command is started a "child_start" event is generated in the Trace2 log. For normal synchronous children, a "child_exit" event is later generated when the child exits or is terminated. The two events include information, such as the "child_id" and "pid", to allow post analysis to match-up the command line and exit status. When a child is started in the background (and may outlive the parent process), it is not possible for the parent to emit a "child_exit" event. Create a new "child_ready" event to indicate whether the child was successfully started. Also include the "child_id" and "pid" to allow similar post processing. This will be used in a later commit with the new "start_bg_command()". Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com> Signed-off-by: Junio C Hamano <gitster@pobox.com>
Jeff Hostetler committed
Sep 20, 2021 at 15:36 UTC
64bc75244b5bdc26112cf7b8533a832b692a5fda
7 files changed
+152
Documentation/technical/api-trace2.txt
+40
@@ -613,6 +613,46 @@ stopping after the waitpid() and includes OS process creation overhead).
613
So this time will be slightly larger than the atexit time reported by
614
the child process itself.
615
616
+`"child_ready"`::
617
+ This event is generated after the current process has started
618
+ a background process and released all handles to it.
619
++
620
+------------
621
+{
622
+ "event":"child_ready",
623
+ ...
624
+ "child_id":2,
625
+ "pid":14708, # child PID
626
+ "ready":"ready", # child ready state
627
+ "t_rel":0.110605 # observed run-time of child process
628
+}
629
+------------
630
++
631
+Note that the session-id of the child process is not available to
632
+the current/spawning process, so the child's PID is reported here as
633
+a hint for post-processing. (But it is only a hint because the child
634
+process may be a shell script which doesn't have a session-id.)
635
++
636
+This event is generated after the child is started in the background
637
+and given a little time to boot up and start working. If the child
638
+startups normally and while the parent is still waiting, the "ready"
639
+field will have the value "ready".
640
+If the child is too slow to start and the parent times out, the field
641
+will have the value "timeout".
642
+If the child starts but the parent is unable to probe it, the field
643
+will have the value "error".
644
++
645
+After the parent process emits this event, it will release all of its
646
+handles to the child process and treat the child as a background
647
+daemon. So even if the child does eventually finish booting up,
648
+the parent will not emit an updated event.
649
++
650
+Note that the `t_rel` field contains the observed run time in seconds
651
+when the parent released the child process into the background.
652
+The child is assumed to be a long-running daemon process and may
653
+outlive the parent process. So the parent's child event times should
654
+not be compared to the child's atexit times.
655
+
656
`"exec"`::
657
This event is generated before git attempts to `exec()`
658
another command rather than starting a child process.
trace2.c
+31
@@ -394,6 +394,37 @@ void trace2_child_exit_fl(const char *file, int line, struct child_process *cmd,
394
us_elapsed_child);
395
}
396
397
+void trace2_child_ready_fl(const char *file, int line,
398
+ struct child_process *cmd,
399
+ const char *ready)
400
+{
401
+ struct tr2_tgt *tgt_j;
402
+ int j;
403
+ uint64_t us_now;
404
+ uint64_t us_elapsed_absolute;
405
+ uint64_t us_elapsed_child;
406
+
407
+ if (!trace2_enabled)
408
+ return;
409
+
410
+ us_now = getnanotime() / 1000;
411
+ us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
412
+
413
+ if (cmd->trace2_child_us_start)
414
+ us_elapsed_child = us_now - cmd->trace2_child_us_start;
415
+ else
416
+ us_elapsed_child = 0;
417
+
418
+ for_each_wanted_builtin (j, tgt_j)
419
+ if (tgt_j->pfn_child_ready_fl)
420
+ tgt_j->pfn_child_ready_fl(file, line,
421
+ us_elapsed_absolute,
422
+ cmd->trace2_child_id,
423
+ cmd->pid,
424
+ ready,
425
+ us_elapsed_child);
426
+}
427
+
428
int trace2_exec_fl(const char *file, int line, const char *exe,
429
const char **argv)
430
{
trace2.h
+25
@@ -253,6 +253,31 @@ void trace2_child_exit_fl(const char *file, int line, struct child_process *cmd,
253
#define trace2_child_exit(cmd, code) \
254
trace2_child_exit_fl(__FILE__, __LINE__, (cmd), (code))
255
256
+/**
257
+ * Emits a "child_ready" message containing the "child-id" and a flag
258
+ * indicating whether the child was considered "ready" when we
259
+ * released it.
260
+ *
261
+ * This function should be called after starting a daemon process in
262
+ * the background (and after giving it sufficient time to boot
263
+ * up) to indicate that we no longer control or own it.
264
+ *
265
+ * The "ready" argument should contain one of { "ready", "timeout",
266
+ * "error" } to indicate the state of the running daemon when we
267
+ * released it.
268
+ *
269
+ * If the daemon process fails to start or it exits or is terminated
270
+ * while we are still waiting for it, the caller should emit a
271
+ * regular "child_exit" to report the normal process exit information.
272
+ *
273
+ */
274
+void trace2_child_ready_fl(const char *file, int line,
275
+ struct child_process *cmd,
276
+ const char *ready);
277
+
278
+#define trace2_child_ready(cmd, ready) \
279
+ trace2_child_ready_fl(__FILE__, __LINE__, (cmd), (ready))
280
+
281
/**
282
* Emit an 'exec' event prior to calling one of exec(), execv(),
283
* execvp(), and etc. On Unix-derived systems, this will be the
trace2/tr2_tgt.h
+5
@@ -45,6 +45,10 @@ typedef void(tr2_tgt_evt_child_exit_fl_t)(const char *file, int line,
45
uint64_t us_elapsed_absolute, int cid,
46
int pid, int code,
47
uint64_t us_elapsed_child);
48
+typedef void(tr2_tgt_evt_child_ready_fl_t)(const char *file, int line,
49
+ uint64_t us_elapsed_absolute,
50
+ int cid, int pid, const char *ready,
51
+ uint64_t us_elapsed_child);
52
53
typedef void(tr2_tgt_evt_thread_start_fl_t)(const char *file, int line,
54
uint64_t us_elapsed_absolute);
@@ -116,6 +120,7 @@ struct tr2_tgt {
120
tr2_tgt_evt_alias_fl_t *pfn_alias_fl;
121
tr2_tgt_evt_child_start_fl_t *pfn_child_start_fl;
122
tr2_tgt_evt_child_exit_fl_t *pfn_child_exit_fl;
123
+ tr2_tgt_evt_child_ready_fl_t *pfn_child_ready_fl;
124
tr2_tgt_evt_thread_start_fl_t *pfn_thread_start_fl;
125
tr2_tgt_evt_thread_exit_fl_t *pfn_thread_exit_fl;
126
tr2_tgt_evt_exec_fl_t *pfn_exec_fl;
trace2/tr2_tgt_event.c
+22
@@ -383,6 +383,27 @@ static void fn_child_exit_fl(const char *file, int line,
383
jw_release(&jw);
384
}
385
386
+static void fn_child_ready_fl(const char *file, int line,
387
+ uint64_t us_elapsed_absolute, int cid, int pid,
388
+ const char *ready, uint64_t us_elapsed_child)
389
+{
390
+ const char *event_name = "child_ready";
391
+ struct json_writer jw = JSON_WRITER_INIT;
392
+ double t_rel = (double)us_elapsed_child / 1000000.0;
393
+
394
+ jw_object_begin(&jw, 0);
395
+ event_fmt_prepare(event_name, file, line, NULL, &jw);
396
+ jw_object_intmax(&jw, "child_id", cid);
397
+ jw_object_intmax(&jw, "pid", pid);
398
+ jw_object_string(&jw, "ready", ready);
399
+ jw_object_double(&jw, "t_rel", 6, t_rel);
400
+ jw_end(&jw);
401
+
402
+ tr2_dst_write_line(&tr2dst_event, &jw.json);
403
+
404
+ jw_release(&jw);
405
+}
406
+
407
static void fn_thread_start_fl(const char *file, int line,
408
uint64_t us_elapsed_absolute)
409
{
@@ -610,6 +631,7 @@ struct tr2_tgt tr2_tgt_event = {
631
fn_alias_fl,
632
fn_child_start_fl,
633
fn_child_exit_fl,
634
+ fn_child_ready_fl,
635
fn_thread_start_fl,
636
fn_thread_exit_fl,
637
fn_exec_fl,
trace2/tr2_tgt_normal.c
+14
@@ -251,6 +251,19 @@ static void fn_child_exit_fl(const char *file, int line,
251
strbuf_release(&buf_payload);
252
}
253
254
+static void fn_child_ready_fl(const char *file, int line,
255
+ uint64_t us_elapsed_absolute, int cid, int pid,
256
+ const char *ready, uint64_t us_elapsed_child)
257
+{
258
+ struct strbuf buf_payload = STRBUF_INIT;
259
+ double elapsed = (double)us_elapsed_child / 1000000.0;
260
+
261
+ strbuf_addf(&buf_payload, "child_ready[%d] pid:%d ready:%s elapsed:%.6f",
262
+ cid, pid, ready, elapsed);
263
+ normal_io_write_fl(file, line, &buf_payload);
264
+ strbuf_release(&buf_payload);
265
+}
266
+
267
static void fn_exec_fl(const char *file, int line, uint64_t us_elapsed_absolute,
268
int exec_id, const char *exe, const char **argv)
269
{
@@ -330,6 +343,7 @@ struct tr2_tgt tr2_tgt_normal = {
343
fn_alias_fl,
344
fn_child_start_fl,
345
fn_child_exit_fl,
346
+ fn_child_ready_fl,
347
NULL, /* thread_start */
348
NULL, /* thread_exit */
349
fn_exec_fl,
trace2/tr2_tgt_perf.c
+15
@@ -360,6 +360,20 @@ static void fn_child_exit_fl(const char *file, int line,
360
strbuf_release(&buf_payload);
361
}
362
363
+static void fn_child_ready_fl(const char *file, int line,
364
+ uint64_t us_elapsed_absolute, int cid, int pid,
365
+ const char *ready, uint64_t us_elapsed_child)
366
+{
367
+ const char *event_name = "child_ready";
368
+ struct strbuf buf_payload = STRBUF_INIT;
369
+
370
+ strbuf_addf(&buf_payload, "[ch%d] pid:%d ready:%s", cid, pid, ready);
371
+
372
+ perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
373
+ &us_elapsed_child, NULL, &buf_payload);
374
+ strbuf_release(&buf_payload);
375
+}
376
+
377
static void fn_thread_start_fl(const char *file, int line,
378
uint64_t us_elapsed_absolute)
379
{
@@ -553,6 +567,7 @@ struct tr2_tgt tr2_tgt_perf = {
567
fn_alias_fl,
568
fn_child_start_fl,
569
fn_child_exit_fl,
570
+ fn_child_ready_fl,
571
fn_thread_start_fl,
572
fn_thread_exit_fl,
573
fn_exec_fl,