A more structured way to obtain execution trace has been added.
* jh/trace2:
trace2: add for_each macros to clang-format
trace2: t/helper/test-trace2, t0210.sh, t0211.sh, t0212.sh
trace2:data: add subverb for rebase
trace2:data: add subverb to reset command
trace2:data: add subverb to checkout command
trace2:data: pack-objects: add trace2 regions
trace2:data: add trace2 instrumentation to index read/write
trace2:data: add trace2 hook classification
trace2:data: add trace2 transport child classification
trace2:data: add trace2 sub-process classification
trace2:data: add editor/pager child classification
trace2:data: add trace2 regions to wt-status
trace2: collect Windows-specific process information
trace2: create new combined trace facility
trace2: Documentation/technical/api-trace2.txt
# A list of macros that should be interpreted as foreach loops instead of as
# function calls.
-ForEachMacros: ['for_each_string_list_item']
+ForEachMacros: ['for_each_string_list_item', 'for_each_wanted_builtin', 'for_each_builtin', 'for_each_ut']
# The maximum number of consecutive empty lines to keep.
MaxEmptyLinesToKeep: 1
--- /dev/null
+= 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").
TEST_BUILTINS_OBJS += test-submodule-config.o
TEST_BUILTINS_OBJS += test-submodule-nested-repo-config.o
TEST_BUILTINS_OBJS += test-subprocess.o
+TEST_BUILTINS_OBJS += test-trace2.o
TEST_BUILTINS_OBJS += test-urlmatch-normalization.o
TEST_BUILTINS_OBJS += test-xml-encode.o
TEST_BUILTINS_OBJS += test-wildmatch.o
LIB_OBJS += thread-utils.o
LIB_OBJS += tmp-objdir.o
LIB_OBJS += trace.o
+LIB_OBJS += trace2.o
+LIB_OBJS += trace2/tr2_cfg.o
+LIB_OBJS += trace2/tr2_cmd_name.o
+LIB_OBJS += trace2/tr2_dst.o
+LIB_OBJS += trace2/tr2_sid.o
+LIB_OBJS += trace2/tr2_tbuf.o
+LIB_OBJS += trace2/tr2_tgt_event.o
+LIB_OBJS += trace2/tr2_tgt_normal.o
+LIB_OBJS += trace2/tr2_tgt_perf.o
+LIB_OBJS += trace2/tr2_tls.o
LIB_OBJS += trailer.o
LIB_OBJS += transport.o
LIB_OBJS += transport-helper.o
LIB_OBJS += compat/inet_pton.o
BASIC_CFLAGS += -DNO_INET_PTON
endif
-ifndef NO_UNIX_SOCKETS
+ifdef NO_UNIX_SOCKETS
+ BASIC_CFLAGS += -DNO_UNIX_SOCKETS
+else
LIB_OBJS += unix-socket.o
PROGRAM_OBJS += credential-cache.o
PROGRAM_OBJS += credential-cache--daemon.o
cp.in = xopen(am_path(state, "rewritten"), O_RDONLY);
cp.stdout_to_stderr = 1;
+ cp.trace2_hook_name = "post-rewrite";
ret = run_command(&cp);
struct lock_file lock_file = LOCK_INIT;
int nr_checkouts = 0, nr_unmerged = 0;
+ trace2_cmd_mode(opts->patch_mode ? "patch" : "path");
+
if (opts->track != BRANCH_TRACK_UNSPECIFIED)
die(_("'%s' cannot be used with updating paths"), "--track");
void *path_to_free;
struct object_id rev;
int flag, writeout_error = 0;
+
+ trace2_cmd_mode("branch");
+
memset(&old_branch_info, 0, sizeof(old_branch_info));
old_branch_info.path = path_to_free = resolve_refdup("HEAD", 0, &rev, &flag);
if (old_branch_info.path)
int status;
struct strbuf branch_ref = STRBUF_INIT;
+ trace2_cmd_mode("unborn");
+
if (!opts->new_branch)
die(_("You are on a branch yet to be born"));
strbuf_addf(&branch_ref, "refs/heads/%s", opts->new_branch);
#include "object-store.h"
#include "dir.h"
#include "midx.h"
+#include "trace2.h"
#define IN_PACK(obj) oe_in_pack(&to_pack, obj)
#define SIZE(obj) oe_size(&to_pack, obj)
}
}
+ trace2_region_enter("pack-objects", "enumerate-objects",
+ the_repository);
prepare_packing_data(the_repository, &to_pack);
if (progress)
if (include_tag && nr_result)
for_each_ref(add_ref_tag, NULL);
stop_progress(&progress_state);
+ trace2_region_leave("pack-objects", "enumerate-objects",
+ the_repository);
if (non_empty && !nr_result)
return 0;
- if (nr_result)
+ if (nr_result) {
+ trace2_region_enter("pack-objects", "prepare-pack",
+ the_repository);
prepare_pack(window, depth);
+ trace2_region_leave("pack-objects", "prepare-pack",
+ the_repository);
+ }
+
+ trace2_region_enter("pack-objects", "write-pack-file", the_repository);
write_pack_file();
+ trace2_region_leave("pack-objects", "write-pack-file", the_repository);
+
if (progress)
fprintf_ln(stderr,
_("Total %"PRIu32" (delta %"PRIu32"),"
ACTION_EDIT_TODO,
ACTION_SHOW_CURRENT_PATCH,
} action = NO_ACTION;
+ static const char *action_names[] = { N_("undefined"),
+ N_("continue"),
+ N_("skip"),
+ N_("abort"),
+ N_("quit"),
+ N_("edit_todo"),
+ N_("show_current_patch"),
+ NULL };
const char *gpg_sign = NULL;
struct string_list exec = STRING_LIST_INIT_NODUP;
const char *rebase_merges = NULL;
die(_("The --edit-todo action can only be used during "
"interactive rebase."));
+ if (trace2_is_enabled()) {
+ if (is_interactive(&options))
+ trace2_cmd_mode("interactive");
+ else if (exec.nr)
+ trace2_cmd_mode("interactive-exec");
+ else
+ trace2_cmd_mode(action_names[action]);
+ }
+
switch (action) {
case ACTION_CONTINUE: {
struct object_id head;
proc.argv = argv;
proc.in = -1;
proc.stdout_to_stderr = 1;
+ proc.trace2_hook_name = hook_name;
+
if (feed_state->push_options) {
int i;
for (i = 0; i < feed_state->push_options->nr; i++)
proc.stdout_to_stderr = 1;
proc.err = use_sideband ? -1 : 0;
proc.argv = argv;
+ proc.trace2_hook_name = "update";
code = start_command(&proc);
if (code)
proc.no_stdin = 1;
proc.stdout_to_stderr = 1;
proc.err = use_sideband ? -1 : 0;
+ proc.trace2_hook_name = "post-update";
if (!start_command(&proc)) {
if (use_sideband)
if (patch_mode) {
if (reset_type != NONE)
die(_("--patch is incompatible with --{hard,mixed,soft}"));
+ trace2_cmd_mode("patch-interactive");
return run_add_interactive(rev, "--patch=reset", &pathspec);
}
if (reset_type == NONE)
reset_type = MIXED; /* by default */
+ if (pathspec.nr)
+ trace2_cmd_mode("path");
+ else
+ trace2_cmd_mode(reset_type_names[reset_type]);
+
if (reset_type != SOFT && (reset_type != MIXED || get_git_work_tree()))
setup_work_tree();
{
int i;
- run_processes_parallel(suc->max_jobs,
- update_clone_get_next_task,
- update_clone_start_failure,
- update_clone_task_finished,
- suc);
+ run_processes_parallel_tr2(suc->max_jobs, update_clone_get_next_task,
+ update_clone_start_failure,
+ update_clone_task_finished, suc, "submodule",
+ "parallel/update");
/*
* We saved the output and put it out all at once now.
cp.dir = path;
cp.env = env;
cp.argv = NULL;
+ cp.trace2_hook_name = "post-checkout";
argv_array_pushl(&cp.args, absolute_path(hook),
oid_to_hex(&null_oid),
oid_to_hex(&commit->object.oid),
#include "gettext.h"
#include "convert.h"
#include "trace.h"
+#include "trace2.h"
#include "string-list.h"
#include "pack-revindex.h"
#include "hash.h"
int main(int argc, const char **argv)
{
+ int result;
+
/*
* Always open file descriptors 0/1/2 to avoid clobbering files
* in die(). It also avoids messing up when the pipes are dup'ed
* onto stdin/stdout/stderr in the child processes we spawn.
*/
sanitize_stdfds();
+ restore_sigpipe_to_default();
+
+ trace2_initialize();
+ trace2_cmd_start(argv);
+ trace2_collect_process_info();
git_resolve_executable_dir(argv[0]);
attr_start();
- restore_sigpipe_to_default();
+ result = cmd_main(argc, argv);
+
+ trace2_cmd_exit(result);
- return cmd_main(argc, argv);
+ return result;
}
return 0;
prog = path_lookup(interpr, 1);
if (prog) {
+ int exec_id;
int argc = 0;
const char **argv2;
while (argv[argc]) argc++;
ALLOC_ARRAY(argv2, argc + 1);
argv2[0] = (char *)cmd; /* full path to the script file */
memcpy(&argv2[1], &argv[1], sizeof(*argv) * argc);
+ exec_id = trace2_exec(prog, argv2);
pid = mingw_spawnv(prog, argv2, 1);
if (pid >= 0) {
int status;
if (waitpid(pid, &status, 0) < 0)
status = 255;
+ trace2_exec_result(exec_id, status);
exit(status);
}
+ trace2_exec_result(exec_id, -1);
pid = 1; /* indicate that we tried but failed */
free(prog);
free(argv2);
/* check if git_command is a shell script */
if (!try_shell_exec(cmd, argv)) {
int pid, status;
+ int exec_id;
+ exec_id = trace2_exec(cmd, (const char **)argv);
pid = mingw_spawnv(cmd, (const char **)argv, 0);
- if (pid < 0)
+ if (pid < 0) {
+ trace2_exec_result(exec_id, -1);
return -1;
+ }
if (waitpid(pid, &status, 0) < 0)
status = 255;
+ trace2_exec_result(exec_id, status);
exit(status);
}
return -1;
errno = EINVAL;
return -1;
}
-/* bash cannot reliably detect negative return codes as failure */
-#define exit(code) exit((code) & 0xff)
+
#define sigemptyset(x) (void)0
static inline int sigaddset(sigset_t *set, int signum)
{ return 0; }
--- /dev/null
+#include "../../cache.h"
+#include "../../json-writer.h"
+#include <Psapi.h>
+#include <tlHelp32.h>
+
+/*
+ * An arbitrarily chosen value to limit the size of the ancestor
+ * array built in git_processes().
+ */
+#define NR_PIDS_LIMIT 10
+
+/*
+ * Find the process data for the given PID in the given snapshot
+ * and update the PROCESSENTRY32 data.
+ */
+static int find_pid(DWORD pid, HANDLE hSnapshot, PROCESSENTRY32 *pe32)
+{
+ pe32->dwSize = sizeof(PROCESSENTRY32);
+
+ if (Process32First(hSnapshot, pe32)) {
+ do {
+ if (pe32->th32ProcessID == pid)
+ return 1;
+ } while (Process32Next(hSnapshot, pe32));
+ }
+ return 0;
+}
+
+/*
+ * Accumulate JSON array of our parent processes:
+ * [
+ * exe-name-parent,
+ * exe-name-grand-parent,
+ * ...
+ * ]
+ *
+ * Note: we only report the filename of the process executable; the
+ * only way to get its full pathname is to use OpenProcess()
+ * and GetModuleFileNameEx() or QueryfullProcessImageName()
+ * and that seems rather expensive (on top of the cost of
+ * getting the snapshot).
+ *
+ * Note: we compute the set of parent processes by walking the PPID
+ * link in each visited PROCESSENTRY32 record. This search
+ * stops when an ancestor process is not found in the snapshot
+ * (because it exited before the current or intermediate parent
+ * process exited).
+ *
+ * This search may compute an incorrect result if the PPID link
+ * refers to the PID of an exited parent and that PID has been
+ * recycled and given to a new unrelated process.
+ *
+ * Worse, it is possible for a child or descendant of the
+ * current process to be given the recycled PID and cause a
+ * PPID-cycle. This would cause an infinite loop building our
+ * parent process array.
+ *
+ * Note: for completeness, the "System Idle" process has PID=0 and
+ * PPID=0 and could cause another PPID-cycle. We don't expect
+ * Git to be a descendant of the idle process, but because of
+ * PID recycling, it might be possible to get a PPID link value
+ * of 0. This too would cause an infinite loop.
+ *
+ * Therefore, we keep an array of the visited PPIDs to guard against
+ * cycles.
+ *
+ * We use a fixed-size array rather than ALLOC_GROW to keep things
+ * simple and avoid the alloc/realloc overhead. It is OK if we
+ * truncate the search and return a partial answer.
+ */
+static void get_processes(struct json_writer *jw, HANDLE hSnapshot)
+{
+ PROCESSENTRY32 pe32;
+ DWORD pid;
+ DWORD pid_list[NR_PIDS_LIMIT];
+ int k, nr_pids = 0;
+
+ pid = GetCurrentProcessId();
+ while (find_pid(pid, hSnapshot, &pe32)) {
+ /* Only report parents. Omit self from the JSON output. */
+ if (nr_pids)
+ jw_array_string(jw, pe32.szExeFile);
+
+ /* Check for cycle in snapshot. (Yes, it happened.) */
+ for (k = 0; k < nr_pids; k++)
+ if (pid == pid_list[k]) {
+ jw_array_string(jw, "(cycle)");
+ return;
+ }
+
+ if (nr_pids == NR_PIDS_LIMIT) {
+ jw_array_string(jw, "(truncated)");
+ return;
+ }
+
+ pid_list[nr_pids++] = pid;
+
+ pid = pe32.th32ParentProcessID;
+ }
+}
+
+/*
+ * Emit JSON data for the current and parent processes. Individual
+ * trace2 targets can decide how to actually print it.
+ */
+static void get_ancestry(void)
+{
+ HANDLE hSnapshot = CreateToolhelp32Snapshot(TH32CS_SNAPPROCESS, 0);
+
+ if (hSnapshot != INVALID_HANDLE_VALUE) {
+ struct json_writer jw = JSON_WRITER_INIT;
+
+ jw_array_begin(&jw, 0);
+ get_processes(&jw, hSnapshot);
+ jw_end(&jw);
+
+ trace2_data_json("process", the_repository, "windows/ancestry",
+ &jw);
+
+ jw_release(&jw);
+ CloseHandle(hSnapshot);
+ }
+}
+
+/*
+ * Is a debugger attached to the current process?
+ *
+ * This will catch debug runs (where the debugger started the process).
+ * This is the normal case. Since this code is called during our startup,
+ * it will not report instances where a debugger is attached dynamically
+ * to a running git process, but that is relatively rare.
+ */
+static void get_is_being_debugged(void)
+{
+ if (IsDebuggerPresent())
+ trace2_data_intmax("process", the_repository,
+ "windows/debugger_present", 1);
+}
+
+void trace2_collect_process_info(void)
+{
+ if (!trace2_is_enabled())
+ return;
+
+ get_is_being_debugged();
+ get_ancestry();
+}
void git_config_set(const char *key, const char *value)
{
git_config_set_multivar(key, value, NULL, 0);
+
+ trace2_cmd_set_config(key, value);
}
/*
BASIC_CFLAGS = -nologo -I. -I../zlib -Icompat/vcbuild -Icompat/vcbuild/include -DWIN32 -D_CONSOLE -DHAVE_STRING_H -D_CRT_SECURE_NO_WARNINGS -D_CRT_NONSTDC_NO_DEPRECATE
COMPAT_OBJS = compat/msvc.o compat/winansi.o \
compat/win32/pthread.o compat/win32/syslog.o \
+ compat/win32/trace2_win32_process_info.o \
compat/win32/dirent.o
COMPAT_CFLAGS = -D__USE_MINGW_ACCESS -DNOGDI -DHAVE_STRING_H -Icompat -Icompat/regex -Icompat/win32 -DSTRIP_EXTENSION=\".exe\"
BASIC_LDFLAGS = -IGNORE:4217 -IGNORE:4049 -NOLOGO -SUBSYSTEM:CONSOLE
COMPAT_CFLAGS += -DNOGDI -Icompat -Icompat/win32
COMPAT_CFLAGS += -DSTRIP_EXTENSION=\".exe\"
COMPAT_OBJS += compat/mingw.o compat/winansi.o \
+ compat/win32/trace2_win32_process_info.o \
compat/win32/path-utils.o \
compat/win32/pthread.o compat/win32/syslog.o \
compat/win32/dirent.o
conn = NULL;
} else if (protocol == PROTO_GIT) {
conn = git_connect_git(fd, hostandport, path, prog, version, flags);
+ conn->trace2_child_class = "transport/git";
} else {
struct strbuf cmd = STRBUF_INIT;
const char *const *var;
strbuf_release(&cmd);
return NULL;
}
+ conn->trace2_child_class = "transport/ssh";
fill_ssh_args(conn, ssh_host, port, version, flags);
} else {
transport_check_allowed("file");
+ conn->trace2_child_class = "transport/file";
if (version > 0) {
argv_array_pushf(&conn->env_array, GIT_PROTOCOL_ENVIRONMENT "=version=%d",
version);
p.argv = args;
p.env = env;
p.use_shell = 1;
+ p.trace2_child_class = "editor";
if (start_command(&p) < 0)
return error("unable to start editor '%s'", editor);
return -1;
}
+ trace2_cmd_path(buf->buf);
+
return 0;
}
extern int cmd_main(int, const char **);
+/*
+ * Intercept all calls to exit() and route them to trace2 to
+ * optionally emit a message before calling the real exit().
+ */
+int trace2_cmd_exit_fl(const char *file, int line, int code);
+#define exit(code) exit(trace2_cmd_exit_fl(__FILE__, __LINE__, (code)))
+
/*
* You can mark a stack variable with UNLEAK(var) to avoid it being
* reported as a leak by tools like LSAN or valgrind. The argument
git_set_exec_path(cmd + 1);
else {
puts(git_exec_path());
+ trace2_cmd_name("_query_");
exit(0);
}
} else if (!strcmp(cmd, "--html-path")) {
puts(system_path(GIT_HTML_PATH));
+ trace2_cmd_name("_query_");
exit(0);
} else if (!strcmp(cmd, "--man-path")) {
puts(system_path(GIT_MAN_PATH));
+ trace2_cmd_name("_query_");
exit(0);
} else if (!strcmp(cmd, "--info-path")) {
puts(system_path(GIT_INFO_PATH));
+ trace2_cmd_name("_query_");
exit(0);
} else if (!strcmp(cmd, "-p") || !strcmp(cmd, "--paginate")) {
use_pager = 1;
(*argv)++;
(*argc)--;
} else if (skip_prefix(cmd, "--list-cmds=", &cmd)) {
+ trace2_cmd_name("_query_");
if (!strcmp(cmd, "parseopt")) {
struct string_list list = STRING_LIST_INIT_DUP;
int i;
commit_pager_choice();
child.use_shell = 1;
+ child.trace2_child_class = "shell_alias";
argv_array_push(&child.args, alias_string + 1);
argv_array_pushv(&child.args, (*argv) + 1);
+ trace2_cmd_alias(alias_command, child.args.argv);
+ trace2_cmd_list_config();
+ trace2_cmd_name("_run_shell_alias_");
+
ret = run_command(&child);
if (ret >= 0) /* normal exit */
exit(ret);
/* insert after command name */
memcpy(new_argv + count, *argv + 1, sizeof(char *) * *argcp);
+ trace2_cmd_alias(alias_command, new_argv);
+ trace2_cmd_list_config();
+
*argv = new_argv;
*argcp += count - 1;
setup_work_tree();
trace_argv_printf(argv, "trace: built-in: git");
+ trace2_cmd_name(p->cmd);
+ trace2_cmd_list_config();
validate_cache_entries(the_repository->index);
status = p->fn(argc, argv, prefix);
cmd.clean_on_exit = 1;
cmd.wait_after_clean = 1;
cmd.silent_exec_failure = 1;
+ cmd.trace2_child_class = "dashed";
+ trace2_cmd_name("_run_dashed_");
+
+ /*
+ * The code in run_command() logs trace2 child_start/child_exit
+ * events, so we do not need to report exec/exec_result events here.
+ */
trace_argv_printf(cmd.args.argv, "trace: exec:");
/*
* the program.
*/
status = run_command(&cmd);
+
+ /*
+ * If the child process ran and we are now going to exit, emit a
+ * generic string as our trace2 command verb to indicate that we
+ * launched a dashed command.
+ */
if (status >= 0)
exit(status);
else if (errno != ENOENT)
if (!done_alias)
handle_builtin(*argcp, *argv);
+#if 0 // TODO In GFW, need to amend a7924b655e940b06cb547c235d6bed9767929673 to include trace2_ and _tr2 lines.
+ else if (get_builtin(**argv)) {
+ struct argv_array args = ARGV_ARRAY_INIT;
+ int i;
+
+ /*
+ * The current process is committed to launching a
+ * child process to run the command named in (**argv)
+ * and exiting. Log a generic string as the trace2
+ * command verb to indicate this. Note that the child
+ * process will log the actual verb when it runs.
+ */
+ trace2_cmd_name("_run_git_alias_");
+
+ if (get_super_prefix())
+ die("%s doesn't support --super-prefix", **argv);
+
+ commit_pager_choice();
+
+ argv_array_push(&args, "git");
+ for (i = 0; i < *argcp; i++)
+ argv_array_push(&args, (*argv)[i]);
+
+ trace_argv_printf(args.argv, "trace: exec:");
+
+ /*
+ * if we fail because the command is not found, it is
+ * OK to return. Otherwise, we just pass along the status code.
+ */
+ i = run_command_v_opt_tr2(args.argv, RUN_SILENT_EXEC_FAILURE |
+ RUN_CLEAN_ON_EXIT, "git_alias");
+ if (i >= 0 || errno != ENOENT)
+ exit(i);
+ die("could not execute builtin %s", **argv);
+ }
+#endif // a7924b655e940b06cb547c235d6bed9767929673
+
/* .. then try the external ones */
execv_dashed_external(*argv);
argv_array_push(&pager_process->args, pager);
pager_process->use_shell = 1;
setup_pager_env(&pager_process->env_array);
+ pager_process->trace2_child_class = "pager";
}
void setup_pager(void)
load_index_extensions(&p);
}
munmap((void *)mmap, mmap_size);
+
+ /*
+ * TODO trace2: replace "the_repository" with the actual repo instance
+ * that is associated with the given "istate".
+ */
+ trace2_data_intmax("index", the_repository, "read/version",
+ istate->version);
+ trace2_data_intmax("index", the_repository, "read/cache_nr",
+ istate->cache_nr);
+
return istate->cache_nr;
unmap:
if (istate->initialized)
return istate->cache_nr;
+ /*
+ * TODO trace2: replace "the_repository" with the actual repo instance
+ * that is associated with the given "istate".
+ */
+ trace2_region_enter_printf("index", "do_read_index", the_repository,
+ "%s", path);
trace_performance_enter();
ret = do_read_index(istate, path, 0);
trace_performance_leave("read cache %s", path);
+ trace2_region_leave_printf("index", "do_read_index", the_repository,
+ "%s", path);
split_index = istate->split_index;
if (!split_index || is_null_oid(&split_index->base_oid)) {
base_oid_hex = oid_to_hex(&split_index->base_oid);
base_path = xstrfmt("%s/sharedindex.%s", gitdir, base_oid_hex);
+ trace2_region_enter_printf("index", "shared/do_read_index",
+ the_repository, "%s", base_path);
ret = do_read_index(split_index->base, base_path, 1);
+ trace2_region_leave_printf("index", "shared/do_read_index",
+ the_repository, "%s", base_path);
if (!oideq(&split_index->base_oid, &split_index->base->oid))
die(_("broken index, expect %s in %s, got %s"),
base_oid_hex, base_path,
istate->timestamp.sec = (unsigned int)st.st_mtime;
istate->timestamp.nsec = ST_MTIME_NSEC(st);
trace_performance_since(start, "write index, changed mask = %x", istate->cache_changed);
+
+ /*
+ * TODO trace2: replace "the_repository" with the actual repo instance
+ * that is associated with the given "istate".
+ */
+ trace2_data_intmax("index", the_repository, "write/version",
+ istate->version);
+ trace2_data_intmax("index", the_repository, "write/cache_nr",
+ istate->cache_nr);
+
return 0;
}
static int do_write_locked_index(struct index_state *istate, struct lock_file *lock,
unsigned flags)
{
- int ret = do_write_index(istate, lock->tempfile, 0);
+ int ret;
+
+ /*
+ * TODO trace2: replace "the_repository" with the actual repo instance
+ * that is associated with the given "istate".
+ */
+ trace2_region_enter_printf("index", "do_write_index", the_repository,
+ "%s", lock->tempfile->filename.buf);
+ ret = do_write_index(istate, lock->tempfile, 0);
+ trace2_region_leave_printf("index", "do_write_index", the_repository,
+ "%s", lock->tempfile->filename.buf);
+
if (ret)
return ret;
if (flags & COMMIT_LOCK)
int ret;
move_cache_to_base_index(istate);
+
+ trace2_region_enter_printf("index", "shared/do_write_index",
+ the_repository, "%s", (*temp)->filename.buf);
ret = do_write_index(si->base, *temp, 1);
+ trace2_region_enter_printf("index", "shared/do_write_index",
+ the_repository, "%s", (*temp)->filename.buf);
+
if (ret)
return ret;
ret = adjust_shared_perm(get_tempfile_path(*temp));
string_list_init(&options.deepen_not, 1);
string_list_init(&options.push_options, 1);
+ /*
+ * Just report "remote-curl" here (folding all the various aliases
+ * ("git-remote-http", "git-remote-https", and etc.) here since they
+ * are all just copies of the same actual executable.
+ */
+ trace2_cmd_name("remote-curl");
+
remote = remote_get(argv[1]);
if (argc > 2) {
void repo_set_worktree(struct repository *repo, const char *path)
{
repo->worktree = real_pathdup(path, 1);
+
+ trace2_def_repo(repo);
}
static int read_and_verify_repository_format(struct repository_format *format,
/* Repository's current hash algorithm, as serialized on disk. */
const struct git_hash_algo *hash_algo;
+ /* A unique-id for tracing purposes. */
+ int trace2_repo_id;
+
/* Configurations */
/* Indicate if a repository has a different 'commondir' from 'gitdir' */
int sane_execvp(const char *file, char * const argv[])
{
+#ifndef GIT_WINDOWS_NATIVE
+ /*
+ * execvp() doesn't return, so we all we can do is tell trace2
+ * what we are about to do and let it leave a hint in the log
+ * (unless of course the execvp() fails).
+ *
+ * we skip this for Windows because the compat layer already
+ * has to emulate the execvp() call anyway.
+ */
+ int exec_id = trace2_exec(file, (const char **)argv);
+#endif
+
if (!execvp(file, argv))
return 0; /* cannot happen ;-) */
+#ifndef GIT_WINDOWS_NATIVE
+ {
+ int ec = errno;
+ trace2_exec_result(exec_id, ec);
+ errno = ec;
+ }
+#endif
+
/*
* When a command can't be found because one of the directories
* listed in $PATH is unsearchable, execvp reports EACCES, but
cmd->err = fderr[0];
}
+ trace2_child_start(cmd);
trace_run_command(cmd);
fflush(NULL);
#endif
if (cmd->pid < 0) {
+ trace2_child_exit(cmd, -1);
+
if (need_in)
close_pair(fdin);
else if (cmd->in)
int finish_command(struct child_process *cmd)
{
int ret = wait_or_whine(cmd->pid, cmd->argv[0], 0);
+ trace2_child_exit(cmd, ret);
child_process_clear(cmd);
return ret;
}
int finish_command_in_signal(struct child_process *cmd)
{
- return wait_or_whine(cmd->pid, cmd->argv[0], 1);
+ int ret = wait_or_whine(cmd->pid, cmd->argv[0], 1);
+ trace2_child_exit(cmd, ret);
+ return ret;
}
return run_command_v_opt_cd_env(argv, opt, NULL, NULL);
}
+int run_command_v_opt_tr2(const char **argv, int opt, const char *tr2_class)
+{
+ return run_command_v_opt_cd_env_tr2(argv, opt, NULL, NULL, tr2_class);
+}
+
int run_command_v_opt_cd_env(const char **argv, int opt, const char *dir, const char *const *env)
+{
+ return run_command_v_opt_cd_env_tr2(argv, opt, dir, env, NULL);
+}
+
+int run_command_v_opt_cd_env_tr2(const char **argv, int opt, const char *dir,
+ const char *const *env, const char *tr2_class)
{
struct child_process cmd = CHILD_PROCESS_INIT;
cmd.argv = argv;
cmd.clean_on_exit = opt & RUN_CLEAN_ON_EXIT ? 1 : 0;
cmd.dir = dir;
cmd.env = env;
+ cmd.trace2_child_class = tr2_class;
return run_command(&cmd);
}
hook.env = env;
hook.no_stdin = 1;
hook.stdout_to_stderr = 1;
+ hook.trace2_hook_name = name;
return run_command(&hook);
}
pp_cleanup(&pp);
return 0;
}
+
+int run_processes_parallel_tr2(int n, get_next_task_fn get_next_task,
+ start_failure_fn start_failure,
+ task_finished_fn task_finished, void *pp_cb,
+ const char *tr2_category, const char *tr2_label)
+{
+ int result;
+
+ trace2_region_enter_printf(tr2_category, tr2_label, NULL, "max:%d",
+ ((n < 1) ? online_cpus() : n));
+
+ result = run_processes_parallel(n, get_next_task, start_failure,
+ task_finished, pp_cb);
+
+ trace2_region_leave(tr2_category, tr2_label, NULL);
+
+ return result;
+}
struct argv_array args;
struct argv_array env_array;
pid_t pid;
+
+ int trace2_child_id;
+ uint64_t trace2_child_us_start;
+ const char *trace2_child_class;
+ const char *trace2_hook_name;
+
/*
* Using .in, .out, .err:
* - Specify 0 for no redirections (child inherits stdin, stdout,
#define RUN_USING_SHELL 16
#define RUN_CLEAN_ON_EXIT 32
int run_command_v_opt(const char **argv, int opt);
-
+int run_command_v_opt_tr2(const char **argv, int opt, const char *tr2_class);
/*
* env (the environment) is to be formatted like environ: "VAR=VALUE".
* To unset an environment variable use just "VAR".
*/
int run_command_v_opt_cd_env(const char **argv, int opt, const char *dir, const char *const *env);
+int run_command_v_opt_cd_env_tr2(const char **argv, int opt, const char *dir,
+ const char *const *env, const char *tr2_class);
/**
* Execute the given command, sending "in" to its stdin, and capturing its
start_failure_fn,
task_finished_fn,
void *pp_cb);
+int run_processes_parallel_tr2(int n, get_next_task_fn, start_failure_fn,
+ task_finished_fn, void *pp_cb,
+ const char *tr2_category, const char *tr2_label);
#endif
proc.argv = argv;
proc.in = -1;
proc.stdout_to_stderr = 1;
+ proc.trace2_hook_name = "post-rewrite";
code = start_command(&proc);
if (code)
hook.in = open(rebase_path_rewritten_list(),
O_RDONLY);
hook.stdout_to_stderr = 1;
+ hook.trace2_hook_name = "post-rewrite";
argv_array_push(&hook.args, post_rewrite_hook);
argv_array_push(&hook.args, "rebase");
/* we don't care if this hook failed */
*/
#include "git-compat-util.h"
+#include "trace2.h"
/* Substitution of environment variables in shell format strings.
Copyright (C) 2003-2007 Free Software Foundation, Inc.
/* Default values for command line options. */
/* unsigned short int show_variables = 0; */
+ trace2_cmd_name("sh-i18n--envsubst");
+
switch (argc)
{
case 1:
process->out = -1;
process->clean_on_exit = 1;
process->clean_on_exit_handler = subprocess_exit_handler;
+ process->trace2_child_class = "subprocess";
err = start_command(process);
if (err) {
calculate_changed_submodule_paths(r, &spf.changed_submodule_names);
string_list_sort(&spf.changed_submodule_names);
- run_processes_parallel(max_parallel_jobs,
- get_next_submodule,
- fetch_start_failure,
- fetch_finish,
- &spf);
+ run_processes_parallel_tr2(max_parallel_jobs,
+ get_next_submodule,
+ fetch_start_failure,
+ fetch_finish,
+ &spf,
+ "submodule", "parallel/fetch");
argv_array_clear(&spf.args);
out:
#include "cache.h"
#include "parse-options.h"
#include "string-list.h"
+#include "trace2.h"
static int boolean = 0;
static int integer = 0;
int i;
int ret = 0;
+ trace2_cmd_name("_parse_");
+
argc = parse_options(argc, (const char **)argv, prefix, options, usage, 0);
if (length_cb.called) {
#include "git-compat-util.h"
#include "test-tool.h"
+#include "trace2.h"
struct test_cmd {
const char *name;
{ "submodule-config", cmd__submodule_config },
{ "submodule-nested-repo-config", cmd__submodule_nested_repo_config },
{ "subprocess", cmd__subprocess },
+ { "trace2", cmd__trace2 },
{ "urlmatch-normalization", cmd__urlmatch_normalization },
{ "xml-encode", cmd__xml_encode },
{ "wildmatch", cmd__wildmatch },
if (!strcmp(cmds[i].name, argv[1])) {
argv++;
argc--;
+ trace2_cmd_name(cmds[i].name);
+ trace2_cmd_list_config();
return cmds[i].fn(argc, argv);
}
}
int cmd__submodule_config(int argc, const char **argv);
int cmd__submodule_nested_repo_config(int argc, const char **argv);
int cmd__subprocess(int argc, const char **argv);
+int cmd__trace2(int argc, const char **argv);
int cmd__urlmatch_normalization(int argc, const char **argv);
int cmd__xml_encode(int argc, const char **argv);
int cmd__wildmatch(int argc, const char **argv);
--- /dev/null
+#include "test-tool.h"
+#include "cache.h"
+#include "argv-array.h"
+#include "run-command.h"
+#include "exec-cmd.h"
+#include "config.h"
+
+typedef int(fn_unit_test)(int argc, const char **argv);
+
+struct unit_test {
+ fn_unit_test *ut_fn;
+ const char *ut_name;
+ const char *ut_usage;
+};
+
+#define MyOk 0
+#define MyError 1
+
+static int get_i(int *p_value, const char *data)
+{
+ char *endptr;
+
+ if (!data || !*data)
+ return MyError;
+
+ *p_value = strtol(data, &endptr, 10);
+ if (*endptr || errno == ERANGE)
+ return MyError;
+
+ return MyOk;
+}
+
+/*
+ * Cause process to exit with the requested value via "return".
+ *
+ * Rely on test-tool.c:cmd_main() to call trace2_cmd_exit()
+ * with our result.
+ *
+ * Test harness can confirm:
+ * [] the process-exit value.
+ * [] the "code" field in the "exit" trace2 event.
+ * [] the "code" field in the "atexit" trace2 event.
+ * [] the "name" field in the "cmd_name" trace2 event.
+ * [] "def_param" events for all of the "interesting" pre-defined
+ * config settings.
+ */
+static int ut_001return(int argc, const char **argv)
+{
+ int rc;
+
+ if (get_i(&rc, argv[0]))
+ die("expect <exit_code>");
+
+ return rc;
+}
+
+/*
+ * Cause the process to exit with the requested value via "exit()".
+ *
+ * Test harness can confirm:
+ * [] the "code" field in the "exit" trace2 event.
+ * [] the "code" field in the "atexit" trace2 event.
+ * [] the "name" field in the "cmd_name" trace2 event.
+ * [] "def_param" events for all of the "interesting" pre-defined
+ * config settings.
+ */
+static int ut_002exit(int argc, const char **argv)
+{
+ int rc;
+
+ if (get_i(&rc, argv[0]))
+ die("expect <exit_code>");
+
+ exit(rc);
+}
+
+/*
+ * Send an "error" event with each value in argv. Normally, git only issues
+ * a single "error" event immediately before issuing an "exit" event (such
+ * as in die() or BUG()), but multiple "error" events are allowed.
+ *
+ * Test harness can confirm:
+ * [] a trace2 "error" event for each value in argv.
+ * [] the "name" field in the "cmd_name" trace2 event.
+ * [] (optional) the file:line in the "exit" event refers to this function.
+ */
+static int ut_003error(int argc, const char **argv)
+{
+ int k;
+
+ if (!argv[0] || !*argv[0])
+ die("expect <error_message>");
+
+ for (k = 0; k < argc; k++)
+ error("%s", argv[k]);
+
+ return 0;
+}
+
+/*
+ * Run a child process and wait for it to finish and exit with its return code.
+ * test-tool trace2 004child [<child-command-line>]
+ *
+ * For example:
+ * test-tool trace2 004child git version
+ * test-tool trace2 004child test-tool trace2 001return 0
+ * test-tool trace2 004child test-tool trace2 004child test-tool trace2 004child
+ * test-tool trace2 004child git -c alias.xyz=version xyz
+ *
+ * Test harness can confirm:
+ * [] the "name" field in the "cmd_name" trace2 event.
+ * [] that the outer process has a single component SID (or depth "d0" in
+ * the PERF stream).
+ * [] that "child_start" and "child_exit" events are generated for the child.
+ * [] if the child process is an instrumented executable:
+ * [] that "version", "start", ..., "exit", and "atexit" events are
+ * generated by the child process.
+ * [] that the child process events have a multiple component SID (or
+ * depth "dN+1" in the PERF stream).
+ * [] that the child exit code is propagated to the parent process "exit"
+ * and "atexit" events..
+ * [] (optional) that the "t_abs" field in the child process "atexit" event
+ * is less than the "t_rel" field in the "child_exit" event of the parent
+ * process.
+ * [] if the child process is like the alias example above,
+ * [] (optional) the child process attempts to run "git-xyx" as a dashed
+ * command.
+ * [] the child process emits an "alias" event with "xyz" => "version"
+ * [] the child process runs "git version" as a child process.
+ * [] the child process has a 3 component SID (or depth "d2" in the PERF
+ * stream).
+ */
+static int ut_004child(int argc, const char **argv)
+{
+ int result;
+
+ /*
+ * Allow empty <child_command_line> so we can do arbitrarily deep
+ * command nesting and let the last one be null.
+ */
+ if (!argc)
+ return 0;
+
+ result = run_command_v_opt(argv, 0);
+ exit(result);
+}
+
+/*
+ * Exec a git command. This may either create a child process (Windows)
+ * or replace the existing process.
+ * test-tool trace2 005exec <git_command_args>
+ *
+ * For example:
+ * test-tool trace2 005exec version
+ *
+ * Test harness can confirm (on Windows):
+ * [] the "name" field in the "cmd_name" trace2 event.
+ * [] that the outer process has a single component SID (or depth "d0" in
+ * the PERF stream).
+ * [] that "exec" and "exec_result" events are generated for the child
+ * process (since the Windows compatibility layer fakes an exec() with
+ * a CreateProcess(), WaitForSingleObject(), and exit()).
+ * [] that the child process has multiple component SID (or depth "dN+1"
+ * in the PERF stream).
+ *
+ * Test harness can confirm (on platforms with a real exec() function):
+ * [] TODO talk about process replacement and how it affects SID.
+ */
+static int ut_005exec(int argc, const char **argv)
+{
+ int result;
+
+ if (!argc)
+ return 0;
+
+ result = execv_git_cmd(argv);
+ return result;
+}
+
+static int ut_006data(int argc, const char **argv)
+{
+ const char *usage_error =
+ "expect <cat0> <k0> <v0> [<cat1> <k1> <v1> [...]]";
+
+ if (argc % 3 != 0)
+ die("%s", usage_error);
+
+ while (argc) {
+ if (!argv[0] || !*argv[0] || !argv[1] || !*argv[1] ||
+ !argv[2] || !*argv[2])
+ die("%s", usage_error);
+
+ trace2_data_string(argv[0], the_repository, argv[1], argv[2]);
+ argv += 3;
+ argc -= 3;
+ }
+
+ return 0;
+}
+
+/*
+ * Usage:
+ * test-tool trace2 <ut_name_1> <ut_usage_1>
+ * test-tool trace2 <ut_name_2> <ut_usage_2>
+ * ...
+ */
+#define USAGE_PREFIX "test-tool trace2"
+
+/* clang-format off */
+static struct unit_test ut_table[] = {
+ { ut_001return, "001return", "<exit_code>" },
+ { ut_002exit, "002exit", "<exit_code>" },
+ { ut_003error, "003error", "<error_message>+" },
+ { ut_004child, "004child", "[<child_command_line>]" },
+ { ut_005exec, "005exec", "<git_command_args>" },
+ { ut_006data, "006data", "[<category> <key> <value>]+" },
+};
+/* clang-format on */
+
+/* clang-format off */
+#define for_each_ut(k, ut_k) \
+ for (k = 0, ut_k = &ut_table[k]; \
+ k < ARRAY_SIZE(ut_table); \
+ k++, ut_k = &ut_table[k])
+/* clang-format on */
+
+static int print_usage(void)
+{
+ int k;
+ struct unit_test *ut_k;
+
+ fprintf(stderr, "usage:\n");
+ for_each_ut (k, ut_k)
+ fprintf(stderr, "\t%s %s %s\n", USAGE_PREFIX, ut_k->ut_name,
+ ut_k->ut_usage);
+
+ return 129;
+}
+
+/*
+ * Issue various trace2 events for testing.
+ *
+ * We assume that these trace2 routines has already been called:
+ * [] trace2_initialize() [common-main.c:main()]
+ * [] trace2_cmd_start() [common-main.c:main()]
+ * [] trace2_cmd_name() [test-tool.c:cmd_main()]
+ * [] tracd2_cmd_list_config() [test-tool.c:cmd_main()]
+ * So that:
+ * [] the various trace2 streams are open.
+ * [] the process SID has been created.
+ * [] the "version" event has been generated.
+ * [] the "start" event has been generated.
+ * [] the "cmd_name" event has been generated.
+ * [] this writes various "def_param" events for interesting config values.
+ *
+ * We further assume that if we return (rather than exit()), trace2_cmd_exit()
+ * will be called by test-tool.c:cmd_main().
+ */
+int cmd__trace2(int argc, const char **argv)
+{
+ int k;
+ struct unit_test *ut_k;
+
+ argc--; /* skip over "trace2" arg */
+ argv++;
+
+ if (argc)
+ for_each_ut (k, ut_k)
+ if (!strcmp(argv[0], ut_k->ut_name))
+ return ut_k->ut_fn(argc - 1, argv + 1);
+
+ return print_usage();
+}
sed -n \
-e "/^GIT_PREFIX=/d" \
-e "/^GIT_TEXTDOMAINDIR=/d" \
+ -e "/^GIT_TR2_PARENT/d" \
-e "/^GIT_/s/=.*//p" |
sort
EOF
--- /dev/null
+#!/bin/sh
+
+test_description='test trace2 facility (normal target)'
+. ./test-lib.sh
+
+# Add t/helper directory to PATH so that we can use a relative
+# path to run nested instances of test-tool.exe (see 004child).
+# This helps with HEREDOC comparisons later.
+TTDIR="$GIT_BUILD_DIR/t/helper/" && export TTDIR
+PATH="$TTDIR:$PATH" && export PATH
+
+# Warning: use of 'test_cmp' may run test-tool.exe and/or git.exe
+# Warning: to do the actual diff/comparison, so the HEREDOCs here
+# Warning: only cover our actual calls to test-tool and/or git.
+# Warning: So you may see extra lines in artifact files when
+# Warning: interactively debugging.
+
+# Turn off any inherited trace2 settings for this test.
+unset GIT_TR2 GIT_TR2_PERF GIT_TR2_EVENT
+unset GIT_TR2_BRIEF
+unset GIT_TR2_CONFIG_PARAMS
+
+V=$(git version | sed -e 's/^git version //') && export V
+
+# There are multiple trace2 targets: normal, perf, and event.
+# Trace2 events will/can be written to each active target (subject
+# to whatever filtering that target decides to do).
+# This script tests the normal target in isolation.
+#
+# Defer setting GIT_TR2 until the actual command line we want to test
+# because hidden git and test-tool commands run by the test harness
+# can contaminate our output.
+
+# Enable "brief" feature which turns off "<clock> <file>:<line> " prefix.
+GIT_TR2_BRIEF=1 && export GIT_TR2_BRIEF
+
+# Basic tests of the trace2 normal stream. Since this stream is used
+# primarily with printf-style debugging/tracing, we do limited testing
+# here.
+#
+# We do confirm the following API features:
+# [] the 'version <v>' event
+# [] the 'start <argv>' event
+# [] the 'cmd_name <name>' event
+# [] the 'exit <time> code:<code>' event
+# [] the 'atexit <time> code:<code>' event
+#
+# Fields of the form _FIELD_ are tokens that have been replaced (such
+# as the elapsed time).
+
+# Verb 001return
+#
+# Implicit return from cmd_<verb> function propagates <code>.
+
+test_expect_success 'normal stream, return code 0' '
+ test_when_finished "rm trace.normal actual expect" &&
+ GIT_TR2="$(pwd)/trace.normal" test-tool trace2 001return 0 &&
+ perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <trace.normal >actual &&
+ cat >expect <<-EOF &&
+ version $V
+ start _EXE_ trace2 001return 0
+ cmd_name trace2 (trace2)
+ exit elapsed:_TIME_ code:0
+ atexit elapsed:_TIME_ code:0
+ EOF
+ test_cmp expect actual
+'
+
+test_expect_success 'normal stream, return code 1' '
+ test_when_finished "rm trace.normal actual expect" &&
+ test_must_fail env GIT_TR2="$(pwd)/trace.normal" test-tool trace2 001return 1 &&
+ perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <trace.normal >actual &&
+ cat >expect <<-EOF &&
+ version $V
+ start _EXE_ trace2 001return 1
+ cmd_name trace2 (trace2)
+ exit elapsed:_TIME_ code:1
+ atexit elapsed:_TIME_ code:1
+ EOF
+ test_cmp expect actual
+'
+
+# Verb 002exit
+#
+# Explicit exit(code) from within cmd_<verb> propagates <code>.
+
+test_expect_success 'normal stream, exit code 0' '
+ test_when_finished "rm trace.normal actual expect" &&
+ GIT_TR2="$(pwd)/trace.normal" test-tool trace2 002exit 0 &&
+ perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <trace.normal >actual &&
+ cat >expect <<-EOF &&
+ version $V
+ start _EXE_ trace2 002exit 0
+ cmd_name trace2 (trace2)
+ exit elapsed:_TIME_ code:0
+ atexit elapsed:_TIME_ code:0
+ EOF
+ test_cmp expect actual
+'
+
+test_expect_success 'normal stream, exit code 1' '
+ test_when_finished "rm trace.normal actual expect" &&
+ test_must_fail env GIT_TR2="$(pwd)/trace.normal" test-tool trace2 002exit 1 &&
+ perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <trace.normal >actual &&
+ cat >expect <<-EOF &&
+ version $V
+ start _EXE_ trace2 002exit 1
+ cmd_name trace2 (trace2)
+ exit elapsed:_TIME_ code:1
+ atexit elapsed:_TIME_ code:1
+ EOF
+ test_cmp expect actual
+'
+
+# Verb 003error
+#
+# To the above, add multiple 'error <msg>' events
+
+test_expect_success 'normal stream, error event' '
+ test_when_finished "rm trace.normal actual expect" &&
+ GIT_TR2="$(pwd)/trace.normal" test-tool trace2 003error "hello world" "this is a test" &&
+ perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <trace.normal >actual &&
+ cat >expect <<-EOF &&
+ version $V
+ start _EXE_ trace2 003error '\''hello world'\'' '\''this is a test'\''
+ cmd_name trace2 (trace2)
+ error hello world
+ error this is a test
+ exit elapsed:_TIME_ code:0
+ atexit elapsed:_TIME_ code:0
+ EOF
+ test_cmp expect actual
+'
+
+test_done
--- /dev/null
+#!/usr/bin/perl
+#
+# Scrub the variable fields from the normal trace2 output to
+# make testing easier.
+
+use strict;
+use warnings;
+
+my $float = '[0-9]*\.[0-9]+([eE][-+]?[0-9]+)?';
+
+# This code assumes that the trace2 data was written with bare
+# turned on (which omits the "<clock> <file>:<line>" prefix.
+
+while (<>) {
+ # Various messages include an elapsed time in the middle
+ # of the message. Replace the time with a placeholder to
+ # simplify our HEREDOC in the test script.
+ s/elapsed:$float/elapsed:_TIME_/g;
+
+ my $line = $_;
+
+ # we expect:
+ # start <argv0> [<argv1> [<argv2> [...]]]
+ #
+ # where argv0 might be a relative or absolute path, with
+ # or without quotes, and platform dependent. Replace argv0
+ # with a token for HEREDOC matching in the test script.
+
+ if ($line =~ m/^start/) {
+ $line =~ /^start\s+(.*)/;
+ my $argv = $1;
+ $argv =~ m/(\'[^\']*\'|[^ ]+)\s+(.*)/;
+ my $argv_0 = $1;
+ my $argv_rest = $2;
+
+ print "start _EXE_ $argv_rest\n";
+ }
+ elsif ($line =~ m/^cmd_path/) {
+ # Likewise, the 'cmd_path' message breaks out argv[0].
+ #
+ # This line is only emitted when RUNTIME_PREFIX is defined,
+ # so just omit it for testing purposes.
+ # print "cmd_path _EXE_\n";
+ }
+ else {
+ print "$line";
+ }
+}
--- /dev/null
+#!/bin/sh
+
+test_description='test trace2 facility (perf target)'
+. ./test-lib.sh
+
+# Add t/helper directory to PATH so that we can use a relative
+# path to run nested instances of test-tool.exe (see 004child).
+# This helps with HEREDOC comparisons later.
+TTDIR="$GIT_BUILD_DIR/t/helper/" && export TTDIR
+PATH="$TTDIR:$PATH" && export PATH
+
+# Warning: use of 'test_cmp' may run test-tool.exe and/or git.exe
+# Warning: to do the actual diff/comparison, so the HEREDOCs here
+# Warning: only cover our actual calls to test-tool and/or git.
+# Warning: So you may see extra lines in artifact files when
+# Warning: interactively debugging.
+
+# Turn off any inherited trace2 settings for this test.
+unset GIT_TR2 GIT_TR2_PERF GIT_TR2_EVENT
+unset GIT_TR2_PERF_BRIEF
+unset GIT_TR2_CONFIG_PARAMS
+
+V=$(git version | sed -e 's/^git version //') && export V
+
+# There are multiple trace2 targets: normal, perf, and event.
+# Trace2 events will/can be written to each active target (subject
+# to whatever filtering that target decides to do).
+# Test each target independently.
+#
+# Defer setting GIT_TR2_PERF until the actual command we want to
+# test because hidden git and test-tool commands in the test
+# harness can contaminate our output.
+
+# Enable "brief" feature which turns off the prefix:
+# "<clock> <file>:<line> | <nr_parents> | "
+GIT_TR2_PERF_BRIEF=1 && export GIT_TR2_PERF_BRIEF
+
+# Repeat some of the t0210 tests using the perf target stream instead of
+# the normal stream.
+#
+# Tokens here of the form _FIELD_ have been replaced in the observed output.
+
+# Verb 001return
+#
+# Implicit return from cmd_<verb> function propagates <code>.
+
+test_expect_success 'perf stream, return code 0' '
+ test_when_finished "rm trace.perf actual expect" &&
+ GIT_TR2_PERF="$(pwd)/trace.perf" test-tool trace2 001return 0 &&
+ perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
+ cat >expect <<-EOF &&
+ d0|main|version|||||$V
+ d0|main|start|||||_EXE_ trace2 001return 0
+ d0|main|cmd_name|||||trace2 (trace2)
+ d0|main|exit||_T_ABS_|||code:0
+ d0|main|atexit||_T_ABS_|||code:0
+ EOF
+ test_cmp expect actual
+'
+
+test_expect_success 'perf stream, return code 1' '
+ test_when_finished "rm trace.perf actual expect" &&
+ test_must_fail env GIT_TR2_PERF="$(pwd)/trace.perf" test-tool trace2 001return 1 &&
+ perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
+ cat >expect <<-EOF &&
+ d0|main|version|||||$V
+ d0|main|start|||||_EXE_ trace2 001return 1
+ d0|main|cmd_name|||||trace2 (trace2)
+ d0|main|exit||_T_ABS_|||code:1
+ d0|main|atexit||_T_ABS_|||code:1
+ EOF
+ test_cmp expect actual
+'
+
+# Verb 003error
+#
+# To the above, add multiple 'error <msg>' events
+
+test_expect_success 'perf stream, error event' '
+ test_when_finished "rm trace.perf actual expect" &&
+ GIT_TR2_PERF="$(pwd)/trace.perf" test-tool trace2 003error "hello world" "this is a test" &&
+ perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
+ cat >expect <<-EOF &&
+ d0|main|version|||||$V
+ d0|main|start|||||_EXE_ trace2 003error '\''hello world'\'' '\''this is a test'\''
+ d0|main|cmd_name|||||trace2 (trace2)
+ d0|main|error|||||hello world
+ d0|main|error|||||this is a test
+ d0|main|exit||_T_ABS_|||code:0
+ d0|main|atexit||_T_ABS_|||code:0
+ EOF
+ test_cmp expect actual
+'
+
+# Verb 004child
+#
+# Test nested spawning of child processes.
+#
+# Conceptually, this looks like:
+# P1: TT trace2 004child
+# P2: |--- TT trace2 004child
+# P3: |--- TT trace2 001return 0
+#
+# Which should generate events:
+# P1: version
+# P1: start
+# P1: cmd_name
+# P1: child_start
+# P2: version
+# P2: start
+# P2: cmd_name
+# P2: child_start
+# P3: version
+# P3: start
+# P3: cmd_name
+# P3: exit
+# P3: atexit
+# P2: child_exit
+# P2: exit
+# P2: atexit
+# P1: child_exit
+# P1: exit
+# P1: atexit
+
+test_expect_success 'perf stream, child processes' '
+ test_when_finished "rm trace.perf actual expect" &&
+ GIT_TR2_PERF="$(pwd)/trace.perf" test-tool trace2 004child test-tool trace2 004child test-tool trace2 001return 0 &&
+ perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
+ cat >expect <<-EOF &&
+ d0|main|version|||||$V
+ d0|main|start|||||_EXE_ trace2 004child test-tool trace2 004child test-tool trace2 001return 0
+ d0|main|cmd_name|||||trace2 (trace2)
+ d0|main|child_start||_T_ABS_|||[ch0] class:? argv: test-tool trace2 004child test-tool trace2 001return 0
+ d1|main|version|||||$V
+ d1|main|start|||||_EXE_ trace2 004child test-tool trace2 001return 0
+ d1|main|cmd_name|||||trace2 (trace2/trace2)
+ d1|main|child_start||_T_ABS_|||[ch0] class:? argv: test-tool trace2 001return 0
+ d2|main|version|||||$V
+ d2|main|start|||||_EXE_ trace2 001return 0
+ d2|main|cmd_name|||||trace2 (trace2/trace2/trace2)
+ d2|main|exit||_T_ABS_|||code:0
+ d2|main|atexit||_T_ABS_|||code:0
+ d1|main|child_exit||_T_ABS_|_T_REL_||[ch0] pid:_PID_ code:0
+ d1|main|exit||_T_ABS_|||code:0
+ d1|main|atexit||_T_ABS_|||code:0
+ d0|main|child_exit||_T_ABS_|_T_REL_||[ch0] pid:_PID_ code:0
+ d0|main|exit||_T_ABS_|||code:0
+ d0|main|atexit||_T_ABS_|||code:0
+ EOF
+ test_cmp expect actual
+'
+
+test_done
--- /dev/null
+#!/usr/bin/perl
+#
+# Scrub the variable fields from the perf trace2 output to
+# make testing easier.
+
+use strict;
+use warnings;
+
+my $qpath = '\'[^\']*\'|[^ ]*';
+
+my $col_depth=0;
+my $col_thread=1;
+my $col_event=2;
+my $col_repo=3;
+my $col_t_abs=4;
+my $col_t_rel=5;
+my $col_category=6;
+my $col_rest=7;
+
+# This code assumes that the trace2 data was written with bare
+# turned on (which omits the "<clock> <file>:<line> | <parents>"
+# prefix.
+
+while (<>) {
+ my @tokens = split /\|/;
+
+ foreach my $col (@tokens) { $col =~ s/^\s+|\s+$//g; }
+
+ if ($tokens[$col_event] =~ m/^start/) {
+ # The 'start' message lists the contents of argv in $col_rest.
+ # On some platforms (Windows), argv[0] is *sometimes* a canonical
+ # absolute path to the EXE rather than the value passed in the
+ # shell script. Replace it with a placeholder to simplify our
+ # HEREDOC in the test script.
+ my $argv0;
+ my $argvRest;
+ $tokens[$col_rest] =~ s/^($qpath)\W*(.*)/_EXE_ $2/;
+ }
+ elsif ($tokens[$col_event] =~ m/cmd_path/) {
+ # Likewise, the 'cmd_path' message breaks out argv[0].
+ #
+ # This line is only emitted when RUNTIME_PREFIX is defined,
+ # so just omit it for testing purposes.
+ # $tokens[$col_rest] = "_EXE_";
+ goto SKIP_LINE;
+ }
+ elsif ($tokens[$col_event] =~ m/child_exit/) {
+ $tokens[$col_rest] =~ s/ pid:\d* / pid:_PID_ /;
+ }
+ elsif ($tokens[$col_event] =~ m/data/) {
+ if ($tokens[$col_category] =~ m/process/) {
+ # 'data' and 'data_json' events containing 'process'
+ # category data are assumed to be platform-specific
+ # and highly variable. Just omit them.
+ goto SKIP_LINE;
+ }
+ }
+
+ # t_abs and t_rel are either blank or a float. Replace the float
+ # with a constant for matching the HEREDOC in the test script.
+ if ($tokens[$col_t_abs] =~ m/\d/) {
+ $tokens[$col_t_abs] = "_T_ABS_";
+ }
+ if ($tokens[$col_t_rel] =~ m/\d/) {
+ $tokens[$col_t_rel] = "_T_REL_";
+ }
+
+ my $out;
+
+ $out = join('|', @tokens);
+ print "$out\n";
+
+ SKIP_LINE:
+}
+
+
--- /dev/null
+#!/bin/sh
+
+test_description='test trace2 facility'
+. ./test-lib.sh
+
+perl -MJSON::PP -e 0 >/dev/null 2>&1 && test_set_prereq JSON_PP
+
+# Add t/helper directory to PATH so that we can use a relative
+# path to run nested instances of test-tool.exe (see 004child).
+# This helps with HEREDOC comparisons later.
+TTDIR="$GIT_BUILD_DIR/t/helper/" && export TTDIR
+PATH="$TTDIR:$PATH" && export PATH
+
+# Warning: use of 'test_cmp' may run test-tool.exe and/or git.exe
+# Warning: to do the actual diff/comparison, so the HEREDOCs here
+# Warning: only cover our actual calls to test-tool and/or git.
+# Warning: So you may see extra lines in artifact files when
+# Warning: interactively debugging.
+
+# Turn off any inherited trace2 settings for this test.
+unset GIT_TR2 GIT_TR2_PERF GIT_TR2_EVENT
+unset GIT_TR2_BARE
+unset GIT_TR2_CONFIG_PARAMS
+
+V=$(git version | sed -e 's/^git version //') && export V
+
+# There are multiple trace2 targets: normal, perf, and event.
+# Trace2 events will/can be written to each active target (subject
+# to whatever filtering that target decides to do).
+# Test each target independently.
+#
+# Defer setting GIT_TR2_PERF until the actual command we want to
+# test because hidden git and test-tool commands in the test
+# harness can contaminate our output.
+
+# We don't bother repeating the 001return and 002exit tests, since they
+# have coverage in the normal and perf targets.
+
+# Verb 003error
+#
+# To the above, add multiple 'error <msg>' events
+
+test_expect_success JSON_PP 'event stream, error event' '
+ test_when_finished "rm trace.event actual expect" &&
+ GIT_TR2_EVENT="$(pwd)/trace.event" test-tool trace2 003error "hello world" "this is a test" &&
+ perl "$TEST_DIRECTORY/t0212/parse_events.perl" <trace.event >actual &&
+ sed -e "s/^|//" >expect <<-EOF &&
+ |VAR1 = {
+ | "_SID0_":{
+ | "argv":[
+ | "_EXE_",
+ | "trace2",
+ | "003error",
+ | "hello world",
+ | "this is a test"
+ | ],
+ | "errors":[
+ | "%s",
+ | "%s"
+ | ],
+ | "exit_code":0,
+ | "hierarchy":"trace2",
+ | "name":"trace2",
+ | "version":"$V"
+ | }
+ |};
+ EOF
+ test_cmp expect actual
+'
+
+# Verb 004child
+#
+# Test nested spawning of child processes.
+#
+# Conceptually, this looks like:
+# P1: TT trace2 004child
+# P2: |--- TT trace2 004child
+# P3: |--- TT trace2 001return 0
+
+test_expect_success JSON_PP 'event stream, return code 0' '
+ test_when_finished "rm trace.event actual expect" &&
+ GIT_TR2_EVENT="$(pwd)/trace.event" test-tool trace2 004child test-tool trace2 004child test-tool trace2 001return 0 &&
+ perl "$TEST_DIRECTORY/t0212/parse_events.perl" <trace.event >actual &&
+ sed -e "s/^|//" >expect <<-EOF &&
+ |VAR1 = {
+ | "_SID0_":{
+ | "argv":[
+ | "_EXE_",
+ | "trace2",
+ | "004child",
+ | "test-tool",
+ | "trace2",
+ | "004child",
+ | "test-tool",
+ | "trace2",
+ | "001return",
+ | "0"
+ | ],
+ | "child":{
+ | "0":{
+ | "child_argv":[
+ | "_EXE_",
+ | "trace2",
+ | "004child",
+ | "test-tool",
+ | "trace2",
+ | "001return",
+ | "0"
+ | ],
+ | "child_class":"?",
+ | "child_code":0,
+ | "use_shell":0
+ | }
+ | },
+ | "exit_code":0,
+ | "hierarchy":"trace2",
+ | "name":"trace2",
+ | "version":"$V"
+ | },
+ | "_SID0_/_SID1_":{
+ | "argv":[
+ | "_EXE_",
+ | "trace2",
+ | "004child",
+ | "test-tool",
+ | "trace2",
+ | "001return",
+ | "0"
+ | ],
+ | "child":{
+ | "0":{
+ | "child_argv":[
+ | "_EXE_",
+ | "trace2",
+ | "001return",
+ | "0"
+ | ],
+ | "child_class":"?",
+ | "child_code":0,
+ | "use_shell":0
+ | }
+ | },
+ | "exit_code":0,
+ | "hierarchy":"trace2/trace2",
+ | "name":"trace2",
+ | "version":"$V"
+ | },
+ | "_SID0_/_SID1_/_SID2_":{
+ | "argv":[
+ | "_EXE_",
+ | "trace2",
+ | "001return",
+ | "0"
+ | ],
+ | "exit_code":0,
+ | "hierarchy":"trace2/trace2/trace2",
+ | "name":"trace2",
+ | "version":"$V"
+ | }
+ |};
+ EOF
+ test_cmp expect actual
+'
+
+# Test listing of all "interesting" config settings.
+
+test_expect_success JSON_PP 'event stream, list config' '
+ test_when_finished "rm trace.event actual expect" &&
+ git config --local t0212.abc 1 &&
+ git config --local t0212.def "hello world" &&
+ GIT_TR2_EVENT="$(pwd)/trace.event" GIT_TR2_CONFIG_PARAMS="t0212.*" test-tool trace2 001return 0 &&
+ perl "$TEST_DIRECTORY/t0212/parse_events.perl" <trace.event >actual &&
+ sed -e "s/^|//" >expect <<-EOF &&
+ |VAR1 = {
+ | "_SID0_":{
+ | "argv":[
+ | "_EXE_",
+ | "trace2",
+ | "001return",
+ | "0"
+ | ],
+ | "exit_code":0,
+ | "hierarchy":"trace2",
+ | "name":"trace2",
+ | "params":[
+ | {
+ | "param":"t0212.abc",
+ | "value":"1"
+ | },
+ | {
+ | "param":"t0212.def",
+ | "value":"hello world"
+ | }
+ | ],
+ | "version":"$V"
+ | }
+ |};
+ EOF
+ test_cmp expect actual
+'
+
+test_expect_success JSON_PP 'basic trace2_data' '
+ test_when_finished "rm trace.event actual expect" &&
+ GIT_TR2_EVENT="$(pwd)/trace.event" test-tool trace2 006data test_category k1 v1 test_category k2 v2 &&
+ perl "$TEST_DIRECTORY/t0212/parse_events.perl" <trace.event >actual &&
+ sed -e "s/^|//" >expect <<-EOF &&
+ |VAR1 = {
+ | "_SID0_":{
+ | "argv":[
+ | "_EXE_",
+ | "trace2",
+ | "006data",
+ | "test_category",
+ | "k1",
+ | "v1",
+ | "test_category",
+ | "k2",
+ | "v2"
+ | ],
+ | "data":{
+ | "test_category":{
+ | "k1":"v1",
+ | "k2":"v2"
+ | }
+ | },
+ | "exit_code":0,
+ | "hierarchy":"trace2",
+ | "name":"trace2",
+ | "version":"$V"
+ | }
+ |};
+ EOF
+ test_cmp expect actual
+'
+
+test_done
--- /dev/null
+#!/usr/bin/perl
+#
+# Parse event stream and convert individual events into a summary
+# record for the process.
+#
+# Git.exe generates one or more "event" records for each API method,
+# such as "start <argv>" and "exit <code>", during the life of the git
+# process. Additionally, the input may contain interleaved events
+# from multiple concurrent git processes and/or multiple threads from
+# within a git process.
+#
+# Accumulate events for each process (based on its unique SID) in a
+# dictionary and emit process summary records.
+#
+# Convert some of the variable fields (such as elapsed time) into
+# placeholders (or omit them) to make HEREDOC comparisons easier in
+# the test scripts.
+#
+# We may also omit fields not (currently) useful for testing purposes.
+
+use strict;
+use warnings;
+use JSON::PP;
+use Data::Dumper;
+use Getopt::Long;
+
+# The version of the trace2 event target format that we understand.
+# This is reported in the 'version' event in the 'evt' field.
+# It comes from the GIT_TR2_EVENT_VERSION macro in trace2/tr2_tgt_event.c
+my $evt_version = '1';
+
+my $show_children = 1;
+my $show_exec = 1;
+my $show_threads = 1;
+
+# A hack to generate test HEREDOC data for pasting into the test script.
+# Usage:
+# cd "t/trash directory.t0212-trace2-event"
+# $TT trace ... >trace.event
+# VV=$(../../git.exe version | sed -e 's/^git version //')
+# perl ../t0212/parse_events.perl --HEREDOC --VERSION=$VV <trace.event >heredoc
+# Then paste heredoc into your new test.
+
+my $gen_heredoc = 0;
+my $gen_version = '';
+
+GetOptions("children!" => \$show_children,
+ "exec!" => \$show_exec,
+ "threads!" => \$show_threads,
+ "HEREDOC!" => \$gen_heredoc,
+ "VERSION=s" => \$gen_version )
+ or die("Error in command line arguments\n");
+
+
+# SIDs contains timestamps and PIDs of the process and its parents.
+# This makes it difficult to match up in a HEREDOC in the test script.
+# Build a map from actual SIDs to predictable constant values and yet
+# keep the parent/child relationships. For example:
+# {..., "sid":"1539706952458276-8652", ...}
+# {..., "sid":"1539706952458276-8652/1539706952649493-15452", ...}
+# becomes:
+# {..., "sid":"_SID1_", ...}
+# {..., "sid":"_SID1_/_SID2_", ...}
+my $sid_map;
+my $sid_count = 0;
+
+my $processes;
+
+while (<>) {
+ my $line = decode_json( $_ );
+
+ my $sid = "";
+ my $sid_sep = "";
+
+ my $raw_sid = $line->{'sid'};
+ my @raw_sid_parts = split /\//, $raw_sid;
+ foreach my $raw_sid_k (@raw_sid_parts) {
+ if (!exists $sid_map->{$raw_sid_k}) {
+ $sid_map->{$raw_sid_k} = '_SID' . $sid_count . '_';
+ $sid_count++;
+ }
+ $sid = $sid . $sid_sep . $sid_map->{$raw_sid_k};
+ $sid_sep = '/';
+ }
+
+ my $event = $line->{'event'};
+
+ if ($event eq 'version') {
+ $processes->{$sid}->{'version'} = $line->{'exe'};
+ if ($gen_heredoc == 1 && $gen_version eq $line->{'exe'}) {
+ # If we are generating data FOR the test script, replace
+ # the reported git.exe version with a reference to an
+ # environment variable. When our output is pasted into
+ # the test script, it will then be expanded in future
+ # test runs to the THEN current version of git.exe.
+ # We assume that the test script uses env var $V.
+ $processes->{$sid}->{'version'} = "\$V";
+ }
+ }
+
+ elsif ($event eq 'start') {
+ $processes->{$sid}->{'argv'} = $line->{'argv'};
+ $processes->{$sid}->{'argv'}[0] = "_EXE_";
+ }
+
+ elsif ($event eq 'exit') {
+ $processes->{$sid}->{'exit_code'} = $line->{'code'};
+ }
+
+ elsif ($event eq 'atexit') {
+ $processes->{$sid}->{'exit_code'} = $line->{'code'};
+ }
+
+ elsif ($event eq 'error') {
+ # For HEREDOC purposes, use the error message format string if
+ # available, rather than the formatted message (which probably
+ # has an absolute pathname).
+ if (exists $line->{'fmt'}) {
+ push( @{$processes->{$sid}->{'errors'}}, $line->{'fmt'} );
+ }
+ elsif (exists $line->{'msg'}) {
+ push( @{$processes->{$sid}->{'errors'}}, $line->{'msg'} );
+ }
+ }
+
+ elsif ($event eq 'cmd_path') {
+ ## $processes->{$sid}->{'path'} = $line->{'path'};
+ #
+ # Like in the 'start' event, we need to replace the value of
+ # argv[0] with a token for HEREDOC purposes. However, the
+ # event is only emitted when RUNTIME_PREFIX is defined, so
+ # just omit it for testing purposes.
+ # $processes->{$sid}->{'path'} = "_EXE_";
+ }
+
+ elsif ($event eq 'cmd_name') {
+ $processes->{$sid}->{'name'} = $line->{'name'};
+ $processes->{$sid}->{'hierarchy'} = $line->{'hierarchy'};
+ }
+
+ elsif ($event eq 'alias') {
+ $processes->{$sid}->{'alias'}->{'key'} = $line->{'alias'};
+ $processes->{$sid}->{'alias'}->{'argv'} = $line->{'argv'};
+ }
+
+ elsif ($event eq 'def_param') {
+ my $kv;
+ $kv->{'param'} = $line->{'param'};
+ $kv->{'value'} = $line->{'value'};
+ push( @{$processes->{$sid}->{'params'}}, $kv );
+ }
+
+ elsif ($event eq 'child_start') {
+ if ($show_children == 1) {
+ $processes->{$sid}->{'child'}->{$line->{'child_id'}}->{'child_class'} = $line->{'child_class'};
+ $processes->{$sid}->{'child'}->{$line->{'child_id'}}->{'child_argv'} = $line->{'argv'};
+ $processes->{$sid}->{'child'}->{$line->{'child_id'}}->{'child_argv'}[0] = "_EXE_";
+ $processes->{$sid}->{'child'}->{$line->{'child_id'}}->{'use_shell'} = $line->{'use_shell'} ? 1 : 0;
+ }
+ }
+
+ elsif ($event eq 'child_exit') {
+ if ($show_children == 1) {
+ $processes->{$sid}->{'child'}->{$line->{'child_id'}}->{'child_code'} = $line->{'code'};
+ }
+ }
+
+ # TODO decide what information we want to test from thread events.
+
+ elsif ($event eq 'thread_start') {
+ if ($show_threads == 1) {
+ }
+ }
+
+ elsif ($event eq 'thread_exit') {
+ if ($show_threads == 1) {
+ }
+ }
+
+ # TODO decide what information we want to test from exec events.
+
+ elsif ($event eq 'exec') {
+ if ($show_exec == 1) {
+ }
+ }
+
+ elsif ($event eq 'exec_result') {
+ if ($show_exec == 1) {
+ }
+ }
+
+ elsif ($event eq 'def_param') {
+ # Accumulate parameter key/value pairs by key rather than in an array
+ # so that we get overwrite (last one wins) effects.
+ $processes->{$sid}->{'params'}->{$line->{'param'}} = $line->{'value'};
+ }
+
+ elsif ($event eq 'def_repo') {
+ # $processes->{$sid}->{'repos'}->{$line->{'repo'}} = $line->{'worktree'};
+ $processes->{$sid}->{'repos'}->{$line->{'repo'}} = "_WORKTREE_";
+ }
+
+ # A series of potentially nested and threaded region and data events
+ # is fundamentally incompatibile with the type of summary record we
+ # are building in this script. Since they are intended for
+ # perf-trace-like analysis rather than a result summary, we ignore
+ # most of them here.
+
+ # elsif ($event eq 'region_enter') {
+ # }
+ # elsif ($event eq 'region_leave') {
+ # }
+
+ elsif ($event eq 'data') {
+ my $cat = $line->{'category'};
+ if ($cat eq 'test_category') {
+
+ my $key = $line->{'key'};
+ my $value = $line->{'value'};
+ $processes->{$sid}->{'data'}->{$cat}->{$key} = $value;
+ }
+ }
+
+ # This trace2 target does not emit 'printf' events.
+ #
+ # elsif ($event eq 'printf') {
+ # }
+}
+
+# Dump the resulting hash into something that we can compare against
+# in the test script. These options make Dumper output look a little
+# bit like JSON. Also convert variable references of the form "$VAR*"
+# so that the matching HEREDOC doesn't need to escape it.
+
+$Data::Dumper::Sortkeys = 1;
+$Data::Dumper::Indent = 1;
+$Data::Dumper::Purity = 1;
+$Data::Dumper::Pair = ':';
+
+my $out = Dumper($processes);
+$out =~ s/'/"/g;
+$out =~ s/\$VAR/VAR/g;
+
+# Finally, if we're running this script to generate (manually confirmed)
+# data to add to the test script, guard the indentation.
+
+if ($gen_heredoc == 1) {
+ $out =~ s/^/\t\|/gms;
+}
+
+print $out;
--- /dev/null
+#include "cache.h"
+#include "config.h"
+#include "json-writer.h"
+#include "quote.h"
+#include "run-command.h"
+#include "sigchain.h"
+#include "thread-utils.h"
+#include "version.h"
+#include "trace2/tr2_cfg.h"
+#include "trace2/tr2_cmd_name.h"
+#include "trace2/tr2_dst.h"
+#include "trace2/tr2_sid.h"
+#include "trace2/tr2_tgt.h"
+#include "trace2/tr2_tls.h"
+
+static int trace2_enabled;
+
+static int tr2_next_child_id; /* modify under lock */
+static int tr2_next_exec_id; /* modify under lock */
+static int tr2_next_repo_id = 1; /* modify under lock. zero is reserved */
+
+/*
+ * A table of the builtin TRACE2 targets. Each of these may be independently
+ * enabled or disabled. Each TRACE2 API method will try to write an event to
+ * *each* of the enabled targets.
+ */
+/* clang-format off */
+static struct tr2_tgt *tr2_tgt_builtins[] =
+{
+ &tr2_tgt_normal,
+ &tr2_tgt_perf,
+ &tr2_tgt_event,
+ NULL
+};
+/* clang-format on */
+
+/* clang-format off */
+#define for_each_builtin(j, tgt_j) \
+ for (j = 0, tgt_j = tr2_tgt_builtins[j]; \
+ tgt_j; \
+ j++, tgt_j = tr2_tgt_builtins[j])
+/* clang-format on */
+
+/* clang-format off */
+#define for_each_wanted_builtin(j, tgt_j) \
+ for_each_builtin(j, tgt_j) \
+ if (tr2_dst_trace_want(tgt_j->pdst))
+/* clang-format on */
+
+/*
+ * Force (rather than lazily) initialize any of the requested
+ * builtin TRACE2 targets at startup (and before we've seen an
+ * actual TRACE2 event call) so we can see if we need to setup
+ * the TR2 and TLS machinery.
+ *
+ * Return the number of builtin targets enabled.
+ */
+static int tr2_tgt_want_builtins(void)
+{
+ struct tr2_tgt *tgt_j;
+ int j;
+ int sum = 0;
+
+ for_each_builtin (j, tgt_j)
+ if (tgt_j->pfn_init())
+ sum++;
+
+ return sum;
+}
+
+/*
+ * Properly terminate each builtin target. Give each target
+ * a chance to write a summary event and/or flush if necessary
+ * and then close the fd.
+ */
+static void tr2_tgt_disable_builtins(void)
+{
+ struct tr2_tgt *tgt_j;
+ int j;
+
+ for_each_builtin (j, tgt_j)
+ tgt_j->pfn_term();
+}
+
+static int tr2main_exit_code;
+
+/*
+ * Our atexit routine should run after everything has finished.
+ *
+ * Note that events generated here might not actually appear if
+ * we are writing to fd 1 or 2 and our atexit routine runs after
+ * the pager's atexit routine (since it closes them to shutdown
+ * the pipes).
+ */
+static void tr2main_atexit_handler(void)
+{
+ struct tr2_tgt *tgt_j;
+ int j;
+ uint64_t us_now;
+ uint64_t us_elapsed_absolute;
+
+ us_now = getnanotime() / 1000;
+ us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
+
+ /*
+ * Clear any unbalanced regions so that our atexit message
+ * does not appear nested. This improves the appearance of
+ * the trace output if someone calls die(), for example.
+ */
+ tr2tls_pop_unwind_self();
+
+ for_each_wanted_builtin (j, tgt_j)
+ if (tgt_j->pfn_atexit)
+ tgt_j->pfn_atexit(us_elapsed_absolute,
+ tr2main_exit_code);
+
+ tr2_tgt_disable_builtins();
+
+ tr2tls_release();
+ tr2_sid_release();
+ tr2_cmd_name_release();
+ tr2_cfg_free_patterns();
+
+ trace2_enabled = 0;
+}
+
+static void tr2main_signal_handler(int signo)
+{
+ struct tr2_tgt *tgt_j;
+ int j;
+ uint64_t us_now;
+ uint64_t us_elapsed_absolute;
+
+ us_now = getnanotime() / 1000;
+ us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
+
+ for_each_wanted_builtin (j, tgt_j)
+ if (tgt_j->pfn_signal)
+ tgt_j->pfn_signal(us_elapsed_absolute, signo);
+
+ sigchain_pop(signo);
+ raise(signo);
+}
+
+void trace2_initialize_fl(const char *file, int line)
+{
+ struct tr2_tgt *tgt_j;
+ int j;
+
+ if (trace2_enabled)
+ return;
+
+ if (!tr2_tgt_want_builtins())
+ return;
+ trace2_enabled = 1;
+
+ tr2_sid_get();
+
+ atexit(tr2main_atexit_handler);
+ sigchain_push(SIGPIPE, tr2main_signal_handler);
+ tr2tls_init();
+
+ /*
+ * Emit 'version' message on each active builtin target.
+ */
+ for_each_wanted_builtin (j, tgt_j)
+ if (tgt_j->pfn_version_fl)
+ tgt_j->pfn_version_fl(file, line);
+}
+
+int trace2_is_enabled(void)
+{
+ return trace2_enabled;
+}
+
+void trace2_cmd_start_fl(const char *file, int line, const char **argv)
+{
+ struct tr2_tgt *tgt_j;
+ int j;
+
+ if (!trace2_enabled)
+ return;
+
+ for_each_wanted_builtin (j, tgt_j)
+ if (tgt_j->pfn_start_fl)
+ tgt_j->pfn_start_fl(file, line, argv);
+}
+
+int trace2_cmd_exit_fl(const char *file, int line, int code)
+{
+ struct tr2_tgt *tgt_j;
+ int j;
+ uint64_t us_now;
+ uint64_t us_elapsed_absolute;
+
+ code &= 0xff;
+
+ if (!trace2_enabled)
+ return code;
+
+ tr2main_exit_code = code;
+
+ us_now = getnanotime() / 1000;
+ us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
+
+ for_each_wanted_builtin (j, tgt_j)
+ if (tgt_j->pfn_exit_fl)
+ tgt_j->pfn_exit_fl(file, line, us_elapsed_absolute,
+ code);
+
+ return code;
+}
+
+void trace2_cmd_error_va_fl(const char *file, int line, const char *fmt,
+ va_list ap)
+{
+ struct tr2_tgt *tgt_j;
+ int j;
+
+ if (!trace2_enabled)
+ return;
+
+ /*
+ * We expect each target function to treat 'ap' as constant
+ * and use va_copy (because an 'ap' can only be walked once).
+ */
+ for_each_wanted_builtin (j, tgt_j)
+ if (tgt_j->pfn_error_va_fl)
+ tgt_j->pfn_error_va_fl(file, line, fmt, ap);
+}
+
+void trace2_cmd_path_fl(const char *file, int line, const char *pathname)
+{
+ struct tr2_tgt *tgt_j;
+ int j;
+
+ if (!trace2_enabled)
+ return;
+
+ for_each_wanted_builtin (j, tgt_j)
+ if (tgt_j->pfn_command_path_fl)
+ tgt_j->pfn_command_path_fl(file, line, pathname);
+}
+
+void trace2_cmd_name_fl(const char *file, int line, const char *name)
+{
+ struct tr2_tgt *tgt_j;
+ const char *hierarchy;
+ int j;
+
+ if (!trace2_enabled)
+ return;
+
+ tr2_cmd_name_append_hierarchy(name);
+ hierarchy = tr2_cmd_name_get_hierarchy();
+
+ for_each_wanted_builtin (j, tgt_j)
+ if (tgt_j->pfn_command_name_fl)
+ tgt_j->pfn_command_name_fl(file, line, name, hierarchy);
+}
+
+void trace2_cmd_mode_fl(const char *file, int line, const char *mode)
+{
+ struct tr2_tgt *tgt_j;
+ int j;
+
+ if (!trace2_enabled)
+ return;
+
+ for_each_wanted_builtin (j, tgt_j)
+ if (tgt_j->pfn_command_mode_fl)
+ tgt_j->pfn_command_mode_fl(file, line, mode);
+}
+
+void trace2_cmd_alias_fl(const char *file, int line, const char *alias,
+ const char **argv)
+{
+ struct tr2_tgt *tgt_j;
+ int j;
+
+ if (!trace2_enabled)
+ return;
+
+ for_each_wanted_builtin (j, tgt_j)
+ if (tgt_j->pfn_alias_fl)
+ tgt_j->pfn_alias_fl(file, line, alias, argv);
+}
+
+void trace2_cmd_list_config_fl(const char *file, int line)
+{
+ if (!trace2_enabled)
+ return;
+
+ tr2_cfg_list_config_fl(file, line);
+}
+
+void trace2_cmd_set_config_fl(const char *file, int line, const char *key,
+ const char *value)
+{
+ if (!trace2_enabled)
+ return;
+
+ tr2_cfg_set_fl(file, line, key, value);
+}
+
+void trace2_child_start_fl(const char *file, int line,
+ struct child_process *cmd)
+{
+ struct tr2_tgt *tgt_j;
+ int j;
+ uint64_t us_now;
+ uint64_t us_elapsed_absolute;
+
+ if (!trace2_enabled)
+ return;
+
+ us_now = getnanotime() / 1000;
+ us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
+
+ cmd->trace2_child_id = tr2tls_locked_increment(&tr2_next_child_id);
+ cmd->trace2_child_us_start = us_now;
+
+ for_each_wanted_builtin (j, tgt_j)
+ if (tgt_j->pfn_child_start_fl)
+ tgt_j->pfn_child_start_fl(file, line,
+ us_elapsed_absolute, cmd);
+}
+
+void trace2_child_exit_fl(const char *file, int line, struct child_process *cmd,
+ int child_exit_code)
+{
+ struct tr2_tgt *tgt_j;
+ int j;
+ uint64_t us_now;
+ uint64_t us_elapsed_absolute;
+ uint64_t us_elapsed_child;
+
+ if (!trace2_enabled)
+ return;
+
+ us_now = getnanotime() / 1000;
+ us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
+
+ if (cmd->trace2_child_us_start)
+ us_elapsed_child = us_now - cmd->trace2_child_us_start;
+ else
+ us_elapsed_child = 0;
+
+ for_each_wanted_builtin (j, tgt_j)
+ if (tgt_j->pfn_child_exit_fl)
+ tgt_j->pfn_child_exit_fl(file, line,
+ us_elapsed_absolute,
+ cmd->trace2_child_id, cmd->pid,
+ child_exit_code,
+ us_elapsed_child);
+}
+
+int trace2_exec_fl(const char *file, int line, const char *exe,
+ const char **argv)
+{
+ struct tr2_tgt *tgt_j;
+ int j;
+ int exec_id;
+ uint64_t us_now;
+ uint64_t us_elapsed_absolute;
+
+ if (!trace2_enabled)
+ return -1;
+
+ us_now = getnanotime() / 1000;
+ us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
+
+ exec_id = tr2tls_locked_increment(&tr2_next_exec_id);
+
+ for_each_wanted_builtin (j, tgt_j)
+ if (tgt_j->pfn_exec_fl)
+ tgt_j->pfn_exec_fl(file, line, us_elapsed_absolute,
+ exec_id, exe, argv);
+
+ return exec_id;
+}
+
+void trace2_exec_result_fl(const char *file, int line, int exec_id, int code)
+{
+ struct tr2_tgt *tgt_j;
+ int j;
+ uint64_t us_now;
+ uint64_t us_elapsed_absolute;
+
+ if (!trace2_enabled)
+ return;
+
+ us_now = getnanotime() / 1000;
+ us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
+
+ for_each_wanted_builtin (j, tgt_j)
+ if (tgt_j->pfn_exec_result_fl)
+ tgt_j->pfn_exec_result_fl(
+ file, line, us_elapsed_absolute, exec_id, code);
+}
+
+void trace2_thread_start_fl(const char *file, int line, const char *thread_name)
+{
+ struct tr2_tgt *tgt_j;
+ int j;
+ uint64_t us_now;
+ uint64_t us_elapsed_absolute;
+
+ if (!trace2_enabled)
+ return;
+
+ if (tr2tls_is_main_thread()) {
+ /*
+ * We should only be called from the new thread's thread-proc,
+ * so this is technically a bug. But in those cases where the
+ * main thread also runs the thread-proc function (or when we
+ * are built with threading disabled), we need to allow it.
+ *
+ * Convert this call to a region-enter so the nesting looks
+ * correct.
+ */
+ trace2_region_enter_printf_fl(file, line, NULL, NULL, NULL,
+ "thread-proc on main: %s",
+ thread_name);
+ return;
+ }
+
+ us_now = getnanotime() / 1000;
+ us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
+
+ tr2tls_create_self(thread_name);
+
+ for_each_wanted_builtin (j, tgt_j)
+ if (tgt_j->pfn_thread_start_fl)
+ tgt_j->pfn_thread_start_fl(file, line,
+ us_elapsed_absolute);
+}
+
+void trace2_thread_exit_fl(const char *file, int line)
+{
+ struct tr2_tgt *tgt_j;
+ int j;
+ uint64_t us_now;
+ uint64_t us_elapsed_absolute;
+ uint64_t us_elapsed_thread;
+
+ if (!trace2_enabled)
+ return;
+
+ if (tr2tls_is_main_thread()) {
+ /*
+ * We should only be called from the exiting thread's
+ * thread-proc, so this is technically a bug. But in
+ * those cases where the main thread also runs the
+ * thread-proc function (or when we are built with
+ * threading disabled), we need to allow it.
+ *
+ * Convert this call to a region-leave so the nesting
+ * looks correct.
+ */
+ trace2_region_leave_printf_fl(file, line, NULL, NULL, NULL,
+ "thread-proc on main");
+ return;
+ }
+
+ us_now = getnanotime() / 1000;
+ us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
+
+ /*
+ * Clear any unbalanced regions and then get the relative time
+ * for the outer-most region (which we pushed when the thread
+ * started). This gives us the run time of the thread.
+ */
+ tr2tls_pop_unwind_self();
+ us_elapsed_thread = tr2tls_region_elasped_self(us_now);
+
+ for_each_wanted_builtin (j, tgt_j)
+ if (tgt_j->pfn_thread_exit_fl)
+ tgt_j->pfn_thread_exit_fl(file, line,
+ us_elapsed_absolute,
+ us_elapsed_thread);
+
+ tr2tls_unset_self();
+}
+
+void trace2_def_param_fl(const char *file, int line, const char *param,
+ const char *value)
+{
+ struct tr2_tgt *tgt_j;
+ int j;
+
+ if (!trace2_enabled)
+ return;
+
+ for_each_wanted_builtin (j, tgt_j)
+ if (tgt_j->pfn_param_fl)
+ tgt_j->pfn_param_fl(file, line, param, value);
+}
+
+void trace2_def_repo_fl(const char *file, int line, struct repository *repo)
+{
+ struct tr2_tgt *tgt_j;
+ int j;
+
+ if (!trace2_enabled)
+ return;
+
+ if (repo->trace2_repo_id)
+ return;
+
+ repo->trace2_repo_id = tr2tls_locked_increment(&tr2_next_repo_id);
+
+ for_each_wanted_builtin (j, tgt_j)
+ if (tgt_j->pfn_repo_fl)
+ tgt_j->pfn_repo_fl(file, line, repo);
+}
+
+void trace2_region_enter_printf_va_fl(const char *file, int line,
+ const char *category, const char *label,
+ const struct repository *repo,
+ const char *fmt, va_list ap)
+{
+ struct tr2_tgt *tgt_j;
+ int j;
+ uint64_t us_now;
+ uint64_t us_elapsed_absolute;
+
+ if (!trace2_enabled)
+ return;
+
+ us_now = getnanotime() / 1000;
+ us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
+
+ /*
+ * Print the region-enter message at the current nesting
+ * (indentation) level and then push a new level.
+ *
+ * We expect each target function to treat 'ap' as constant
+ * and use va_copy.
+ */
+ for_each_wanted_builtin (j, tgt_j)
+ if (tgt_j->pfn_region_enter_printf_va_fl)
+ tgt_j->pfn_region_enter_printf_va_fl(
+ file, line, us_elapsed_absolute, category,
+ label, repo, fmt, ap);
+
+ tr2tls_push_self(us_now);
+}
+
+void trace2_region_enter_fl(const char *file, int line, const char *category,
+ const char *label, const struct repository *repo)
+{
+ trace2_region_enter_printf_va_fl(file, line, category, label, repo,
+ NULL, NULL);
+}
+
+void trace2_region_enter_printf_fl(const char *file, int line,
+ const char *category, const char *label,
+ const struct repository *repo,
+ const char *fmt, ...)
+{
+ va_list ap;
+
+ va_start(ap, fmt);
+ trace2_region_enter_printf_va_fl(file, line, category, label, repo, fmt,
+ ap);
+ va_end(ap);
+}
+
+#ifndef HAVE_VARIADIC_MACROS
+void trace2_region_enter_printf(const char *category, const char *label,
+ const struct repository *repo, const char *fmt,
+ ...)
+{
+ va_list ap;
+
+ va_start(ap, fmt);
+ trace2_region_enter_printf_va_fl(NULL, 0, category, label, repo, fmt,
+ ap);
+ va_end(ap);
+}
+#endif
+
+void trace2_region_leave_printf_va_fl(const char *file, int line,
+ const char *category, const char *label,
+ const struct repository *repo,
+ const char *fmt, va_list ap)
+{
+ struct tr2_tgt *tgt_j;
+ int j;
+ uint64_t us_now;
+ uint64_t us_elapsed_absolute;
+ uint64_t us_elapsed_region;
+
+ if (!trace2_enabled)
+ return;
+
+ us_now = getnanotime() / 1000;
+ us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
+
+ /*
+ * Get the elapsed time in the current region before we
+ * pop it off the stack. Pop the stack. And then print
+ * the perf message at the new (shallower) level so that
+ * it lines up with the corresponding push/enter.
+ */
+ us_elapsed_region = tr2tls_region_elasped_self(us_now);
+
+ tr2tls_pop_self();
+
+ /*
+ * We expect each target function to treat 'ap' as constant
+ * and use va_copy.
+ */
+ for_each_wanted_builtin (j, tgt_j)
+ if (tgt_j->pfn_region_leave_printf_va_fl)
+ tgt_j->pfn_region_leave_printf_va_fl(
+ file, line, us_elapsed_absolute,
+ us_elapsed_region, category, label, repo, fmt,
+ ap);
+}
+
+void trace2_region_leave_fl(const char *file, int line, const char *category,
+ const char *label, const struct repository *repo)
+{
+ trace2_region_leave_printf_va_fl(file, line, category, label, repo,
+ NULL, NULL);
+}
+
+void trace2_region_leave_printf_fl(const char *file, int line,
+ const char *category, const char *label,
+ const struct repository *repo,
+ const char *fmt, ...)
+{
+ va_list ap;
+
+ va_start(ap, fmt);
+ trace2_region_leave_printf_va_fl(file, line, category, label, repo, fmt,
+ ap);
+ va_end(ap);
+}
+
+#ifndef HAVE_VARIADIC_MACROS
+void trace2_region_leave_printf(const char *category, const char *label,
+ const struct repository *repo, const char *fmt,
+ ...)
+{
+ va_list ap;
+
+ va_start(ap, fmt);
+ trace2_region_leave_printf_va_fl(NULL, 0, category, label, repo, fmt,
+ ap);
+ va_end(ap);
+}
+#endif
+
+void trace2_data_string_fl(const char *file, int line, const char *category,
+ const struct repository *repo, const char *key,
+ const char *value)
+{
+ struct tr2_tgt *tgt_j;
+ int j;
+ uint64_t us_now;
+ uint64_t us_elapsed_absolute;
+ uint64_t us_elapsed_region;
+
+ if (!trace2_enabled)
+ return;
+
+ us_now = getnanotime() / 1000;
+ us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
+ us_elapsed_region = tr2tls_region_elasped_self(us_now);
+
+ for_each_wanted_builtin (j, tgt_j)
+ if (tgt_j->pfn_data_fl)
+ tgt_j->pfn_data_fl(file, line, us_elapsed_absolute,
+ us_elapsed_region, category, repo,
+ key, value);
+}
+
+void trace2_data_intmax_fl(const char *file, int line, const char *category,
+ const struct repository *repo, const char *key,
+ intmax_t value)
+{
+ struct strbuf buf_string = STRBUF_INIT;
+
+ if (!trace2_enabled)
+ return;
+
+ strbuf_addf(&buf_string, "%" PRIdMAX, value);
+ trace2_data_string_fl(file, line, category, repo, key, buf_string.buf);
+ strbuf_release(&buf_string);
+}
+
+void trace2_data_json_fl(const char *file, int line, const char *category,
+ const struct repository *repo, const char *key,
+ const struct json_writer *value)
+{
+ struct tr2_tgt *tgt_j;
+ int j;
+ uint64_t us_now;
+ uint64_t us_elapsed_absolute;
+ uint64_t us_elapsed_region;
+
+ if (!trace2_enabled)
+ return;
+
+ us_now = getnanotime() / 1000;
+ us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
+ us_elapsed_region = tr2tls_region_elasped_self(us_now);
+
+ for_each_wanted_builtin (j, tgt_j)
+ if (tgt_j->pfn_data_fl)
+ tgt_j->pfn_data_json_fl(file, line, us_elapsed_absolute,
+ us_elapsed_region, category,
+ repo, key, value);
+}
+
+void trace2_printf_va_fl(const char *file, int line, const char *fmt,
+ va_list ap)
+{
+ struct tr2_tgt *tgt_j;
+ int j;
+ uint64_t us_now;
+ uint64_t us_elapsed_absolute;
+
+ if (!trace2_enabled)
+ return;
+
+ us_now = getnanotime() / 1000;
+ us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
+
+ /*
+ * We expect each target function to treat 'ap' as constant
+ * and use va_copy.
+ */
+ for_each_wanted_builtin (j, tgt_j)
+ if (tgt_j->pfn_printf_va_fl)
+ tgt_j->pfn_printf_va_fl(file, line, us_elapsed_absolute,
+ fmt, ap);
+}
+
+void trace2_printf_fl(const char *file, int line, const char *fmt, ...)
+{
+ va_list ap;
+
+ va_start(ap, fmt);
+ trace2_printf_va_fl(file, line, fmt, ap);
+ va_end(ap);
+}
+
+#ifndef HAVE_VARIADIC_MACROS
+void trace2_printf(const char *fmt, ...)
+{
+ va_list ap;
+
+ va_start(ap, fmt);
+ trace2_printf_va_fl(NULL, 0, fmt, ap);
+ va_end(ap);
+}
+#endif
--- /dev/null
+#ifndef TRACE2_H
+#define TRACE2_H
+
+struct child_process;
+struct repository;
+struct json_writer;
+
+/*
+ * The public TRACE2 routines are grouped into the following groups:
+ *
+ * [] trace2_initialize -- initialization.
+ * [] trace2_cmd_* -- emit command/control messages.
+ * [] trace2_child* -- emit child start/stop messages.
+ * [] trace2_exec* -- emit exec start/stop messages.
+ * [] trace2_thread* -- emit thread start/stop messages.
+ * [] trace2_def* -- emit definition/parameter mesasges.
+ * [] trace2_region* -- emit region nesting messages.
+ * [] trace2_data* -- emit region/thread/repo data messages.
+ * [] trace2_printf* -- legacy trace[1] messages.
+ */
+
+/*
+ * Initialize TRACE2 tracing facility if any of the builtin TRACE2
+ * targets are enabled in the environment. Emits a 'version' event.
+ *
+ * Cleanup/Termination is handled automatically by a registered
+ * atexit() routine.
+ */
+void trace2_initialize_fl(const char *file, int line);
+
+#define trace2_initialize() trace2_initialize_fl(__FILE__, __LINE__)
+
+/*
+ * Return true if trace2 is enabled.
+ */
+int trace2_is_enabled(void);
+
+/*
+ * Emit a 'start' event with the original (unmodified) argv.
+ */
+void trace2_cmd_start_fl(const char *file, int line, const char **argv);
+
+#define trace2_cmd_start(argv) trace2_cmd_start_fl(__FILE__, __LINE__, (argv))
+
+/*
+ * Emit an 'exit' event.
+ *
+ * Write the exit-code that will be passed to exit() or returned
+ * from main().
+ *
+ * Use this prior to actually calling exit().
+ * See "#define exit()" in git-compat-util.h
+ */
+int trace2_cmd_exit_fl(const char *file, int line, int code);
+
+#define trace2_cmd_exit(code) (trace2_cmd_exit_fl(__FILE__, __LINE__, (code)))
+
+/*
+ * Emit an 'error' event.
+ *
+ * Write an error message to the TRACE2 targets.
+ */
+void trace2_cmd_error_va_fl(const char *file, int line, const char *fmt,
+ va_list ap);
+
+#define trace2_cmd_error_va(fmt, ap) \
+ trace2_cmd_error_va_fl(__FILE__, __LINE__, (fmt), (ap))
+
+/*
+ * Emit a 'pathname' event with the canonical pathname of the current process
+ * This gives post-processors a simple field to identify the command without
+ * having to parse the argv. For example, to distinguish invocations from
+ * installed versus debug executables.
+ */
+void trace2_cmd_path_fl(const char *file, int line, const char *pathname);
+
+#define trace2_cmd_path(p) trace2_cmd_path_fl(__FILE__, __LINE__, (p))
+
+/*
+ * Emit a 'cmd_name' event with the canonical name of the command.
+ * This gives post-processors a simple field to identify the command
+ * without having to parse the argv.
+ */
+void trace2_cmd_name_fl(const char *file, int line, const char *name);
+
+#define trace2_cmd_name(v) trace2_cmd_name_fl(__FILE__, __LINE__, (v))
+
+/*
+ * Emit a 'cmd_mode' event to further describe the command being run.
+ * For example, "checkout" can checkout a single file or can checkout a
+ * different branch. This gives post-processors a simple field to compare
+ * equivalent commands without having to parse the argv.
+ */
+void trace2_cmd_mode_fl(const char *file, int line, const char *mode);
+
+#define trace2_cmd_mode(sv) trace2_cmd_mode_fl(__FILE__, __LINE__, (sv))
+
+/*
+ * Emit an 'alias' expansion event.
+ */
+void trace2_cmd_alias_fl(const char *file, int line, const char *alias,
+ const char **argv);
+
+#define trace2_cmd_alias(alias, argv) \
+ trace2_cmd_alias_fl(__FILE__, __LINE__, (alias), (argv))
+
+/*
+ * Emit one or more 'def_param' events for "interesting" configuration
+ * settings.
+ *
+ * The environment variable "GIT_TR2_CONFIG_PARAMS" can be set to a
+ * list of patterns considered important. For example:
+ *
+ * GIT_TR2_CONFIG_PARAMS="core.*,remote.*.url"
+ *
+ * Note: this routine does a read-only iteration on the config data
+ * (using read_early_config()), so it must not be called until enough
+ * of the process environment has been established. This includes the
+ * location of the git and worktree directories, expansion of any "-c"
+ * and "-C" command line options, and etc.
+ */
+void trace2_cmd_list_config_fl(const char *file, int line);
+
+#define trace2_cmd_list_config() trace2_cmd_list_config_fl(__FILE__, __LINE__)
+
+/*
+ * Emit a "def_param" event for the given config key/value pair IF
+ * we consider the key to be "interesting".
+ *
+ * Use this for new/updated config settings created/updated after
+ * trace2_cmd_list_config() is called.
+ */
+void trace2_cmd_set_config_fl(const char *file, int line, const char *key,
+ const char *value);
+
+#define trace2_cmd_set_config(k, v) \
+ trace2_cmd_set_config_fl(__FILE__, __LINE__, (k), (v))
+
+/*
+ * Emit a 'child_start' event prior to spawning a child process.
+ *
+ * Before calling optionally set "cmd->trace2_child_class" to a string
+ * describing the type of the child process. For example, "editor" or
+ * "pager".
+ */
+void trace2_child_start_fl(const char *file, int line,
+ struct child_process *cmd);
+
+#define trace2_child_start(cmd) trace2_child_start_fl(__FILE__, __LINE__, (cmd))
+
+/*
+ * Emit a 'child_exit' event after the child process completes.
+ */
+void trace2_child_exit_fl(const char *file, int line, struct child_process *cmd,
+ int child_exit_code);
+
+#define trace2_child_exit(cmd, code) \
+ trace2_child_exit_fl(__FILE__, __LINE__, (cmd), (code))
+
+/*
+ * Emit an 'exec' event prior to calling one of exec(), execv(),
+ * execvp(), and etc. On Unix-derived systems, this will be the
+ * last event emitted for the current process, unless the exec
+ * fails. On Windows, exec() behaves like 'child_start' and a
+ * waitpid(), so additional events may be emitted.
+ *
+ * Returns the "exec_id".
+ */
+int trace2_exec_fl(const char *file, int line, const char *exe,
+ const char **argv);
+
+#define trace2_exec(exe, argv) trace2_exec_fl(__FILE__, __LINE__, (exe), (argv))
+
+/*
+ * Emit an 'exec_result' when possible. On Unix-derived systems,
+ * this should be called after exec() returns (which only happens
+ * when there is an error starting the new process). On Windows,
+ * this should be called after the waitpid().
+ *
+ * The "exec_id" should be the value returned from trace2_exec().
+ */
+void trace2_exec_result_fl(const char *file, int line, int exec_id, int code);
+
+#define trace2_exec_result(id, code) \
+ trace2_exec_result_fl(__FILE__, __LINE__, (id), (code))
+
+/*
+ * Emit a 'thread_start' event. This must be called from inside the
+ * thread-proc to set up the trace2 TLS data for the thread.
+ *
+ * Thread names should be descriptive, like "preload_index".
+ * Thread names will be decorated with an instance number automatically.
+ */
+void trace2_thread_start_fl(const char *file, int line,
+ const char *thread_name);
+
+#define trace2_thread_start(thread_name) \
+ trace2_thread_start_fl(__FILE__, __LINE__, (thread_name))
+
+/*
+ * Emit a 'thread_exit' event. This must be called from inside the
+ * thread-proc to report thread-specific data and cleanup TLS data
+ * for the thread.
+ */
+void trace2_thread_exit_fl(const char *file, int line);
+
+#define trace2_thread_exit() trace2_thread_exit_fl(__FILE__, __LINE__)
+
+/*
+ * Emit a 'param' event.
+ *
+ * Write a "<param> = <value>" pair describing some aspect of the
+ * run such as an important configuration setting or command line
+ * option that significantly changes command behavior.
+ */
+void trace2_def_param_fl(const char *file, int line, const char *param,
+ const char *value);
+
+#define trace2_def_param(param, value) \
+ trace2_def_param_fl(__FILE__, __LINE__, (param), (value))
+
+/*
+ * Tell trace2 about a newly instantiated repo object and assign
+ * a trace2-repo-id to be used in subsequent activity events.
+ *
+ * Emits a 'worktree' event for this repo instance.
+ */
+void trace2_def_repo_fl(const char *file, int line, struct repository *repo);
+
+#define trace2_def_repo(repo) trace2_def_repo_fl(__FILE__, __LINE__, repo)
+
+/*
+ * Emit a 'region_enter' event for <category>.<label> with optional
+ * repo-id and printf message.
+ *
+ * Enter a new nesting level on the current thread and remember the
+ * current time. This controls the indenting of all subsequent events
+ * on this thread.
+ */
+void trace2_region_enter_fl(const char *file, int line, const char *category,
+ const char *label, const struct repository *repo);
+
+#define trace2_region_enter(category, label, repo) \
+ trace2_region_enter_fl(__FILE__, __LINE__, (category), (label), (repo))
+
+void trace2_region_enter_printf_va_fl(const char *file, int line,
+ const char *category, const char *label,
+ const struct repository *repo,
+ const char *fmt, va_list ap);
+
+#define trace2_region_enter_printf_va(category, label, repo, fmt, ap) \
+ trace2_region_enter_printf_va_fl(__FILE__, __LINE__, (category), \
+ (label), (repo), (fmt), (ap))
+
+void trace2_region_enter_printf_fl(const char *file, int line,
+ const char *category, const char *label,
+ const struct repository *repo,
+ const char *fmt, ...);
+
+#ifdef HAVE_VARIADIC_MACROS
+#define trace2_region_enter_printf(category, label, repo, ...) \
+ trace2_region_enter_printf_fl(__FILE__, __LINE__, (category), (label), \
+ (repo), __VA_ARGS__)
+#else
+/* clang-format off */
+__attribute__((format (region_enter_printf, 4, 5)))
+void trace2_region_enter_printf(const char *category, const char *label,
+ const struct repository *repo, const char *fmt,
+ ...);
+/* clang-format on */
+#endif
+
+/*
+ * Emit a 'region_leave' event for <category>.<label> with optional
+ * repo-id and printf message.
+ *
+ * Leave current nesting level and report the elapsed time spent
+ * in this nesting level.
+ */
+void trace2_region_leave_fl(const char *file, int line, const char *category,
+ const char *label, const struct repository *repo);
+
+#define trace2_region_leave(category, label, repo) \
+ trace2_region_leave_fl(__FILE__, __LINE__, (category), (label), (repo))
+
+void trace2_region_leave_printf_va_fl(const char *file, int line,
+ const char *category, const char *label,
+ const struct repository *repo,
+ const char *fmt, va_list ap);
+
+#define trace2_region_leave_printf_va(category, label, repo, fmt, ap) \
+ trace2_region_leave_printf_va_fl(__FILE__, __LINE__, (category), \
+ (label), (repo), (fmt), (ap))
+
+void trace2_region_leave_printf_fl(const char *file, int line,
+ const char *category, const char *label,
+ const struct repository *repo,
+ const char *fmt, ...);
+
+#ifdef HAVE_VARIADIC_MACROS
+#define trace2_region_leave_printf(category, label, repo, ...) \
+ trace2_region_leave_printf_fl(__FILE__, __LINE__, (category), (label), \
+ (repo), __VA_ARGS__)
+#else
+/* clang-format off */
+__attribute__((format (region_leave_printf, 4, 5)))
+void trace2_region_leave_printf(const char *category, const char *label,
+ const struct repository *repo, const char *fmt,
+ ...);
+/* clang-format on */
+#endif
+
+/*
+ * Emit a key-value pair 'data' event of the form <category>.<key> = <value>.
+ * This event implicitly contains information about thread, nesting region,
+ * and optional repo-id.
+ *
+ * On event-based TRACE2 targets, this generates a 'data' event suitable
+ * for post-processing. On printf-based TRACE2 targets, this is converted
+ * into a fixed-format printf message.
+ */
+void trace2_data_string_fl(const char *file, int line, const char *category,
+ const struct repository *repo, const char *key,
+ const char *value);
+
+#define trace2_data_string(category, repo, key, value) \
+ trace2_data_string_fl(__FILE__, __LINE__, (category), (repo), (key), \
+ (value))
+
+void trace2_data_intmax_fl(const char *file, int line, const char *category,
+ const struct repository *repo, const char *key,
+ intmax_t value);
+
+#define trace2_data_intmax(category, repo, key, value) \
+ trace2_data_intmax_fl(__FILE__, __LINE__, (category), (repo), (key), \
+ (value))
+
+void trace2_data_json_fl(const char *file, int line, const char *category,
+ const struct repository *repo, const char *key,
+ const struct json_writer *jw);
+
+#define trace2_data_json(category, repo, key, value) \
+ trace2_data_json_fl(__FILE__, __LINE__, (category), (repo), (key), \
+ (value))
+
+/*
+ * Emit a 'printf' event.
+ *
+ * Write an arbitrary formatted message to the TRACE2 targets. These
+ * text messages should be considered as human-readable strings without
+ * any formatting guidelines. Post-processors may choose to ignore
+ * them.
+ */
+void trace2_printf_va_fl(const char *file, int line, const char *fmt,
+ va_list ap);
+
+#define trace2_printf_va(fmt, ap) \
+ trace2_printf_va_fl(__FILE__, __LINE__, (fmt), (ap))
+
+void trace2_printf_fl(const char *file, int line, const char *fmt, ...);
+
+#ifdef HAVE_VARIADIC_MACROS
+#define trace2_printf(...) trace2_printf_fl(__FILE__, __LINE__, __VA_ARGS__)
+#else
+/* clang-format off */
+__attribute__((format (printf, 1, 2)))
+void trace2_printf(const char *fmt, ...);
+/* clang-format on */
+#endif
+
+/*
+ * Optional platform-specific code to dump information about the
+ * current and any parent process(es). This is intended to allow
+ * post-processors to know who spawned this git instance and anything
+ * else the platform may be able to tell us about the current process.
+ */
+#if defined(GIT_WINDOWS_NATIVE)
+void trace2_collect_process_info(void);
+#else
+#define trace2_collect_process_info() \
+ do { \
+ } while (0)
+#endif
+
+#endif /* TRACE2_H */
--- /dev/null
+#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);
+}
--- /dev/null
+#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 */
--- /dev/null
+#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);
+}
--- /dev/null
+#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 */
--- /dev/null
+#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);
+}
--- /dev/null
+#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 */
--- /dev/null
+#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);
+}
--- /dev/null
+#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 */
--- /dev/null
+#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);
+}
--- /dev/null
+#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 */
--- /dev/null
+#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 */
--- /dev/null
+#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 */
+};
--- /dev/null
+#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,
+};
--- /dev/null
+#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,
+};
--- /dev/null
+#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;
+}
--- /dev/null
+#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 */
argv_array_pushf(&helper->env_array, "%s=%s",
GIT_DIR_ENVIRONMENT, get_git_dir());
+ helper->trace2_child_class = helper->args.argv[0]; /* "remote-<name>" */
+
code = start_command(helper);
if (code < 0 && errno == ENOENT)
die(_("unable to find remote helper for '%s'"), data->name);
proc.argv = argv;
proc.in = -1;
+ proc.trace2_hook_name = "pre-push";
if (start_command(&proc)) {
finish_command(&proc);
static NORETURN void usage_builtin(const char *err, va_list params)
{
vreportf("usage: ", err, params);
+
+ /*
+ * When we detect a usage error *before* the command dispatch in
+ * cmd_main(), we don't know what verb to report. Force it to this
+ * to facilitate post-processing.
+ */
+ trace2_cmd_name("_usage_");
+
+ /*
+ * Currently, the (err, params) are usually just the static usage
+ * string which isn't very useful here. Usually, the call site
+ * manually calls fprintf(stderr,...) with the actual detailed
+ * syntax error before calling usage().
+ *
+ * TODO It would be nice to update the call sites to pass both
+ * the static usage string and the detailed error message.
+ */
+
exit(129);
}
static NORETURN void die_builtin(const char *err, va_list params)
{
+ /*
+ * We call this trace2 function first and expect it to va_copy 'params'
+ * before using it (because an 'ap' can only be walked once).
+ */
+ trace2_cmd_error_va(err, params);
+
vreportf("fatal: ", err, params);
+
exit(128);
}
static void error_builtin(const char *err, va_list params)
{
+ /*
+ * We call this trace2 function first and expect it to va_copy 'params'
+ * before using it (because an 'ap' can only be walked once).
+ */
+ trace2_cmd_error_va(err, params);
+
vreportf("error: ", err, params);
}
void wt_status_collect(struct wt_status *s)
{
+ trace2_region_enter("status", "worktrees", s->repo);
wt_status_collect_changes_worktree(s);
- if (s->is_initial)
+ trace2_region_leave("status", "worktrees", s->repo);
+
+ if (s->is_initial) {
+ trace2_region_enter("status", "initial", s->repo);
wt_status_collect_changes_initial(s);
- else
+ trace2_region_leave("status", "initial", s->repo);
+ } else {
+ 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);
wt_status_get_state(s->repo, &s->state, s->branch && !strcmp(s->branch, "HEAD"));
if (s->state.merge_in_progress && !has_unmerged(s))
void wt_status_print(struct wt_status *s)
{
+ trace2_data_intmax("status", s->repo, "count/changed", s->change.nr);
+ trace2_data_intmax("status", s->repo, "count/untracked",
+ s->untracked.nr);
+ trace2_data_intmax("status", s->repo, "count/ignored", s->ignored.nr);
+
+ trace2_region_enter("status", "print", s->repo);
+
switch (s->status_format) {
case STATUS_FORMAT_SHORT:
wt_shortstatus_print(s);
wt_longstatus_print(s);
break;
}
+
+ trace2_region_leave("status", "print", s->repo);
}
/**