mirror of
https://github.com/git/git
synced 2024-08-27 19:49:21 +00:00
![Jeff Hostetler](/assets/img/avatar_default.png)
Created design document for Trace2 feature. Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com> Signed-off-by: Junio C Hamano <gitster@pobox.com>
1350 lines
44 KiB
Plaintext
1350 lines
44 KiB
Plaintext
= Trace2 API
|
|
|
|
The Trace2 API can be used to print debug, performance, and telemetry
|
|
information to stderr or a file. The Trace2 feature is inactive unless
|
|
explicitly enabled by enabling one or more Trace2 Targets.
|
|
|
|
The Trace2 API is intended to replace the existing (Trace1)
|
|
printf-style tracing provided by the existing `GIT_TRACE` and
|
|
`GIT_TRACE_PERFORMANCE` facilities. During initial implementation,
|
|
Trace2 and Trace1 may operate in parallel.
|
|
|
|
The Trace2 API defines a set of high-level messages with known fields,
|
|
such as (`start`: `argv`) and (`exit`: {`exit-code`, `elapsed-time`}).
|
|
|
|
Trace2 instrumentation throughout the Git code base sends Trace2
|
|
messages to the enabled Trace2 Targets. Targets transform these
|
|
messages content into purpose-specific formats and write events to
|
|
their data streams. In this manner, the Trace2 API can drive
|
|
many different types of analysis.
|
|
|
|
Targets are defined using a VTable allowing easy extension to other
|
|
formats in the future. This might be used to define a binary format,
|
|
for example.
|
|
|
|
== Trace2 Targets
|
|
|
|
Trace2 defines the following set of Trace2 Targets.
|
|
Format details are given in a later section.
|
|
|
|
`GIT_TR2` (NORMAL)::
|
|
|
|
a simple printf format like GIT_TRACE.
|
|
+
|
|
------------
|
|
$ export GIT_TR2=~/log.normal
|
|
$ git version
|
|
git version 2.20.1.155.g426c96fcdb
|
|
------------
|
|
+
|
|
------------
|
|
$ cat ~/log.normal
|
|
12:28:42.620009 common-main.c:38 version 2.20.1.155.g426c96fcdb
|
|
12:28:42.620989 common-main.c:39 start git version
|
|
12:28:42.621101 git.c:432 cmd_name version (version)
|
|
12:28:42.621215 git.c:662 exit elapsed:0.001227 code:0
|
|
12:28:42.621250 trace2/tr2_tgt_normal.c:124 atexit elapsed:0.001265 code:0
|
|
------------
|
|
|
|
`GIT_TR2_PERF` (PERF)::
|
|
|
|
a column-based format to replace GIT_TRACE_PERFORMANCE suitable for
|
|
development and testing, possibly to complement tools like gprof.
|
|
+
|
|
------------
|
|
$ export GIT_TR2_PERF=~/log.perf
|
|
$ git version
|
|
git version 2.20.1.155.g426c96fcdb
|
|
------------
|
|
+
|
|
------------
|
|
$ cat ~/log.perf
|
|
12:28:42.620675 common-main.c:38 | d0 | main | version | | | | | 2.20.1.155.g426c96fcdb
|
|
12:28:42.621001 common-main.c:39 | d0 | main | start | | | | | git version
|
|
12:28:42.621111 git.c:432 | d0 | main | cmd_name | | | | | version (version)
|
|
12:28:42.621225 git.c:662 | d0 | main | exit | | 0.001227 | | | code:0
|
|
12:28:42.621259 trace2/tr2_tgt_perf.c:211 | d0 | main | atexit | | 0.001265 | | | code:0
|
|
------------
|
|
|
|
`GIT_TR2_EVENT` (EVENT)::
|
|
|
|
a JSON-based format of event data suitable for telemetry analysis.
|
|
+
|
|
------------
|
|
$ export GIT_TR2_EVENT=~/log.event
|
|
$ git version
|
|
git version 2.20.1.155.g426c96fcdb
|
|
------------
|
|
+
|
|
------------
|
|
$ cat ~/log.event
|
|
{"event":"version","sid":"1547659722619736-11614","thread":"main","time":"2019-01-16 17:28:42.620713","file":"common-main.c","line":38,"evt":"1","exe":"2.20.1.155.g426c96fcdb"}
|
|
{"event":"start","sid":"1547659722619736-11614","thread":"main","time":"2019-01-16 17:28:42.621027","file":"common-main.c","line":39,"argv":["git","version"]}
|
|
{"event":"cmd_name","sid":"1547659722619736-11614","thread":"main","time":"2019-01-16 17:28:42.621122","file":"git.c","line":432,"name":"version","hierarchy":"version"}
|
|
{"event":"exit","sid":"1547659722619736-11614","thread":"main","time":"2019-01-16 17:28:42.621236","file":"git.c","line":662,"t_abs":0.001227,"code":0}
|
|
{"event":"atexit","sid":"1547659722619736-11614","thread":"main","time":"2019-01-16 17:28:42.621268","file":"trace2/tr2_tgt_event.c","line":163,"t_abs":0.001265,"code":0}
|
|
------------
|
|
|
|
== Enabling a Target
|
|
|
|
A Trace2 Target is enabled when the corresponding environment variable
|
|
(`GIT_TR2`, `GIT_TR2_PERF`, or `GIT_TR2_EVENT`) is set. The following
|
|
values are recognized.
|
|
|
|
`0`::
|
|
`false`::
|
|
|
|
Disables the target.
|
|
|
|
`1`::
|
|
`true`::
|
|
|
|
Enables the target and writes stream to `STDERR`.
|
|
|
|
`[2-9]`::
|
|
|
|
Enables the target and writes to the already opened file descriptor.
|
|
|
|
`<absolute-pathname>`::
|
|
|
|
Enables the target, opens and writes to the file in append mode.
|
|
|
|
`af_unix:[<socket_type>:]<absolute-pathname>`::
|
|
|
|
Enables the target, opens and writes to a Unix Domain Socket
|
|
(on platforms that support them).
|
|
+
|
|
Socket type can be either `stream` or `dgram`. If the socket type is
|
|
omitted, Git will try both.
|
|
|
|
== Trace2 API
|
|
|
|
All public Trace2 functions and macros are defined in `trace2.h` and
|
|
`trace2.c`. All public symbols are prefixed with `trace2_`.
|
|
|
|
There are no public Trace2 data structures.
|
|
|
|
The Trace2 code also defines a set of private functions and data types
|
|
in the `trace2/` directory. These symbols are prefixed with `tr2_`
|
|
and should only be used by functions in `trace2.c`.
|
|
|
|
== Conventions for Public Functions and Macros
|
|
|
|
The functions defined by the Trace2 API are declared and documented
|
|
in `trace2.h`. It defines the API functions and wrapper macros for
|
|
Trace2.
|
|
|
|
Some functions have a `_fl()` suffix to indicate that they take `file`
|
|
and `line-number` arguments.
|
|
|
|
Some functions have a `_va_fl()` suffix to indicate that they also
|
|
take a `va_list` argument.
|
|
|
|
Some functions have a `_printf_fl()` suffix to indicate that they also
|
|
take a varargs argument.
|
|
|
|
There are CPP wrapper macros and ifdefs to hide most of these details.
|
|
See `trace2.h` for more details. The following discussion will only
|
|
describe the simplified forms.
|
|
|
|
== Public API
|
|
|
|
All Trace2 API functions send a messsage to all of the active
|
|
Trace2 Targets. This section describes the set of available
|
|
messages.
|
|
|
|
It helps to divide these functions into groups for discussion
|
|
purposes.
|
|
|
|
=== Basic Command Messages
|
|
|
|
These are concerned with the lifetime of the overall git process.
|
|
|
|
`void trace2_initialize()`::
|
|
|
|
Determines if any Trace2 Targets should be enabled and
|
|
initializes the Trace2 facility. This includes starting the
|
|
elapsed time clocks and thread local storage (TLS).
|
|
+
|
|
This function emits a "version" message containing the version of git
|
|
and the Trace2 protocol.
|
|
+
|
|
This function should be called from `main()` as early as possible in
|
|
the life of the process.
|
|
|
|
`int trace2_is_enabled()`::
|
|
|
|
Returns 1 if Trace2 is enabled (at least one target is
|
|
active).
|
|
|
|
`void trace2_cmd_start(int argc, const char **argv)`::
|
|
|
|
Emits a "start" message containing the process command line
|
|
arguments.
|
|
|
|
`int trace2_cmd_exit(int exit_code)`::
|
|
|
|
Emits an "exit" message containing the process exit-code and
|
|
elapsed time.
|
|
+
|
|
Returns the exit-code.
|
|
|
|
`void trace2_cmd_error(const char *fmt, va_list ap)`::
|
|
|
|
Emits an "error" message containing a formatted error message.
|
|
|
|
`void trace2_cmd_path(const char *pathname)`::
|
|
|
|
Emits a "cmd_path" message with the full pathname of the
|
|
current process.
|
|
|
|
=== Command Detail Messages
|
|
|
|
These are concerned with describing the specific Git command
|
|
after the command line, config, and environment are inspected.
|
|
|
|
`void trace2_cmd_name(const char *name)`::
|
|
|
|
Emits a "cmd_name" message with the canonical name of the
|
|
command, for example "status" or "checkout".
|
|
|
|
`void trace2_cmd_mode(const char *mode)`::
|
|
|
|
Emits a "cmd_mode" message with a qualifier name to further
|
|
describe the current git command.
|
|
+
|
|
This message is intended to be used with git commands having multiple
|
|
major modes. For example, a "checkout" command can checkout a new
|
|
branch or it can checkout a single file, so the checkout code could
|
|
emit a cmd_mode message of "branch" or "file".
|
|
|
|
`void trace2_cmd_alias(const char *alias, const char **argv_expansion)`::
|
|
|
|
Emits an "alias" message containing the alias used and the
|
|
argument expansion.
|
|
|
|
`void trace2_def_param(const char *parameter, const char *value)`::
|
|
|
|
Emits a "def_param" message containing a key/value pair.
|
|
+
|
|
This message is intended to report some global aspect of the current
|
|
command, such as a configuration setting or command line switch that
|
|
significantly affects program performance or behavior, such as
|
|
`core.abbrev`, `status.showUntrackedFiles`, or `--no-ahead-behind`.
|
|
|
|
`void trace2_cmd_list_config()`::
|
|
|
|
Emits a "def_param" messages for "important" configuration
|
|
settings.
|
|
+
|
|
The environment variable `GIT_TR2_CONFIG_PARAMS` can be set to a
|
|
list of patterns of important configuration settings, for example:
|
|
`core.*,remote.*.url`. This function will iterate over all config
|
|
settings and emit a "def_param" message for each match.
|
|
|
|
`void trace2_cmd_set_config(const char *key, const char *value)`::
|
|
|
|
Emits a "def_param" message for a specific configuration
|
|
setting IFF it matches the `GIT_TR2_CONFIG_PARAMS` pattern.
|
|
+
|
|
This is used to hook into `git_config_set()` and catch any
|
|
configuration changes and update a value previously reported by
|
|
`trace2_cmd_list_config()`.
|
|
|
|
`void trace2_def_repo(struct repository *repo)`::
|
|
|
|
Registers a repository with the Trace2 layer. Assigns a
|
|
unique "repo-id" to `repo->trace2_repo_id`.
|
|
+
|
|
Emits a "worktree" messages containing the repo-id and the worktree
|
|
pathname.
|
|
+
|
|
Region and data messages (described later) may refer to this repo-id.
|
|
+
|
|
The main/top-level repository will have repo-id value 1 (aka "r1").
|
|
+
|
|
The repo-id field is in anticipation of future in-proc submodule
|
|
repositories.
|
|
|
|
=== Child Process Messages
|
|
|
|
These are concerned with the various spawned child processes,
|
|
including shell scripts, git commands, editors, pagers, and hooks.
|
|
|
|
`void trace2_child_start(struct child_process *cmd)`::
|
|
|
|
Emits a "child_start" message containing the "child-id",
|
|
"child-argv", and "child-classification".
|
|
+
|
|
Before calling this, set `cmd->trace2_child_class` to a name
|
|
describing the type of child process, for example "editor".
|
|
+
|
|
This function assigns a unique "child-id" to `cmd->trace2_child_id`.
|
|
This field is used later during the "child_exit" message to associate
|
|
it with the "child_start" message.
|
|
+
|
|
This function should be called before spawning the child process.
|
|
|
|
`void trace2_child_exit(struct child_proess *cmd, int child_exit_code)`::
|
|
|
|
Emits a "child_exit" message containing the "child-id",
|
|
the child's elapsed time and exit-code.
|
|
+
|
|
The reported elapsed time includes the process creation overhead and
|
|
time spend waiting for it to exit, so it may be slightly longer than
|
|
the time reported by the child itself.
|
|
+
|
|
This function should be called after reaping the child process.
|
|
|
|
`int trace2_exec(const char *exe, const char **argv)`::
|
|
|
|
Emits a "exec" message containing the "exec-id" and the
|
|
argv of the new process.
|
|
+
|
|
This function should be called before calling one of the `exec()`
|
|
variants, such as `execvp()`.
|
|
+
|
|
This function returns a unique "exec-id". This value is used later
|
|
if the exec() fails and a "exec-result" message is necessary.
|
|
|
|
`void trace2_exec_result(int exec_id, int error_code)`::
|
|
|
|
Emits a "exec_result" message containing the "exec-id"
|
|
and the error code.
|
|
+
|
|
On Unix-based systems, `exec()` does not return if successful.
|
|
This message is used to indicate that the `exec()` failed and
|
|
that the current program is continuing.
|
|
|
|
=== Git Thread Messages
|
|
|
|
These messages are concerned with Git thread usage.
|
|
|
|
`void trace2_thread_start(const char *thread_name)`::
|
|
|
|
Emits a "thread_start" message.
|
|
+
|
|
The `thread_name` field should be a descriptive name, such as the
|
|
unique name of the thread-proc. A unique "thread-id" will be added
|
|
to the name to uniquely identify thread instances.
|
|
+
|
|
Region and data messages (described later) may refer to this thread
|
|
name.
|
|
+
|
|
This function must be called by the thread-proc of the new thread
|
|
(so that TLS data is properly initialized) and not by the caller
|
|
of `pthread_create()`.
|
|
|
|
`void trace2_thread_exit()`::
|
|
|
|
Emits a "thread_exit" message containing the thread name
|
|
and the thread elapsed time.
|
|
+
|
|
This function must be called by the thread-proc before it returns
|
|
(so that the coorect TLS data is used and cleaned up. It should
|
|
not be called by the caller of `pthread_join()`.
|
|
|
|
=== Region and Data Messages
|
|
|
|
These are concerned with recording performance data
|
|
over regions or spans of code.
|
|
|
|
`void trace2_region_enter(const char *category, const char *label, const struct repository *repo)`::
|
|
|
|
`void trace2_region_enter_printf(const char *category, const char *label, const struct repository *repo, const char *fmt, ...)`::
|
|
|
|
`void trace2_region_enter_printf_va(const char *category, const char *label, const struct repository *repo, const char *fmt, va_list ap)`::
|
|
|
|
Emits a thread-relative "region_enter" message with optional
|
|
printf string.
|
|
+
|
|
This function pushes a new region nesting stack level on the current
|
|
thread and starts a clock for the new stack frame.
|
|
+
|
|
The `category` field is an arbitrary category name used to classify
|
|
regions by feature area, such as "status" or "index". At this time
|
|
it is only just printed along with the rest of the message. It may
|
|
be used in the future to filter messages.
|
|
+
|
|
The `label` field is an arbitrary label used to describe the activity
|
|
being started, such as "read_recursive" or "do_read_index".
|
|
+
|
|
The `repo` field, if set, will be used to get the "repo-id", so that
|
|
recursive oerations can be attributed to the correct repository.
|
|
|
|
`void trace2_region_leave(const char *category, const char *label, const struct repository *repo)`::
|
|
|
|
`void trace2_region_leave_printf(const char *category, const char *label, const struct repository *repo, const char *fmt, ...)`::
|
|
|
|
`void trace2_region_leave_printf_va(const char *category, const char *label, const struct repository *repo, const char *fmt, va_list ap)`::
|
|
|
|
Emits a thread-relative "region_leave" message with optional
|
|
printf string.
|
|
+
|
|
This function pops the region nesting stack on the current thread
|
|
and reports the elapsed time of the stack frame.
|
|
+
|
|
The `category`, `label`, and `repo` fields are the same as above.
|
|
The `category` and `label` do not need to match the correpsonding
|
|
"region_enter" message, but it makes the data stream easier to
|
|
understand.
|
|
|
|
`void trace2_data_string(const char *category, const struct repository *repo, const char *key, const char * value)`::
|
|
|
|
`void trace2_data_intmax(const char *category, const struct repository *repo, const char *key, intmax value)`::
|
|
|
|
`void trace2_data_json(const char *category, const struct repository *repo, const char *key, const struct json_writer *jw)`::
|
|
|
|
Emits a region- and thread-relative "data" or "data_json" message.
|
|
+
|
|
This is a key/value pair message containing information about the
|
|
current thread, region stack, and repository. This could be used
|
|
to print the number of files in a directory during a multi-threaded
|
|
recursive tree walk.
|
|
|
|
`void trace2_printf(const char *fmt, ...)`::
|
|
|
|
`void trace2_printf_va(const char *fmt, va_list ap)`::
|
|
|
|
Emits a region- and thread-relative "printf" message.
|
|
|
|
== Trace2 Target Formats
|
|
|
|
=== NORMAL Format
|
|
|
|
NORMAL format is enabled when the `GIT_TR2` environment variable is
|
|
set.
|
|
|
|
Events are written as lines of the form:
|
|
|
|
------------
|
|
[<time> SP <filename>:<line> SP+] <event-name> [[SP] <event-message>] LF
|
|
------------
|
|
|
|
`<event-name>`::
|
|
|
|
is the event name.
|
|
|
|
`<event-message>`::
|
|
is a free-form printf message intended for human consumption.
|
|
+
|
|
Note that this may contain embedded LF or CRLF characters that are
|
|
not escaped, so the event may spill across multiple lines.
|
|
|
|
If `GIT_TR2_BRIEF` is true, the `time`, `filename`, and `line` fields
|
|
are omitted.
|
|
|
|
This target is intended to be more of a summary (like GIT_TRACE) and
|
|
less detailed than the other targets. It ignores thread, region, and
|
|
data messages, for example.
|
|
|
|
=== PERF Format
|
|
|
|
PERF format is enabled when the `GIT_TR2_PERF` environment variable
|
|
is set.
|
|
|
|
Events are written as lines of the form:
|
|
|
|
------------
|
|
[<time> SP <filename>:<line> SP+
|
|
BAR SP] d<depth> SP
|
|
BAR SP <thread-name> SP+
|
|
BAR SP <event-name> SP+
|
|
BAR SP [r<repo-id>] SP+
|
|
BAR SP [<t_abs>] SP+
|
|
BAR SP [<t_rel>] SP+
|
|
BAR SP [<category>] SP+
|
|
BAR SP DOTS* <perf-event-message>
|
|
LF
|
|
------------
|
|
|
|
`<depth>`::
|
|
is the git process depth. This is the number of parent
|
|
git processes. A top-level git command has depth value "d0".
|
|
A child of it has depth value "d1". A second level child
|
|
has depth value "d2" and so on.
|
|
|
|
`<thread-name>`::
|
|
is a unique name for the thread. The primary thread
|
|
is called "main". Other thread names are of the form "th%d:%s"
|
|
and include a unique number and the name of the thread-proc.
|
|
|
|
`<event-name>`::
|
|
is the event name.
|
|
|
|
`<repo-id>`::
|
|
when present, is a number indicating the repository
|
|
in use. A `def_repo` event is emitted when a repository is
|
|
opened. This defines the repo-id and associated worktree.
|
|
Subsequent repo-specific events will reference this repo-id.
|
|
+
|
|
Currently, this is always "r1" for the main repository.
|
|
This field is in anticipation of in-proc submodules in the future.
|
|
|
|
`<t_abs>`::
|
|
when present, is the absolute time in seconds since the
|
|
program started.
|
|
|
|
`<t_rel>`::
|
|
when present, is time in seconds relative to the start of
|
|
the current region. For a thread-exit event, it is the elapsed
|
|
time of the thread.
|
|
|
|
`<category>`::
|
|
is present on region and data events and is used to
|
|
indicate a broad category, such as "index" or "status".
|
|
|
|
`<perf-event-message>`::
|
|
is a free-form printf message intended for human consumption.
|
|
|
|
------------
|
|
15:33:33.532712 wt-status.c:2310 | d0 | main | region_enter | r1 | 0.126064 | | status | label:print
|
|
15:33:33.532712 wt-status.c:2331 | d0 | main | region_leave | r1 | 0.127568 | 0.001504 | status | label:print
|
|
------------
|
|
|
|
If `GIT_TR2_PERF_BRIEF` is true, the `time`, `file`, and `line`
|
|
fields are omitted.
|
|
|
|
------------
|
|
d0 | main | region_leave | r1 | 0.011717 | 0.009122 | index | label:preload
|
|
------------
|
|
|
|
The PERF target is intended for interactive performance analysis
|
|
during development and is quite noisy.
|
|
|
|
=== EVENT Format
|
|
|
|
EVENT format is enabled when the `GIT_TR2_EVENT` environment
|
|
variable is set.
|
|
|
|
Each event is a JSON-object containing multiple key/value pairs
|
|
written as a single line and followed by a LF.
|
|
|
|
------------
|
|
'{' <key> ':' <value> [',' <key> ':' <value>]* '}' LF
|
|
------------
|
|
|
|
Some key/value pairs are common to all events and some are
|
|
event-specific.
|
|
|
|
==== Common Key/Value Pairs
|
|
|
|
The following key/value pairs are common to all events:
|
|
|
|
------------
|
|
{
|
|
"event":"version",
|
|
"sid":"1547659722619736-11614",
|
|
"thread":"main",
|
|
"time":"2019-01-16 17:28:42.620713",
|
|
"file":"common-main.c",
|
|
"line":38,
|
|
...
|
|
}
|
|
------------
|
|
|
|
`"event":<event>`::
|
|
is the event name.
|
|
|
|
`"sid":<sid>`::
|
|
is the session-id. This is a unique string to identify the
|
|
process instance to allow all events emitted by a process to
|
|
be identified. A session-id is used instead of a PID because
|
|
PIDs are recycled by the OS. For child git processes, the
|
|
session-id is prepended with the session-id of the parent git
|
|
process to allow parent-child relationships to be identified
|
|
during post-processing.
|
|
|
|
`"thread":<thread>`::
|
|
is the thread name.
|
|
|
|
`"time":<time>`::
|
|
is the UTC time of the event.
|
|
|
|
`"file":<filename>`::
|
|
is source file generating the event.
|
|
|
|
`"line":<line-number>`::
|
|
is the integer source line number generating the event.
|
|
|
|
`"repo":<repo-id>`::
|
|
when present, is the integer repo-id as described previously.
|
|
|
|
If `GIT_TR2_EVENT_BRIEF` is true, the `file` and `line` fields are omitted
|
|
from all events and the `time` field is only present on the "start" and
|
|
"atexit" events.
|
|
|
|
==== Event-Specific Key/Value Pairs
|
|
|
|
`"version"`::
|
|
This event gives the version of the executable and the EVENT format.
|
|
+
|
|
------------
|
|
{
|
|
"event":"version",
|
|
...
|
|
"evt":"1", # EVENT format version
|
|
"exe":"2.20.1.155.g426c96fcdb" # git version
|
|
}
|
|
------------
|
|
|
|
`"start"`::
|
|
This event contains the complete argv received by main().
|
|
+
|
|
------------
|
|
{
|
|
"event":"start",
|
|
...
|
|
"argv":["git","version"]
|
|
}
|
|
------------
|
|
|
|
`"exit"`::
|
|
This event is emitted when git calls `exit()`.
|
|
+
|
|
------------
|
|
{
|
|
"event":"exit",
|
|
...
|
|
"t_abs":0.001227, # elapsed time in seconds
|
|
"code":0 # exit code
|
|
}
|
|
------------
|
|
|
|
`"atexit"`::
|
|
This event is emitted by the Trace2 `atexit` routine during
|
|
final shutdown. It should be the last event emitted by the
|
|
process.
|
|
+
|
|
(The elapsed time reported here is greater than the time reported in
|
|
the "exit" event because it runs after all other atexit tasks have
|
|
completed.)
|
|
+
|
|
------------
|
|
{
|
|
"event":"atexit",
|
|
...
|
|
"t_abs":0.001227, # elapsed time in seconds
|
|
"code":0 # exit code
|
|
}
|
|
------------
|
|
|
|
`"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.
|
|
+
|
|
------------
|
|
{
|
|
"event":"signal",
|
|
...
|
|
"t_abs":0.001227, # elapsed time in seconds
|
|
"signal":13 # SIGTERM, SIGINT, etc.
|
|
}
|
|
------------
|
|
|
|
`"error"`::
|
|
This event is emitted when one of the `error()`, `die()`,
|
|
or `usage()` functions are called.
|
|
+
|
|
------------
|
|
{
|
|
"event":"error",
|
|
...
|
|
"msg":"invalid option: --cahced", # formatted error message
|
|
"fmt":"invalid option: %s" # error format string
|
|
}
|
|
------------
|
|
+
|
|
The error event may be emitted more than once. The format string
|
|
allows post-processors to group errors by type without worrying
|
|
about specific error arguments.
|
|
|
|
`"cmd_path"`::
|
|
This event contains the discovered full path of the git
|
|
executable (on platforms that are configured to resolve it).
|
|
+
|
|
------------
|
|
{
|
|
"event":"cmd_path",
|
|
...
|
|
"path":"C:/work/gfw/git.exe"
|
|
}
|
|
------------
|
|
|
|
`"cmd_name"`::
|
|
This event contains the command name for this git process
|
|
and the hierarchy of commands from parent git processes.
|
|
+
|
|
------------
|
|
{
|
|
"event":"cmd_name",
|
|
...
|
|
"name":"pack-objects",
|
|
"hierarchy":"push/pack-objects"
|
|
}
|
|
------------
|
|
+
|
|
Normally, the "name" field contains the canonical name of the
|
|
command. When a canonical name is not available, one of
|
|
these special values are used:
|
|
+
|
|
------------
|
|
"_query_" # "git --html-path"
|
|
"_run_dashed_" # when "git foo" tries to run "git-foo"
|
|
"_run_shell_alias_" # alias expansion to a shell command
|
|
"_run_git_alias_" # alias expansion to a git command
|
|
"_usage_" # usage error
|
|
------------
|
|
|
|
`"cmd_mode"`::
|
|
This event, when present, describes the command variant This
|
|
event may be emitted more than once.
|
|
+
|
|
------------
|
|
{
|
|
"event":"cmd_mode",
|
|
...
|
|
"name":"branch"
|
|
}
|
|
------------
|
|
+
|
|
The "name" field is an arbitrary string to describe the command mode.
|
|
For example, checkout can checkout a branch or an individual file.
|
|
And these variations typically have different performance
|
|
characteristics that are not comparable.
|
|
|
|
`"alias"`::
|
|
This event is present when an alias is expanded.
|
|
+
|
|
------------
|
|
{
|
|
"event":"alias",
|
|
...
|
|
"alias":"l", # registered alias
|
|
"argv":["log","--graph"] # alias expansion
|
|
}
|
|
------------
|
|
|
|
`"child_start"`::
|
|
This event describes a child process that is about to be
|
|
spawned.
|
|
+
|
|
------------
|
|
{
|
|
"event":"child_start",
|
|
...
|
|
"child_id":2,
|
|
"child_class":"?",
|
|
"use_shell":false,
|
|
"argv":["git","rev-list","--objects","--stdin","--not","--all","--quiet"]
|
|
|
|
"hook_name":"<hook_name>" # present when child_class is "hook"
|
|
"cd":"<path>" # present when cd is required
|
|
}
|
|
------------
|
|
+
|
|
The "child_id" field can be used to match this child_start with the
|
|
corresponding child_exit event.
|
|
+
|
|
The "child_class" field is a rough classification, such as "editor",
|
|
"pager", "transport/*", and "hook". Unclassified children are classified
|
|
with "?".
|
|
|
|
`"child_exit"`::
|
|
This event is generated after the current process has returned
|
|
from the waitpid() and collected the exit information from the
|
|
child.
|
|
+
|
|
------------
|
|
{
|
|
"event":"child_exit",
|
|
...
|
|
"child_id":2,
|
|
"pid":14708, # child PID
|
|
"code":0, # child exit-code
|
|
"t_rel":0.110605 # observed run-time of child process
|
|
}
|
|
------------
|
|
+
|
|
Note that the session-id of the child process is not available to
|
|
the current/spawning process, so the child's PID is reported here as
|
|
a hint for post-processing. (But it is only a hint because the child
|
|
proces may be a shell script which doesn't have a session-id.)
|
|
+
|
|
Note that the `t_rel` field contains the observed run time in seconds
|
|
for the child process (starting before the fork/exec/spawn and
|
|
stopping after the waitpid() and includes OS process creation overhead).
|
|
So this time will be slightly larger than the atexit time reported by
|
|
the child process itself.
|
|
|
|
`"exec"`::
|
|
This event is generated before git attempts to `exec()`
|
|
another command rather than starting a child process.
|
|
+
|
|
------------
|
|
{
|
|
"event":"exec",
|
|
...
|
|
"exec_id":0,
|
|
"exe":"git",
|
|
"argv":["foo", "bar"]
|
|
}
|
|
------------
|
|
+
|
|
The "exec_id" field is a command-unique id and is only useful if the
|
|
`exec()` fails and a corresponding exec_result event is generated.
|
|
|
|
`"exec_result"`::
|
|
This event is generated if the `exec()` fails and control
|
|
returns to the current git command.
|
|
+
|
|
------------
|
|
{
|
|
"event":"exec_result",
|
|
...
|
|
"exec_id":0,
|
|
"code":1 # error code (errno) from exec()
|
|
}
|
|
------------
|
|
|
|
`"thread_start"`::
|
|
This event is generated when a thread is started. It is
|
|
generated from *within* the new thread's thread-proc (for TLS
|
|
reasons).
|
|
+
|
|
------------
|
|
{
|
|
"event":"thread_start",
|
|
...
|
|
"thread":"th02:preload_thread" # thread name
|
|
}
|
|
------------
|
|
|
|
`"thread_exit"`::
|
|
This event is generated when a thread exits. It is generated
|
|
from *within* the thread's thread-proc (for TLS reasons).
|
|
+
|
|
------------
|
|
{
|
|
"event":"thread_exit",
|
|
...
|
|
"thread":"th02:preload_thread", # thread name
|
|
"t_rel":0.007328 # thread elapsed time
|
|
}
|
|
------------
|
|
|
|
`"def_param"`::
|
|
This event is generated to log a global parameter.
|
|
+
|
|
------------
|
|
{
|
|
"event":"def_param",
|
|
...
|
|
"param":"core.abbrev",
|
|
"value":"7"
|
|
}
|
|
------------
|
|
|
|
`"def_repo"`::
|
|
This event defines a repo-id and associates it with the root
|
|
of the worktree.
|
|
+
|
|
------------
|
|
{
|
|
"event":"def_repo",
|
|
...
|
|
"repo":1,
|
|
"worktree":"/Users/jeffhost/work/gfw"
|
|
}
|
|
------------
|
|
+
|
|
As stated earlier, the repo-id is currently always 1, so there will
|
|
only be one def_repo event. Later, if in-proc submodules are
|
|
supported, a def_repo event should be emitted for each submodule
|
|
visited.
|
|
|
|
`"region_enter"`::
|
|
This event is generated when entering a region.
|
|
+
|
|
------------
|
|
{
|
|
"event":"region_enter",
|
|
...
|
|
"repo":1, # optional
|
|
"nesting":1, # current region stack depth
|
|
"category":"index", # optional
|
|
"label":"do_read_index", # optional
|
|
"msg":".git/index" # optional
|
|
}
|
|
------------
|
|
+
|
|
The `category` field may be used in a future enhancement to
|
|
do category-based filtering.
|
|
+
|
|
The `GIT_TR2_EVENT_NESTING` environment variable can be used to
|
|
filter deeply nested regions and data events. It defaults to "2".
|
|
|
|
`"region_leave"`::
|
|
This event is generated when leaving a region.
|
|
+
|
|
------------
|
|
{
|
|
"event":"region_leave",
|
|
...
|
|
"repo":1, # optional
|
|
"t_rel":0.002876, # time spent in region in seconds
|
|
"nesting":1, # region stack depth
|
|
"category":"index", # optional
|
|
"label":"do_read_index", # optional
|
|
"msg":".git/index" # optional
|
|
}
|
|
------------
|
|
|
|
`"data"`::
|
|
This event is generated to log a thread- and region-local
|
|
key/value pair.
|
|
+
|
|
------------
|
|
{
|
|
"event":"data",
|
|
...
|
|
"repo":1, # optional
|
|
"t_abs":0.024107, # absolute elapsed time
|
|
"t_rel":0.001031, # elapsed time in region/thread
|
|
"nesting":2, # region stack depth
|
|
"category":"index",
|
|
"key":"read/cache_nr",
|
|
"value":"3552"
|
|
}
|
|
------------
|
|
+
|
|
The "value" field may be an integer or a string.
|
|
|
|
`"data-json"`::
|
|
This event is generated to log a pre-formatted JSON string
|
|
containing structured data.
|
|
+
|
|
------------
|
|
{
|
|
"event":"data_json",
|
|
...
|
|
"repo":1, # optional
|
|
"t_abs":0.015905,
|
|
"t_rel":0.015905,
|
|
"nesting":1,
|
|
"category":"process",
|
|
"key":"windows/ancestry",
|
|
"value":["bash.exe","bash.exe"]
|
|
}
|
|
------------
|
|
|
|
== Example Trace2 API Usage
|
|
|
|
Here is a hypothetical usage of the Trace2 API showing the intended
|
|
usage (without worrying about the actual Git details).
|
|
|
|
Initialization::
|
|
|
|
Initialization happens in `main()`. Behind the scenes, an
|
|
`atexit` and `signal` handler are registered.
|
|
+
|
|
----------------
|
|
int main(int argc, const char **argv)
|
|
{
|
|
int exit_code;
|
|
|
|
trace2_initialize();
|
|
trace2_cmd_start(argv);
|
|
|
|
exit_code = cmd_main(argc, argv);
|
|
|
|
trace2_cmd_exit(exit_code);
|
|
|
|
return exit_code;
|
|
}
|
|
----------------
|
|
|
|
Command Details::
|
|
|
|
After the basics are established, additional command
|
|
information can be sent to Trace2 as it is discovered.
|
|
+
|
|
----------------
|
|
int cmd_checkout(int argc, const char **argv)
|
|
{
|
|
trace2_cmd_name("checkout");
|
|
trace2_cmd_mode("branch");
|
|
trace2_def_repo(the_repository);
|
|
|
|
// emit "def_param" messages for "interesting" config settings.
|
|
trace2_cmd_list_config();
|
|
|
|
if (do_something())
|
|
trace2_cmd_error("Path '%s': cannot do something", path);
|
|
|
|
return 0;
|
|
}
|
|
----------------
|
|
|
|
Child Processes::
|
|
|
|
Wrap code spawning child processes.
|
|
+
|
|
----------------
|
|
void run_child(...)
|
|
{
|
|
int child_exit_code;
|
|
struct child_process cmd = CHILD_PROCESS_INIT;
|
|
...
|
|
cmd.trace2_child_class = "editor";
|
|
|
|
trace2_child_start(&cmd);
|
|
child_exit_code = spawn_child_and_wait_for_it();
|
|
trace2_child_exit(&cmd, child_exit_code);
|
|
}
|
|
----------------
|
|
+
|
|
For example, the following fetch command spawned ssh, index-pack,
|
|
rev-list, and gc. This example also shows that fetch took
|
|
5.199 seconds and of that 4.932 was in ssh.
|
|
+
|
|
----------------
|
|
$ export GIT_TR2_BRIEF=1
|
|
$ export GIT_TR2=~/log.normal
|
|
$ git fetch origin
|
|
...
|
|
----------------
|
|
+
|
|
----------------
|
|
$ cat ~/log.normal
|
|
version 2.20.1.vfs.1.1.47.g534dbe1ad1
|
|
start git fetch origin
|
|
worktree /Users/jeffhost/work/gfw
|
|
cmd_name fetch (fetch)
|
|
child_start[0] ssh git@github.com ...
|
|
child_start[1] git index-pack ...
|
|
... (Trace2 events from child processes omitted)
|
|
child_exit[1] pid:14707 code:0 elapsed:0.076353
|
|
child_exit[0] pid:14706 code:0 elapsed:4.931869
|
|
child_start[2] git rev-list ...
|
|
... (Trace2 events from child process omitted)
|
|
child_exit[2] pid:14708 code:0 elapsed:0.110605
|
|
child_start[3] git gc --auto
|
|
... (Trace2 events from child process omitted)
|
|
child_exit[3] pid:14709 code:0 elapsed:0.006240
|
|
exit elapsed:5.198503 code:0
|
|
atexit elapsed:5.198541 code:0
|
|
----------------
|
|
+
|
|
When a git process is a (direct or indirect) child of another
|
|
git process, it inherits Trace2 context information. This
|
|
allows the child to print the command hierarchy. This example
|
|
shows gc as child[3] of fetch. When the gc process reports
|
|
its name as "gc", it also reports the hierarchy as "fetch/gc".
|
|
(In this example, trace2 messages from the child process is
|
|
indented for clarity.)
|
|
+
|
|
----------------
|
|
$ export GIT_TR2_BRIEF=1
|
|
$ export GIT_TR2=~/log.normal
|
|
$ git fetch origin
|
|
...
|
|
----------------
|
|
+
|
|
----------------
|
|
$ cat ~/log.normal
|
|
version 2.20.1.160.g5676107ecd.dirty
|
|
start git fetch official
|
|
worktree /Users/jeffhost/work/gfw
|
|
cmd_name fetch (fetch)
|
|
...
|
|
child_start[3] git gc --auto
|
|
version 2.20.1.160.g5676107ecd.dirty
|
|
start /Users/jeffhost/work/gfw/git gc --auto
|
|
worktree /Users/jeffhost/work/gfw
|
|
cmd_name gc (fetch/gc)
|
|
exit elapsed:0.001959 code:0
|
|
atexit elapsed:0.001997 code:0
|
|
child_exit[3] pid:20303 code:0 elapsed:0.007564
|
|
exit elapsed:3.868938 code:0
|
|
atexit elapsed:3.868970 code:0
|
|
----------------
|
|
|
|
Regions::
|
|
|
|
Regions can be use to time an interesting section of code.
|
|
+
|
|
----------------
|
|
void wt_status_collect(struct wt_status *s)
|
|
{
|
|
trace2_region_enter("status", "worktrees", s->repo);
|
|
wt_status_collect_changes_worktree(s);
|
|
trace2_region_leave("status", "worktrees", s->repo);
|
|
|
|
trace2_region_enter("status", "index", s->repo);
|
|
wt_status_collect_changes_index(s);
|
|
trace2_region_leave("status", "index", s->repo);
|
|
|
|
trace2_region_enter("status", "untracked", s->repo);
|
|
wt_status_collect_untracked(s);
|
|
trace2_region_leave("status", "untracked", s->repo);
|
|
}
|
|
|
|
void wt_status_print(struct wt_status *s)
|
|
{
|
|
trace2_region_enter("status", "print", s->repo);
|
|
switch (s->status_format) {
|
|
...
|
|
}
|
|
trace2_region_leave("status", "print", s->repo);
|
|
}
|
|
----------------
|
|
+
|
|
In this example, scanning for untracked files ran from +0.012568 to
|
|
+0.027149 (since the process started) and took 0.014581 seconds.
|
|
+
|
|
----------------
|
|
$ export GIT_TR2_PERF_BRIEF=1
|
|
$ export GIT_TR2_PERF=~/log.perf
|
|
$ git status
|
|
...
|
|
|
|
$ cat ~/log.perf
|
|
d0 | main | version | | | | | 2.20.1.160.g5676107ecd.dirty
|
|
d0 | main | start | | | | | git status
|
|
d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
|
|
d0 | main | cmd_name | | | | | status (status)
|
|
...
|
|
d0 | main | region_enter | r1 | 0.010988 | | status | label:worktrees
|
|
d0 | main | region_leave | r1 | 0.011236 | 0.000248 | status | label:worktrees
|
|
d0 | main | region_enter | r1 | 0.011260 | | status | label:index
|
|
d0 | main | region_leave | r1 | 0.012542 | 0.001282 | status | label:index
|
|
d0 | main | region_enter | r1 | 0.012568 | | status | label:untracked
|
|
d0 | main | region_leave | r1 | 0.027149 | 0.014581 | status | label:untracked
|
|
d0 | main | region_enter | r1 | 0.027411 | | status | label:print
|
|
d0 | main | region_leave | r1 | 0.028741 | 0.001330 | status | label:print
|
|
d0 | main | exit | | 0.028778 | | | code:0
|
|
d0 | main | atexit | | 0.028809 | | | code:0
|
|
----------------
|
|
+
|
|
Regions may be nested. This causes messages to be indented in the
|
|
PERF target, for example.
|
|
Elapsed times are relative to the start of the correpsonding nesting
|
|
level as expected. For example, if we add region message to:
|
|
+
|
|
----------------
|
|
static enum path_treatment read_directory_recursive(struct dir_struct *dir,
|
|
struct index_state *istate, const char *base, int baselen,
|
|
struct untracked_cache_dir *untracked, int check_only,
|
|
int stop_at_first_file, const struct pathspec *pathspec)
|
|
{
|
|
enum path_treatment state, subdir_state, dir_state = path_none;
|
|
|
|
trace2_region_enter_printf("dir", "read_recursive", NULL, "%.*s", baselen, base);
|
|
...
|
|
trace2_region_leave_printf("dir", "read_recursive", NULL, "%.*s", baselen, base);
|
|
return dir_state;
|
|
}
|
|
----------------
|
|
+
|
|
We can further investigate the time spent scanning for untracked files.
|
|
+
|
|
----------------
|
|
$ export GIT_TR2_PERF_BRIEF=1
|
|
$ export GIT_TR2_PERF=~/log.perf
|
|
$ git status
|
|
...
|
|
$ cat ~/log.perf
|
|
d0 | main | version | | | | | 2.20.1.162.gb4ccea44db.dirty
|
|
d0 | main | start | | | | | git status
|
|
d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
|
|
d0 | main | cmd_name | | | | | status (status)
|
|
...
|
|
d0 | main | region_enter | r1 | 0.015047 | | status | label:untracked
|
|
d0 | main | region_enter | | 0.015132 | | dir | ..label:read_recursive
|
|
d0 | main | region_enter | | 0.016341 | | dir | ....label:read_recursive vcs-svn/
|
|
d0 | main | region_leave | | 0.016422 | 0.000081 | dir | ....label:read_recursive vcs-svn/
|
|
d0 | main | region_enter | | 0.016446 | | dir | ....label:read_recursive xdiff/
|
|
d0 | main | region_leave | | 0.016522 | 0.000076 | dir | ....label:read_recursive xdiff/
|
|
d0 | main | region_enter | | 0.016612 | | dir | ....label:read_recursive git-gui/
|
|
d0 | main | region_enter | | 0.016698 | | dir | ......label:read_recursive git-gui/po/
|
|
d0 | main | region_enter | | 0.016810 | | dir | ........label:read_recursive git-gui/po/glossary/
|
|
d0 | main | region_leave | | 0.016863 | 0.000053 | dir | ........label:read_recursive git-gui/po/glossary/
|
|
...
|
|
d0 | main | region_enter | | 0.031876 | | dir | ....label:read_recursive builtin/
|
|
d0 | main | region_leave | | 0.032270 | 0.000394 | dir | ....label:read_recursive builtin/
|
|
d0 | main | region_leave | | 0.032414 | 0.017282 | dir | ..label:read_recursive
|
|
d0 | main | region_leave | r1 | 0.032454 | 0.017407 | status | label:untracked
|
|
...
|
|
d0 | main | exit | | 0.034279 | | | code:0
|
|
d0 | main | atexit | | 0.034322 | | | code:0
|
|
----------------
|
|
+
|
|
Trace2 regions are similar to the existing trace_performance_enter()
|
|
and trace_performance_leave() routines, but are thread safe and
|
|
maintain per-thread stacks of timers.
|
|
|
|
Data Messages::
|
|
|
|
Data messages added to a region.
|
|
+
|
|
----------------
|
|
int read_index_from(struct index_state *istate, const char *path,
|
|
const char *gitdir)
|
|
{
|
|
trace2_region_enter_printf("index", "do_read_index", the_repository, "%s", path);
|
|
|
|
...
|
|
|
|
trace2_data_intmax("index", the_repository, "read/version", istate->version);
|
|
trace2_data_intmax("index", the_repository, "read/cache_nr", istate->cache_nr);
|
|
|
|
trace2_region_leave_printf("index", "do_read_index", the_repository, "%s", path);
|
|
}
|
|
----------------
|
|
+
|
|
This example shows that the index contained 3552 entries.
|
|
+
|
|
----------------
|
|
$ export GIT_TR2_PERF_BRIEF=1
|
|
$ export GIT_TR2_PERF=~/log.perf
|
|
$ git status
|
|
...
|
|
$ cat ~/log.perf
|
|
d0 | main | version | | | | | 2.20.1.156.gf9916ae094.dirty
|
|
d0 | main | start | | | | | git status
|
|
d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
|
|
d0 | main | cmd_name | | | | | status (status)
|
|
d0 | main | region_enter | r1 | 0.001791 | | index | label:do_read_index .git/index
|
|
d0 | main | data | r1 | 0.002494 | 0.000703 | index | ..read/version:2
|
|
d0 | main | data | r1 | 0.002520 | 0.000729 | index | ..read/cache_nr:3552
|
|
d0 | main | region_leave | r1 | 0.002539 | 0.000748 | index | label:do_read_index .git/index
|
|
...
|
|
----------------
|
|
|
|
Thread Events::
|
|
|
|
Thread messages added to a thread-proc.
|
|
+
|
|
For example, the multithreaded preload-index code can be
|
|
instrumented with a region around the thread pool and then
|
|
per-thread start and exit events within the threadproc.
|
|
+
|
|
----------------
|
|
static void *preload_thread(void *_data)
|
|
{
|
|
// start the per-thread clock and emit a message.
|
|
trace2_thread_start("preload_thread");
|
|
|
|
// report which chunk of the array this thread was assigned.
|
|
trace2_data_intmax("index", the_repository, "offset", p->offset);
|
|
trace2_data_intmax("index", the_repository, "count", nr);
|
|
|
|
do {
|
|
...
|
|
} while (--nr > 0);
|
|
...
|
|
|
|
// report elapsed time taken by this thread.
|
|
trace2_thread_exit();
|
|
return NULL;
|
|
}
|
|
|
|
void preload_index(struct index_state *index,
|
|
const struct pathspec *pathspec,
|
|
unsigned int refresh_flags)
|
|
{
|
|
trace2_region_enter("index", "preload", the_repository);
|
|
|
|
for (i = 0; i < threads; i++) {
|
|
... /* create thread */
|
|
}
|
|
|
|
for (i = 0; i < threads; i++) {
|
|
... /* join thread */
|
|
}
|
|
|
|
trace2_region_leave("index", "preload", the_repository);
|
|
}
|
|
----------------
|
|
+
|
|
In this example preload_index() was executed by the `main` thread
|
|
and started the `preload` region. Seven threads, named
|
|
`th01:preload_thread` through `th07:preload_thread`, were started.
|
|
Events from each thread are atomically appended to the shared target
|
|
stream as they occur so they may appear in random order with respect
|
|
other threads. Finally, the main thread waits for the threads to
|
|
finish and leaves the region.
|
|
+
|
|
Data events are tagged with the active thread name. They are used
|
|
to report the per-thread parameters.
|
|
+
|
|
----------------
|
|
$ export GIT_TR2_PERF_BRIEF=1
|
|
$ export GIT_TR2_PERF=~/log.perf
|
|
$ git status
|
|
...
|
|
$ cat ~/log.perf
|
|
...
|
|
d0 | main | region_enter | r1 | 0.002595 | | index | label:preload
|
|
d0 | th01:preload_thread | thread_start | | 0.002699 | | |
|
|
d0 | th02:preload_thread | thread_start | | 0.002721 | | |
|
|
d0 | th01:preload_thread | data | r1 | 0.002736 | 0.000037 | index | offset:0
|
|
d0 | th02:preload_thread | data | r1 | 0.002751 | 0.000030 | index | offset:2032
|
|
d0 | th03:preload_thread | thread_start | | 0.002711 | | |
|
|
d0 | th06:preload_thread | thread_start | | 0.002739 | | |
|
|
d0 | th01:preload_thread | data | r1 | 0.002766 | 0.000067 | index | count:508
|
|
d0 | th06:preload_thread | data | r1 | 0.002856 | 0.000117 | index | offset:2540
|
|
d0 | th03:preload_thread | data | r1 | 0.002824 | 0.000113 | index | offset:1016
|
|
d0 | th04:preload_thread | thread_start | | 0.002710 | | |
|
|
d0 | th02:preload_thread | data | r1 | 0.002779 | 0.000058 | index | count:508
|
|
d0 | th06:preload_thread | data | r1 | 0.002966 | 0.000227 | index | count:508
|
|
d0 | th07:preload_thread | thread_start | | 0.002741 | | |
|
|
d0 | th07:preload_thread | data | r1 | 0.003017 | 0.000276 | index | offset:3048
|
|
d0 | th05:preload_thread | thread_start | | 0.002712 | | |
|
|
d0 | th05:preload_thread | data | r1 | 0.003067 | 0.000355 | index | offset:1524
|
|
d0 | th05:preload_thread | data | r1 | 0.003090 | 0.000378 | index | count:508
|
|
d0 | th07:preload_thread | data | r1 | 0.003037 | 0.000296 | index | count:504
|
|
d0 | th03:preload_thread | data | r1 | 0.002971 | 0.000260 | index | count:508
|
|
d0 | th04:preload_thread | data | r1 | 0.002983 | 0.000273 | index | offset:508
|
|
d0 | th04:preload_thread | data | r1 | 0.007311 | 0.004601 | index | count:508
|
|
d0 | th05:preload_thread | thread_exit | | 0.008781 | 0.006069 | |
|
|
d0 | th01:preload_thread | thread_exit | | 0.009561 | 0.006862 | |
|
|
d0 | th03:preload_thread | thread_exit | | 0.009742 | 0.007031 | |
|
|
d0 | th06:preload_thread | thread_exit | | 0.009820 | 0.007081 | |
|
|
d0 | th02:preload_thread | thread_exit | | 0.010274 | 0.007553 | |
|
|
d0 | th07:preload_thread | thread_exit | | 0.010477 | 0.007736 | |
|
|
d0 | th04:preload_thread | thread_exit | | 0.011657 | 0.008947 | |
|
|
d0 | main | region_leave | r1 | 0.011717 | 0.009122 | index | label:preload
|
|
...
|
|
d0 | main | exit | | 0.029996 | | | code:0
|
|
d0 | main | atexit | | 0.030027 | | | code:0
|
|
----------------
|
|
+
|
|
In this example, the preload region took 0.009122 seconds. The 7 threads
|
|
took between 0.006069 and 0.008947 seconds to work on their portion of
|
|
the index. Thread "th01" worked on 508 items at offset 0. Thread "th02"
|
|
worked on 508 items at offset 2032. Thread "th04" worked on 508 itemts
|
|
at offset 508.
|
|
+
|
|
This example also shows that thread names are assigned in a racy manner
|
|
as each thread starts and allocates TLS storage.
|
|
|
|
== Future Work
|
|
|
|
=== Relationship to the Existing Trace Api (api-trace.txt)
|
|
|
|
There are a few issues to resolve before we can completely
|
|
switch to Trace2.
|
|
|
|
* Updating existing tests that assume GIT_TRACE format messages.
|
|
|
|
* How to best handle custom GIT_TRACE_<key> messages?
|
|
|
|
** The GIT_TRACE_<key> mechanism allows each <key> to write to a
|
|
different file (in addition to just stderr).
|
|
|
|
** Do we want to maintain that ability or simply write to the existing
|
|
Trace2 targets (and convert <key> to a "category").
|