diff options
author | Jeff Hostetler <jeffhost@microsoft.com> | 2019-02-22 14:25:01 -0800 |
---|---|---|
committer | Junio C Hamano <gitster@pobox.com> | 2019-02-22 15:27:59 -0800 |
commit | ee4512ed481a126dadd33334186e0e759d7f2f47 (patch) | |
tree | 4bc0418115d44b1833c1d24d2ac1c92f067b7ad3 /trace2 | |
parent | trace2: Documentation/technical/api-trace2.txt (diff) | |
download | tgif-ee4512ed481a126dadd33334186e0e759d7f2f47.tar.xz |
trace2: create new combined trace facility
Create a new unified tracing facility for git. The eventual intent is to
replace the current trace_printf* and trace_performance* routines with a
unified set of git_trace2* routines.
In addition to the usual printf-style API, trace2 provides higer-level
event verbs with fixed-fields allowing structured data to be written.
This makes post-processing and analysis easier for external tools.
Trace2 defines 3 output targets. These are set using the environment
variables "GIT_TR2", "GIT_TR2_PERF", and "GIT_TR2_EVENT". These may be
set to "1" or to an absolute pathname (just like the current GIT_TRACE).
* GIT_TR2 is intended to be a replacement for GIT_TRACE and logs command
summary data.
* GIT_TR2_PERF is intended as a replacement for GIT_TRACE_PERFORMANCE.
It extends the output with columns for the command process, thread,
repo, absolute and relative elapsed times. It reports events for
child process start/stop, thread start/stop, and per-thread function
nesting.
* GIT_TR2_EVENT is a new structured format. It writes event data as a
series of JSON records.
Calls to trace2 functions log to any of the 3 output targets enabled
without the need to call different trace_printf* or trace_performance*
routines.
Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
Diffstat (limited to 'trace2')
-rw-r--r-- | trace2/tr2_cfg.c | 90 | ||||
-rw-r--r-- | trace2/tr2_cfg.h | 19 | ||||
-rw-r--r-- | trace2/tr2_cmd_name.c | 30 | ||||
-rw-r--r-- | trace2/tr2_cmd_name.h | 24 | ||||
-rw-r--r-- | trace2/tr2_dst.c | 252 | ||||
-rw-r--r-- | trace2/tr2_dst.h | 36 | ||||
-rw-r--r-- | trace2/tr2_sid.c | 67 | ||||
-rw-r--r-- | trace2/tr2_sid.h | 18 | ||||
-rw-r--r-- | trace2/tr2_tbuf.c | 32 | ||||
-rw-r--r-- | trace2/tr2_tbuf.h | 23 | ||||
-rw-r--r-- | trace2/tr2_tgt.h | 133 | ||||
-rw-r--r-- | trace2/tr2_tgt_event.c | 588 | ||||
-rw-r--r-- | trace2/tr2_tgt_normal.c | 323 | ||||
-rw-r--r-- | trace2/tr2_tgt_perf.c | 534 | ||||
-rw-r--r-- | trace2/tr2_tls.c | 164 | ||||
-rw-r--r-- | trace2/tr2_tls.h | 97 |
16 files changed, 2430 insertions, 0 deletions
diff --git a/trace2/tr2_cfg.c b/trace2/tr2_cfg.c new file mode 100644 index 0000000000..b329921ac5 --- /dev/null +++ b/trace2/tr2_cfg.c @@ -0,0 +1,90 @@ +#include "cache.h" +#include "config.h" +#include "tr2_cfg.h" + +#define TR2_ENVVAR_CFG_PARAM "GIT_TR2_CONFIG_PARAMS" + +static struct strbuf **tr2_cfg_patterns; +static int tr2_cfg_count_patterns; +static int tr2_cfg_loaded; + +/* + * Parse a string containing a comma-delimited list of config keys + * or wildcard patterns into a list of strbufs. + */ +static int tr2_cfg_load_patterns(void) +{ + struct strbuf **s; + const char *envvar; + + if (tr2_cfg_loaded) + return tr2_cfg_count_patterns; + tr2_cfg_loaded = 1; + + envvar = getenv(TR2_ENVVAR_CFG_PARAM); + if (!envvar || !*envvar) + return tr2_cfg_count_patterns; + + tr2_cfg_patterns = strbuf_split_buf(envvar, strlen(envvar), ',', -1); + for (s = tr2_cfg_patterns; *s; s++) { + struct strbuf *buf = *s; + + if (buf->len && buf->buf[buf->len - 1] == ',') + strbuf_setlen(buf, buf->len - 1); + strbuf_trim_trailing_newline(*s); + strbuf_trim(*s); + } + + tr2_cfg_count_patterns = s - tr2_cfg_patterns; + return tr2_cfg_count_patterns; +} + +void tr2_cfg_free_patterns(void) +{ + if (tr2_cfg_patterns) + strbuf_list_free(tr2_cfg_patterns); + tr2_cfg_count_patterns = 0; + tr2_cfg_loaded = 0; +} + +struct tr2_cfg_data { + const char *file; + int line; +}; + +/* + * See if the given config key matches any of our patterns of interest. + */ +static int tr2_cfg_cb(const char *key, const char *value, void *d) +{ + struct strbuf **s; + struct tr2_cfg_data *data = (struct tr2_cfg_data *)d; + + for (s = tr2_cfg_patterns; *s; s++) { + struct strbuf *buf = *s; + int wm = wildmatch(buf->buf, key, WM_CASEFOLD); + if (wm == WM_MATCH) { + trace2_def_param_fl(data->file, data->line, key, value); + return 0; + } + } + + return 0; +} + +void tr2_cfg_list_config_fl(const char *file, int line) +{ + struct tr2_cfg_data data = { file, line }; + + if (tr2_cfg_load_patterns() > 0) + read_early_config(tr2_cfg_cb, &data); +} + +void tr2_cfg_set_fl(const char *file, int line, const char *key, + const char *value) +{ + struct tr2_cfg_data data = { file, line }; + + if (tr2_cfg_load_patterns() > 0) + tr2_cfg_cb(key, value, &data); +} diff --git a/trace2/tr2_cfg.h b/trace2/tr2_cfg.h new file mode 100644 index 0000000000..d9c98f64dd --- /dev/null +++ b/trace2/tr2_cfg.h @@ -0,0 +1,19 @@ +#ifndef TR2_CFG_H +#define TR2_CFG_H + +/* + * Iterate over all config settings and emit 'def_param' events for the + * "interesting" ones to TRACE2. + */ +void tr2_cfg_list_config_fl(const char *file, int line); + +/* + * Emit a "def_param" event for the given key/value pair IF we consider + * the key to be "interesting". + */ +void tr2_cfg_set_fl(const char *file, int line, const char *key, + const char *value); + +void tr2_cfg_free_patterns(void); + +#endif /* TR2_CFG_H */ diff --git a/trace2/tr2_cmd_name.c b/trace2/tr2_cmd_name.c new file mode 100644 index 0000000000..e999592b4c --- /dev/null +++ b/trace2/tr2_cmd_name.c @@ -0,0 +1,30 @@ +#include "cache.h" +#include "trace2/tr2_cmd_name.h" + +#define TR2_ENVVAR_PARENT_NAME "GIT_TR2_PARENT_NAME" + +static struct strbuf tr2cmdname_hierarchy = STRBUF_INIT; + +void tr2_cmd_name_append_hierarchy(const char *name) +{ + const char *parent_name = getenv(TR2_ENVVAR_PARENT_NAME); + + strbuf_reset(&tr2cmdname_hierarchy); + if (parent_name && *parent_name) { + strbuf_addstr(&tr2cmdname_hierarchy, parent_name); + strbuf_addch(&tr2cmdname_hierarchy, '/'); + } + strbuf_addstr(&tr2cmdname_hierarchy, name); + + setenv(TR2_ENVVAR_PARENT_NAME, tr2cmdname_hierarchy.buf, 1); +} + +const char *tr2_cmd_name_get_hierarchy(void) +{ + return tr2cmdname_hierarchy.buf; +} + +void tr2_cmd_name_release(void) +{ + strbuf_release(&tr2cmdname_hierarchy); +} diff --git a/trace2/tr2_cmd_name.h b/trace2/tr2_cmd_name.h new file mode 100644 index 0000000000..ab70b67a8e --- /dev/null +++ b/trace2/tr2_cmd_name.h @@ -0,0 +1,24 @@ +#ifndef TR2_CMD_NAME_H +#define TR2_CMD_NAME_H + +/* + * Append the current command name to the list being maintained + * in the environment. + * + * The hierarchy for a top-level git command is just the current + * command name. For a child git process, the hierarchy includes the + * names of the parent processes. + * + * The hierarchy for the current process will be exported to the + * environment and inherited by child processes. + */ +void tr2_cmd_name_append_hierarchy(const char *name); + +/* + * Get the command name hierarchy for the current process. + */ +const char *tr2_cmd_name_get_hierarchy(void); + +void tr2_cmd_name_release(void); + +#endif /* TR2_CMD_NAME_H */ diff --git a/trace2/tr2_dst.c b/trace2/tr2_dst.c new file mode 100644 index 0000000000..fd490a43ad --- /dev/null +++ b/trace2/tr2_dst.c @@ -0,0 +1,252 @@ +#include "cache.h" +#include "trace2/tr2_dst.h" + +/* + * If a Trace2 target cannot be opened for writing, we should issue a + * warning to stderr, but this is very annoying if the target is a pipe + * or socket and beyond the user's control -- especially since every + * git command (and sub-command) will print the message. So we silently + * eat these warnings and just discard the trace data. + * + * Enable the following environment variable to see these warnings. + */ +#define TR2_ENVVAR_DST_DEBUG "GIT_TR2_DST_DEBUG" + +static int tr2_dst_want_warning(void) +{ + static int tr2env_dst_debug = -1; + + if (tr2env_dst_debug == -1) { + const char *env_value = getenv(TR2_ENVVAR_DST_DEBUG); + if (!env_value || !*env_value) + tr2env_dst_debug = 0; + else + tr2env_dst_debug = atoi(env_value) > 0; + } + + return tr2env_dst_debug; +} + +void tr2_dst_trace_disable(struct tr2_dst *dst) +{ + if (dst->need_close) + close(dst->fd); + dst->fd = 0; + dst->initialized = 1; + dst->need_close = 0; +} + +static int tr2_dst_try_path(struct tr2_dst *dst, const char *tgt_value) +{ + int fd = open(tgt_value, O_WRONLY | O_APPEND | O_CREAT, 0666); + if (fd == -1) { + if (tr2_dst_want_warning()) + warning("trace2: could not open '%s' for '%s' tracing: %s", + tgt_value, dst->env_var_name, strerror(errno)); + + tr2_dst_trace_disable(dst); + return 0; + } + + dst->fd = fd; + dst->need_close = 1; + dst->initialized = 1; + + return dst->fd; +} + +#ifndef NO_UNIX_SOCKETS +#define PREFIX_AF_UNIX "af_unix:" +#define PREFIX_AF_UNIX_STREAM "af_unix:stream:" +#define PREFIX_AF_UNIX_DGRAM "af_unix:dgram:" + +static int tr2_dst_try_uds_connect(const char *path, int sock_type, int *out_fd) +{ + int fd; + struct sockaddr_un sa; + + fd = socket(AF_UNIX, sock_type, 0); + if (fd == -1) + return errno; + + sa.sun_family = AF_UNIX; + strlcpy(sa.sun_path, path, sizeof(sa.sun_path)); + + if (connect(fd, (struct sockaddr *)&sa, sizeof(sa)) == -1) { + int e = errno; + close(fd); + return e; + } + + *out_fd = fd; + return 0; +} + +#define TR2_DST_UDS_TRY_STREAM (1 << 0) +#define TR2_DST_UDS_TRY_DGRAM (1 << 1) + +static int tr2_dst_try_unix_domain_socket(struct tr2_dst *dst, + const char *tgt_value) +{ + unsigned int uds_try = 0; + int fd; + int e; + const char *path = NULL; + + /* + * Allow "af_unix:[<type>:]<absolute_path>" + * + * Trace2 always writes complete individual messages (without + * chunking), so we can talk to either DGRAM or STREAM type sockets. + * + * Allow the user to explicitly request the socket type. + * + * If they omit the socket type, try one and then the other. + */ + + if (skip_prefix(tgt_value, PREFIX_AF_UNIX_STREAM, &path)) + uds_try |= TR2_DST_UDS_TRY_STREAM; + + else if (skip_prefix(tgt_value, PREFIX_AF_UNIX_DGRAM, &path)) + uds_try |= TR2_DST_UDS_TRY_DGRAM; + + else if (skip_prefix(tgt_value, PREFIX_AF_UNIX, &path)) + uds_try |= TR2_DST_UDS_TRY_STREAM | TR2_DST_UDS_TRY_DGRAM; + + if (!path || !*path) { + if (tr2_dst_want_warning()) + warning("trace2: invalid AF_UNIX value '%s' for '%s' tracing", + tgt_value, dst->env_var_name); + + tr2_dst_trace_disable(dst); + return 0; + } + + if (!is_absolute_path(path) || + strlen(path) >= sizeof(((struct sockaddr_un *)0)->sun_path)) { + if (tr2_dst_want_warning()) + warning("trace2: invalid AF_UNIX path '%s' for '%s' tracing", + path, dst->env_var_name); + + tr2_dst_trace_disable(dst); + return 0; + } + + if (uds_try & TR2_DST_UDS_TRY_STREAM) { + e = tr2_dst_try_uds_connect(path, SOCK_STREAM, &fd); + if (!e) + goto connected; + if (e != EPROTOTYPE) + goto error; + } + if (uds_try & TR2_DST_UDS_TRY_DGRAM) { + e = tr2_dst_try_uds_connect(path, SOCK_DGRAM, &fd); + if (!e) + goto connected; + } + +error: + if (tr2_dst_want_warning()) + warning("trace2: could not connect to socket '%s' for '%s' tracing: %s", + path, dst->env_var_name, strerror(e)); + + tr2_dst_trace_disable(dst); + return 0; + +connected: + dst->fd = fd; + dst->need_close = 1; + dst->initialized = 1; + + return dst->fd; +} +#endif + +static void tr2_dst_malformed_warning(struct tr2_dst *dst, + const char *tgt_value) +{ + struct strbuf buf = STRBUF_INIT; + + strbuf_addf(&buf, "trace2: unknown value for '%s': '%s'", + dst->env_var_name, tgt_value); + warning("%s", buf.buf); + + strbuf_release(&buf); +} + +int tr2_dst_get_trace_fd(struct tr2_dst *dst) +{ + const char *tgt_value; + + /* don't open twice */ + if (dst->initialized) + return dst->fd; + + dst->initialized = 1; + + tgt_value = getenv(dst->env_var_name); + + if (!tgt_value || !strcmp(tgt_value, "") || !strcmp(tgt_value, "0") || + !strcasecmp(tgt_value, "false")) { + dst->fd = 0; + return dst->fd; + } + + if (!strcmp(tgt_value, "1") || !strcasecmp(tgt_value, "true")) { + dst->fd = STDERR_FILENO; + return dst->fd; + } + + if (strlen(tgt_value) == 1 && isdigit(*tgt_value)) { + dst->fd = atoi(tgt_value); + return dst->fd; + } + + if (is_absolute_path(tgt_value)) + return tr2_dst_try_path(dst, tgt_value); + +#ifndef NO_UNIX_SOCKETS + if (starts_with(tgt_value, PREFIX_AF_UNIX)) + return tr2_dst_try_unix_domain_socket(dst, tgt_value); +#endif + + /* Always warn about malformed values. */ + tr2_dst_malformed_warning(dst, tgt_value); + tr2_dst_trace_disable(dst); + return 0; +} + +int tr2_dst_trace_want(struct tr2_dst *dst) +{ + return !!tr2_dst_get_trace_fd(dst); +} + +void tr2_dst_write_line(struct tr2_dst *dst, struct strbuf *buf_line) +{ + int fd = tr2_dst_get_trace_fd(dst); + + strbuf_complete_line(buf_line); /* ensure final NL on buffer */ + + /* + * We do not use write_in_full() because we do not want + * a short-write to try again. We are using O_APPEND mode + * files and the kernel handles the atomic seek+write. If + * another thread or git process is concurrently writing to + * this fd or file, our remainder-write may not be contiguous + * with our initial write of this message. And that will + * confuse readers. So just don't bother. + * + * It is assumed that TRACE2 messages are short enough that + * the system can write them in 1 attempt and we won't see + * a short-write. + * + * If we get an IO error, just close the trace dst. + */ + if (write(fd, buf_line->buf, buf_line->len) >= 0) + return; + + if (tr2_dst_want_warning()) + warning("unable to write trace to '%s': %s", dst->env_var_name, + strerror(errno)); + tr2_dst_trace_disable(dst); +} diff --git a/trace2/tr2_dst.h b/trace2/tr2_dst.h new file mode 100644 index 0000000000..9a64f05b02 --- /dev/null +++ b/trace2/tr2_dst.h @@ -0,0 +1,36 @@ +#ifndef TR2_DST_H +#define TR2_DST_H + +struct strbuf; + +struct tr2_dst { + const char *const env_var_name; + int fd; + unsigned int initialized : 1; + unsigned int need_close : 1; +}; + +/* + * Disable TRACE2 on the destination. In TRACE2 a destination (DST) + * wraps a file descriptor; it is associated with a TARGET which + * defines the formatting. + */ +void tr2_dst_trace_disable(struct tr2_dst *dst); + +/* + * Return the file descriptor for the DST. + * If 0, the dst is closed or disabled. + */ +int tr2_dst_get_trace_fd(struct tr2_dst *dst); + +/* + * Return true if the DST is opened for writing. + */ +int tr2_dst_trace_want(struct tr2_dst *dst); + +/* + * Write a single line/message to the trace file. + */ +void tr2_dst_write_line(struct tr2_dst *dst, struct strbuf *buf_line); + +#endif /* TR2_DST_H */ diff --git a/trace2/tr2_sid.c b/trace2/tr2_sid.c new file mode 100644 index 0000000000..984524a43c --- /dev/null +++ b/trace2/tr2_sid.c @@ -0,0 +1,67 @@ +#include "cache.h" +#include "trace2/tr2_sid.h" + +#define TR2_ENVVAR_PARENT_SID "GIT_TR2_PARENT_SID" + +static struct strbuf tr2sid_buf = STRBUF_INIT; +static int tr2sid_nr_git_parents; + +/* + * Compute a "unique" session id (SID) for the current process. This allows + * all events from this process to have a single label (much like a PID). + * + * Export this into our environment so that all child processes inherit it. + * + * If we were started by another git instance, use our parent's SID as a + * prefix. (This lets us track parent/child relationships even if there + * is an intermediate shell process.) + * + * Additionally, count the number of nested git processes. + */ +static void tr2_sid_compute(void) +{ + uint64_t us_now; + const char *parent_sid; + + if (tr2sid_buf.len) + return; + + parent_sid = getenv(TR2_ENVVAR_PARENT_SID); + if (parent_sid && *parent_sid) { + const char *p; + for (p = parent_sid; *p; p++) + if (*p == '/') + tr2sid_nr_git_parents++; + + strbuf_addstr(&tr2sid_buf, parent_sid); + strbuf_addch(&tr2sid_buf, '/'); + tr2sid_nr_git_parents++; + } + + us_now = getnanotime() / 1000; + strbuf_addf(&tr2sid_buf, "%" PRIuMAX "-%" PRIdMAX, (uintmax_t)us_now, + (intmax_t)getpid()); + + setenv(TR2_ENVVAR_PARENT_SID, tr2sid_buf.buf, 1); +} + +const char *tr2_sid_get(void) +{ + if (!tr2sid_buf.len) + tr2_sid_compute(); + + return tr2sid_buf.buf; +} + +int tr2_sid_depth(void) +{ + if (!tr2sid_buf.len) + tr2_sid_compute(); + + return tr2sid_nr_git_parents; +} + +void tr2_sid_release(void) +{ + strbuf_release(&tr2sid_buf); +} diff --git a/trace2/tr2_sid.h b/trace2/tr2_sid.h new file mode 100644 index 0000000000..9bef321708 --- /dev/null +++ b/trace2/tr2_sid.h @@ -0,0 +1,18 @@ +#ifndef TR2_SID_H +#define TR2_SID_H + +/* + * Get our session id. Compute if necessary. + */ +const char *tr2_sid_get(void); + +/* + * Get our process depth. A top-level git process invoked from the + * command line will have depth=0. A child git process will have + * depth=1 and so on. + */ +int tr2_sid_depth(void); + +void tr2_sid_release(void); + +#endif /* TR2_SID_H */ diff --git a/trace2/tr2_tbuf.c b/trace2/tr2_tbuf.c new file mode 100644 index 0000000000..0844910423 --- /dev/null +++ b/trace2/tr2_tbuf.c @@ -0,0 +1,32 @@ +#include "cache.h" +#include "tr2_tbuf.h" + +void tr2_tbuf_local_time(struct tr2_tbuf *tb) +{ + struct timeval tv; + struct tm tm; + time_t secs; + + gettimeofday(&tv, NULL); + secs = tv.tv_sec; + localtime_r(&secs, &tm); + + xsnprintf(tb->buf, sizeof(tb->buf), "%02d:%02d:%02d.%06ld", tm.tm_hour, + tm.tm_min, tm.tm_sec, (long)tv.tv_usec); +} + +void tr2_tbuf_utc_time(struct tr2_tbuf *tb) +{ + struct timeval tv; + struct tm tm; + time_t secs; + + gettimeofday(&tv, NULL); + secs = tv.tv_sec; + gmtime_r(&secs, &tm); + + xsnprintf(tb->buf, sizeof(tb->buf), + "%4d-%02d-%02d %02d:%02d:%02d.%06ld", tm.tm_year + 1900, + tm.tm_mon + 1, tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec, + (long)tv.tv_usec); +} diff --git a/trace2/tr2_tbuf.h b/trace2/tr2_tbuf.h new file mode 100644 index 0000000000..9cdefa3957 --- /dev/null +++ b/trace2/tr2_tbuf.h @@ -0,0 +1,23 @@ +#ifndef TR2_TBUF_H +#define TR2_TBUF_H + +/* + * A simple wrapper around a fixed buffer to avoid C syntax + * quirks and the need to pass around an additional size_t + * argument. + */ +struct tr2_tbuf { + char buf[32]; +}; + +/* + * Fill buffer with formatted local time string. + */ +void tr2_tbuf_local_time(struct tr2_tbuf *tb); + +/* + * Fill buffer with formatted UTC time string. + */ +void tr2_tbuf_utc_time(struct tr2_tbuf *tb); + +#endif /* TR2_TBUF_H */ diff --git a/trace2/tr2_tgt.h b/trace2/tr2_tgt.h new file mode 100644 index 0000000000..297bb8ffbe --- /dev/null +++ b/trace2/tr2_tgt.h @@ -0,0 +1,133 @@ +#ifndef TR2_TGT_H +#define TR2_TGT_H + +struct child_process; +struct repository; +struct json_writer; + +/* + * Function prototypes for a TRACE2 "target" vtable. + */ + +typedef int(tr2_tgt_init_t)(void); +typedef void(tr2_tgt_term_t)(void); + +typedef void(tr2_tgt_evt_version_fl_t)(const char *file, int line); + +typedef void(tr2_tgt_evt_start_fl_t)(const char *file, int line, + const char **argv); +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_atexit_t)(uint64_t us_elapsed_absolute, int code); + +typedef void(tr2_tgt_evt_error_va_fl_t)(const char *file, int line, + const char *fmt, va_list ap); + +typedef void(tr2_tgt_evt_command_path_fl_t)(const char *file, int line, + const char *command_path); +typedef void(tr2_tgt_evt_command_name_fl_t)(const char *file, int line, + const char *name, + const char *hierarchy); +typedef void(tr2_tgt_evt_command_mode_fl_t)(const char *file, int line, + const char *mode); + +typedef void(tr2_tgt_evt_alias_fl_t)(const char *file, int line, + const char *alias, const char **argv); + +typedef void(tr2_tgt_evt_child_start_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, + const struct child_process *cmd); +typedef void(tr2_tgt_evt_child_exit_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, int cid, + int pid, int code, + uint64_t us_elapsed_child); + +typedef void(tr2_tgt_evt_thread_start_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute); +typedef void(tr2_tgt_evt_thread_exit_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, + uint64_t us_elapsed_thread); + +typedef void(tr2_tgt_evt_exec_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, int exec_id, + const char *exe, const char **argv); +typedef void(tr2_tgt_evt_exec_result_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, + int exec_id, int code); + +typedef void(tr2_tgt_evt_param_fl_t)(const char *file, int line, + const char *param, const char *value); + +typedef void(tr2_tgt_evt_repo_fl_t)(const char *file, int line, + const struct repository *repo); + +typedef void(tr2_tgt_evt_region_enter_printf_va_fl_t)( + const char *file, int line, uint64_t us_elapsed_absolute, + const char *category, const char *label, const struct repository *repo, + const char *fmt, va_list ap); +typedef void(tr2_tgt_evt_region_leave_printf_va_fl_t)( + const char *file, int line, uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, const char *category, const char *label, + const struct repository *repo, const char *fmt, va_list ap); + +typedef void(tr2_tgt_evt_data_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, + const char *category, + const struct repository *repo, + const char *key, const char *value); +typedef void(tr2_tgt_evt_data_json_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, + const char *category, + const struct repository *repo, + const char *key, + const struct json_writer *value); + +typedef void(tr2_tgt_evt_printf_va_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, + const char *fmt, va_list ap); + +/* + * "vtable" for a TRACE2 target. Use NULL if a target does not want + * to emit that message. + */ +/* clang-format off */ +struct tr2_tgt { + struct tr2_dst *pdst; + + tr2_tgt_init_t *pfn_init; + tr2_tgt_term_t *pfn_term; + + tr2_tgt_evt_version_fl_t *pfn_version_fl; + 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_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; + tr2_tgt_evt_command_name_fl_t *pfn_command_name_fl; + tr2_tgt_evt_command_mode_fl_t *pfn_command_mode_fl; + tr2_tgt_evt_alias_fl_t *pfn_alias_fl; + tr2_tgt_evt_child_start_fl_t *pfn_child_start_fl; + tr2_tgt_evt_child_exit_fl_t *pfn_child_exit_fl; + tr2_tgt_evt_thread_start_fl_t *pfn_thread_start_fl; + tr2_tgt_evt_thread_exit_fl_t *pfn_thread_exit_fl; + tr2_tgt_evt_exec_fl_t *pfn_exec_fl; + tr2_tgt_evt_exec_result_fl_t *pfn_exec_result_fl; + tr2_tgt_evt_param_fl_t *pfn_param_fl; + tr2_tgt_evt_repo_fl_t *pfn_repo_fl; + tr2_tgt_evt_region_enter_printf_va_fl_t *pfn_region_enter_printf_va_fl; + tr2_tgt_evt_region_leave_printf_va_fl_t *pfn_region_leave_printf_va_fl; + tr2_tgt_evt_data_fl_t *pfn_data_fl; + tr2_tgt_evt_data_json_fl_t *pfn_data_json_fl; + tr2_tgt_evt_printf_va_fl_t *pfn_printf_va_fl; +}; +/* clang-format on */ + +extern struct tr2_tgt tr2_tgt_event; +extern struct tr2_tgt tr2_tgt_normal; +extern struct tr2_tgt tr2_tgt_perf; + +#endif /* TR2_TGT_H */ diff --git a/trace2/tr2_tgt_event.c b/trace2/tr2_tgt_event.c new file mode 100644 index 0000000000..107cb5317d --- /dev/null +++ b/trace2/tr2_tgt_event.c @@ -0,0 +1,588 @@ +#include "cache.h" +#include "config.h" +#include "json-writer.h" +#include "run-command.h" +#include "version.h" +#include "trace2/tr2_dst.h" +#include "trace2/tr2_tbuf.h" +#include "trace2/tr2_sid.h" +#include "trace2/tr2_tgt.h" +#include "trace2/tr2_tls.h" + +static struct tr2_dst tr2dst_event = { "GIT_TR2_EVENT", 0, 0, 0 }; + +/* + * The version number of the JSON data generated by the EVENT target + * in this source file. Update this if you make a significant change + * to the JSON fields or message structure. You probably do not need + * to update this if you just add another call to one of the existing + * TRACE2 API methods. + */ +#define TR2_EVENT_VERSION "1" + +/* + * Region nesting limit for messages written to the event target. + * + * The "region_enter" and "region_leave" messages (especially recursive + * messages such as those produced while diving the worktree or index) + * are primarily intended for the performance target during debugging. + * + * Some of the outer-most messages, however, may be of interest to the + * event target. Set this environment variable to a larger integer for + * more detail in the event target. + */ +#define TR2_ENVVAR_EVENT_NESTING "GIT_TR2_EVENT_NESTING" +static int tr2env_event_nesting_wanted = 2; + +/* + * Set this environment variable to true to omit the <time>, <file>, and + * <line> fields from most events. + */ +#define TR2_ENVVAR_EVENT_BRIEF "GIT_TR2_EVENT_BRIEF" +static int tr2env_event_brief; + +static int fn_init(void) +{ + int want = tr2_dst_trace_want(&tr2dst_event); + int want_nesting; + int want_brief; + char *nesting; + char *brief; + + if (!want) + return want; + + nesting = getenv(TR2_ENVVAR_EVENT_NESTING); + if (nesting && ((want_nesting = atoi(nesting)) > 0)) + tr2env_event_nesting_wanted = want_nesting; + + brief = getenv(TR2_ENVVAR_EVENT_BRIEF); + if (brief && ((want_brief = atoi(brief)) > 0)) + tr2env_event_brief = want_brief; + + return want; +} + +static void fn_term(void) +{ + tr2_dst_trace_disable(&tr2dst_event); +} + +/* + * Append common key-value pairs to the currently open JSON object. + * "event:"<event_name>" + * "sid":"<sid>" + * "thread":"<thread_name>" + * "time":"<time>" + * "file":"<filename>" + * "line":<line_number> + * "repo":<repo_id> + */ +static void event_fmt_prepare(const char *event_name, const char *file, + int line, const struct repository *repo, + struct json_writer *jw) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + struct tr2_tbuf tb_now; + + jw_object_string(jw, "event", event_name); + jw_object_string(jw, "sid", tr2_sid_get()); + jw_object_string(jw, "thread", ctx->thread_name.buf); + + /* + * In brief mode, only emit <time> on these 2 event types. + */ + if (!tr2env_event_brief || !strcmp(event_name, "version") || + !strcmp(event_name, "atexit")) { + tr2_tbuf_utc_time(&tb_now); + jw_object_string(jw, "time", tb_now.buf); + } + + if (!tr2env_event_brief && file && *file) { + jw_object_string(jw, "file", file); + jw_object_intmax(jw, "line", line); + } + + if (repo) + jw_object_intmax(jw, "repo", repo->trace2_repo_id); +} + +static void fn_version_fl(const char *file, int line) +{ + const char *event_name = "version"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_string(&jw, "evt", TR2_EVENT_VERSION); + jw_object_string(&jw, "exe", git_version_string); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_start_fl(const char *file, int line, const char **argv) +{ + const char *event_name = "start"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_inline_begin_array(&jw, "argv"); + jw_array_argv(&jw, argv); + jw_end(&jw); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_exit_fl(const char *file, int line, uint64_t us_elapsed_absolute, + int code) +{ + const char *event_name = "exit"; + 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); + jw_object_double(&jw, "t_abs", 6, t_abs); + jw_object_intmax(&jw, "code", code); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_signal(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); + jw_object_double(&jw, "t_abs", 6, t_abs); + jw_object_intmax(&jw, "signo", signo); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_atexit(uint64_t us_elapsed_absolute, int code) +{ + const char *event_name = "atexit"; + 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); + jw_object_double(&jw, "t_abs", 6, t_abs); + jw_object_intmax(&jw, "code", code); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void maybe_add_string_va(struct json_writer *jw, const char *field_name, + const char *fmt, va_list ap) +{ + if (fmt && *fmt && ap) { + va_list copy_ap; + struct strbuf buf = STRBUF_INIT; + + va_copy(copy_ap, ap); + strbuf_vaddf(&buf, fmt, copy_ap); + va_end(copy_ap); + + jw_object_string(jw, field_name, buf.buf); + strbuf_release(&buf); + return; + } + + if (fmt && *fmt) { + jw_object_string(jw, field_name, fmt); + return; + } +} + +static void fn_error_va_fl(const char *file, int line, const char *fmt, + va_list ap) +{ + const char *event_name = "error"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + maybe_add_string_va(&jw, "msg", fmt, ap); + /* + * Also emit the format string as a field in case + * post-processors want to aggregate common error + * messages by type without argument fields (such + * as pathnames or branch names) cluttering it up. + */ + if (fmt && *fmt) + jw_object_string(&jw, "fmt", fmt); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_command_path_fl(const char *file, int line, const char *pathname) +{ + const char *event_name = "cmd_path"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_string(&jw, "path", pathname); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_command_name_fl(const char *file, int line, const char *name, + const char *hierarchy) +{ + const char *event_name = "cmd_name"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_string(&jw, "name", name); + if (hierarchy && *hierarchy) + jw_object_string(&jw, "hierarchy", hierarchy); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_command_mode_fl(const char *file, int line, const char *mode) +{ + const char *event_name = "cmd_mode"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_string(&jw, "name", mode); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_alias_fl(const char *file, int line, const char *alias, + const char **argv) +{ + const char *event_name = "alias"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_string(&jw, "alias", alias); + jw_object_inline_begin_array(&jw, "argv"); + jw_array_argv(&jw, argv); + jw_end(&jw); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_child_start_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + const struct child_process *cmd) +{ + const char *event_name = "child_start"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_intmax(&jw, "child_id", cmd->trace2_child_id); + if (cmd->trace2_hook_name) { + jw_object_string(&jw, "child_class", "hook"); + jw_object_string(&jw, "hook_name", cmd->trace2_hook_name); + } else { + const char *child_class = + cmd->trace2_child_class ? cmd->trace2_child_class : "?"; + jw_object_string(&jw, "child_class", child_class); + } + if (cmd->dir) + jw_object_string(&jw, "cd", cmd->dir); + jw_object_bool(&jw, "use_shell", cmd->use_shell); + jw_object_inline_begin_array(&jw, "argv"); + if (cmd->git_cmd) + jw_array_string(&jw, "git"); + jw_array_argv(&jw, cmd->argv); + jw_end(&jw); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_child_exit_fl(const char *file, int line, + uint64_t us_elapsed_absolute, int cid, int pid, + int code, uint64_t us_elapsed_child) +{ + const char *event_name = "child_exit"; + struct json_writer jw = JSON_WRITER_INIT; + double t_rel = (double)us_elapsed_child / 1000000.0; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_intmax(&jw, "child_id", cid); + jw_object_intmax(&jw, "pid", pid); + jw_object_intmax(&jw, "code", code); + jw_object_double(&jw, "t_rel", 6, t_rel); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + + jw_release(&jw); +} + +static void fn_thread_start_fl(const char *file, int line, + uint64_t us_elapsed_absolute) +{ + const char *event_name = "thread_start"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_thread_exit_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + uint64_t us_elapsed_thread) +{ + const char *event_name = "thread_exit"; + struct json_writer jw = JSON_WRITER_INIT; + double t_rel = (double)us_elapsed_thread / 1000000.0; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_double(&jw, "t_rel", 6, t_rel); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_exec_fl(const char *file, int line, uint64_t us_elapsed_absolute, + int exec_id, const char *exe, const char **argv) +{ + const char *event_name = "exec"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_intmax(&jw, "exec_id", exec_id); + if (exe) + jw_object_string(&jw, "exe", exe); + jw_object_inline_begin_array(&jw, "argv"); + jw_array_argv(&jw, argv); + jw_end(&jw); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_exec_result_fl(const char *file, int line, + uint64_t us_elapsed_absolute, int exec_id, + int code) +{ + const char *event_name = "exec_result"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_intmax(&jw, "exec_id", exec_id); + jw_object_intmax(&jw, "code", code); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_param_fl(const char *file, int line, const char *param, + const char *value) +{ + const char *event_name = "def_param"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_string(&jw, "param", param); + jw_object_string(&jw, "value", value); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_repo_fl(const char *file, int line, + const struct repository *repo) +{ + const char *event_name = "def_repo"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, repo, &jw); + jw_object_string(&jw, "worktree", repo->worktree); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_region_enter_printf_va_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + const char *category, + const char *label, + const struct repository *repo, + const char *fmt, va_list ap) +{ + const char *event_name = "region_enter"; + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + if (ctx->nr_open_regions <= tr2env_event_nesting_wanted) { + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, repo, &jw); + jw_object_intmax(&jw, "nesting", ctx->nr_open_regions); + if (category) + jw_object_string(&jw, "category", category); + if (label) + jw_object_string(&jw, "label", label); + maybe_add_string_va(&jw, "msg", fmt, ap); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); + } +} + +static void fn_region_leave_printf_va_fl( + const char *file, int line, uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, const char *category, const char *label, + const struct repository *repo, const char *fmt, va_list ap) +{ + const char *event_name = "region_leave"; + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + if (ctx->nr_open_regions <= tr2env_event_nesting_wanted) { + struct json_writer jw = JSON_WRITER_INIT; + double t_rel = (double)us_elapsed_region / 1000000.0; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, repo, &jw); + jw_object_double(&jw, "t_rel", 6, t_rel); + jw_object_intmax(&jw, "nesting", ctx->nr_open_regions); + if (category) + jw_object_string(&jw, "category", category); + if (label) + jw_object_string(&jw, "label", label); + maybe_add_string_va(&jw, "msg", fmt, ap); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); + } +} + +static void fn_data_fl(const char *file, int line, uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, const char *category, + const struct repository *repo, const char *key, + const char *value) +{ + const char *event_name = "data"; + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + if (ctx->nr_open_regions <= tr2env_event_nesting_wanted) { + struct json_writer jw = JSON_WRITER_INIT; + double t_abs = (double)us_elapsed_absolute / 1000000.0; + double t_rel = (double)us_elapsed_region / 1000000.0; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, repo, &jw); + jw_object_double(&jw, "t_abs", 6, t_abs); + jw_object_double(&jw, "t_rel", 6, t_rel); + jw_object_intmax(&jw, "nesting", ctx->nr_open_regions); + jw_object_string(&jw, "category", category); + jw_object_string(&jw, "key", key); + jw_object_string(&jw, "value", value); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); + } +} + +static void fn_data_json_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, const char *category, + const struct repository *repo, const char *key, + const struct json_writer *value) +{ + const char *event_name = "data_json"; + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + if (ctx->nr_open_regions <= tr2env_event_nesting_wanted) { + struct json_writer jw = JSON_WRITER_INIT; + double t_abs = (double)us_elapsed_absolute / 1000000.0; + double t_rel = (double)us_elapsed_region / 1000000.0; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, repo, &jw); + jw_object_double(&jw, "t_abs", 6, t_abs); + jw_object_double(&jw, "t_rel", 6, t_rel); + jw_object_intmax(&jw, "nesting", ctx->nr_open_regions); + jw_object_string(&jw, "category", category); + jw_object_string(&jw, "key", key); + jw_object_sub_jw(&jw, "value", value); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); + } +} + +struct tr2_tgt tr2_tgt_event = { + &tr2dst_event, + + fn_init, + fn_term, + + fn_version_fl, + fn_start_fl, + fn_exit_fl, + fn_signal, + fn_atexit, + fn_error_va_fl, + fn_command_path_fl, + fn_command_name_fl, + fn_command_mode_fl, + fn_alias_fl, + fn_child_start_fl, + fn_child_exit_fl, + fn_thread_start_fl, + fn_thread_exit_fl, + fn_exec_fl, + fn_exec_result_fl, + fn_param_fl, + fn_repo_fl, + fn_region_enter_printf_va_fl, + fn_region_leave_printf_va_fl, + fn_data_fl, + fn_data_json_fl, + NULL, /* printf */ +}; diff --git a/trace2/tr2_tgt_normal.c b/trace2/tr2_tgt_normal.c new file mode 100644 index 0000000000..547183d5b6 --- /dev/null +++ b/trace2/tr2_tgt_normal.c @@ -0,0 +1,323 @@ +#include "cache.h" +#include "config.h" +#include "run-command.h" +#include "quote.h" +#include "version.h" +#include "trace2/tr2_dst.h" +#include "trace2/tr2_tbuf.h" +#include "trace2/tr2_tgt.h" +#include "trace2/tr2_tls.h" + +static struct tr2_dst tr2dst_normal = { "GIT_TR2", 0, 0, 0 }; + +/* + * Set this environment variable to true to omit the "<time> <file>:<line>" + * fields from each line written to the builtin normal target. + * + * Unit tests may want to use this to help with testing. + */ +#define TR2_ENVVAR_NORMAL_BRIEF "GIT_TR2_BRIEF" +static int tr2env_normal_brief; + +#define TR2FMT_NORMAL_FL_WIDTH (50) + +static int fn_init(void) +{ + int want = tr2_dst_trace_want(&tr2dst_normal); + int want_brief; + char *brief; + + if (!want) + return want; + + brief = getenv(TR2_ENVVAR_NORMAL_BRIEF); + if (brief && *brief && + ((want_brief = git_parse_maybe_bool(brief)) != -1)) + tr2env_normal_brief = want_brief; + + return want; +} + +static void fn_term(void) +{ + tr2_dst_trace_disable(&tr2dst_normal); +} + +static void normal_fmt_prepare(const char *file, int line, struct strbuf *buf) +{ + strbuf_setlen(buf, 0); + + if (!tr2env_normal_brief) { + struct tr2_tbuf tb_now; + + tr2_tbuf_local_time(&tb_now); + strbuf_addstr(buf, tb_now.buf); + strbuf_addch(buf, ' '); + + if (file && *file) + strbuf_addf(buf, "%s:%d ", file, line); + while (buf->len < TR2FMT_NORMAL_FL_WIDTH) + strbuf_addch(buf, ' '); + } +} + +static void normal_io_write_fl(const char *file, int line, + const struct strbuf *buf_payload) +{ + struct strbuf buf_line = STRBUF_INIT; + + normal_fmt_prepare(file, line, &buf_line); + strbuf_addbuf(&buf_line, buf_payload); + tr2_dst_write_line(&tr2dst_normal, &buf_line); + strbuf_release(&buf_line); +} + +static void fn_version_fl(const char *file, int line) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "version %s", git_version_string); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_start_fl(const char *file, int line, const char **argv) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addstr(&buf_payload, "start "); + sq_quote_argv_pretty(&buf_payload, argv); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_exit_fl(const char *file, int line, uint64_t us_elapsed_absolute, + int code) +{ + struct strbuf buf_payload = STRBUF_INIT; + double elapsed = (double)us_elapsed_absolute / 1000000.0; + + strbuf_addf(&buf_payload, "exit elapsed:%.6f code:%d", elapsed, code); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_signal(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); + strbuf_release(&buf_payload); +} + +static void fn_atexit(uint64_t us_elapsed_absolute, int code) +{ + struct strbuf buf_payload = STRBUF_INIT; + double elapsed = (double)us_elapsed_absolute / 1000000.0; + + strbuf_addf(&buf_payload, "atexit elapsed:%.6f code:%d", elapsed, code); + normal_io_write_fl(__FILE__, __LINE__, &buf_payload); + strbuf_release(&buf_payload); +} + +static void maybe_append_string_va(struct strbuf *buf, const char *fmt, + va_list ap) +{ + if (fmt && *fmt && ap) { + va_list copy_ap; + + va_copy(copy_ap, ap); + strbuf_vaddf(buf, fmt, copy_ap); + va_end(copy_ap); + return; + } + + if (fmt && *fmt) { + strbuf_addstr(buf, fmt); + return; + } +} + +static void fn_error_va_fl(const char *file, int line, const char *fmt, + va_list ap) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addstr(&buf_payload, "error "); + maybe_append_string_va(&buf_payload, fmt, ap); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_command_path_fl(const char *file, int line, const char *pathname) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "cmd_path %s", pathname); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_command_name_fl(const char *file, int line, const char *name, + const char *hierarchy) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "cmd_name %s", name); + if (hierarchy && *hierarchy) + strbuf_addf(&buf_payload, " (%s)", hierarchy); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_command_mode_fl(const char *file, int line, const char *mode) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "cmd_mode %s", mode); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_alias_fl(const char *file, int line, const char *alias, + const char **argv) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "alias %s ->", alias); + sq_quote_argv_pretty(&buf_payload, argv); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_child_start_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + const struct child_process *cmd) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "child_start[%d] ", cmd->trace2_child_id); + + if (cmd->dir) { + strbuf_addstr(&buf_payload, " cd"); + sq_quote_buf_pretty(&buf_payload, cmd->dir); + strbuf_addstr(&buf_payload, "; "); + } + + /* + * TODO if (cmd->env) { Consider dumping changes to environment. } + * See trace_add_env() in run-command.c as used by original trace.c + */ + + if (cmd->git_cmd) + strbuf_addstr(&buf_payload, "git"); + sq_quote_argv_pretty(&buf_payload, cmd->argv); + + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_child_exit_fl(const char *file, int line, + uint64_t us_elapsed_absolute, int cid, int pid, + int code, uint64_t us_elapsed_child) +{ + struct strbuf buf_payload = STRBUF_INIT; + double elapsed = (double)us_elapsed_child / 1000000.0; + + strbuf_addf(&buf_payload, "child_exit[%d] pid:%d code:%d elapsed:%.6f", + cid, pid, code, elapsed); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_exec_fl(const char *file, int line, uint64_t us_elapsed_absolute, + int exec_id, const char *exe, const char **argv) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "exec[%d] ", exec_id); + if (exe) + strbuf_addstr(&buf_payload, exe); + sq_quote_argv_pretty(&buf_payload, argv); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_exec_result_fl(const char *file, int line, + uint64_t us_elapsed_absolute, int exec_id, + int code) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "exec_result[%d] code:%d", exec_id, code); + if (code > 0) + strbuf_addf(&buf_payload, " err:%s", strerror(code)); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_param_fl(const char *file, int line, const char *param, + const char *value) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "def_param %s=%s", param, value); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_repo_fl(const char *file, int line, + const struct repository *repo) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addstr(&buf_payload, "worktree "); + sq_quote_buf_pretty(&buf_payload, repo->worktree); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_printf_va_fl(const char *file, int line, + uint64_t us_elapsed_absolute, const char *fmt, + va_list ap) +{ + struct strbuf buf_payload = STRBUF_INIT; + + maybe_append_string_va(&buf_payload, fmt, ap); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +struct tr2_tgt tr2_tgt_normal = { + &tr2dst_normal, + + fn_init, + fn_term, + + fn_version_fl, + fn_start_fl, + fn_exit_fl, + fn_signal, + fn_atexit, + fn_error_va_fl, + fn_command_path_fl, + fn_command_name_fl, + fn_command_mode_fl, + fn_alias_fl, + fn_child_start_fl, + fn_child_exit_fl, + NULL, /* thread_start */ + NULL, /* thread_exit */ + fn_exec_fl, + fn_exec_result_fl, + fn_param_fl, + fn_repo_fl, + NULL, /* region_enter */ + NULL, /* region_leave */ + NULL, /* data */ + NULL, /* data_json */ + fn_printf_va_fl, +}; diff --git a/trace2/tr2_tgt_perf.c b/trace2/tr2_tgt_perf.c new file mode 100644 index 0000000000..f0746fcf86 --- /dev/null +++ b/trace2/tr2_tgt_perf.c @@ -0,0 +1,534 @@ +#include "cache.h" +#include "config.h" +#include "run-command.h" +#include "quote.h" +#include "version.h" +#include "json-writer.h" +#include "trace2/tr2_dst.h" +#include "trace2/tr2_sid.h" +#include "trace2/tr2_tbuf.h" +#include "trace2/tr2_tgt.h" +#include "trace2/tr2_tls.h" + +static struct tr2_dst tr2dst_perf = { "GIT_TR2_PERF", 0, 0, 0 }; + +/* + * Set this environment variable to true to omit the "<time> <file>:<line>" + * fields from each line written to the builtin performance target. + * + * Unit tests may want to use this to help with testing. + */ +#define TR2_ENVVAR_PERF_BRIEF "GIT_TR2_PERF_BRIEF" +static int tr2env_perf_brief; + +#define TR2FMT_PERF_FL_WIDTH (50) +#define TR2FMT_PERF_MAX_EVENT_NAME (12) +#define TR2FMT_PERF_REPO_WIDTH (4) +#define TR2FMT_PERF_CATEGORY_WIDTH (10) + +#define TR2_DOTS_BUFFER_SIZE (100) +#define TR2_INDENT (2) +#define TR2_INDENT_LENGTH(ctx) (((ctx)->nr_open_regions - 1) * TR2_INDENT) + +static struct strbuf dots = STRBUF_INIT; + +static int fn_init(void) +{ + int want = tr2_dst_trace_want(&tr2dst_perf); + int want_brief; + char *brief; + + if (!want) + return want; + + strbuf_addchars(&dots, '.', TR2_DOTS_BUFFER_SIZE); + + brief = getenv(TR2_ENVVAR_PERF_BRIEF); + if (brief && *brief && + ((want_brief = git_parse_maybe_bool(brief)) != -1)) + tr2env_perf_brief = want_brief; + + return want; +} + +static void fn_term(void) +{ + tr2_dst_trace_disable(&tr2dst_perf); + + strbuf_release(&dots); +} + +/* + * Format trace line prefix in human-readable classic format for + * the performance target: + * "[<time> [<file>:<line>] <bar>] <nr_parents> <bar> + * <thread_name> <bar> <event_name> <bar> [<repo>] <bar> + * [<elapsed_absolute>] [<elapsed_relative>] <bar> + * [<category>] <bar> [<dots>] " + */ +static void perf_fmt_prepare(const char *event_name, + struct tr2tls_thread_ctx *ctx, const char *file, + int line, const struct repository *repo, + uint64_t *p_us_elapsed_absolute, + uint64_t *p_us_elapsed_relative, + const char *category, struct strbuf *buf) +{ + int len; + + strbuf_setlen(buf, 0); + + if (!tr2env_perf_brief) { + struct tr2_tbuf tb_now; + + tr2_tbuf_local_time(&tb_now); + strbuf_addstr(buf, tb_now.buf); + strbuf_addch(buf, ' '); + + if (file && *file) + strbuf_addf(buf, "%s:%d ", file, line); + while (buf->len < TR2FMT_PERF_FL_WIDTH) + strbuf_addch(buf, ' '); + + strbuf_addstr(buf, "| "); + } + + strbuf_addf(buf, "d%d | ", tr2_sid_depth()); + strbuf_addf(buf, "%-*s | %-*s | ", TR2_MAX_THREAD_NAME, + ctx->thread_name.buf, TR2FMT_PERF_MAX_EVENT_NAME, + event_name); + + len = buf->len + TR2FMT_PERF_REPO_WIDTH; + if (repo) + strbuf_addf(buf, "r%d ", repo->trace2_repo_id); + while (buf->len < len) + strbuf_addch(buf, ' '); + strbuf_addstr(buf, "| "); + + if (p_us_elapsed_absolute) + strbuf_addf(buf, "%9.6f | ", + ((double)(*p_us_elapsed_absolute)) / 1000000.0); + else + strbuf_addf(buf, "%9s | ", " "); + + if (p_us_elapsed_relative) + strbuf_addf(buf, "%9.6f | ", + ((double)(*p_us_elapsed_relative)) / 1000000.0); + else + strbuf_addf(buf, "%9s | ", " "); + + strbuf_addf(buf, "%-*s | ", TR2FMT_PERF_CATEGORY_WIDTH, + (category ? category : "")); + + if (ctx->nr_open_regions > 0) { + int len_indent = TR2_INDENT_LENGTH(ctx); + while (len_indent > dots.len) { + strbuf_addbuf(buf, &dots); + len_indent -= dots.len; + } + strbuf_addf(buf, "%.*s", len_indent, dots.buf); + } +} + +static void perf_io_write_fl(const char *file, int line, const char *event_name, + const struct repository *repo, + uint64_t *p_us_elapsed_absolute, + uint64_t *p_us_elapsed_relative, + const char *category, + const struct strbuf *buf_payload) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + struct strbuf buf_line = STRBUF_INIT; + + perf_fmt_prepare(event_name, ctx, file, line, repo, + p_us_elapsed_absolute, p_us_elapsed_relative, category, + &buf_line); + strbuf_addbuf(&buf_line, buf_payload); + tr2_dst_write_line(&tr2dst_perf, &buf_line); + strbuf_release(&buf_line); +} + +static void fn_version_fl(const char *file, int line) +{ + const char *event_name = "version"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addstr(&buf_payload, git_version_string); + + perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL, + &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_start_fl(const char *file, int line, const char **argv) +{ + const char *event_name = "start"; + struct strbuf buf_payload = STRBUF_INIT; + + sq_quote_argv_pretty(&buf_payload, argv); + + perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL, + &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_exit_fl(const char *file, int line, uint64_t us_elapsed_absolute, + int code) +{ + const char *event_name = "exit"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "code:%d", code); + + 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) +{ + 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, + &us_elapsed_absolute, NULL, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_atexit(uint64_t us_elapsed_absolute, int code) +{ + const char *event_name = "atexit"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "code:%d", code); + + perf_io_write_fl(__FILE__, __LINE__, event_name, NULL, + &us_elapsed_absolute, NULL, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void maybe_append_string_va(struct strbuf *buf, const char *fmt, + va_list ap) +{ + if (fmt && *fmt && ap) { + va_list copy_ap; + + va_copy(copy_ap, ap); + strbuf_vaddf(buf, fmt, copy_ap); + va_end(copy_ap); + return; + } + + if (fmt && *fmt) { + strbuf_addstr(buf, fmt); + return; + } +} + +static void fn_error_va_fl(const char *file, int line, const char *fmt, + va_list ap) +{ + const char *event_name = "error"; + struct strbuf buf_payload = STRBUF_INIT; + + maybe_append_string_va(&buf_payload, fmt, ap); + + perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL, + &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_command_path_fl(const char *file, int line, const char *pathname) +{ + const char *event_name = "cmd_path"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addstr(&buf_payload, pathname); + + perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL, + &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_command_name_fl(const char *file, int line, const char *name, + const char *hierarchy) +{ + const char *event_name = "cmd_name"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addstr(&buf_payload, name); + if (hierarchy && *hierarchy) + strbuf_addf(&buf_payload, " (%s)", hierarchy); + + perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL, + &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_command_mode_fl(const char *file, int line, const char *mode) +{ + const char *event_name = "cmd_mode"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addstr(&buf_payload, mode); + + perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL, + &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_alias_fl(const char *file, int line, const char *alias, + const char **argv) +{ + const char *event_name = "alias"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "alias:%s argv:", alias); + sq_quote_argv_pretty(&buf_payload, argv); + + perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL, + &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_child_start_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + const struct child_process *cmd) +{ + const char *event_name = "child_start"; + struct strbuf buf_payload = STRBUF_INIT; + + if (cmd->trace2_hook_name) { + strbuf_addf(&buf_payload, "[ch%d] class:hook hook:%s", + cmd->trace2_child_id, cmd->trace2_hook_name); + } else { + const char *child_class = + cmd->trace2_child_class ? cmd->trace2_child_class : "?"; + strbuf_addf(&buf_payload, "[ch%d] class:%s", + cmd->trace2_child_id, child_class); + } + + if (cmd->dir) { + strbuf_addstr(&buf_payload, " cd:"); + sq_quote_buf_pretty(&buf_payload, cmd->dir); + } + + strbuf_addstr(&buf_payload, " argv:"); + if (cmd->git_cmd) + strbuf_addstr(&buf_payload, " git"); + sq_quote_argv_pretty(&buf_payload, cmd->argv); + + perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute, + NULL, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_child_exit_fl(const char *file, int line, + uint64_t us_elapsed_absolute, int cid, int pid, + int code, uint64_t us_elapsed_child) +{ + const char *event_name = "child_exit"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "[ch%d] pid:%d code:%d", cid, pid, code); + + perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute, + &us_elapsed_child, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_thread_start_fl(const char *file, int line, + uint64_t us_elapsed_absolute) +{ + const char *event_name = "thread_start"; + struct strbuf buf_payload = STRBUF_INIT; + + perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute, + NULL, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_thread_exit_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + uint64_t us_elapsed_thread) +{ + const char *event_name = "thread_exit"; + struct strbuf buf_payload = STRBUF_INIT; + + perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute, + &us_elapsed_thread, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_exec_fl(const char *file, int line, uint64_t us_elapsed_absolute, + int exec_id, const char *exe, const char **argv) +{ + const char *event_name = "exec"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "id:%d ", exec_id); + strbuf_addstr(&buf_payload, "argv:"); + if (exe) + strbuf_addf(&buf_payload, " %s", exe); + sq_quote_argv_pretty(&buf_payload, argv); + + perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute, + NULL, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_exec_result_fl(const char *file, int line, + uint64_t us_elapsed_absolute, int exec_id, + int code) +{ + const char *event_name = "exec_result"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "id:%d code:%d", exec_id, code); + if (code > 0) + strbuf_addf(&buf_payload, " err:%s", strerror(code)); + + perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute, + NULL, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_param_fl(const char *file, int line, const char *param, + const char *value) +{ + const char *event_name = "def_param"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "%s:%s", param, value); + + perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL, + &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_repo_fl(const char *file, int line, + const struct repository *repo) +{ + const char *event_name = "def_repo"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addstr(&buf_payload, "worktree:"); + sq_quote_buf_pretty(&buf_payload, repo->worktree); + + perf_io_write_fl(file, line, event_name, repo, NULL, NULL, NULL, + &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_region_enter_printf_va_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + const char *category, + const char *label, + const struct repository *repo, + const char *fmt, va_list ap) +{ + const char *event_name = "region_enter"; + struct strbuf buf_payload = STRBUF_INIT; + + if (label) + strbuf_addf(&buf_payload, "label:%s ", label); + maybe_append_string_va(&buf_payload, fmt, ap); + + perf_io_write_fl(file, line, event_name, repo, &us_elapsed_absolute, + NULL, category, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_region_leave_printf_va_fl( + const char *file, int line, uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, const char *category, const char *label, + const struct repository *repo, const char *fmt, va_list ap) +{ + const char *event_name = "region_leave"; + struct strbuf buf_payload = STRBUF_INIT; + + if (label) + strbuf_addf(&buf_payload, "label:%s ", label); + maybe_append_string_va(&buf_payload, fmt, ap); + + perf_io_write_fl(file, line, event_name, repo, &us_elapsed_absolute, + &us_elapsed_region, category, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_data_fl(const char *file, int line, uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, const char *category, + const struct repository *repo, const char *key, + const char *value) +{ + const char *event_name = "data"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "%s:%s", key, value); + + perf_io_write_fl(file, line, event_name, repo, &us_elapsed_absolute, + &us_elapsed_region, category, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_data_json_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, const char *category, + const struct repository *repo, const char *key, + const struct json_writer *value) +{ + const char *event_name = "data_json"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "%s:%s", key, value->json.buf); + + perf_io_write_fl(file, line, event_name, repo, &us_elapsed_absolute, + &us_elapsed_region, category, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_printf_va_fl(const char *file, int line, + uint64_t us_elapsed_absolute, const char *fmt, + va_list ap) +{ + const char *event_name = "printf"; + struct strbuf buf_payload = STRBUF_INIT; + + maybe_append_string_va(&buf_payload, fmt, ap); + + perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute, + NULL, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +struct tr2_tgt tr2_tgt_perf = { + &tr2dst_perf, + + fn_init, + fn_term, + + fn_version_fl, + fn_start_fl, + fn_exit_fl, + fn_signal, + fn_atexit, + fn_error_va_fl, + fn_command_path_fl, + fn_command_name_fl, + fn_command_mode_fl, + fn_alias_fl, + fn_child_start_fl, + fn_child_exit_fl, + fn_thread_start_fl, + fn_thread_exit_fl, + fn_exec_fl, + fn_exec_result_fl, + fn_param_fl, + fn_repo_fl, + fn_region_enter_printf_va_fl, + fn_region_leave_printf_va_fl, + fn_data_fl, + fn_data_json_fl, + fn_printf_va_fl, +}; diff --git a/trace2/tr2_tls.c b/trace2/tr2_tls.c new file mode 100644 index 0000000000..8e65b0361d --- /dev/null +++ b/trace2/tr2_tls.c @@ -0,0 +1,164 @@ +#include "cache.h" +#include "thread-utils.h" +#include "trace2/tr2_tls.h" + +/* + * Initialize size of the thread stack for nested regions. + * This is used to store nested region start times. Note that + * this stack is per-thread and not per-trace-key. + */ +#define TR2_REGION_NESTING_INITIAL_SIZE (100) + +static struct tr2tls_thread_ctx *tr2tls_thread_main; +static uint64_t tr2tls_us_start_main; + +static pthread_mutex_t tr2tls_mutex; +static pthread_key_t tr2tls_key; + +static int tr2_next_thread_id; /* modify under lock */ + +struct tr2tls_thread_ctx *tr2tls_create_self(const char *thread_name) +{ + uint64_t us_now = getnanotime() / 1000; + struct tr2tls_thread_ctx *ctx = xcalloc(1, sizeof(*ctx)); + + /* + * Implicitly "tr2tls_push_self()" to capture the thread's start + * time in array_us_start[0]. For the main thread this gives us the + * application run time. + */ + ctx->alloc = TR2_REGION_NESTING_INITIAL_SIZE; + ctx->array_us_start = (uint64_t *)xcalloc(ctx->alloc, sizeof(uint64_t)); + ctx->array_us_start[ctx->nr_open_regions++] = us_now; + + ctx->thread_id = tr2tls_locked_increment(&tr2_next_thread_id); + + strbuf_init(&ctx->thread_name, 0); + if (ctx->thread_id) + strbuf_addf(&ctx->thread_name, "th%02d:", ctx->thread_id); + strbuf_addstr(&ctx->thread_name, thread_name); + if (ctx->thread_name.len > TR2_MAX_THREAD_NAME) + strbuf_setlen(&ctx->thread_name, TR2_MAX_THREAD_NAME); + + pthread_setspecific(tr2tls_key, ctx); + + return ctx; +} + +struct tr2tls_thread_ctx *tr2tls_get_self(void) +{ + struct tr2tls_thread_ctx *ctx = pthread_getspecific(tr2tls_key); + + /* + * If the thread-proc did not call trace2_thread_start(), we won't + * have any TLS data associated with the current thread. Fix it + * here and silently continue. + */ + if (!ctx) + ctx = tr2tls_create_self("unknown"); + + return ctx; +} + +int tr2tls_is_main_thread(void) +{ + struct tr2tls_thread_ctx *ctx = pthread_getspecific(tr2tls_key); + + return ctx == tr2tls_thread_main; +} + +void tr2tls_unset_self(void) +{ + struct tr2tls_thread_ctx *ctx; + + ctx = tr2tls_get_self(); + + pthread_setspecific(tr2tls_key, NULL); + + free(ctx->array_us_start); + free(ctx); +} + +void tr2tls_push_self(uint64_t us_now) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + + ALLOC_GROW(ctx->array_us_start, ctx->nr_open_regions + 1, ctx->alloc); + ctx->array_us_start[ctx->nr_open_regions++] = us_now; +} + +void tr2tls_pop_self(void) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + + if (!ctx->nr_open_regions) + BUG("no open regions in thread '%s'", ctx->thread_name.buf); + + ctx->nr_open_regions--; +} + +void tr2tls_pop_unwind_self(void) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + + while (ctx->nr_open_regions > 1) + tr2tls_pop_self(); +} + +uint64_t tr2tls_region_elasped_self(uint64_t us) +{ + struct tr2tls_thread_ctx *ctx; + uint64_t us_start; + + ctx = tr2tls_get_self(); + if (!ctx->nr_open_regions) + return 0; + + us_start = ctx->array_us_start[ctx->nr_open_regions - 1]; + + return us - us_start; +} + +uint64_t tr2tls_absolute_elapsed(uint64_t us) +{ + if (!tr2tls_thread_main) + return 0; + + return us - tr2tls_us_start_main; +} + +void tr2tls_init(void) +{ + pthread_key_create(&tr2tls_key, NULL); + init_recursive_mutex(&tr2tls_mutex); + + tr2tls_thread_main = tr2tls_create_self("main"); + /* + * Keep a copy of the absolute start time of the main thread + * in a fixed variable since other threads need to access it. + * This also eliminates the need to lock accesses to the main + * thread's array (because of reallocs). + */ + tr2tls_us_start_main = tr2tls_thread_main->array_us_start[0]; +} + +void tr2tls_release(void) +{ + tr2tls_unset_self(); + tr2tls_thread_main = NULL; + + pthread_mutex_destroy(&tr2tls_mutex); + pthread_key_delete(tr2tls_key); +} + +int tr2tls_locked_increment(int *p) +{ + int current_value; + + pthread_mutex_lock(&tr2tls_mutex); + current_value = *p; + *p = current_value + 1; + pthread_mutex_unlock(&tr2tls_mutex); + + return current_value; +} diff --git a/trace2/tr2_tls.h b/trace2/tr2_tls.h new file mode 100644 index 0000000000..bb80e3f8e7 --- /dev/null +++ b/trace2/tr2_tls.h @@ -0,0 +1,97 @@ +#ifndef TR2_TLS_H +#define TR2_TLS_H + +#include "strbuf.h" + +/* + * Arbitry limit for thread names for column alignment. + */ +#define TR2_MAX_THREAD_NAME (24) + +struct tr2tls_thread_ctx { + struct strbuf thread_name; + uint64_t *array_us_start; + int alloc; + int nr_open_regions; /* plays role of "nr" in ALLOC_GROW */ + int thread_id; +}; + +/* + * Create TLS data for the current thread. This gives us a place to + * put per-thread data, such as thread start time, function nesting + * and a per-thread label for our messages. + * + * We assume the first thread is "main". Other threads are given + * non-zero thread-ids to help distinguish messages from concurrent + * threads. + * + * Truncate the thread name if necessary to help with column alignment + * in printf-style messages. + * + * In this and all following functions the term "self" refers to the + * current thread. + */ +struct tr2tls_thread_ctx *tr2tls_create_self(const char *thread_name); + +/* + * Get our TLS data. + */ +struct tr2tls_thread_ctx *tr2tls_get_self(void); + +/* + * return true if the current thread is the main thread. + */ +int tr2tls_is_main_thread(void); + +/* + * Free our TLS data. + */ +void tr2tls_unset_self(void); + +/* + * Begin a new nested region and remember the start time. + */ +void tr2tls_push_self(uint64_t us_now); + +/* + * End the innermost nested region. + */ +void tr2tls_pop_self(void); + +/* + * Pop any extra (above the first) open regions on the current + * thread and discard. During a thread-exit, we should only + * have region[0] that was pushed in trace2_thread_start() if + * the thread exits normally. + */ +void tr2tls_pop_unwind_self(void); + +/* + * Compute the elapsed time since the innermost region in the + * current thread started and the given time (usually now). + */ +uint64_t tr2tls_region_elasped_self(uint64_t us); + +/* + * Compute the elapsed time since the main thread started + * and the given time (usually now). This is assumed to + * be the absolute run time of the process. + */ +uint64_t tr2tls_absolute_elapsed(uint64_t us); + +/* + * Initialize the tr2 TLS system. + */ +void tr2tls_init(void); + +/* + * Free all tr2 TLS resources. + */ +void tr2tls_release(void); + +/* + * Protected increment of an integer. + */ +int tr2tls_locked_increment(int *p); + +#endif /* TR2_TLS_H */ |