On 2022.05.26 02:30, Ævar Arnfjörð Bjarmason wrote:
> Add a wrapper for the abort(3) function to correspond to the existing
> wrapper for exit(3). See ee4512ed481 (trace2: create new combined
> trace facility, 2019-02-22) for the introduction of the exit(3)
> wrapper. See also the more recent 368b5843158 (common-main.c: call
> exit(), don't return, 2021-12-07) discussing how the exit() wrapper
> macro it and the trace2 machinery interact.
>
> As reported (off the ML) by Josh Steadmon we have "start" events that
> are not followed by corresponding "exit" events. I first considered
> logging an "exit" here, but that would be incorrect, we didn't call
> exit, on abort() we do the equivalent of:
>
> kill(getpid(), SIGABRT);
>
> So let's instead update the documentation to note that those
> interested in seeing a marker for process exit need to be looking for
> either an "exit" or a "signal" event.
>
> We then need to add a *_fl() function similar to the existing
> "tr2main_signal_handler()" function. Until now we'd only been emitting
> these "signal" events from our own signal handlers.
>
> Reported-by: Josh Steadmon <steadmon@xxxxxxxxxx>
> Signed-off-by: Ævar Arnfjörð Bjarmason <avarab@xxxxxxxxx>
> ---
> Documentation/technical/api-trace2.txt | 13 +++++++++----
> git-compat-util.h | 9 +++++++++
> t/t0210-trace2-normal.sh | 1 +
> trace2.c | 19 +++++++++++++++++++
> trace2.h | 8 ++++++++
> trace2/tr2_tgt.h | 3 +++
> trace2/tr2_tgt_event.c | 11 +++++++++--
> trace2/tr2_tgt_normal.c | 11 +++++++++--
> trace2/tr2_tgt_perf.c | 11 +++++++++--
> 9 files changed, 76 insertions(+), 10 deletions(-)
>
> diff --git a/Documentation/technical/api-trace2.txt b/Documentation/technical/api-trace2.txt
> index f4a8a690878..55ecfd8c30c 100644
> --- a/Documentation/technical/api-trace2.txt
> +++ b/Documentation/technical/api-trace2.txt
> @@ -421,7 +421,9 @@ only present on the "start" and "atexit" events.
> ------------
>
> `"exit"`::
> - This event is emitted when git calls `exit()`.
> + This event is emitted when git calls `exit()`. This event will
> + be produced for all regular ending of the git process, but it
> + might also exit via a "signal".
> +
> ------------
> {
> @@ -435,7 +437,7 @@ only present on the "start" and "atexit" events.
> `"atexit"`::
> This event is emitted by the Trace2 `atexit` routine during
> final shutdown. It should be the last event emitted by the
> - process.
> + process, unless it was aborted (see "signal").
> +
> (The elapsed time reported here is greater than the time reported in
> the "exit" event because it runs after all other atexit tasks have
> @@ -452,8 +454,11 @@ completed.)
>
> `"signal"`::
> This event is emitted when the program is terminated by a user
> - signal. Depending on the platform, the signal event may
> - prevent the "atexit" event from being generated.
> + signal, which includes git itself calling abort(3). Depending
> + on the platform, the signal event may prevent the "exit"
> + and/or "atexit" events from being generated. E.g. if BUG() was
> + invoked we'll emit an "error" event followed by a "signal"
> + event, and nothing else.
> +
> ------------
> {
> diff --git a/git-compat-util.h b/git-compat-util.h
> index 58fd813bd01..ea3177b2771 100644
> --- a/git-compat-util.h
> +++ b/git-compat-util.h
> @@ -1403,6 +1403,15 @@ int cmd_main(int, const char **);
> int trace2_cmd_exit_fl(const char *file, int line, int code);
> #define exit(code) exit(trace2_cmd_exit_fl(__FILE__, __LINE__, (code)))
>
> +/*
> + * Intercept calls to abort() to log that we aborted.
> + */
> +void trace2_cmd_signal_fl(const char *file, int line, int signo);
> +#define abort() do { \
> + trace2_cmd_signal_fl(__FILE__, __LINE__, SIGABRT); \
> + abort(); \
> +} while (0)
> +
> /*
> * You can mark a stack variable with UNLEAK(var) to avoid it being
> * reported as a leak by tools like LSAN or valgrind. The argument
> diff --git a/t/t0210-trace2-normal.sh b/t/t0210-trace2-normal.sh
> index 910a6af8058..25fffdba80e 100755
> --- a/t/t0210-trace2-normal.sh
> +++ b/t/t0210-trace2-normal.sh
> @@ -162,6 +162,7 @@ test_expect_success 'BUG messages are written to trace2' '
> start _EXE_ trace2 007bug
> cmd_name trace2 (trace2)
> error the bug message
> + signal elapsed:_TIME_ code:6
> EOF
> test_cmp expect actual
> '
> diff --git a/trace2.c b/trace2.c
> index e01cf77f1a8..250b2424bfa 100644
> --- a/trace2.c
> +++ b/trace2.c
> @@ -230,6 +230,25 @@ int trace2_cmd_exit_fl(const char *file, int line, int code)
> return code;
> }
>
> +void trace2_cmd_signal_fl(const char *file, int line, int signo)
> +{
> + struct tr2_tgt *tgt_j;
> + int j;
> + uint64_t us_now;
> + uint64_t us_elapsed_absolute;
> +
> + if (!trace2_enabled)
> + return;
> +
> + us_now = getnanotime() / 1000;
> + us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
> +
> + for_each_wanted_builtin (j, tgt_j)
> + if (tgt_j->pfn_signal_fl)
> + tgt_j->pfn_signal_fl(file, line, us_elapsed_absolute,
> + signo);
> +}
> +
> void trace2_cmd_error_va_fl(const char *file, int line, const char *fmt,
> va_list ap)
> {
> diff --git a/trace2.h b/trace2.h
> index 1b109f57d0a..4f456f2fc62 100644
> --- a/trace2.h
> +++ b/trace2.h
> @@ -112,6 +112,14 @@ int trace2_cmd_exit_fl(const char *file, int line, int code);
>
> #define trace2_cmd_exit(code) (trace2_cmd_exit_fl(__FILE__, __LINE__, (code)))
>
> +/*
> + * Emit a 'signal' event. Used to log that we called abort() e.g. via
> + * the BUG() function.
> + */
> +void trace2_cmd_signal_fl(const char *file, int line, int signo);
> +
> +#define trace2_cmd_signal(signo) (trace2_cmd_signal_fl(__FILE__, __LINE__, (signo)))
> +
> /*
> * Emit an 'error' event.
> *
> diff --git a/trace2/tr2_tgt.h b/trace2/tr2_tgt.h
> index 65f94e15748..fbc33650c5d 100644
> --- a/trace2/tr2_tgt.h
> +++ b/trace2/tr2_tgt.h
> @@ -20,6 +20,8 @@ typedef void(tr2_tgt_evt_start_fl_t)(const char *file, int line,
> typedef void(tr2_tgt_evt_exit_fl_t)(const char *file, int line,
> uint64_t us_elapsed_absolute, int code);
> typedef void(tr2_tgt_evt_signal_t)(uint64_t us_elapsed_absolute, int signo);
> +typedef void(tr2_tgt_evt_signal_fl_t)(const char *file, int line,
> + uint64_t us_elapsed_absolute, int signo);
> typedef void(tr2_tgt_evt_atexit_t)(uint64_t us_elapsed_absolute, int code);
>
> typedef void(tr2_tgt_evt_error_va_fl_t)(const char *file, int line,
> @@ -111,6 +113,7 @@ struct tr2_tgt {
> tr2_tgt_evt_start_fl_t *pfn_start_fl;
> tr2_tgt_evt_exit_fl_t *pfn_exit_fl;
> tr2_tgt_evt_signal_t *pfn_signal;
> + tr2_tgt_evt_signal_fl_t *pfn_signal_fl;
> tr2_tgt_evt_atexit_t *pfn_atexit;
> tr2_tgt_evt_error_va_fl_t *pfn_error_va_fl;
> tr2_tgt_evt_command_path_fl_t *pfn_command_path_fl;
> diff --git a/trace2/tr2_tgt_event.c b/trace2/tr2_tgt_event.c
> index c5c8cfbbaa0..df947378a51 100644
> --- a/trace2/tr2_tgt_event.c
> +++ b/trace2/tr2_tgt_event.c
> @@ -177,14 +177,15 @@ static void fn_exit_fl(const char *file, int line, uint64_t us_elapsed_absolute,
> jw_release(&jw);
> }
>
> -static void fn_signal(uint64_t us_elapsed_absolute, int signo)
> +static void fn_signal_fl(const char *file, int line,
> + uint64_t us_elapsed_absolute, int signo)
> {
> const char *event_name = "signal";
> struct json_writer jw = JSON_WRITER_INIT;
> double t_abs = (double)us_elapsed_absolute / 1000000.0;
>
> jw_object_begin(&jw, 0);
> - event_fmt_prepare(event_name, __FILE__, __LINE__, NULL, &jw);
> + event_fmt_prepare(event_name, file, line, NULL, &jw);
> jw_object_double(&jw, "t_abs", 6, t_abs);
> jw_object_intmax(&jw, "signo", signo);
> jw_end(&jw);
> @@ -193,6 +194,11 @@ static void fn_signal(uint64_t us_elapsed_absolute, int signo)
> jw_release(&jw);
> }
>
> +static void fn_signal(uint64_t us_elapsed_absolute, int signo)
> +{
> + fn_signal_fl(__FILE__, __LINE__, us_elapsed_absolute, signo);
> +}
> +
I believe the only caller of this would be
trace2.c:tr2main_signal_handler(), so could we just switch that one to
use pfn_signal_fl and get rid of pfn_signal altogether?
> static void fn_atexit(uint64_t us_elapsed_absolute, int code)
> {
> const char *event_name = "atexit";
> @@ -624,6 +630,7 @@ struct tr2_tgt tr2_tgt_event = {
> .pfn_start_fl = fn_start_fl,
> .pfn_exit_fl = fn_exit_fl,
> .pfn_signal = fn_signal,
> + .pfn_signal_fl = fn_signal_fl,
> .pfn_atexit = fn_atexit,
> .pfn_error_va_fl = fn_error_va_fl,
> .pfn_command_path_fl = fn_command_path_fl,
> diff --git a/trace2/tr2_tgt_normal.c b/trace2/tr2_tgt_normal.c
> index c42fbade7f0..8e2bc5027fe 100644
> --- a/trace2/tr2_tgt_normal.c
> +++ b/trace2/tr2_tgt_normal.c
> @@ -105,17 +105,23 @@ static void fn_exit_fl(const char *file, int line, uint64_t us_elapsed_absolute,
> strbuf_release(&buf_payload);
> }
>
> -static void fn_signal(uint64_t us_elapsed_absolute, int signo)
> +static void fn_signal_fl(const char *file, int line,
> + uint64_t us_elapsed_absolute, int signo)
> {
> struct strbuf buf_payload = STRBUF_INIT;
> double elapsed = (double)us_elapsed_absolute / 1000000.0;
>
> strbuf_addf(&buf_payload, "signal elapsed:%.6f code:%d", elapsed,
> signo);
> - normal_io_write_fl(__FILE__, __LINE__, &buf_payload);
> + normal_io_write_fl(file, line, &buf_payload);
> strbuf_release(&buf_payload);
> }
>
> +static void fn_signal(uint64_t us_elapsed_absolute, int signo)
> +{
> + fn_signal_fl(__FILE__, __LINE__, us_elapsed_absolute, signo);
> +}
> +
> static void fn_atexit(uint64_t us_elapsed_absolute, int code)
> {
> struct strbuf buf_payload = STRBUF_INIT;
> @@ -336,6 +342,7 @@ struct tr2_tgt tr2_tgt_normal = {
> .pfn_start_fl = fn_start_fl,
> .pfn_exit_fl = fn_exit_fl,
> .pfn_signal = fn_signal,
> + .pfn_signal_fl = fn_signal_fl,
> .pfn_atexit = fn_atexit,
> .pfn_error_va_fl = fn_error_va_fl,
> .pfn_command_path_fl = fn_command_path_fl,
> diff --git a/trace2/tr2_tgt_perf.c b/trace2/tr2_tgt_perf.c
> index a1eff8bea31..4ce18d3f12e 100644
> --- a/trace2/tr2_tgt_perf.c
> +++ b/trace2/tr2_tgt_perf.c
> @@ -193,18 +193,24 @@ static void fn_exit_fl(const char *file, int line, uint64_t us_elapsed_absolute,
> strbuf_release(&buf_payload);
> }
>
> -static void fn_signal(uint64_t us_elapsed_absolute, int signo)
> +static void fn_signal_fl(const char *file, int line,
> + uint64_t us_elapsed_absolute, int signo)
> {
> const char *event_name = "signal";
> struct strbuf buf_payload = STRBUF_INIT;
>
> strbuf_addf(&buf_payload, "signo:%d", signo);
>
> - perf_io_write_fl(__FILE__, __LINE__, event_name, NULL,
> + perf_io_write_fl(file, line, event_name, NULL,
> &us_elapsed_absolute, NULL, NULL, &buf_payload);
> strbuf_release(&buf_payload);
> }
>
> +static void fn_signal(uint64_t us_elapsed_absolute, int signo)
> +{
> + fn_signal_fl(__FILE__, __LINE__, us_elapsed_absolute, signo);
> +}
> +
> static void fn_atexit(uint64_t us_elapsed_absolute, int code)
> {
> const char *event_name = "atexit";
> @@ -560,6 +566,7 @@ struct tr2_tgt tr2_tgt_perf = {
> .pfn_start_fl = fn_start_fl,
> .pfn_exit_fl = fn_exit_fl,
> .pfn_signal = fn_signal,
> + .pfn_signal_fl = fn_signal_fl,
> .pfn_atexit = fn_atexit,
> .pfn_error_va_fl = fn_error_va_fl,
> .pfn_command_path_fl = fn_command_path_fl,
> --
> 2.36.1.1046.g586767a6996
>
