3 The Trace2 API can be used to print debug, performance, and telemetry
4 information to stderr or a file. The Trace2 feature is inactive unless
5 explicitly enabled by enabling one or more Trace2 Targets.
7 The Trace2 API is intended to replace the existing (Trace1)
8 printf-style tracing provided by the existing `GIT_TRACE` and
9 `GIT_TRACE_PERFORMANCE` facilities. During initial implementation,
10 Trace2 and Trace1 may operate in parallel.
12 The Trace2 API defines a set of high-level messages with known fields,
13 such as (`start`: `argv`) and (`exit`: {`exit-code`, `elapsed-time`}).
15 Trace2 instrumentation throughout the Git code base sends Trace2
16 messages to the enabled Trace2 Targets. Targets transform these
17 messages content into purpose-specific formats and write events to
18 their data streams. In this manner, the Trace2 API can drive
19 many different types of analysis.
21 Targets are defined using a VTable allowing easy extension to other
22 formats in the future. This might be used to define a binary format,
27 Trace2 defines the following set of Trace2 Targets.
28 Format details are given in a later section.
32 a simple printf format like GIT_TRACE.
35 $ export GIT_TR2=~/log.normal
37 git version 2.20.1.155.g426c96fcdb
42 12:28:42.620009 common-main.c:38 version 2.20.1.155.g426c96fcdb
43 12:28:42.620989 common-main.c:39 start git version
44 12:28:42.621101 git.c:432 cmd_name version (version)
45 12:28:42.621215 git.c:662 exit elapsed:0.001227 code:0
46 12:28:42.621250 trace2/tr2_tgt_normal.c:124 atexit elapsed:0.001265 code:0
49 `GIT_TR2_PERF` (PERF)::
51 a column-based format to replace GIT_TRACE_PERFORMANCE suitable for
52 development and testing, possibly to complement tools like gprof.
55 $ export GIT_TR2_PERF=~/log.perf
57 git version 2.20.1.155.g426c96fcdb
62 12:28:42.620675 common-main.c:38 | d0 | main | version | | | | | 2.20.1.155.g426c96fcdb
63 12:28:42.621001 common-main.c:39 | d0 | main | start | | | | | git version
64 12:28:42.621111 git.c:432 | d0 | main | cmd_name | | | | | version (version)
65 12:28:42.621225 git.c:662 | d0 | main | exit | | 0.001227 | | | code:0
66 12:28:42.621259 trace2/tr2_tgt_perf.c:211 | d0 | main | atexit | | 0.001265 | | | code:0
69 `GIT_TR2_EVENT` (EVENT)::
71 a JSON-based format of event data suitable for telemetry analysis.
74 $ export GIT_TR2_EVENT=~/log.event
76 git version 2.20.1.155.g426c96fcdb
81 {"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"}
82 {"event":"start","sid":"1547659722619736-11614","thread":"main","time":"2019-01-16 17:28:42.621027","file":"common-main.c","line":39,"argv":["git","version"]}
83 {"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"}
84 {"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}
85 {"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}
90 A Trace2 Target is enabled when the corresponding environment variable
91 (`GIT_TR2`, `GIT_TR2_PERF`, or `GIT_TR2_EVENT`) is set. The following
92 values are recognized.
102 Enables the target and writes stream to `STDERR`.
106 Enables the target and writes to the already opened file descriptor.
108 `<absolute-pathname>`::
110 Enables the target, opens and writes to the file in append mode.
112 If the target already exists and is a directory, the traces will be
113 written to files (one per process) underneath the given directory. They
114 will be named according to the last component of the SID (optionally
115 followed by a counter to avoid filename collisions).
117 `af_unix:[<socket_type>:]<absolute-pathname>`::
119 Enables the target, opens and writes to a Unix Domain Socket
120 (on platforms that support them).
122 Socket type can be either `stream` or `dgram`. If the socket type is
123 omitted, Git will try both.
127 All public Trace2 functions and macros are defined in `trace2.h` and
128 `trace2.c`. All public symbols are prefixed with `trace2_`.
130 There are no public Trace2 data structures.
132 The Trace2 code also defines a set of private functions and data types
133 in the `trace2/` directory. These symbols are prefixed with `tr2_`
134 and should only be used by functions in `trace2.c`.
136 == Conventions for Public Functions and Macros
138 The functions defined by the Trace2 API are declared and documented
139 in `trace2.h`. It defines the API functions and wrapper macros for
142 Some functions have a `_fl()` suffix to indicate that they take `file`
143 and `line-number` arguments.
145 Some functions have a `_va_fl()` suffix to indicate that they also
146 take a `va_list` argument.
148 Some functions have a `_printf_fl()` suffix to indicate that they also
149 take a varargs argument.
151 There are CPP wrapper macros and ifdefs to hide most of these details.
152 See `trace2.h` for more details. The following discussion will only
153 describe the simplified forms.
157 All Trace2 API functions send a messsage to all of the active
158 Trace2 Targets. This section describes the set of available
161 It helps to divide these functions into groups for discussion
164 === Basic Command Messages
166 These are concerned with the lifetime of the overall git process.
168 `void trace2_initialize()`::
170 Determines if any Trace2 Targets should be enabled and
171 initializes the Trace2 facility. This includes starting the
172 elapsed time clocks and thread local storage (TLS).
174 This function emits a "version" message containing the version of git
175 and the Trace2 protocol.
177 This function should be called from `main()` as early as possible in
178 the life of the process.
180 `int trace2_is_enabled()`::
182 Returns 1 if Trace2 is enabled (at least one target is
185 `void trace2_cmd_start(int argc, const char **argv)`::
187 Emits a "start" message containing the process command line
190 `int trace2_cmd_exit(int exit_code)`::
192 Emits an "exit" message containing the process exit-code and
195 Returns the exit-code.
197 `void trace2_cmd_error(const char *fmt, va_list ap)`::
199 Emits an "error" message containing a formatted error message.
201 `void trace2_cmd_path(const char *pathname)`::
203 Emits a "cmd_path" message with the full pathname of the
206 === Command Detail Messages
208 These are concerned with describing the specific Git command
209 after the command line, config, and environment are inspected.
211 `void trace2_cmd_name(const char *name)`::
213 Emits a "cmd_name" message with the canonical name of the
214 command, for example "status" or "checkout".
216 `void trace2_cmd_mode(const char *mode)`::
218 Emits a "cmd_mode" message with a qualifier name to further
219 describe the current git command.
221 This message is intended to be used with git commands having multiple
222 major modes. For example, a "checkout" command can checkout a new
223 branch or it can checkout a single file, so the checkout code could
224 emit a cmd_mode message of "branch" or "file".
226 `void trace2_cmd_alias(const char *alias, const char **argv_expansion)`::
228 Emits an "alias" message containing the alias used and the
231 `void trace2_def_param(const char *parameter, const char *value)`::
233 Emits a "def_param" message containing a key/value pair.
235 This message is intended to report some global aspect of the current
236 command, such as a configuration setting or command line switch that
237 significantly affects program performance or behavior, such as
238 `core.abbrev`, `status.showUntrackedFiles`, or `--no-ahead-behind`.
240 `void trace2_cmd_list_config()`::
242 Emits a "def_param" messages for "important" configuration
245 The environment variable `GIT_TR2_CONFIG_PARAMS` can be set to a
246 list of patterns of important configuration settings, for example:
247 `core.*,remote.*.url`. This function will iterate over all config
248 settings and emit a "def_param" message for each match.
250 `void trace2_cmd_set_config(const char *key, const char *value)`::
252 Emits a "def_param" message for a specific configuration
253 setting IFF it matches the `GIT_TR2_CONFIG_PARAMS` pattern.
255 This is used to hook into `git_config_set()` and catch any
256 configuration changes and update a value previously reported by
257 `trace2_cmd_list_config()`.
259 `void trace2_def_repo(struct repository *repo)`::
261 Registers a repository with the Trace2 layer. Assigns a
262 unique "repo-id" to `repo->trace2_repo_id`.
264 Emits a "worktree" messages containing the repo-id and the worktree
267 Region and data messages (described later) may refer to this repo-id.
269 The main/top-level repository will have repo-id value 1 (aka "r1").
271 The repo-id field is in anticipation of future in-proc submodule
274 === Child Process Messages
276 These are concerned with the various spawned child processes,
277 including shell scripts, git commands, editors, pagers, and hooks.
279 `void trace2_child_start(struct child_process *cmd)`::
281 Emits a "child_start" message containing the "child-id",
282 "child-argv", and "child-classification".
284 Before calling this, set `cmd->trace2_child_class` to a name
285 describing the type of child process, for example "editor".
287 This function assigns a unique "child-id" to `cmd->trace2_child_id`.
288 This field is used later during the "child_exit" message to associate
289 it with the "child_start" message.
291 This function should be called before spawning the child process.
293 `void trace2_child_exit(struct child_proess *cmd, int child_exit_code)`::
295 Emits a "child_exit" message containing the "child-id",
296 the child's elapsed time and exit-code.
298 The reported elapsed time includes the process creation overhead and
299 time spend waiting for it to exit, so it may be slightly longer than
300 the time reported by the child itself.
302 This function should be called after reaping the child process.
304 `int trace2_exec(const char *exe, const char **argv)`::
306 Emits a "exec" message containing the "exec-id" and the
307 argv of the new process.
309 This function should be called before calling one of the `exec()`
310 variants, such as `execvp()`.
312 This function returns a unique "exec-id". This value is used later
313 if the exec() fails and a "exec-result" message is necessary.
315 `void trace2_exec_result(int exec_id, int error_code)`::
317 Emits a "exec_result" message containing the "exec-id"
320 On Unix-based systems, `exec()` does not return if successful.
321 This message is used to indicate that the `exec()` failed and
322 that the current program is continuing.
324 === Git Thread Messages
326 These messages are concerned with Git thread usage.
328 `void trace2_thread_start(const char *thread_name)`::
330 Emits a "thread_start" message.
332 The `thread_name` field should be a descriptive name, such as the
333 unique name of the thread-proc. A unique "thread-id" will be added
334 to the name to uniquely identify thread instances.
336 Region and data messages (described later) may refer to this thread
339 This function must be called by the thread-proc of the new thread
340 (so that TLS data is properly initialized) and not by the caller
341 of `pthread_create()`.
343 `void trace2_thread_exit()`::
345 Emits a "thread_exit" message containing the thread name
346 and the thread elapsed time.
348 This function must be called by the thread-proc before it returns
349 (so that the coorect TLS data is used and cleaned up. It should
350 not be called by the caller of `pthread_join()`.
352 === Region and Data Messages
354 These are concerned with recording performance data
355 over regions or spans of code.
357 `void trace2_region_enter(const char *category, const char *label, const struct repository *repo)`::
359 `void trace2_region_enter_printf(const char *category, const char *label, const struct repository *repo, const char *fmt, ...)`::
361 `void trace2_region_enter_printf_va(const char *category, const char *label, const struct repository *repo, const char *fmt, va_list ap)`::
363 Emits a thread-relative "region_enter" message with optional
366 This function pushes a new region nesting stack level on the current
367 thread and starts a clock for the new stack frame.
369 The `category` field is an arbitrary category name used to classify
370 regions by feature area, such as "status" or "index". At this time
371 it is only just printed along with the rest of the message. It may
372 be used in the future to filter messages.
374 The `label` field is an arbitrary label used to describe the activity
375 being started, such as "read_recursive" or "do_read_index".
377 The `repo` field, if set, will be used to get the "repo-id", so that
378 recursive oerations can be attributed to the correct repository.
380 `void trace2_region_leave(const char *category, const char *label, const struct repository *repo)`::
382 `void trace2_region_leave_printf(const char *category, const char *label, const struct repository *repo, const char *fmt, ...)`::
384 `void trace2_region_leave_printf_va(const char *category, const char *label, const struct repository *repo, const char *fmt, va_list ap)`::
386 Emits a thread-relative "region_leave" message with optional
389 This function pops the region nesting stack on the current thread
390 and reports the elapsed time of the stack frame.
392 The `category`, `label`, and `repo` fields are the same as above.
393 The `category` and `label` do not need to match the correpsonding
394 "region_enter" message, but it makes the data stream easier to
397 `void trace2_data_string(const char *category, const struct repository *repo, const char *key, const char * value)`::
399 `void trace2_data_intmax(const char *category, const struct repository *repo, const char *key, intmax value)`::
401 `void trace2_data_json(const char *category, const struct repository *repo, const char *key, const struct json_writer *jw)`::
403 Emits a region- and thread-relative "data" or "data_json" message.
405 This is a key/value pair message containing information about the
406 current thread, region stack, and repository. This could be used
407 to print the number of files in a directory during a multi-threaded
410 `void trace2_printf(const char *fmt, ...)`::
412 `void trace2_printf_va(const char *fmt, va_list ap)`::
414 Emits a region- and thread-relative "printf" message.
416 == Trace2 Target Formats
420 NORMAL format is enabled when the `GIT_TR2` environment variable is
423 Events are written as lines of the form:
426 [<time> SP <filename>:<line> SP+] <event-name> [[SP] <event-message>] LF
434 is a free-form printf message intended for human consumption.
436 Note that this may contain embedded LF or CRLF characters that are
437 not escaped, so the event may spill across multiple lines.
439 If `GIT_TR2_BRIEF` is true, the `time`, `filename`, and `line` fields
442 This target is intended to be more of a summary (like GIT_TRACE) and
443 less detailed than the other targets. It ignores thread, region, and
444 data messages, for example.
448 PERF format is enabled when the `GIT_TR2_PERF` environment variable
451 Events are written as lines of the form:
454 [<time> SP <filename>:<line> SP+
456 BAR SP <thread-name> SP+
457 BAR SP <event-name> SP+
458 BAR SP [r<repo-id>] SP+
461 BAR SP [<category>] SP+
462 BAR SP DOTS* <perf-event-message>
467 is the git process depth. This is the number of parent
468 git processes. A top-level git command has depth value "d0".
469 A child of it has depth value "d1". A second level child
470 has depth value "d2" and so on.
473 is a unique name for the thread. The primary thread
474 is called "main". Other thread names are of the form "th%d:%s"
475 and include a unique number and the name of the thread-proc.
481 when present, is a number indicating the repository
482 in use. A `def_repo` event is emitted when a repository is
483 opened. This defines the repo-id and associated worktree.
484 Subsequent repo-specific events will reference this repo-id.
486 Currently, this is always "r1" for the main repository.
487 This field is in anticipation of in-proc submodules in the future.
490 when present, is the absolute time in seconds since the
494 when present, is time in seconds relative to the start of
495 the current region. For a thread-exit event, it is the elapsed
499 is present on region and data events and is used to
500 indicate a broad category, such as "index" or "status".
502 `<perf-event-message>`::
503 is a free-form printf message intended for human consumption.
506 15:33:33.532712 wt-status.c:2310 | d0 | main | region_enter | r1 | 0.126064 | | status | label:print
507 15:33:33.532712 wt-status.c:2331 | d0 | main | region_leave | r1 | 0.127568 | 0.001504 | status | label:print
510 If `GIT_TR2_PERF_BRIEF` is true, the `time`, `file`, and `line`
514 d0 | main | region_leave | r1 | 0.011717 | 0.009122 | index | label:preload
517 The PERF target is intended for interactive performance analysis
518 during development and is quite noisy.
522 EVENT format is enabled when the `GIT_TR2_EVENT` environment
525 Each event is a JSON-object containing multiple key/value pairs
526 written as a single line and followed by a LF.
529 '{' <key> ':' <value> [',' <key> ':' <value>]* '}' LF
532 Some key/value pairs are common to all events and some are
535 ==== Common Key/Value Pairs
537 The following key/value pairs are common to all events:
542 "sid":"1547659722619736-11614",
544 "time":"2019-01-16 17:28:42.620713",
545 "file":"common-main.c",
555 is the session-id. This is a unique string to identify the
556 process instance to allow all events emitted by a process to
557 be identified. A session-id is used instead of a PID because
558 PIDs are recycled by the OS. For child git processes, the
559 session-id is prepended with the session-id of the parent git
560 process to allow parent-child relationships to be identified
561 during post-processing.
563 `"thread":<thread>`::
567 is the UTC time of the event.
569 `"file":<filename>`::
570 is source file generating the event.
572 `"line":<line-number>`::
573 is the integer source line number generating the event.
576 when present, is the integer repo-id as described previously.
578 If `GIT_TR2_EVENT_BRIEF` is true, the `file` and `line` fields are omitted
579 from all events and the `time` field is only present on the "start" and
582 ==== Event-Specific Key/Value Pairs
585 This event gives the version of the executable and the EVENT format.
591 "evt":"1", # EVENT format version
592 "exe":"2.20.1.155.g426c96fcdb" # git version
597 This event contains the complete argv received by main().
603 "argv":["git","version"]
608 This event is emitted when git calls `exit()`.
614 "t_abs":0.001227, # elapsed time in seconds
620 This event is emitted by the Trace2 `atexit` routine during
621 final shutdown. It should be the last event emitted by the
624 (The elapsed time reported here is greater than the time reported in
625 the "exit" event because it runs after all other atexit tasks have
632 "t_abs":0.001227, # elapsed time in seconds
638 This event is emitted when the program is terminated by a user
639 signal. Depending on the platform, the signal event may
640 prevent the "atexit" event from being generated.
646 "t_abs":0.001227, # elapsed time in seconds
647 "signal":13 # SIGTERM, SIGINT, etc.
652 This event is emitted when one of the `error()`, `die()`,
653 or `usage()` functions are called.
659 "msg":"invalid option: --cahced", # formatted error message
660 "fmt":"invalid option: %s" # error format string
664 The error event may be emitted more than once. The format string
665 allows post-processors to group errors by type without worrying
666 about specific error arguments.
669 This event contains the discovered full path of the git
670 executable (on platforms that are configured to resolve it).
676 "path":"C:/work/gfw/git.exe"
681 This event contains the command name for this git process
682 and the hierarchy of commands from parent git processes.
688 "name":"pack-objects",
689 "hierarchy":"push/pack-objects"
693 Normally, the "name" field contains the canonical name of the
694 command. When a canonical name is not available, one of
695 these special values are used:
698 "_query_" # "git --html-path"
699 "_run_dashed_" # when "git foo" tries to run "git-foo"
700 "_run_shell_alias_" # alias expansion to a shell command
701 "_run_git_alias_" # alias expansion to a git command
702 "_usage_" # usage error
706 This event, when present, describes the command variant This
707 event may be emitted more than once.
717 The "name" field is an arbitrary string to describe the command mode.
718 For example, checkout can checkout a branch or an individual file.
719 And these variations typically have different performance
720 characteristics that are not comparable.
723 This event is present when an alias is expanded.
729 "alias":"l", # registered alias
730 "argv":["log","--graph"] # alias expansion
735 This event describes a child process that is about to be
740 "event":"child_start",
745 "argv":["git","rev-list","--objects","--stdin","--not","--all","--quiet"]
747 "hook_name":"<hook_name>" # present when child_class is "hook"
748 "cd":"<path>" # present when cd is required
752 The "child_id" field can be used to match this child_start with the
753 corresponding child_exit event.
755 The "child_class" field is a rough classification, such as "editor",
756 "pager", "transport/*", and "hook". Unclassified children are classified
760 This event is generated after the current process has returned
761 from the waitpid() and collected the exit information from the
766 "event":"child_exit",
769 "pid":14708, # child PID
770 "code":0, # child exit-code
771 "t_rel":0.110605 # observed run-time of child process
775 Note that the session-id of the child process is not available to
776 the current/spawning process, so the child's PID is reported here as
777 a hint for post-processing. (But it is only a hint because the child
778 proces may be a shell script which doesn't have a session-id.)
780 Note that the `t_rel` field contains the observed run time in seconds
781 for the child process (starting before the fork/exec/spawn and
782 stopping after the waitpid() and includes OS process creation overhead).
783 So this time will be slightly larger than the atexit time reported by
784 the child process itself.
787 This event is generated before git attempts to `exec()`
788 another command rather than starting a child process.
796 "argv":["foo", "bar"]
800 The "exec_id" field is a command-unique id and is only useful if the
801 `exec()` fails and a corresponding exec_result event is generated.
804 This event is generated if the `exec()` fails and control
805 returns to the current git command.
809 "event":"exec_result",
812 "code":1 # error code (errno) from exec()
817 This event is generated when a thread is started. It is
818 generated from *within* the new thread's thread-proc (for TLS
823 "event":"thread_start",
825 "thread":"th02:preload_thread" # thread name
830 This event is generated when a thread exits. It is generated
831 from *within* the thread's thread-proc (for TLS reasons).
835 "event":"thread_exit",
837 "thread":"th02:preload_thread", # thread name
838 "t_rel":0.007328 # thread elapsed time
843 This event is generated to log a global parameter.
849 "param":"core.abbrev",
855 This event defines a repo-id and associates it with the root
863 "worktree":"/Users/jeffhost/work/gfw"
867 As stated earlier, the repo-id is currently always 1, so there will
868 only be one def_repo event. Later, if in-proc submodules are
869 supported, a def_repo event should be emitted for each submodule
873 This event is generated when entering a region.
877 "event":"region_enter",
880 "nesting":1, # current region stack depth
881 "category":"index", # optional
882 "label":"do_read_index", # optional
883 "msg":".git/index" # optional
887 The `category` field may be used in a future enhancement to
888 do category-based filtering.
890 The `GIT_TR2_EVENT_NESTING` environment variable can be used to
891 filter deeply nested regions and data events. It defaults to "2".
894 This event is generated when leaving a region.
898 "event":"region_leave",
901 "t_rel":0.002876, # time spent in region in seconds
902 "nesting":1, # region stack depth
903 "category":"index", # optional
904 "label":"do_read_index", # optional
905 "msg":".git/index" # optional
910 This event is generated to log a thread- and region-local
918 "t_abs":0.024107, # absolute elapsed time
919 "t_rel":0.001031, # elapsed time in region/thread
920 "nesting":2, # region stack depth
922 "key":"read/cache_nr",
927 The "value" field may be an integer or a string.
930 This event is generated to log a pre-formatted JSON string
931 containing structured data.
941 "category":"process",
942 "key":"windows/ancestry",
943 "value":["bash.exe","bash.exe"]
947 == Example Trace2 API Usage
949 Here is a hypothetical usage of the Trace2 API showing the intended
950 usage (without worrying about the actual Git details).
954 Initialization happens in `main()`. Behind the scenes, an
955 `atexit` and `signal` handler are registered.
958 int main(int argc, const char **argv)
963 trace2_cmd_start(argv);
965 exit_code = cmd_main(argc, argv);
967 trace2_cmd_exit(exit_code);
975 After the basics are established, additional command
976 information can be sent to Trace2 as it is discovered.
979 int cmd_checkout(int argc, const char **argv)
981 trace2_cmd_name("checkout");
982 trace2_cmd_mode("branch");
983 trace2_def_repo(the_repository);
985 // emit "def_param" messages for "interesting" config settings.
986 trace2_cmd_list_config();
989 trace2_cmd_error("Path '%s': cannot do something", path);
997 Wrap code spawning child processes.
1002 int child_exit_code;
1003 struct child_process cmd = CHILD_PROCESS_INIT;
1005 cmd.trace2_child_class = "editor";
1007 trace2_child_start(&cmd);
1008 child_exit_code = spawn_child_and_wait_for_it();
1009 trace2_child_exit(&cmd, child_exit_code);
1013 For example, the following fetch command spawned ssh, index-pack,
1014 rev-list, and gc. This example also shows that fetch took
1015 5.199 seconds and of that 4.932 was in ssh.
1018 $ export GIT_TR2_BRIEF=1
1019 $ export GIT_TR2=~/log.normal
1026 version 2.20.1.vfs.1.1.47.g534dbe1ad1
1027 start git fetch origin
1028 worktree /Users/jeffhost/work/gfw
1029 cmd_name fetch (fetch)
1030 child_start[0] ssh git@github.com ...
1031 child_start[1] git index-pack ...
1032 ... (Trace2 events from child processes omitted)
1033 child_exit[1] pid:14707 code:0 elapsed:0.076353
1034 child_exit[0] pid:14706 code:0 elapsed:4.931869
1035 child_start[2] git rev-list ...
1036 ... (Trace2 events from child process omitted)
1037 child_exit[2] pid:14708 code:0 elapsed:0.110605
1038 child_start[3] git gc --auto
1039 ... (Trace2 events from child process omitted)
1040 child_exit[3] pid:14709 code:0 elapsed:0.006240
1041 exit elapsed:5.198503 code:0
1042 atexit elapsed:5.198541 code:0
1045 When a git process is a (direct or indirect) child of another
1046 git process, it inherits Trace2 context information. This
1047 allows the child to print the command hierarchy. This example
1048 shows gc as child[3] of fetch. When the gc process reports
1049 its name as "gc", it also reports the hierarchy as "fetch/gc".
1050 (In this example, trace2 messages from the child process is
1051 indented for clarity.)
1054 $ export GIT_TR2_BRIEF=1
1055 $ export GIT_TR2=~/log.normal
1062 version 2.20.1.160.g5676107ecd.dirty
1063 start git fetch official
1064 worktree /Users/jeffhost/work/gfw
1065 cmd_name fetch (fetch)
1067 child_start[3] git gc --auto
1068 version 2.20.1.160.g5676107ecd.dirty
1069 start /Users/jeffhost/work/gfw/git gc --auto
1070 worktree /Users/jeffhost/work/gfw
1071 cmd_name gc (fetch/gc)
1072 exit elapsed:0.001959 code:0
1073 atexit elapsed:0.001997 code:0
1074 child_exit[3] pid:20303 code:0 elapsed:0.007564
1075 exit elapsed:3.868938 code:0
1076 atexit elapsed:3.868970 code:0
1081 Regions can be use to time an interesting section of code.
1084 void wt_status_collect(struct wt_status *s)
1086 trace2_region_enter("status", "worktrees", s->repo);
1087 wt_status_collect_changes_worktree(s);
1088 trace2_region_leave("status", "worktrees", s->repo);
1090 trace2_region_enter("status", "index", s->repo);
1091 wt_status_collect_changes_index(s);
1092 trace2_region_leave("status", "index", s->repo);
1094 trace2_region_enter("status", "untracked", s->repo);
1095 wt_status_collect_untracked(s);
1096 trace2_region_leave("status", "untracked", s->repo);
1099 void wt_status_print(struct wt_status *s)
1101 trace2_region_enter("status", "print", s->repo);
1102 switch (s->status_format) {
1105 trace2_region_leave("status", "print", s->repo);
1109 In this example, scanning for untracked files ran from +0.012568 to
1110 +0.027149 (since the process started) and took 0.014581 seconds.
1113 $ export GIT_TR2_PERF_BRIEF=1
1114 $ export GIT_TR2_PERF=~/log.perf
1119 d0 | main | version | | | | | 2.20.1.160.g5676107ecd.dirty
1120 d0 | main | start | | | | | git status
1121 d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
1122 d0 | main | cmd_name | | | | | status (status)
1124 d0 | main | region_enter | r1 | 0.010988 | | status | label:worktrees
1125 d0 | main | region_leave | r1 | 0.011236 | 0.000248 | status | label:worktrees
1126 d0 | main | region_enter | r1 | 0.011260 | | status | label:index
1127 d0 | main | region_leave | r1 | 0.012542 | 0.001282 | status | label:index
1128 d0 | main | region_enter | r1 | 0.012568 | | status | label:untracked
1129 d0 | main | region_leave | r1 | 0.027149 | 0.014581 | status | label:untracked
1130 d0 | main | region_enter | r1 | 0.027411 | | status | label:print
1131 d0 | main | region_leave | r1 | 0.028741 | 0.001330 | status | label:print
1132 d0 | main | exit | | 0.028778 | | | code:0
1133 d0 | main | atexit | | 0.028809 | | | code:0
1136 Regions may be nested. This causes messages to be indented in the
1137 PERF target, for example.
1138 Elapsed times are relative to the start of the correpsonding nesting
1139 level as expected. For example, if we add region message to:
1142 static enum path_treatment read_directory_recursive(struct dir_struct *dir,
1143 struct index_state *istate, const char *base, int baselen,
1144 struct untracked_cache_dir *untracked, int check_only,
1145 int stop_at_first_file, const struct pathspec *pathspec)
1147 enum path_treatment state, subdir_state, dir_state = path_none;
1149 trace2_region_enter_printf("dir", "read_recursive", NULL, "%.*s", baselen, base);
1151 trace2_region_leave_printf("dir", "read_recursive", NULL, "%.*s", baselen, base);
1156 We can further investigate the time spent scanning for untracked files.
1159 $ export GIT_TR2_PERF_BRIEF=1
1160 $ export GIT_TR2_PERF=~/log.perf
1164 d0 | main | version | | | | | 2.20.1.162.gb4ccea44db.dirty
1165 d0 | main | start | | | | | git status
1166 d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
1167 d0 | main | cmd_name | | | | | status (status)
1169 d0 | main | region_enter | r1 | 0.015047 | | status | label:untracked
1170 d0 | main | region_enter | | 0.015132 | | dir | ..label:read_recursive
1171 d0 | main | region_enter | | 0.016341 | | dir | ....label:read_recursive vcs-svn/
1172 d0 | main | region_leave | | 0.016422 | 0.000081 | dir | ....label:read_recursive vcs-svn/
1173 d0 | main | region_enter | | 0.016446 | | dir | ....label:read_recursive xdiff/
1174 d0 | main | region_leave | | 0.016522 | 0.000076 | dir | ....label:read_recursive xdiff/
1175 d0 | main | region_enter | | 0.016612 | | dir | ....label:read_recursive git-gui/
1176 d0 | main | region_enter | | 0.016698 | | dir | ......label:read_recursive git-gui/po/
1177 d0 | main | region_enter | | 0.016810 | | dir | ........label:read_recursive git-gui/po/glossary/
1178 d0 | main | region_leave | | 0.016863 | 0.000053 | dir | ........label:read_recursive git-gui/po/glossary/
1180 d0 | main | region_enter | | 0.031876 | | dir | ....label:read_recursive builtin/
1181 d0 | main | region_leave | | 0.032270 | 0.000394 | dir | ....label:read_recursive builtin/
1182 d0 | main | region_leave | | 0.032414 | 0.017282 | dir | ..label:read_recursive
1183 d0 | main | region_leave | r1 | 0.032454 | 0.017407 | status | label:untracked
1185 d0 | main | exit | | 0.034279 | | | code:0
1186 d0 | main | atexit | | 0.034322 | | | code:0
1189 Trace2 regions are similar to the existing trace_performance_enter()
1190 and trace_performance_leave() routines, but are thread safe and
1191 maintain per-thread stacks of timers.
1195 Data messages added to a region.
1198 int read_index_from(struct index_state *istate, const char *path,
1201 trace2_region_enter_printf("index", "do_read_index", the_repository, "%s", path);
1205 trace2_data_intmax("index", the_repository, "read/version", istate->version);
1206 trace2_data_intmax("index", the_repository, "read/cache_nr", istate->cache_nr);
1208 trace2_region_leave_printf("index", "do_read_index", the_repository, "%s", path);
1212 This example shows that the index contained 3552 entries.
1215 $ export GIT_TR2_PERF_BRIEF=1
1216 $ export GIT_TR2_PERF=~/log.perf
1220 d0 | main | version | | | | | 2.20.1.156.gf9916ae094.dirty
1221 d0 | main | start | | | | | git status
1222 d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
1223 d0 | main | cmd_name | | | | | status (status)
1224 d0 | main | region_enter | r1 | 0.001791 | | index | label:do_read_index .git/index
1225 d0 | main | data | r1 | 0.002494 | 0.000703 | index | ..read/version:2
1226 d0 | main | data | r1 | 0.002520 | 0.000729 | index | ..read/cache_nr:3552
1227 d0 | main | region_leave | r1 | 0.002539 | 0.000748 | index | label:do_read_index .git/index
1233 Thread messages added to a thread-proc.
1235 For example, the multithreaded preload-index code can be
1236 instrumented with a region around the thread pool and then
1237 per-thread start and exit events within the threadproc.
1240 static void *preload_thread(void *_data)
1242 // start the per-thread clock and emit a message.
1243 trace2_thread_start("preload_thread");
1245 // report which chunk of the array this thread was assigned.
1246 trace2_data_intmax("index", the_repository, "offset", p->offset);
1247 trace2_data_intmax("index", the_repository, "count", nr);
1254 // report elapsed time taken by this thread.
1255 trace2_thread_exit();
1259 void preload_index(struct index_state *index,
1260 const struct pathspec *pathspec,
1261 unsigned int refresh_flags)
1263 trace2_region_enter("index", "preload", the_repository);
1265 for (i = 0; i < threads; i++) {
1266 ... /* create thread */
1269 for (i = 0; i < threads; i++) {
1270 ... /* join thread */
1273 trace2_region_leave("index", "preload", the_repository);
1277 In this example preload_index() was executed by the `main` thread
1278 and started the `preload` region. Seven threads, named
1279 `th01:preload_thread` through `th07:preload_thread`, were started.
1280 Events from each thread are atomically appended to the shared target
1281 stream as they occur so they may appear in random order with respect
1282 other threads. Finally, the main thread waits for the threads to
1283 finish and leaves the region.
1285 Data events are tagged with the active thread name. They are used
1286 to report the per-thread parameters.
1289 $ export GIT_TR2_PERF_BRIEF=1
1290 $ export GIT_TR2_PERF=~/log.perf
1295 d0 | main | region_enter | r1 | 0.002595 | | index | label:preload
1296 d0 | th01:preload_thread | thread_start | | 0.002699 | | |
1297 d0 | th02:preload_thread | thread_start | | 0.002721 | | |
1298 d0 | th01:preload_thread | data | r1 | 0.002736 | 0.000037 | index | offset:0
1299 d0 | th02:preload_thread | data | r1 | 0.002751 | 0.000030 | index | offset:2032
1300 d0 | th03:preload_thread | thread_start | | 0.002711 | | |
1301 d0 | th06:preload_thread | thread_start | | 0.002739 | | |
1302 d0 | th01:preload_thread | data | r1 | 0.002766 | 0.000067 | index | count:508
1303 d0 | th06:preload_thread | data | r1 | 0.002856 | 0.000117 | index | offset:2540
1304 d0 | th03:preload_thread | data | r1 | 0.002824 | 0.000113 | index | offset:1016
1305 d0 | th04:preload_thread | thread_start | | 0.002710 | | |
1306 d0 | th02:preload_thread | data | r1 | 0.002779 | 0.000058 | index | count:508
1307 d0 | th06:preload_thread | data | r1 | 0.002966 | 0.000227 | index | count:508
1308 d0 | th07:preload_thread | thread_start | | 0.002741 | | |
1309 d0 | th07:preload_thread | data | r1 | 0.003017 | 0.000276 | index | offset:3048
1310 d0 | th05:preload_thread | thread_start | | 0.002712 | | |
1311 d0 | th05:preload_thread | data | r1 | 0.003067 | 0.000355 | index | offset:1524
1312 d0 | th05:preload_thread | data | r1 | 0.003090 | 0.000378 | index | count:508
1313 d0 | th07:preload_thread | data | r1 | 0.003037 | 0.000296 | index | count:504
1314 d0 | th03:preload_thread | data | r1 | 0.002971 | 0.000260 | index | count:508
1315 d0 | th04:preload_thread | data | r1 | 0.002983 | 0.000273 | index | offset:508
1316 d0 | th04:preload_thread | data | r1 | 0.007311 | 0.004601 | index | count:508
1317 d0 | th05:preload_thread | thread_exit | | 0.008781 | 0.006069 | |
1318 d0 | th01:preload_thread | thread_exit | | 0.009561 | 0.006862 | |
1319 d0 | th03:preload_thread | thread_exit | | 0.009742 | 0.007031 | |
1320 d0 | th06:preload_thread | thread_exit | | 0.009820 | 0.007081 | |
1321 d0 | th02:preload_thread | thread_exit | | 0.010274 | 0.007553 | |
1322 d0 | th07:preload_thread | thread_exit | | 0.010477 | 0.007736 | |
1323 d0 | th04:preload_thread | thread_exit | | 0.011657 | 0.008947 | |
1324 d0 | main | region_leave | r1 | 0.011717 | 0.009122 | index | label:preload
1326 d0 | main | exit | | 0.029996 | | | code:0
1327 d0 | main | atexit | | 0.030027 | | | code:0
1330 In this example, the preload region took 0.009122 seconds. The 7 threads
1331 took between 0.006069 and 0.008947 seconds to work on their portion of
1332 the index. Thread "th01" worked on 508 items at offset 0. Thread "th02"
1333 worked on 508 items at offset 2032. Thread "th04" worked on 508 itemts
1336 This example also shows that thread names are assigned in a racy manner
1337 as each thread starts and allocates TLS storage.
1341 === Relationship to the Existing Trace Api (api-trace.txt)
1343 There are a few issues to resolve before we can completely
1346 * Updating existing tests that assume GIT_TRACE format messages.
1348 * How to best handle custom GIT_TRACE_<key> messages?
1350 ** The GIT_TRACE_<key> mechanism allows each <key> to write to a
1351 different file (in addition to just stderr).
1353 ** Do we want to maintain that ability or simply write to the existing
1354 Trace2 targets (and convert <key> to a "category").