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);
+}
+
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
