diff options
67 files changed, 6629 insertions, 23 deletions
diff --git a/.clang-format b/.clang-format index de1c8b5..41d4cd2 100644 --- a/.clang-format +++ b/.clang-format @@ -149,7 +149,7 @@ Cpp11BracedListStyle: false # 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 diff --git a/Documentation/technical/api-trace2.txt b/Documentation/technical/api-trace2.txt new file mode 100644 index 0000000..2de565f --- /dev/null +++ b/Documentation/technical/api-trace2.txt @@ -0,0 +1,1349 @@ += 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"). @@ -773,6 +773,7 @@ TEST_BUILTINS_OBJS += test-string-list.o 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 @@ -1017,6 +1018,16 @@ LIB_OBJS += tempfile.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 @@ -1596,7 +1607,9 @@ ifdef NO_INET_PTON 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 diff --git a/builtin/am.c b/builtin/am.c index cd051fe..86e3349 100644 --- a/builtin/am.c +++ b/builtin/am.c @@ -453,6 +453,7 @@ static int run_post_rewrite_hook(const struct am_state *state) cp.in = xopen(am_path(state, "rewritten"), O_RDONLY); cp.stdout_to_stderr = 1; + cp.trace2_hook_name = "post-rewrite"; ret = run_command(&cp); diff --git a/builtin/checkout.c b/builtin/checkout.c index bea08ef..0e6037b 100644 --- a/builtin/checkout.c +++ b/builtin/checkout.c @@ -325,6 +325,8 @@ static int checkout_paths(const struct checkout_opts *opts, 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"); @@ -1014,6 +1016,9 @@ static int switch_branches(const struct checkout_opts *opts, 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) @@ -1251,6 +1256,8 @@ static int switch_unborn_to_new_branch(const struct checkout_opts *opts) 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); diff --git a/builtin/pack-objects.c b/builtin/pack-objects.c index a9fac7c..a154fc2 100644 --- a/builtin/pack-objects.c +++ b/builtin/pack-objects.c @@ -33,6 +33,7 @@ #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) @@ -3473,6 +3474,8 @@ int cmd_pack_objects(int argc, const char **argv, const char *prefix) } } + trace2_region_enter("pack-objects", "enumerate-objects", + the_repository); prepare_packing_data(the_repository, &to_pack); if (progress) @@ -3487,12 +3490,23 @@ int cmd_pack_objects(int argc, const char **argv, const char *prefix) 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")," diff --git a/builtin/rebase.c b/builtin/rebase.c index 7c7bc13..52114cb 100644 --- a/builtin/rebase.c +++ b/builtin/rebase.c @@ -1027,6 +1027,14 @@ int cmd_rebase(int argc, const char **argv, const char *prefix) 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; @@ -1212,6 +1220,15 @@ int cmd_rebase(int argc, const char **argv, const char *prefix) 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; diff --git a/builtin/receive-pack.c b/builtin/receive-pack.c index d58b775..8bc714a 100644 --- a/builtin/receive-pack.c +++ b/builtin/receive-pack.c @@ -694,6 +694,8 @@ static int run_and_feed_hook(const char *hook_name, feed_fn feed, 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++) @@ -807,6 +809,7 @@ static int run_update_hook(struct command *cmd) 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) @@ -1190,6 +1193,7 @@ static void run_update_post_hook(struct command *commands) 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) diff --git a/builtin/reset.c b/builtin/reset.c index 4d18a46..7882829 100644 --- a/builtin/reset.c +++ b/builtin/reset.c @@ -341,6 +341,7 @@ int cmd_reset(int argc, const char **argv, const char *prefix) 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); } @@ -357,6 +358,11 @@ int cmd_reset(int argc, const char **argv, const char *prefix) 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(); diff --git a/builtin/submodule--helper.c b/builtin/submodule--helper.c index b80fc4b..6bcc4f1 100644 --- a/builtin/submodule--helper.c +++ b/builtin/submodule--helper.c @@ -1816,11 +1816,10 @@ static int update_submodules(struct submodule_update_clone *suc) { 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. diff --git a/builtin/worktree.c b/builtin/worktree.c index 3f9907f..6cc094a 100644 --- a/builtin/worktree.c +++ b/builtin/worktree.c @@ -402,6 +402,7 @@ done: 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), @@ -9,6 +9,7 @@ #include "gettext.h" #include "convert.h" #include "trace.h" +#include "trace2.h" #include "string-list.h" #include "pack-revindex.h" #include "hash.h" diff --git a/common-main.c b/common-main.c index 3728f66..d484aec 100644 --- a/common-main.c +++ b/common-main.c @@ -25,12 +25,19 @@ static void restore_sigpipe_to_default(void) 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]); @@ -40,7 +47,9 @@ int main(int argc, const char **argv) attr_start(); - restore_sigpipe_to_default(); + result = cmd_main(argc, argv); + + trace2_cmd_exit(result); - return cmd_main(argc, argv); + return result; } diff --git a/compat/mingw.c b/compat/mingw.c index 8141f77..6b04514 100644 --- a/compat/mingw.c +++ b/compat/mingw.c @@ -1551,19 +1551,23 @@ static int try_shell_exec(const char *cmd, char *const *argv) 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); @@ -1576,12 +1580,17 @@ int mingw_execv(const char *cmd, char *const *argv) /* 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; diff --git a/compat/mingw.h b/compat/mingw.h index 30d9fb3..4d73f8a 100644 --- a/compat/mingw.h +++ b/compat/mingw.h @@ -147,8 +147,7 @@ static inline int fcntl(int fd, int cmd, ...) 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; } diff --git a/compat/win32/trace2_win32_process_info.c b/compat/win32/trace2_win32_process_info.c new file mode 100644 index 0000000..52bd620 --- /dev/null +++ b/compat/win32/trace2_win32_process_info.c @@ -0,0 +1,147 @@ +#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(); +} @@ -2657,6 +2657,8 @@ int git_config_set_gently(const char *key, const char *value) void git_config_set(const char *key, const char *value) { git_config_set_multivar(key, value, NULL, 0); + + trace2_cmd_set_config(key, value); } /* diff --git a/config.mak.uname b/config.mak.uname index b37fa84..c8b0e34 100644 --- a/config.mak.uname +++ b/config.mak.uname @@ -393,6 +393,7 @@ ifeq ($(uname_S),Windows) 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 @@ -546,6 +547,7 @@ ifneq (,$(findstring MINGW,$(uname_S))) 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 @@ -1248,6 +1248,7 @@ struct child_process *git_connect(int fd[2], const char *url, 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; @@ -1290,9 +1291,11 @@ struct child_process *git_connect(int fd[2], const char *url, 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); @@ -78,6 +78,7 @@ static int launch_specified_editor(const char *editor, const char *path, 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); @@ -209,6 +209,8 @@ static int git_get_exec_path(struct strbuf *buf, const char *argv0) return -1; } + trace2_cmd_path(buf->buf); + return 0; } diff --git a/git-compat-util.h b/git-compat-util.h index 6573808..31b4793 100644 --- a/git-compat-util.h +++ b/git-compat-util.h @@ -1260,6 +1260,13 @@ static inline int is_missing_file_error(int errno_) 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 * should generally be the variable itself (not its address and not what @@ -147,16 +147,20 @@ static int handle_options(const char ***argv, int *argc, int *envchanged) 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; @@ -285,6 +289,7 @@ static int handle_options(const char ***argv, int *argc, int *envchanged) (*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; @@ -332,9 +337,14 @@ static int handle_alias(int *argcp, const char ***argv) 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); @@ -369,6 +379,9 @@ static int handle_alias(int *argcp, const char ***argv) /* 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; @@ -417,6 +430,8 @@ static int run_builtin(struct cmd_struct *p, int argc, const char **argv) 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); @@ -666,7 +681,14 @@ static void execv_dashed_external(const char **argv) 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:"); /* @@ -676,6 +698,12 @@ static void execv_dashed_external(const char **argv) * 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) @@ -701,6 +729,43 @@ static int run_argv(int *argcp, const char ***argv) 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); @@ -100,6 +100,7 @@ void prepare_pager_args(struct child_process *pager_process, const char *pager) 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) diff --git a/read-cache.c b/read-cache.c index 4415370..4dc6de1 100644 --- a/read-cache.c +++ b/read-cache.c @@ -2226,6 +2226,16 @@ int do_read_index(struct index_state *istate, const char *path, int must_exist) 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: @@ -2257,9 +2267,17 @@ int read_index_from(struct index_state *istate, const char *path, 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)) { @@ -2275,7 +2293,11 @@ int read_index_from(struct index_state *istate, const char *path, 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, @@ -2983,6 +3005,16 @@ static int do_write_index(struct index_state *istate, struct tempfile *tempfile, 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; } @@ -3002,7 +3034,18 @@ static int commit_locked_index(struct lock_file *lk) 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) @@ -3087,7 +3130,13 @@ static int write_shared_index(struct index_state *istate, 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)); diff --git a/remote-curl.c b/remote-curl.c index bb74210..aad02dc 100644 --- a/remote-curl.c +++ b/remote-curl.c @@ -1385,6 +1385,13 @@ int cmd_main(int argc, const char **argv) 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) { diff --git a/repository.c b/repository.c index 65e6f8b..5cad2dc 100644 --- a/repository.c +++ b/repository.c @@ -126,6 +126,8 @@ out: 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, diff --git a/repository.h b/repository.h index 8981649..4fb6a58 100644 --- a/repository.h +++ b/repository.h @@ -92,6 +92,9 @@ struct repository { /* 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' */ diff --git a/run-command.c b/run-command.c index 3db26b7..3449db3 100644 --- a/run-command.c +++ b/run-command.c @@ -219,9 +219,29 @@ static int exists_in_PATH(const char *file) 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 @@ -712,6 +732,7 @@ fail_pipe: cmd->err = fderr[0]; } + trace2_child_start(cmd); trace_run_command(cmd); fflush(NULL); @@ -926,6 +947,8 @@ end_of_spawn: #endif if (cmd->pid < 0) { + trace2_child_exit(cmd, -1); + if (need_in) close_pair(fdin); else if (cmd->in) @@ -964,13 +987,16 @@ end_of_spawn: 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; } @@ -992,8 +1018,19 @@ int run_command_v_opt(const char **argv, int opt) 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.no_stdin = opt & RUN_COMMAND_NO_STDIN ? 1 : 0; @@ -1004,6 +1041,7 @@ int run_command_v_opt_cd_env(const char **argv, int opt, const char *dir, const 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); } @@ -1319,6 +1357,7 @@ int run_hook_ve(const char *const *env, const char *name, va_list args) hook.env = env; hook.no_stdin = 1; hook.stdout_to_stderr = 1; + hook.trace2_hook_name = name; return run_command(&hook); } @@ -1807,3 +1846,21 @@ int run_processes_parallel(int n, 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; +} diff --git a/run-command.h b/run-command.h index 68f5369..a695069 100644 --- a/run-command.h +++ b/run-command.h @@ -10,6 +10,12 @@ struct child_process { 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, @@ -73,12 +79,14 @@ extern int run_hook_ve(const char *const *env, const char *name, va_list args); #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 @@ -220,5 +228,8 @@ int run_processes_parallel(int n, 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 diff --git a/sequencer.c b/sequencer.c index 3209cde..95dda23 100644 --- a/sequencer.c +++ b/sequencer.c @@ -1103,6 +1103,7 @@ static int run_rewrite_hook(const struct object_id *oldoid, proc.argv = argv; proc.in = -1; proc.stdout_to_stderr = 1; + proc.trace2_hook_name = "post-rewrite"; code = start_command(&proc); if (code) @@ -3786,6 +3787,7 @@ cleanup_head_ref: 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 */ diff --git a/sh-i18n--envsubst.c b/sh-i18n--envsubst.c index 09c6b44..cecfdd3 100644 --- a/sh-i18n--envsubst.c +++ b/sh-i18n--envsubst.c @@ -14,6 +14,7 @@ */ #include "git-compat-util.h" +#include "trace2.h" /* Substitution of environment variables in shell format strings. Copyright (C) 2003-2007 Free Software Foundation, Inc. @@ -67,6 +68,8 @@ cmd_main (int argc, const char *argv[]) /* Default values for command line options. */ /* unsigned short int show_variables = 0; */ + trace2_cmd_name("sh-i18n--envsubst"); + switch (argc) { case 1: diff --git a/sub-process.c b/sub-process.c index 8d2a170..3f4af93 100644 --- a/sub-process.c +++ b/sub-process.c @@ -88,6 +88,7 @@ int subprocess_start(struct hashmap *hashmap, struct subprocess_entry *entry, co 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) { diff --git a/submodule.c b/submodule.c index 934ecfa..174003a 100644 --- a/submodule.c +++ b/submodule.c @@ -1609,11 +1609,12 @@ int fetch_populated_submodules(struct repository *r, 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: diff --git a/t/helper/test-parse-options.c b/t/helper/test-parse-options.c index 47fee66..cc88fba 100644 --- a/t/helper/test-parse-options.c +++ b/t/helper/test-parse-options.c @@ -2,6 +2,7 @@ #include "cache.h" #include "parse-options.h" #include "string-list.h" +#include "trace2.h" static int boolean = 0; static int integer = 0; @@ -153,6 +154,8 @@ int cmd__parse_options(int argc, const char **argv) int i; int ret = 0; + trace2_cmd_name("_parse_"); + argc = parse_options(argc, (const char **)argv, prefix, options, usage, 0); if (length_cb.called) { diff --git a/t/helper/test-tool.c b/t/helper/test-tool.c index 99db740..53c0693 100644 --- a/t/helper/test-tool.c +++ b/t/helper/test-tool.c @@ -1,5 +1,6 @@ #include "git-compat-util.h" #include "test-tool.h" +#include "trace2.h" struct test_cmd { const char *name; @@ -51,6 +52,7 @@ static struct test_cmd cmds[] = { { "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 }, @@ -82,6 +84,8 @@ int cmd_main(int argc, const char **argv) 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); } } diff --git a/t/helper/test-tool.h b/t/helper/test-tool.h index 25abed1..ffab4d1 100644 --- a/t/helper/test-tool.h +++ b/t/helper/test-tool.h @@ -48,6 +48,7 @@ int cmd__string_list(int argc, const char **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); diff --git a/t/helper/test-trace2.c b/t/helper/test-trace2.c new file mode 100644 index 0000000..197819c --- /dev/null +++ b/t/helper/test-trace2.c @@ -0,0 +1,273 @@ +#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(); +} diff --git a/t/t0001-init.sh b/t/t0001-init.sh index 42a263c..5e27604 100755 --- a/t/t0001-init.sh +++ b/t/t0001-init.sh @@ -93,6 +93,7 @@ test_expect_success 'No extra GIT_* on alias scripts' ' sed -n \ -e "/^GIT_PREFIX=/d" \ -e "/^GIT_TEXTDOMAINDIR=/d" \ + -e "/^GIT_TR2_PARENT/d" \ -e "/^GIT_/s/=.*//p" | sort EOF diff --git a/t/t0210-trace2-normal.sh b/t/t0210-trace2-normal.sh new file mode 100755 index 0000000..03a0aed --- /dev/null +++ b/t/t0210-trace2-normal.sh @@ -0,0 +1,135 @@ +#!/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 diff --git a/t/t0210/scrub_normal.perl b/t/t0210/scrub_normal.perl new file mode 100644 index 0000000..c65d1a8 --- /dev/null +++ b/t/t0210/scrub_normal.perl @@ -0,0 +1,48 @@ +#!/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"; + } +} diff --git a/t/t0211-trace2-perf.sh b/t/t0211-trace2-perf.sh new file mode 100755 index 0000000..953e2f7 --- /dev/null +++ b/t/t0211-trace2-perf.sh @@ -0,0 +1,153 @@ +#!/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 diff --git a/t/t0211/scrub_perf.perl b/t/t0211/scrub_perf.perl new file mode 100644 index 0000000..351af78 --- /dev/null +++ b/t/t0211/scrub_perf.perl @@ -0,0 +1,76 @@ +#!/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: +} + + diff --git a/t/t0212-trace2-event.sh b/t/t0212-trace2-event.sh new file mode 100755 index 0000000..028b6c5 --- /dev/null +++ b/t/t0212-trace2-event.sh @@ -0,0 +1,236 @@ +#!/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 diff --git a/t/t0212/parse_events.perl b/t/t0212/parse_events.perl new file mode 100644 index 0000000..a2776ba --- /dev/null +++ b/t/t0212/parse_events.perl @@ -0,0 +1,251 @@ +#!/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; diff --git a/trace2.c b/trace2.c new file mode 100644 index 0000000..ccccd4e --- /dev/null +++ b/trace2.c @@ -0,0 +1,761 @@ +#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 diff --git a/trace2.h b/trace2.h new file mode 100644 index 0000000..ae5020d --- /dev/null +++ b/trace2.h @@ -0,0 +1,385 @@ +#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 */ diff --git a/trace2/tr2_cfg.c b/trace2/tr2_cfg.c new file mode 100644 index 0000000..b329921 --- /dev/null +++ b/trace2/tr2_cfg.c @@ -0,0 +1,90 @@ +#include "cache.h" +#include "config.h" +#include "tr2_cfg.h" + +#define TR2_ENVVAR_CFG_PARAM "GIT_TR2_CONFIG_PARAMS" + +static struct strbuf **tr2_cfg_patterns; +static int tr2_cfg_count_patterns; +static int tr2_cfg_loaded; + +/* + * Parse a string containing a comma-delimited list of config keys + * or wildcard patterns into a list of strbufs. + */ +static int tr2_cfg_load_patterns(void) +{ + struct strbuf **s; + const char *envvar; + + if (tr2_cfg_loaded) + return tr2_cfg_count_patterns; + tr2_cfg_loaded = 1; + + envvar = getenv(TR2_ENVVAR_CFG_PARAM); + if (!envvar || !*envvar) + return tr2_cfg_count_patterns; + + tr2_cfg_patterns = strbuf_split_buf(envvar, strlen(envvar), ',', -1); + for (s = tr2_cfg_patterns; *s; s++) { + struct strbuf *buf = *s; + + if (buf->len && buf->buf[buf->len - 1] == ',') + strbuf_setlen(buf, buf->len - 1); + strbuf_trim_trailing_newline(*s); + strbuf_trim(*s); + } + + tr2_cfg_count_patterns = s - tr2_cfg_patterns; + return tr2_cfg_count_patterns; +} + +void tr2_cfg_free_patterns(void) +{ + if (tr2_cfg_patterns) + strbuf_list_free(tr2_cfg_patterns); + tr2_cfg_count_patterns = 0; + tr2_cfg_loaded = 0; +} + +struct tr2_cfg_data { + const char *file; + int line; +}; + +/* + * See if the given config key matches any of our patterns of interest. + */ +static int tr2_cfg_cb(const char *key, const char *value, void *d) +{ + struct strbuf **s; + struct tr2_cfg_data *data = (struct tr2_cfg_data *)d; + + for (s = tr2_cfg_patterns; *s; s++) { + struct strbuf *buf = *s; + int wm = wildmatch(buf->buf, key, WM_CASEFOLD); + if (wm == WM_MATCH) { + trace2_def_param_fl(data->file, data->line, key, value); + return 0; + } + } + + return 0; +} + +void tr2_cfg_list_config_fl(const char *file, int line) +{ + struct tr2_cfg_data data = { file, line }; + + if (tr2_cfg_load_patterns() > 0) + read_early_config(tr2_cfg_cb, &data); +} + +void tr2_cfg_set_fl(const char *file, int line, const char *key, + const char *value) +{ + struct tr2_cfg_data data = { file, line }; + + if (tr2_cfg_load_patterns() > 0) + tr2_cfg_cb(key, value, &data); +} diff --git a/trace2/tr2_cfg.h b/trace2/tr2_cfg.h new file mode 100644 index 0000000..d9c98f6 --- /dev/null +++ b/trace2/tr2_cfg.h @@ -0,0 +1,19 @@ +#ifndef TR2_CFG_H +#define TR2_CFG_H + +/* + * Iterate over all config settings and emit 'def_param' events for the + * "interesting" ones to TRACE2. + */ +void tr2_cfg_list_config_fl(const char *file, int line); + +/* + * Emit a "def_param" event for the given key/value pair IF we consider + * the key to be "interesting". + */ +void tr2_cfg_set_fl(const char *file, int line, const char *key, + const char *value); + +void tr2_cfg_free_patterns(void); + +#endif /* TR2_CFG_H */ diff --git a/trace2/tr2_cmd_name.c b/trace2/tr2_cmd_name.c new file mode 100644 index 0000000..e999592 --- /dev/null +++ b/trace2/tr2_cmd_name.c @@ -0,0 +1,30 @@ +#include "cache.h" +#include "trace2/tr2_cmd_name.h" + +#define TR2_ENVVAR_PARENT_NAME "GIT_TR2_PARENT_NAME" + +static struct strbuf tr2cmdname_hierarchy = STRBUF_INIT; + +void tr2_cmd_name_append_hierarchy(const char *name) +{ + const char *parent_name = getenv(TR2_ENVVAR_PARENT_NAME); + + strbuf_reset(&tr2cmdname_hierarchy); + if (parent_name && *parent_name) { + strbuf_addstr(&tr2cmdname_hierarchy, parent_name); + strbuf_addch(&tr2cmdname_hierarchy, '/'); + } + strbuf_addstr(&tr2cmdname_hierarchy, name); + + setenv(TR2_ENVVAR_PARENT_NAME, tr2cmdname_hierarchy.buf, 1); +} + +const char *tr2_cmd_name_get_hierarchy(void) +{ + return tr2cmdname_hierarchy.buf; +} + +void tr2_cmd_name_release(void) +{ + strbuf_release(&tr2cmdname_hierarchy); +} diff --git a/trace2/tr2_cmd_name.h b/trace2/tr2_cmd_name.h new file mode 100644 index 0000000..ab70b67 --- /dev/null +++ b/trace2/tr2_cmd_name.h @@ -0,0 +1,24 @@ +#ifndef TR2_CMD_NAME_H +#define TR2_CMD_NAME_H + +/* + * Append the current command name to the list being maintained + * in the environment. + * + * The hierarchy for a top-level git command is just the current + * command name. For a child git process, the hierarchy includes the + * names of the parent processes. + * + * The hierarchy for the current process will be exported to the + * environment and inherited by child processes. + */ +void tr2_cmd_name_append_hierarchy(const char *name); + +/* + * Get the command name hierarchy for the current process. + */ +const char *tr2_cmd_name_get_hierarchy(void); + +void tr2_cmd_name_release(void); + +#endif /* TR2_CMD_NAME_H */ diff --git a/trace2/tr2_dst.c b/trace2/tr2_dst.c new file mode 100644 index 0000000..fd490a4 --- /dev/null +++ b/trace2/tr2_dst.c @@ -0,0 +1,252 @@ +#include "cache.h" +#include "trace2/tr2_dst.h" + +/* + * If a Trace2 target cannot be opened for writing, we should issue a + * warning to stderr, but this is very annoying if the target is a pipe + * or socket and beyond the user's control -- especially since every + * git command (and sub-command) will print the message. So we silently + * eat these warnings and just discard the trace data. + * + * Enable the following environment variable to see these warnings. + */ +#define TR2_ENVVAR_DST_DEBUG "GIT_TR2_DST_DEBUG" + +static int tr2_dst_want_warning(void) +{ + static int tr2env_dst_debug = -1; + + if (tr2env_dst_debug == -1) { + const char *env_value = getenv(TR2_ENVVAR_DST_DEBUG); + if (!env_value || !*env_value) + tr2env_dst_debug = 0; + else + tr2env_dst_debug = atoi(env_value) > 0; + } + + return tr2env_dst_debug; +} + +void tr2_dst_trace_disable(struct tr2_dst *dst) +{ + if (dst->need_close) + close(dst->fd); + dst->fd = 0; + dst->initialized = 1; + dst->need_close = 0; +} + +static int tr2_dst_try_path(struct tr2_dst *dst, const char *tgt_value) +{ + int fd = open(tgt_value, O_WRONLY | O_APPEND | O_CREAT, 0666); + if (fd == -1) { + if (tr2_dst_want_warning()) + warning("trace2: could not open '%s' for '%s' tracing: %s", + tgt_value, dst->env_var_name, strerror(errno)); + + tr2_dst_trace_disable(dst); + return 0; + } + + dst->fd = fd; + dst->need_close = 1; + dst->initialized = 1; + + return dst->fd; +} + +#ifndef NO_UNIX_SOCKETS +#define PREFIX_AF_UNIX "af_unix:" +#define PREFIX_AF_UNIX_STREAM "af_unix:stream:" +#define PREFIX_AF_UNIX_DGRAM "af_unix:dgram:" + +static int tr2_dst_try_uds_connect(const char *path, int sock_type, int *out_fd) +{ + int fd; + struct sockaddr_un sa; + + fd = socket(AF_UNIX, sock_type, 0); + if (fd == -1) + return errno; + + sa.sun_family = AF_UNIX; + strlcpy(sa.sun_path, path, sizeof(sa.sun_path)); + + if (connect(fd, (struct sockaddr *)&sa, sizeof(sa)) == -1) { + int e = errno; + close(fd); + return e; + } + + *out_fd = fd; + return 0; +} + +#define TR2_DST_UDS_TRY_STREAM (1 << 0) +#define TR2_DST_UDS_TRY_DGRAM (1 << 1) + +static int tr2_dst_try_unix_domain_socket(struct tr2_dst *dst, + const char *tgt_value) +{ + unsigned int uds_try = 0; + int fd; + int e; + const char *path = NULL; + + /* + * Allow "af_unix:[<type>:]<absolute_path>" + * + * Trace2 always writes complete individual messages (without + * chunking), so we can talk to either DGRAM or STREAM type sockets. + * + * Allow the user to explicitly request the socket type. + * + * If they omit the socket type, try one and then the other. + */ + + if (skip_prefix(tgt_value, PREFIX_AF_UNIX_STREAM, &path)) + uds_try |= TR2_DST_UDS_TRY_STREAM; + + else if (skip_prefix(tgt_value, PREFIX_AF_UNIX_DGRAM, &path)) + uds_try |= TR2_DST_UDS_TRY_DGRAM; + + else if (skip_prefix(tgt_value, PREFIX_AF_UNIX, &path)) + uds_try |= TR2_DST_UDS_TRY_STREAM | TR2_DST_UDS_TRY_DGRAM; + + if (!path || !*path) { + if (tr2_dst_want_warning()) + warning("trace2: invalid AF_UNIX value '%s' for '%s' tracing", + tgt_value, dst->env_var_name); + + tr2_dst_trace_disable(dst); + return 0; + } + + if (!is_absolute_path(path) || + strlen(path) >= sizeof(((struct sockaddr_un *)0)->sun_path)) { + if (tr2_dst_want_warning()) + warning("trace2: invalid AF_UNIX path '%s' for '%s' tracing", + path, dst->env_var_name); + + tr2_dst_trace_disable(dst); + return 0; + } + + if (uds_try & TR2_DST_UDS_TRY_STREAM) { + e = tr2_dst_try_uds_connect(path, SOCK_STREAM, &fd); + if (!e) + goto connected; + if (e != EPROTOTYPE) + goto error; + } + if (uds_try & TR2_DST_UDS_TRY_DGRAM) { + e = tr2_dst_try_uds_connect(path, SOCK_DGRAM, &fd); + if (!e) + goto connected; + } + +error: + if (tr2_dst_want_warning()) + warning("trace2: could not connect to socket '%s' for '%s' tracing: %s", + path, dst->env_var_name, strerror(e)); + + tr2_dst_trace_disable(dst); + return 0; + +connected: + dst->fd = fd; + dst->need_close = 1; + dst->initialized = 1; + + return dst->fd; +} +#endif + +static void tr2_dst_malformed_warning(struct tr2_dst *dst, + const char *tgt_value) +{ + struct strbuf buf = STRBUF_INIT; + + strbuf_addf(&buf, "trace2: unknown value for '%s': '%s'", + dst->env_var_name, tgt_value); + warning("%s", buf.buf); + + strbuf_release(&buf); +} + +int tr2_dst_get_trace_fd(struct tr2_dst *dst) +{ + const char *tgt_value; + + /* don't open twice */ + if (dst->initialized) + return dst->fd; + + dst->initialized = 1; + + tgt_value = getenv(dst->env_var_name); + + if (!tgt_value || !strcmp(tgt_value, "") || !strcmp(tgt_value, "0") || + !strcasecmp(tgt_value, "false")) { + dst->fd = 0; + return dst->fd; + } + + if (!strcmp(tgt_value, "1") || !strcasecmp(tgt_value, "true")) { + dst->fd = STDERR_FILENO; + return dst->fd; + } + + if (strlen(tgt_value) == 1 && isdigit(*tgt_value)) { + dst->fd = atoi(tgt_value); + return dst->fd; + } + + if (is_absolute_path(tgt_value)) + return tr2_dst_try_path(dst, tgt_value); + +#ifndef NO_UNIX_SOCKETS + if (starts_with(tgt_value, PREFIX_AF_UNIX)) + return tr2_dst_try_unix_domain_socket(dst, tgt_value); +#endif + + /* Always warn about malformed values. */ + tr2_dst_malformed_warning(dst, tgt_value); + tr2_dst_trace_disable(dst); + return 0; +} + +int tr2_dst_trace_want(struct tr2_dst *dst) +{ + return !!tr2_dst_get_trace_fd(dst); +} + +void tr2_dst_write_line(struct tr2_dst *dst, struct strbuf *buf_line) +{ + int fd = tr2_dst_get_trace_fd(dst); + + strbuf_complete_line(buf_line); /* ensure final NL on buffer */ + + /* + * We do not use write_in_full() because we do not want + * a short-write to try again. We are using O_APPEND mode + * files and the kernel handles the atomic seek+write. If + * another thread or git process is concurrently writing to + * this fd or file, our remainder-write may not be contiguous + * with our initial write of this message. And that will + * confuse readers. So just don't bother. + * + * It is assumed that TRACE2 messages are short enough that + * the system can write them in 1 attempt and we won't see + * a short-write. + * + * If we get an IO error, just close the trace dst. + */ + if (write(fd, buf_line->buf, buf_line->len) >= 0) + return; + + if (tr2_dst_want_warning()) + warning("unable to write trace to '%s': %s", dst->env_var_name, + strerror(errno)); + tr2_dst_trace_disable(dst); +} diff --git a/trace2/tr2_dst.h b/trace2/tr2_dst.h new file mode 100644 index 0000000..9a64f05 --- /dev/null +++ b/trace2/tr2_dst.h @@ -0,0 +1,36 @@ +#ifndef TR2_DST_H +#define TR2_DST_H + +struct strbuf; + +struct tr2_dst { + const char *const env_var_name; + int fd; + unsigned int initialized : 1; + unsigned int need_close : 1; +}; + +/* + * Disable TRACE2 on the destination. In TRACE2 a destination (DST) + * wraps a file descriptor; it is associated with a TARGET which + * defines the formatting. + */ +void tr2_dst_trace_disable(struct tr2_dst *dst); + +/* + * Return the file descriptor for the DST. + * If 0, the dst is closed or disabled. + */ +int tr2_dst_get_trace_fd(struct tr2_dst *dst); + +/* + * Return true if the DST is opened for writing. + */ +int tr2_dst_trace_want(struct tr2_dst *dst); + +/* + * Write a single line/message to the trace file. + */ +void tr2_dst_write_line(struct tr2_dst *dst, struct strbuf *buf_line); + +#endif /* TR2_DST_H */ diff --git a/trace2/tr2_sid.c b/trace2/tr2_sid.c new file mode 100644 index 0000000..984524a --- /dev/null +++ b/trace2/tr2_sid.c @@ -0,0 +1,67 @@ +#include "cache.h" +#include "trace2/tr2_sid.h" + +#define TR2_ENVVAR_PARENT_SID "GIT_TR2_PARENT_SID" + +static struct strbuf tr2sid_buf = STRBUF_INIT; +static int tr2sid_nr_git_parents; + +/* + * Compute a "unique" session id (SID) for the current process. This allows + * all events from this process to have a single label (much like a PID). + * + * Export this into our environment so that all child processes inherit it. + * + * If we were started by another git instance, use our parent's SID as a + * prefix. (This lets us track parent/child relationships even if there + * is an intermediate shell process.) + * + * Additionally, count the number of nested git processes. + */ +static void tr2_sid_compute(void) +{ + uint64_t us_now; + const char *parent_sid; + + if (tr2sid_buf.len) + return; + + parent_sid = getenv(TR2_ENVVAR_PARENT_SID); + if (parent_sid && *parent_sid) { + const char *p; + for (p = parent_sid; *p; p++) + if (*p == '/') + tr2sid_nr_git_parents++; + + strbuf_addstr(&tr2sid_buf, parent_sid); + strbuf_addch(&tr2sid_buf, '/'); + tr2sid_nr_git_parents++; + } + + us_now = getnanotime() / 1000; + strbuf_addf(&tr2sid_buf, "%" PRIuMAX "-%" PRIdMAX, (uintmax_t)us_now, + (intmax_t)getpid()); + + setenv(TR2_ENVVAR_PARENT_SID, tr2sid_buf.buf, 1); +} + +const char *tr2_sid_get(void) +{ + if (!tr2sid_buf.len) + tr2_sid_compute(); + + return tr2sid_buf.buf; +} + +int tr2_sid_depth(void) +{ + if (!tr2sid_buf.len) + tr2_sid_compute(); + + return tr2sid_nr_git_parents; +} + +void tr2_sid_release(void) +{ + strbuf_release(&tr2sid_buf); +} diff --git a/trace2/tr2_sid.h b/trace2/tr2_sid.h new file mode 100644 index 0000000..9bef321 --- /dev/null +++ b/trace2/tr2_sid.h @@ -0,0 +1,18 @@ +#ifndef TR2_SID_H +#define TR2_SID_H + +/* + * Get our session id. Compute if necessary. + */ +const char *tr2_sid_get(void); + +/* + * Get our process depth. A top-level git process invoked from the + * command line will have depth=0. A child git process will have + * depth=1 and so on. + */ +int tr2_sid_depth(void); + +void tr2_sid_release(void); + +#endif /* TR2_SID_H */ diff --git a/trace2/tr2_tbuf.c b/trace2/tr2_tbuf.c new file mode 100644 index 0000000..0844910 --- /dev/null +++ b/trace2/tr2_tbuf.c @@ -0,0 +1,32 @@ +#include "cache.h" +#include "tr2_tbuf.h" + +void tr2_tbuf_local_time(struct tr2_tbuf *tb) +{ + struct timeval tv; + struct tm tm; + time_t secs; + + gettimeofday(&tv, NULL); + secs = tv.tv_sec; + localtime_r(&secs, &tm); + + xsnprintf(tb->buf, sizeof(tb->buf), "%02d:%02d:%02d.%06ld", tm.tm_hour, + tm.tm_min, tm.tm_sec, (long)tv.tv_usec); +} + +void tr2_tbuf_utc_time(struct tr2_tbuf *tb) +{ + struct timeval tv; + struct tm tm; + time_t secs; + + gettimeofday(&tv, NULL); + secs = tv.tv_sec; + gmtime_r(&secs, &tm); + + xsnprintf(tb->buf, sizeof(tb->buf), + "%4d-%02d-%02d %02d:%02d:%02d.%06ld", tm.tm_year + 1900, + tm.tm_mon + 1, tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec, + (long)tv.tv_usec); +} diff --git a/trace2/tr2_tbuf.h b/trace2/tr2_tbuf.h new file mode 100644 index 0000000..9cdefa3 --- /dev/null +++ b/trace2/tr2_tbuf.h @@ -0,0 +1,23 @@ +#ifndef TR2_TBUF_H +#define TR2_TBUF_H + +/* + * A simple wrapper around a fixed buffer to avoid C syntax + * quirks and the need to pass around an additional size_t + * argument. + */ +struct tr2_tbuf { + char buf[32]; +}; + +/* + * Fill buffer with formatted local time string. + */ +void tr2_tbuf_local_time(struct tr2_tbuf *tb); + +/* + * Fill buffer with formatted UTC time string. + */ +void tr2_tbuf_utc_time(struct tr2_tbuf *tb); + +#endif /* TR2_TBUF_H */ diff --git a/trace2/tr2_tgt.h b/trace2/tr2_tgt.h new file mode 100644 index 0000000..297bb8f --- /dev/null +++ b/trace2/tr2_tgt.h @@ -0,0 +1,133 @@ +#ifndef TR2_TGT_H +#define TR2_TGT_H + +struct child_process; +struct repository; +struct json_writer; + +/* + * Function prototypes for a TRACE2 "target" vtable. + */ + +typedef int(tr2_tgt_init_t)(void); +typedef void(tr2_tgt_term_t)(void); + +typedef void(tr2_tgt_evt_version_fl_t)(const char *file, int line); + +typedef void(tr2_tgt_evt_start_fl_t)(const char *file, int line, + const char **argv); +typedef void(tr2_tgt_evt_exit_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, int code); +typedef void(tr2_tgt_evt_signal_t)(uint64_t us_elapsed_absolute, int signo); +typedef void(tr2_tgt_evt_atexit_t)(uint64_t us_elapsed_absolute, int code); + +typedef void(tr2_tgt_evt_error_va_fl_t)(const char *file, int line, + const char *fmt, va_list ap); + +typedef void(tr2_tgt_evt_command_path_fl_t)(const char *file, int line, + const char *command_path); +typedef void(tr2_tgt_evt_command_name_fl_t)(const char *file, int line, + const char *name, + const char *hierarchy); +typedef void(tr2_tgt_evt_command_mode_fl_t)(const char *file, int line, + const char *mode); + +typedef void(tr2_tgt_evt_alias_fl_t)(const char *file, int line, + const char *alias, const char **argv); + +typedef void(tr2_tgt_evt_child_start_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, + const struct child_process *cmd); +typedef void(tr2_tgt_evt_child_exit_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, int cid, + int pid, int code, + uint64_t us_elapsed_child); + +typedef void(tr2_tgt_evt_thread_start_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute); +typedef void(tr2_tgt_evt_thread_exit_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, + uint64_t us_elapsed_thread); + +typedef void(tr2_tgt_evt_exec_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, int exec_id, + const char *exe, const char **argv); +typedef void(tr2_tgt_evt_exec_result_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, + int exec_id, int code); + +typedef void(tr2_tgt_evt_param_fl_t)(const char *file, int line, + const char *param, const char *value); + +typedef void(tr2_tgt_evt_repo_fl_t)(const char *file, int line, + const struct repository *repo); + +typedef void(tr2_tgt_evt_region_enter_printf_va_fl_t)( + const char *file, int line, uint64_t us_elapsed_absolute, + const char *category, const char *label, const struct repository *repo, + const char *fmt, va_list ap); +typedef void(tr2_tgt_evt_region_leave_printf_va_fl_t)( + const char *file, int line, uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, const char *category, const char *label, + const struct repository *repo, const char *fmt, va_list ap); + +typedef void(tr2_tgt_evt_data_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, + const char *category, + const struct repository *repo, + const char *key, const char *value); +typedef void(tr2_tgt_evt_data_json_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, + const char *category, + const struct repository *repo, + const char *key, + const struct json_writer *value); + +typedef void(tr2_tgt_evt_printf_va_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, + const char *fmt, va_list ap); + +/* + * "vtable" for a TRACE2 target. Use NULL if a target does not want + * to emit that message. + */ +/* clang-format off */ +struct tr2_tgt { + struct tr2_dst *pdst; + + tr2_tgt_init_t *pfn_init; + tr2_tgt_term_t *pfn_term; + + tr2_tgt_evt_version_fl_t *pfn_version_fl; + tr2_tgt_evt_start_fl_t *pfn_start_fl; + tr2_tgt_evt_exit_fl_t *pfn_exit_fl; + tr2_tgt_evt_signal_t *pfn_signal; + tr2_tgt_evt_atexit_t *pfn_atexit; + tr2_tgt_evt_error_va_fl_t *pfn_error_va_fl; + tr2_tgt_evt_command_path_fl_t *pfn_command_path_fl; + tr2_tgt_evt_command_name_fl_t *pfn_command_name_fl; + tr2_tgt_evt_command_mode_fl_t *pfn_command_mode_fl; + tr2_tgt_evt_alias_fl_t *pfn_alias_fl; + tr2_tgt_evt_child_start_fl_t *pfn_child_start_fl; + tr2_tgt_evt_child_exit_fl_t *pfn_child_exit_fl; + tr2_tgt_evt_thread_start_fl_t *pfn_thread_start_fl; + tr2_tgt_evt_thread_exit_fl_t *pfn_thread_exit_fl; + tr2_tgt_evt_exec_fl_t *pfn_exec_fl; + tr2_tgt_evt_exec_result_fl_t *pfn_exec_result_fl; + tr2_tgt_evt_param_fl_t *pfn_param_fl; + tr2_tgt_evt_repo_fl_t *pfn_repo_fl; + tr2_tgt_evt_region_enter_printf_va_fl_t *pfn_region_enter_printf_va_fl; + tr2_tgt_evt_region_leave_printf_va_fl_t *pfn_region_leave_printf_va_fl; + tr2_tgt_evt_data_fl_t *pfn_data_fl; + tr2_tgt_evt_data_json_fl_t *pfn_data_json_fl; + tr2_tgt_evt_printf_va_fl_t *pfn_printf_va_fl; +}; +/* clang-format on */ + +extern struct tr2_tgt tr2_tgt_event; +extern struct tr2_tgt tr2_tgt_normal; +extern struct tr2_tgt tr2_tgt_perf; + +#endif /* TR2_TGT_H */ diff --git a/trace2/tr2_tgt_event.c b/trace2/tr2_tgt_event.c new file mode 100644 index 0000000..107cb53 --- /dev/null +++ b/trace2/tr2_tgt_event.c @@ -0,0 +1,588 @@ +#include "cache.h" +#include "config.h" +#include "json-writer.h" +#include "run-command.h" +#include "version.h" +#include "trace2/tr2_dst.h" +#include "trace2/tr2_tbuf.h" +#include "trace2/tr2_sid.h" +#include "trace2/tr2_tgt.h" +#include "trace2/tr2_tls.h" + +static struct tr2_dst tr2dst_event = { "GIT_TR2_EVENT", 0, 0, 0 }; + +/* + * The version number of the JSON data generated by the EVENT target + * in this source file. Update this if you make a significant change + * to the JSON fields or message structure. You probably do not need + * to update this if you just add another call to one of the existing + * TRACE2 API methods. + */ +#define TR2_EVENT_VERSION "1" + +/* + * Region nesting limit for messages written to the event target. + * + * The "region_enter" and "region_leave" messages (especially recursive + * messages such as those produced while diving the worktree or index) + * are primarily intended for the performance target during debugging. + * + * Some of the outer-most messages, however, may be of interest to the + * event target. Set this environment variable to a larger integer for + * more detail in the event target. + */ +#define TR2_ENVVAR_EVENT_NESTING "GIT_TR2_EVENT_NESTING" +static int tr2env_event_nesting_wanted = 2; + +/* + * Set this environment variable to true to omit the <time>, <file>, and + * <line> fields from most events. + */ +#define TR2_ENVVAR_EVENT_BRIEF "GIT_TR2_EVENT_BRIEF" +static int tr2env_event_brief; + +static int fn_init(void) +{ + int want = tr2_dst_trace_want(&tr2dst_event); + int want_nesting; + int want_brief; + char *nesting; + char *brief; + + if (!want) + return want; + + nesting = getenv(TR2_ENVVAR_EVENT_NESTING); + if (nesting && ((want_nesting = atoi(nesting)) > 0)) + tr2env_event_nesting_wanted = want_nesting; + + brief = getenv(TR2_ENVVAR_EVENT_BRIEF); + if (brief && ((want_brief = atoi(brief)) > 0)) + tr2env_event_brief = want_brief; + + return want; +} + +static void fn_term(void) +{ + tr2_dst_trace_disable(&tr2dst_event); +} + +/* + * Append common key-value pairs to the currently open JSON object. + * "event:"<event_name>" + * "sid":"<sid>" + * "thread":"<thread_name>" + * "time":"<time>" + * "file":"<filename>" + * "line":<line_number> + * "repo":<repo_id> + */ +static void event_fmt_prepare(const char *event_name, const char *file, + int line, const struct repository *repo, + struct json_writer *jw) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + struct tr2_tbuf tb_now; + + jw_object_string(jw, "event", event_name); + jw_object_string(jw, "sid", tr2_sid_get()); + jw_object_string(jw, "thread", ctx->thread_name.buf); + + /* + * In brief mode, only emit <time> on these 2 event types. + */ + if (!tr2env_event_brief || !strcmp(event_name, "version") || + !strcmp(event_name, "atexit")) { + tr2_tbuf_utc_time(&tb_now); + jw_object_string(jw, "time", tb_now.buf); + } + + if (!tr2env_event_brief && file && *file) { + jw_object_string(jw, "file", file); + jw_object_intmax(jw, "line", line); + } + + if (repo) + jw_object_intmax(jw, "repo", repo->trace2_repo_id); +} + +static void fn_version_fl(const char *file, int line) +{ + const char *event_name = "version"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_string(&jw, "evt", TR2_EVENT_VERSION); + jw_object_string(&jw, "exe", git_version_string); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_start_fl(const char *file, int line, const char **argv) +{ + const char *event_name = "start"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_inline_begin_array(&jw, "argv"); + jw_array_argv(&jw, argv); + jw_end(&jw); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_exit_fl(const char *file, int line, uint64_t us_elapsed_absolute, + int code) +{ + const char *event_name = "exit"; + struct json_writer jw = JSON_WRITER_INIT; + double t_abs = (double)us_elapsed_absolute / 1000000.0; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_double(&jw, "t_abs", 6, t_abs); + jw_object_intmax(&jw, "code", code); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_signal(uint64_t us_elapsed_absolute, int signo) +{ + const char *event_name = "signal"; + struct json_writer jw = JSON_WRITER_INIT; + double t_abs = (double)us_elapsed_absolute / 1000000.0; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, __FILE__, __LINE__, NULL, &jw); + jw_object_double(&jw, "t_abs", 6, t_abs); + jw_object_intmax(&jw, "signo", signo); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_atexit(uint64_t us_elapsed_absolute, int code) +{ + const char *event_name = "atexit"; + struct json_writer jw = JSON_WRITER_INIT; + double t_abs = (double)us_elapsed_absolute / 1000000.0; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, __FILE__, __LINE__, NULL, &jw); + jw_object_double(&jw, "t_abs", 6, t_abs); + jw_object_intmax(&jw, "code", code); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void maybe_add_string_va(struct json_writer *jw, const char *field_name, + const char *fmt, va_list ap) +{ + if (fmt && *fmt && ap) { + va_list copy_ap; + struct strbuf buf = STRBUF_INIT; + + va_copy(copy_ap, ap); + strbuf_vaddf(&buf, fmt, copy_ap); + va_end(copy_ap); + + jw_object_string(jw, field_name, buf.buf); + strbuf_release(&buf); + return; + } + + if (fmt && *fmt) { + jw_object_string(jw, field_name, fmt); + return; + } +} + +static void fn_error_va_fl(const char *file, int line, const char *fmt, + va_list ap) +{ + const char *event_name = "error"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + maybe_add_string_va(&jw, "msg", fmt, ap); + /* + * Also emit the format string as a field in case + * post-processors want to aggregate common error + * messages by type without argument fields (such + * as pathnames or branch names) cluttering it up. + */ + if (fmt && *fmt) + jw_object_string(&jw, "fmt", fmt); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_command_path_fl(const char *file, int line, const char *pathname) +{ + const char *event_name = "cmd_path"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_string(&jw, "path", pathname); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_command_name_fl(const char *file, int line, const char *name, + const char *hierarchy) +{ + const char *event_name = "cmd_name"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_string(&jw, "name", name); + if (hierarchy && *hierarchy) + jw_object_string(&jw, "hierarchy", hierarchy); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_command_mode_fl(const char *file, int line, const char *mode) +{ + const char *event_name = "cmd_mode"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_string(&jw, "name", mode); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_alias_fl(const char *file, int line, const char *alias, + const char **argv) +{ + const char *event_name = "alias"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_string(&jw, "alias", alias); + jw_object_inline_begin_array(&jw, "argv"); + jw_array_argv(&jw, argv); + jw_end(&jw); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_child_start_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + const struct child_process *cmd) +{ + const char *event_name = "child_start"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_intmax(&jw, "child_id", cmd->trace2_child_id); + if (cmd->trace2_hook_name) { + jw_object_string(&jw, "child_class", "hook"); + jw_object_string(&jw, "hook_name", cmd->trace2_hook_name); + } else { + const char *child_class = + cmd->trace2_child_class ? cmd->trace2_child_class : "?"; + jw_object_string(&jw, "child_class", child_class); + } + if (cmd->dir) + jw_object_string(&jw, "cd", cmd->dir); + jw_object_bool(&jw, "use_shell", cmd->use_shell); + jw_object_inline_begin_array(&jw, "argv"); + if (cmd->git_cmd) + jw_array_string(&jw, "git"); + jw_array_argv(&jw, cmd->argv); + jw_end(&jw); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_child_exit_fl(const char *file, int line, + uint64_t us_elapsed_absolute, int cid, int pid, + int code, uint64_t us_elapsed_child) +{ + const char *event_name = "child_exit"; + struct json_writer jw = JSON_WRITER_INIT; + double t_rel = (double)us_elapsed_child / 1000000.0; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_intmax(&jw, "child_id", cid); + jw_object_intmax(&jw, "pid", pid); + jw_object_intmax(&jw, "code", code); + jw_object_double(&jw, "t_rel", 6, t_rel); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + + jw_release(&jw); +} + +static void fn_thread_start_fl(const char *file, int line, + uint64_t us_elapsed_absolute) +{ + const char *event_name = "thread_start"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_thread_exit_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + uint64_t us_elapsed_thread) +{ + const char *event_name = "thread_exit"; + struct json_writer jw = JSON_WRITER_INIT; + double t_rel = (double)us_elapsed_thread / 1000000.0; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_double(&jw, "t_rel", 6, t_rel); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_exec_fl(const char *file, int line, uint64_t us_elapsed_absolute, + int exec_id, const char *exe, const char **argv) +{ + const char *event_name = "exec"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_intmax(&jw, "exec_id", exec_id); + if (exe) + jw_object_string(&jw, "exe", exe); + jw_object_inline_begin_array(&jw, "argv"); + jw_array_argv(&jw, argv); + jw_end(&jw); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_exec_result_fl(const char *file, int line, + uint64_t us_elapsed_absolute, int exec_id, + int code) +{ + const char *event_name = "exec_result"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_intmax(&jw, "exec_id", exec_id); + jw_object_intmax(&jw, "code", code); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_param_fl(const char *file, int line, const char *param, + const char *value) +{ + const char *event_name = "def_param"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_string(&jw, "param", param); + jw_object_string(&jw, "value", value); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_repo_fl(const char *file, int line, + const struct repository *repo) +{ + const char *event_name = "def_repo"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, repo, &jw); + jw_object_string(&jw, "worktree", repo->worktree); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_region_enter_printf_va_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + const char *category, + const char *label, + const struct repository *repo, + const char *fmt, va_list ap) +{ + const char *event_name = "region_enter"; + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + if (ctx->nr_open_regions <= tr2env_event_nesting_wanted) { + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, repo, &jw); + jw_object_intmax(&jw, "nesting", ctx->nr_open_regions); + if (category) + jw_object_string(&jw, "category", category); + if (label) + jw_object_string(&jw, "label", label); + maybe_add_string_va(&jw, "msg", fmt, ap); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); + } +} + +static void fn_region_leave_printf_va_fl( + const char *file, int line, uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, const char *category, const char *label, + const struct repository *repo, const char *fmt, va_list ap) +{ + const char *event_name = "region_leave"; + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + if (ctx->nr_open_regions <= tr2env_event_nesting_wanted) { + struct json_writer jw = JSON_WRITER_INIT; + double t_rel = (double)us_elapsed_region / 1000000.0; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, repo, &jw); + jw_object_double(&jw, "t_rel", 6, t_rel); + jw_object_intmax(&jw, "nesting", ctx->nr_open_regions); + if (category) + jw_object_string(&jw, "category", category); + if (label) + jw_object_string(&jw, "label", label); + maybe_add_string_va(&jw, "msg", fmt, ap); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); + } +} + +static void fn_data_fl(const char *file, int line, uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, const char *category, + const struct repository *repo, const char *key, + const char *value) +{ + const char *event_name = "data"; + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + if (ctx->nr_open_regions <= tr2env_event_nesting_wanted) { + struct json_writer jw = JSON_WRITER_INIT; + double t_abs = (double)us_elapsed_absolute / 1000000.0; + double t_rel = (double)us_elapsed_region / 1000000.0; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, repo, &jw); + jw_object_double(&jw, "t_abs", 6, t_abs); + jw_object_double(&jw, "t_rel", 6, t_rel); + jw_object_intmax(&jw, "nesting", ctx->nr_open_regions); + jw_object_string(&jw, "category", category); + jw_object_string(&jw, "key", key); + jw_object_string(&jw, "value", value); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); + } +} + +static void fn_data_json_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, const char *category, + const struct repository *repo, const char *key, + const struct json_writer *value) +{ + const char *event_name = "data_json"; + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + if (ctx->nr_open_regions <= tr2env_event_nesting_wanted) { + struct json_writer jw = JSON_WRITER_INIT; + double t_abs = (double)us_elapsed_absolute / 1000000.0; + double t_rel = (double)us_elapsed_region / 1000000.0; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, repo, &jw); + jw_object_double(&jw, "t_abs", 6, t_abs); + jw_object_double(&jw, "t_rel", 6, t_rel); + jw_object_intmax(&jw, "nesting", ctx->nr_open_regions); + jw_object_string(&jw, "category", category); + jw_object_string(&jw, "key", key); + jw_object_sub_jw(&jw, "value", value); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); + } +} + +struct tr2_tgt tr2_tgt_event = { + &tr2dst_event, + + fn_init, + fn_term, + + fn_version_fl, + fn_start_fl, + fn_exit_fl, + fn_signal, + fn_atexit, + fn_error_va_fl, + fn_command_path_fl, + fn_command_name_fl, + fn_command_mode_fl, + fn_alias_fl, + fn_child_start_fl, + fn_child_exit_fl, + fn_thread_start_fl, + fn_thread_exit_fl, + fn_exec_fl, + fn_exec_result_fl, + fn_param_fl, + fn_repo_fl, + fn_region_enter_printf_va_fl, + fn_region_leave_printf_va_fl, + fn_data_fl, + fn_data_json_fl, + NULL, /* printf */ +}; diff --git a/trace2/tr2_tgt_normal.c b/trace2/tr2_tgt_normal.c new file mode 100644 index 0000000..547183d --- /dev/null +++ b/trace2/tr2_tgt_normal.c @@ -0,0 +1,323 @@ +#include "cache.h" +#include "config.h" +#include "run-command.h" +#include "quote.h" +#include "version.h" +#include "trace2/tr2_dst.h" +#include "trace2/tr2_tbuf.h" +#include "trace2/tr2_tgt.h" +#include "trace2/tr2_tls.h" + +static struct tr2_dst tr2dst_normal = { "GIT_TR2", 0, 0, 0 }; + +/* + * Set this environment variable to true to omit the "<time> <file>:<line>" + * fields from each line written to the builtin normal target. + * + * Unit tests may want to use this to help with testing. + */ +#define TR2_ENVVAR_NORMAL_BRIEF "GIT_TR2_BRIEF" +static int tr2env_normal_brief; + +#define TR2FMT_NORMAL_FL_WIDTH (50) + +static int fn_init(void) +{ + int want = tr2_dst_trace_want(&tr2dst_normal); + int want_brief; + char *brief; + + if (!want) + return want; + + brief = getenv(TR2_ENVVAR_NORMAL_BRIEF); + if (brief && *brief && + ((want_brief = git_parse_maybe_bool(brief)) != -1)) + tr2env_normal_brief = want_brief; + + return want; +} + +static void fn_term(void) +{ + tr2_dst_trace_disable(&tr2dst_normal); +} + +static void normal_fmt_prepare(const char *file, int line, struct strbuf *buf) +{ + strbuf_setlen(buf, 0); + + if (!tr2env_normal_brief) { + struct tr2_tbuf tb_now; + + tr2_tbuf_local_time(&tb_now); + strbuf_addstr(buf, tb_now.buf); + strbuf_addch(buf, ' '); + + if (file && *file) + strbuf_addf(buf, "%s:%d ", file, line); + while (buf->len < TR2FMT_NORMAL_FL_WIDTH) + strbuf_addch(buf, ' '); + } +} + +static void normal_io_write_fl(const char *file, int line, + const struct strbuf *buf_payload) +{ + struct strbuf buf_line = STRBUF_INIT; + + normal_fmt_prepare(file, line, &buf_line); + strbuf_addbuf(&buf_line, buf_payload); + tr2_dst_write_line(&tr2dst_normal, &buf_line); + strbuf_release(&buf_line); +} + +static void fn_version_fl(const char *file, int line) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "version %s", git_version_string); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_start_fl(const char *file, int line, const char **argv) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addstr(&buf_payload, "start "); + sq_quote_argv_pretty(&buf_payload, argv); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_exit_fl(const char *file, int line, uint64_t us_elapsed_absolute, + int code) +{ + struct strbuf buf_payload = STRBUF_INIT; + double elapsed = (double)us_elapsed_absolute / 1000000.0; + + strbuf_addf(&buf_payload, "exit elapsed:%.6f code:%d", elapsed, code); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_signal(uint64_t us_elapsed_absolute, int signo) +{ + struct strbuf buf_payload = STRBUF_INIT; + double elapsed = (double)us_elapsed_absolute / 1000000.0; + + strbuf_addf(&buf_payload, "signal elapsed:%.6f code:%d", elapsed, + signo); + normal_io_write_fl(__FILE__, __LINE__, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_atexit(uint64_t us_elapsed_absolute, int code) +{ + struct strbuf buf_payload = STRBUF_INIT; + double elapsed = (double)us_elapsed_absolute / 1000000.0; + + strbuf_addf(&buf_payload, "atexit elapsed:%.6f code:%d", elapsed, code); + normal_io_write_fl(__FILE__, __LINE__, &buf_payload); + strbuf_release(&buf_payload); +} + +static void maybe_append_string_va(struct strbuf *buf, const char *fmt, + va_list ap) +{ + if (fmt && *fmt && ap) { + va_list copy_ap; + + va_copy(copy_ap, ap); + strbuf_vaddf(buf, fmt, copy_ap); + va_end(copy_ap); + return; + } + + if (fmt && *fmt) { + strbuf_addstr(buf, fmt); + return; + } +} + +static void fn_error_va_fl(const char *file, int line, const char *fmt, + va_list ap) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addstr(&buf_payload, "error "); + maybe_append_string_va(&buf_payload, fmt, ap); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_command_path_fl(const char *file, int line, const char *pathname) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "cmd_path %s", pathname); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_command_name_fl(const char *file, int line, const char *name, + const char *hierarchy) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "cmd_name %s", name); + if (hierarchy && *hierarchy) + strbuf_addf(&buf_payload, " (%s)", hierarchy); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_command_mode_fl(const char *file, int line, const char *mode) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "cmd_mode %s", mode); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_alias_fl(const char *file, int line, const char *alias, + const char **argv) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "alias %s ->", alias); + sq_quote_argv_pretty(&buf_payload, argv); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_child_start_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + const struct child_process *cmd) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "child_start[%d] ", cmd->trace2_child_id); + + if (cmd->dir) { + strbuf_addstr(&buf_payload, " cd"); + sq_quote_buf_pretty(&buf_payload, cmd->dir); + strbuf_addstr(&buf_payload, "; "); + } + + /* + * TODO if (cmd->env) { Consider dumping changes to environment. } + * See trace_add_env() in run-command.c as used by original trace.c + */ + + if (cmd->git_cmd) + strbuf_addstr(&buf_payload, "git"); + sq_quote_argv_pretty(&buf_payload, cmd->argv); + + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_child_exit_fl(const char *file, int line, + uint64_t us_elapsed_absolute, int cid, int pid, + int code, uint64_t us_elapsed_child) +{ + struct strbuf buf_payload = STRBUF_INIT; + double elapsed = (double)us_elapsed_child / 1000000.0; + + strbuf_addf(&buf_payload, "child_exit[%d] pid:%d code:%d elapsed:%.6f", + cid, pid, code, elapsed); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_exec_fl(const char *file, int line, uint64_t us_elapsed_absolute, + int exec_id, const char *exe, const char **argv) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "exec[%d] ", exec_id); + if (exe) + strbuf_addstr(&buf_payload, exe); + sq_quote_argv_pretty(&buf_payload, argv); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_exec_result_fl(const char *file, int line, + uint64_t us_elapsed_absolute, int exec_id, + int code) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "exec_result[%d] code:%d", exec_id, code); + if (code > 0) + strbuf_addf(&buf_payload, " err:%s", strerror(code)); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_param_fl(const char *file, int line, const char *param, + const char *value) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "def_param %s=%s", param, value); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_repo_fl(const char *file, int line, + const struct repository *repo) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addstr(&buf_payload, "worktree "); + sq_quote_buf_pretty(&buf_payload, repo->worktree); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_printf_va_fl(const char *file, int line, + uint64_t us_elapsed_absolute, const char *fmt, + va_list ap) +{ + struct strbuf buf_payload = STRBUF_INIT; + + maybe_append_string_va(&buf_payload, fmt, ap); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +struct tr2_tgt tr2_tgt_normal = { + &tr2dst_normal, + + fn_init, + fn_term, + + fn_version_fl, + fn_start_fl, + fn_exit_fl, + fn_signal, + fn_atexit, + fn_error_va_fl, + fn_command_path_fl, + fn_command_name_fl, + fn_command_mode_fl, + fn_alias_fl, + fn_child_start_fl, + fn_child_exit_fl, + NULL, /* thread_start */ + NULL, /* thread_exit */ + fn_exec_fl, + fn_exec_result_fl, + fn_param_fl, + fn_repo_fl, + NULL, /* region_enter */ + NULL, /* region_leave */ + NULL, /* data */ + NULL, /* data_json */ + fn_printf_va_fl, +}; diff --git a/trace2/tr2_tgt_perf.c b/trace2/tr2_tgt_perf.c new file mode 100644 index 0000000..f0746fc --- /dev/null +++ b/trace2/tr2_tgt_perf.c @@ -0,0 +1,534 @@ +#include "cache.h" +#include "config.h" +#include "run-command.h" +#include "quote.h" +#include "version.h" +#include "json-writer.h" +#include "trace2/tr2_dst.h" +#include "trace2/tr2_sid.h" +#include "trace2/tr2_tbuf.h" +#include "trace2/tr2_tgt.h" +#include "trace2/tr2_tls.h" + +static struct tr2_dst tr2dst_perf = { "GIT_TR2_PERF", 0, 0, 0 }; + +/* + * Set this environment variable to true to omit the "<time> <file>:<line>" + * fields from each line written to the builtin performance target. + * + * Unit tests may want to use this to help with testing. + */ +#define TR2_ENVVAR_PERF_BRIEF "GIT_TR2_PERF_BRIEF" +static int tr2env_perf_brief; + +#define TR2FMT_PERF_FL_WIDTH (50) +#define TR2FMT_PERF_MAX_EVENT_NAME (12) +#define TR2FMT_PERF_REPO_WIDTH (4) +#define TR2FMT_PERF_CATEGORY_WIDTH (10) + +#define TR2_DOTS_BUFFER_SIZE (100) +#define TR2_INDENT (2) +#define TR2_INDENT_LENGTH(ctx) (((ctx)->nr_open_regions - 1) * TR2_INDENT) + +static struct strbuf dots = STRBUF_INIT; + +static int fn_init(void) +{ + int want = tr2_dst_trace_want(&tr2dst_perf); + int want_brief; + char *brief; + + if (!want) + return want; + + strbuf_addchars(&dots, '.', TR2_DOTS_BUFFER_SIZE); + + brief = getenv(TR2_ENVVAR_PERF_BRIEF); + if (brief && *brief && + ((want_brief = git_parse_maybe_bool(brief)) != -1)) + tr2env_perf_brief = want_brief; + + return want; +} + +static void fn_term(void) +{ + tr2_dst_trace_disable(&tr2dst_perf); + + strbuf_release(&dots); +} + +/* + * Format trace line prefix in human-readable classic format for + * the performance target: + * "[<time> [<file>:<line>] <bar>] <nr_parents> <bar> + * <thread_name> <bar> <event_name> <bar> [<repo>] <bar> + * [<elapsed_absolute>] [<elapsed_relative>] <bar> + * [<category>] <bar> [<dots>] " + */ +static void perf_fmt_prepare(const char *event_name, + struct tr2tls_thread_ctx *ctx, const char *file, + int line, const struct repository *repo, + uint64_t *p_us_elapsed_absolute, + uint64_t *p_us_elapsed_relative, + const char *category, struct strbuf *buf) +{ + int len; + + strbuf_setlen(buf, 0); + + if (!tr2env_perf_brief) { + struct tr2_tbuf tb_now; + + tr2_tbuf_local_time(&tb_now); + strbuf_addstr(buf, tb_now.buf); + strbuf_addch(buf, ' '); + + if (file && *file) + strbuf_addf(buf, "%s:%d ", file, line); + while (buf->len < TR2FMT_PERF_FL_WIDTH) + strbuf_addch(buf, ' '); + + strbuf_addstr(buf, "| "); + } + + strbuf_addf(buf, "d%d | ", tr2_sid_depth()); + strbuf_addf(buf, "%-*s | %-*s | ", TR2_MAX_THREAD_NAME, + ctx->thread_name.buf, TR2FMT_PERF_MAX_EVENT_NAME, + event_name); + + len = buf->len + TR2FMT_PERF_REPO_WIDTH; + if (repo) + strbuf_addf(buf, "r%d ", repo->trace2_repo_id); + while (buf->len < len) + strbuf_addch(buf, ' '); + strbuf_addstr(buf, "| "); + + if (p_us_elapsed_absolute) + strbuf_addf(buf, "%9.6f | ", + ((double)(*p_us_elapsed_absolute)) / 1000000.0); + else + strbuf_addf(buf, "%9s | ", " "); + + if (p_us_elapsed_relative) + strbuf_addf(buf, "%9.6f | ", + ((double)(*p_us_elapsed_relative)) / 1000000.0); + else + strbuf_addf(buf, "%9s | ", " "); + + strbuf_addf(buf, "%-*s | ", TR2FMT_PERF_CATEGORY_WIDTH, + (category ? category : "")); + + if (ctx->nr_open_regions > 0) { + int len_indent = TR2_INDENT_LENGTH(ctx); + while (len_indent > dots.len) { + strbuf_addbuf(buf, &dots); + len_indent -= dots.len; + } + strbuf_addf(buf, "%.*s", len_indent, dots.buf); + } +} + +static void perf_io_write_fl(const char *file, int line, const char *event_name, + const struct repository *repo, + uint64_t *p_us_elapsed_absolute, + uint64_t *p_us_elapsed_relative, + const char *category, + const struct strbuf *buf_payload) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + struct strbuf buf_line = STRBUF_INIT; + + perf_fmt_prepare(event_name, ctx, file, line, repo, + p_us_elapsed_absolute, p_us_elapsed_relative, category, + &buf_line); + strbuf_addbuf(&buf_line, buf_payload); + tr2_dst_write_line(&tr2dst_perf, &buf_line); + strbuf_release(&buf_line); +} + +static void fn_version_fl(const char *file, int line) +{ + const char *event_name = "version"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addstr(&buf_payload, git_version_string); + + perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL, + &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_start_fl(const char *file, int line, const char **argv) +{ + const char *event_name = "start"; + struct strbuf buf_payload = STRBUF_INIT; + + sq_quote_argv_pretty(&buf_payload, argv); + + perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL, + &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_exit_fl(const char *file, int line, uint64_t us_elapsed_absolute, + int code) +{ + const char *event_name = "exit"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "code:%d", code); + + perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute, + NULL, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_signal(uint64_t us_elapsed_absolute, int signo) +{ + const char *event_name = "signal"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "signo:%d", signo); + + perf_io_write_fl(__FILE__, __LINE__, event_name, NULL, + &us_elapsed_absolute, NULL, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_atexit(uint64_t us_elapsed_absolute, int code) +{ + const char *event_name = "atexit"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "code:%d", code); + + perf_io_write_fl(__FILE__, __LINE__, event_name, NULL, + &us_elapsed_absolute, NULL, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void maybe_append_string_va(struct strbuf *buf, const char *fmt, + va_list ap) +{ + if (fmt && *fmt && ap) { + va_list copy_ap; + + va_copy(copy_ap, ap); + strbuf_vaddf(buf, fmt, copy_ap); + va_end(copy_ap); + return; + } + + if (fmt && *fmt) { + strbuf_addstr(buf, fmt); + return; + } +} + +static void fn_error_va_fl(const char *file, int line, const char *fmt, + va_list ap) +{ + const char *event_name = "error"; + struct strbuf buf_payload = STRBUF_INIT; + + maybe_append_string_va(&buf_payload, fmt, ap); + + perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL, + &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_command_path_fl(const char *file, int line, const char *pathname) +{ + const char *event_name = "cmd_path"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addstr(&buf_payload, pathname); + + perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL, + &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_command_name_fl(const char *file, int line, const char *name, + const char *hierarchy) +{ + const char *event_name = "cmd_name"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addstr(&buf_payload, name); + if (hierarchy && *hierarchy) + strbuf_addf(&buf_payload, " (%s)", hierarchy); + + perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL, + &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_command_mode_fl(const char *file, int line, const char *mode) +{ + const char *event_name = "cmd_mode"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addstr(&buf_payload, mode); + + perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL, + &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_alias_fl(const char *file, int line, const char *alias, + const char **argv) +{ + const char *event_name = "alias"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "alias:%s argv:", alias); + sq_quote_argv_pretty(&buf_payload, argv); + + perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL, + &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_child_start_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + const struct child_process *cmd) +{ + const char *event_name = "child_start"; + struct strbuf buf_payload = STRBUF_INIT; + + if (cmd->trace2_hook_name) { + strbuf_addf(&buf_payload, "[ch%d] class:hook hook:%s", + cmd->trace2_child_id, cmd->trace2_hook_name); + } else { + const char *child_class = + cmd->trace2_child_class ? cmd->trace2_child_class : "?"; + strbuf_addf(&buf_payload, "[ch%d] class:%s", + cmd->trace2_child_id, child_class); + } + + if (cmd->dir) { + strbuf_addstr(&buf_payload, " cd:"); + sq_quote_buf_pretty(&buf_payload, cmd->dir); + } + + strbuf_addstr(&buf_payload, " argv:"); + if (cmd->git_cmd) + strbuf_addstr(&buf_payload, " git"); + sq_quote_argv_pretty(&buf_payload, cmd->argv); + + perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute, + NULL, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_child_exit_fl(const char *file, int line, + uint64_t us_elapsed_absolute, int cid, int pid, + int code, uint64_t us_elapsed_child) +{ + const char *event_name = "child_exit"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "[ch%d] pid:%d code:%d", cid, pid, code); + + perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute, + &us_elapsed_child, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_thread_start_fl(const char *file, int line, + uint64_t us_elapsed_absolute) +{ + const char *event_name = "thread_start"; + struct strbuf buf_payload = STRBUF_INIT; + + perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute, + NULL, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_thread_exit_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + uint64_t us_elapsed_thread) +{ + const char *event_name = "thread_exit"; + struct strbuf buf_payload = STRBUF_INIT; + + perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute, + &us_elapsed_thread, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_exec_fl(const char *file, int line, uint64_t us_elapsed_absolute, + int exec_id, const char *exe, const char **argv) +{ + const char *event_name = "exec"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "id:%d ", exec_id); + strbuf_addstr(&buf_payload, "argv:"); + if (exe) + strbuf_addf(&buf_payload, " %s", exe); + sq_quote_argv_pretty(&buf_payload, argv); + + perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute, + NULL, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_exec_result_fl(const char *file, int line, + uint64_t us_elapsed_absolute, int exec_id, + int code) +{ + const char *event_name = "exec_result"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "id:%d code:%d", exec_id, code); + if (code > 0) + strbuf_addf(&buf_payload, " err:%s", strerror(code)); + + perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute, + NULL, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_param_fl(const char *file, int line, const char *param, + const char *value) +{ + const char *event_name = "def_param"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "%s:%s", param, value); + + perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL, + &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_repo_fl(const char *file, int line, + const struct repository *repo) +{ + const char *event_name = "def_repo"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addstr(&buf_payload, "worktree:"); + sq_quote_buf_pretty(&buf_payload, repo->worktree); + + perf_io_write_fl(file, line, event_name, repo, NULL, NULL, NULL, + &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_region_enter_printf_va_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + const char *category, + const char *label, + const struct repository *repo, + const char *fmt, va_list ap) +{ + const char *event_name = "region_enter"; + struct strbuf buf_payload = STRBUF_INIT; + + if (label) + strbuf_addf(&buf_payload, "label:%s ", label); + maybe_append_string_va(&buf_payload, fmt, ap); + + perf_io_write_fl(file, line, event_name, repo, &us_elapsed_absolute, + NULL, category, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_region_leave_printf_va_fl( + const char *file, int line, uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, const char *category, const char *label, + const struct repository *repo, const char *fmt, va_list ap) +{ + const char *event_name = "region_leave"; + struct strbuf buf_payload = STRBUF_INIT; + + if (label) + strbuf_addf(&buf_payload, "label:%s ", label); + maybe_append_string_va(&buf_payload, fmt, ap); + + perf_io_write_fl(file, line, event_name, repo, &us_elapsed_absolute, + &us_elapsed_region, category, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_data_fl(const char *file, int line, uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, const char *category, + const struct repository *repo, const char *key, + const char *value) +{ + const char *event_name = "data"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "%s:%s", key, value); + + perf_io_write_fl(file, line, event_name, repo, &us_elapsed_absolute, + &us_elapsed_region, category, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_data_json_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, const char *category, + const struct repository *repo, const char *key, + const struct json_writer *value) +{ + const char *event_name = "data_json"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "%s:%s", key, value->json.buf); + + perf_io_write_fl(file, line, event_name, repo, &us_elapsed_absolute, + &us_elapsed_region, category, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_printf_va_fl(const char *file, int line, + uint64_t us_elapsed_absolute, const char *fmt, + va_list ap) +{ + const char *event_name = "printf"; + struct strbuf buf_payload = STRBUF_INIT; + + maybe_append_string_va(&buf_payload, fmt, ap); + + perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute, + NULL, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +struct tr2_tgt tr2_tgt_perf = { + &tr2dst_perf, + + fn_init, + fn_term, + + fn_version_fl, + fn_start_fl, + fn_exit_fl, + fn_signal, + fn_atexit, + fn_error_va_fl, + fn_command_path_fl, + fn_command_name_fl, + fn_command_mode_fl, + fn_alias_fl, + fn_child_start_fl, + fn_child_exit_fl, + fn_thread_start_fl, + fn_thread_exit_fl, + fn_exec_fl, + fn_exec_result_fl, + fn_param_fl, + fn_repo_fl, + fn_region_enter_printf_va_fl, + fn_region_leave_printf_va_fl, + fn_data_fl, + fn_data_json_fl, + fn_printf_va_fl, +}; diff --git a/trace2/tr2_tls.c b/trace2/tr2_tls.c new file mode 100644 index 0000000..8e65b03 --- /dev/null +++ b/trace2/tr2_tls.c @@ -0,0 +1,164 @@ +#include "cache.h" +#include "thread-utils.h" +#include "trace2/tr2_tls.h" + +/* + * Initialize size of the thread stack for nested regions. + * This is used to store nested region start times. Note that + * this stack is per-thread and not per-trace-key. + */ +#define TR2_REGION_NESTING_INITIAL_SIZE (100) + +static struct tr2tls_thread_ctx *tr2tls_thread_main; +static uint64_t tr2tls_us_start_main; + +static pthread_mutex_t tr2tls_mutex; +static pthread_key_t tr2tls_key; + +static int tr2_next_thread_id; /* modify under lock */ + +struct tr2tls_thread_ctx *tr2tls_create_self(const char *thread_name) +{ + uint64_t us_now = getnanotime() / 1000; + struct tr2tls_thread_ctx *ctx = xcalloc(1, sizeof(*ctx)); + + /* + * Implicitly "tr2tls_push_self()" to capture the thread's start + * time in array_us_start[0]. For the main thread this gives us the + * application run time. + */ + ctx->alloc = TR2_REGION_NESTING_INITIAL_SIZE; + ctx->array_us_start = (uint64_t *)xcalloc(ctx->alloc, sizeof(uint64_t)); + ctx->array_us_start[ctx->nr_open_regions++] = us_now; + + ctx->thread_id = tr2tls_locked_increment(&tr2_next_thread_id); + + strbuf_init(&ctx->thread_name, 0); + if (ctx->thread_id) + strbuf_addf(&ctx->thread_name, "th%02d:", ctx->thread_id); + strbuf_addstr(&ctx->thread_name, thread_name); + if (ctx->thread_name.len > TR2_MAX_THREAD_NAME) + strbuf_setlen(&ctx->thread_name, TR2_MAX_THREAD_NAME); + + pthread_setspecific(tr2tls_key, ctx); + + return ctx; +} + +struct tr2tls_thread_ctx *tr2tls_get_self(void) +{ + struct tr2tls_thread_ctx *ctx = pthread_getspecific(tr2tls_key); + + /* + * If the thread-proc did not call trace2_thread_start(), we won't + * have any TLS data associated with the current thread. Fix it + * here and silently continue. + */ + if (!ctx) + ctx = tr2tls_create_self("unknown"); + + return ctx; +} + +int tr2tls_is_main_thread(void) +{ + struct tr2tls_thread_ctx *ctx = pthread_getspecific(tr2tls_key); + + return ctx == tr2tls_thread_main; +} + +void tr2tls_unset_self(void) +{ + struct tr2tls_thread_ctx *ctx; + + ctx = tr2tls_get_self(); + + pthread_setspecific(tr2tls_key, NULL); + + free(ctx->array_us_start); + free(ctx); +} + +void tr2tls_push_self(uint64_t us_now) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + + ALLOC_GROW(ctx->array_us_start, ctx->nr_open_regions + 1, ctx->alloc); + ctx->array_us_start[ctx->nr_open_regions++] = us_now; +} + +void tr2tls_pop_self(void) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + + if (!ctx->nr_open_regions) + BUG("no open regions in thread '%s'", ctx->thread_name.buf); + + ctx->nr_open_regions--; +} + +void tr2tls_pop_unwind_self(void) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + + while (ctx->nr_open_regions > 1) + tr2tls_pop_self(); +} + +uint64_t tr2tls_region_elasped_self(uint64_t us) +{ + struct tr2tls_thread_ctx *ctx; + uint64_t us_start; + + ctx = tr2tls_get_self(); + if (!ctx->nr_open_regions) + return 0; + + us_start = ctx->array_us_start[ctx->nr_open_regions - 1]; + + return us - us_start; +} + +uint64_t tr2tls_absolute_elapsed(uint64_t us) +{ + if (!tr2tls_thread_main) + return 0; + + return us - tr2tls_us_start_main; +} + +void tr2tls_init(void) +{ + pthread_key_create(&tr2tls_key, NULL); + init_recursive_mutex(&tr2tls_mutex); + + tr2tls_thread_main = tr2tls_create_self("main"); + /* + * Keep a copy of the absolute start time of the main thread + * in a fixed variable since other threads need to access it. + * This also eliminates the need to lock accesses to the main + * thread's array (because of reallocs). + */ + tr2tls_us_start_main = tr2tls_thread_main->array_us_start[0]; +} + +void tr2tls_release(void) +{ + tr2tls_unset_self(); + tr2tls_thread_main = NULL; + + pthread_mutex_destroy(&tr2tls_mutex); + pthread_key_delete(tr2tls_key); +} + +int tr2tls_locked_increment(int *p) +{ + int current_value; + + pthread_mutex_lock(&tr2tls_mutex); + current_value = *p; + *p = current_value + 1; + pthread_mutex_unlock(&tr2tls_mutex); + + return current_value; +} diff --git a/trace2/tr2_tls.h b/trace2/tr2_tls.h new file mode 100644 index 0000000..bb80e3f --- /dev/null +++ b/trace2/tr2_tls.h @@ -0,0 +1,97 @@ +#ifndef TR2_TLS_H +#define TR2_TLS_H + +#include "strbuf.h" + +/* + * Arbitry limit for thread names for column alignment. + */ +#define TR2_MAX_THREAD_NAME (24) + +struct tr2tls_thread_ctx { + struct strbuf thread_name; + uint64_t *array_us_start; + int alloc; + int nr_open_regions; /* plays role of "nr" in ALLOC_GROW */ + int thread_id; +}; + +/* + * Create TLS data for the current thread. This gives us a place to + * put per-thread data, such as thread start time, function nesting + * and a per-thread label for our messages. + * + * We assume the first thread is "main". Other threads are given + * non-zero thread-ids to help distinguish messages from concurrent + * threads. + * + * Truncate the thread name if necessary to help with column alignment + * in printf-style messages. + * + * In this and all following functions the term "self" refers to the + * current thread. + */ +struct tr2tls_thread_ctx *tr2tls_create_self(const char *thread_name); + +/* + * Get our TLS data. + */ +struct tr2tls_thread_ctx *tr2tls_get_self(void); + +/* + * return true if the current thread is the main thread. + */ +int tr2tls_is_main_thread(void); + +/* + * Free our TLS data. + */ +void tr2tls_unset_self(void); + +/* + * Begin a new nested region and remember the start time. + */ +void tr2tls_push_self(uint64_t us_now); + +/* + * End the innermost nested region. + */ +void tr2tls_pop_self(void); + +/* + * Pop any extra (above the first) open regions on the current + * thread and discard. During a thread-exit, we should only + * have region[0] that was pushed in trace2_thread_start() if + * the thread exits normally. + */ +void tr2tls_pop_unwind_self(void); + +/* + * Compute the elapsed time since the innermost region in the + * current thread started and the given time (usually now). + */ +uint64_t tr2tls_region_elasped_self(uint64_t us); + +/* + * Compute the elapsed time since the main thread started + * and the given time (usually now). This is assumed to + * be the absolute run time of the process. + */ +uint64_t tr2tls_absolute_elapsed(uint64_t us); + +/* + * Initialize the tr2 TLS system. + */ +void tr2tls_init(void); + +/* + * Free all tr2 TLS resources. + */ +void tr2tls_release(void); + +/* + * Protected increment of an integer. + */ +int tr2tls_locked_increment(int *p); + +#endif /* TR2_TLS_H */ diff --git a/transport-helper.c b/transport-helper.c index 1f52c95..cec83bd 100644 --- a/transport-helper.c +++ b/transport-helper.c @@ -127,6 +127,8 @@ static struct child_process *get_helper(struct transport *transport) 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); diff --git a/transport.c b/transport.c index e078812..d0608df 100644 --- a/transport.c +++ b/transport.c @@ -1062,6 +1062,7 @@ static int run_pre_push_hook(struct transport *transport, proc.argv = argv; proc.in = -1; + proc.trace2_hook_name = "pre-push"; if (start_command(&proc)) { finish_command(&proc); @@ -22,17 +22,48 @@ void vreportf(const char *prefix, const char *err, va_list params) 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); } diff --git a/wt-status.c b/wt-status.c index 1f564b1..445a362 100644 --- a/wt-status.c +++ b/wt-status.c @@ -748,12 +748,23 @@ static int has_unmerged(struct wt_status *s) 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)) @@ -2291,6 +2302,13 @@ static void wt_porcelain_v2_print(struct wt_status *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); @@ -2309,6 +2327,8 @@ void wt_status_print(struct wt_status *s) wt_longstatus_print(s); break; } + + trace2_region_leave("status", "print", s->repo); } /** |