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,
25 Trace2 is controlled using `trace2.*` config values in the system and
26 global config files and `GIT_TRACE2*` environment variables. Trace2 does
27 not read from repo local or worktree config files or respect `-c`
28 command line config settings.
32 Trace2 defines the following set of Trace2 Targets.
33 Format details are given in a later section.
35 === The Normal Format Target
37 The normal format target is a tradition printf format and similar
38 to GIT_TRACE format. This format is enabled with the `GIT_TRACE2`
39 environment variable or the `trace2.normalTarget` system or global
45 $ export GIT_TRACE2=~/log.normal
47 git version 2.20.1.155.g426c96fcdb
53 $ git config --global trace2.normalTarget ~/log.normal
55 git version 2.20.1.155.g426c96fcdb
62 12:28:42.620009 common-main.c:38 version 2.20.1.155.g426c96fcdb
63 12:28:42.620989 common-main.c:39 start git version
64 12:28:42.621101 git.c:432 cmd_name version (version)
65 12:28:42.621215 git.c:662 exit elapsed:0.001227 code:0
66 12:28:42.621250 trace2/tr2_tgt_normal.c:124 atexit elapsed:0.001265 code:0
69 === The Performance Format Target
71 The performance format target (PERF) is a column-based format to
72 replace GIT_TRACE_PERFORMANCE and is suitable for development and
73 testing, possibly to complement tools like gprof. This format is
74 enabled with the `GIT_TRACE2_PERF` environment variable or the
75 `trace2.perfTarget` system or global config setting.
80 $ export GIT_TRACE2_PERF=~/log.perf
82 git version 2.20.1.155.g426c96fcdb
88 $ git config --global trace2.perfTarget ~/log.perf
90 git version 2.20.1.155.g426c96fcdb
97 12:28:42.620675 common-main.c:38 | d0 | main | version | | | | | 2.20.1.155.g426c96fcdb
98 12:28:42.621001 common-main.c:39 | d0 | main | start | | 0.001173 | | | git version
99 12:28:42.621111 git.c:432 | d0 | main | cmd_name | | | | | version (version)
100 12:28:42.621225 git.c:662 | d0 | main | exit | | 0.001227 | | | code:0
101 12:28:42.621259 trace2/tr2_tgt_perf.c:211 | d0 | main | atexit | | 0.001265 | | | code:0
104 === The Event Format Target
106 The event format target is a JSON-based format of event data suitable
107 for telemetry analysis. This format is enabled with the `GIT_TRACE2_EVENT`
108 environment variable or the `trace2.eventTarget` system or global config
114 $ export GIT_TRACE2_EVENT=~/log.event
116 git version 2.20.1.155.g426c96fcdb
122 $ git config --global trace2.eventTarget ~/log.event
124 git version 2.20.1.155.g426c96fcdb
131 {"event":"version","sid":"sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.620713Z","file":"common-main.c","line":38,"evt":"2","exe":"2.20.1.155.g426c96fcdb"}
132 {"event":"start","sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.621027Z","file":"common-main.c","line":39,"t_abs":0.001173,"argv":["git","version"]}
133 {"event":"cmd_name","sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.621122Z","file":"git.c","line":432,"name":"version","hierarchy":"version"}
134 {"event":"exit","sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.621236Z","file":"git.c","line":662,"t_abs":0.001227,"code":0}
135 {"event":"atexit","sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.621268Z","file":"trace2/tr2_tgt_event.c","line":163,"t_abs":0.001265,"code":0}
138 === Enabling a Target
140 To enable a target, set the corresponding environment variable or
141 system or global config value to one of the following:
143 include::../trace2-target-values.txt[]
145 When trace files are written to a target directory, they will be named according
146 to the last component of the SID (optionally followed by a counter to avoid
147 filename collisions).
151 All public Trace2 functions and macros are defined in `trace2.h` and
152 `trace2.c`. All public symbols are prefixed with `trace2_`.
154 There are no public Trace2 data structures.
156 The Trace2 code also defines a set of private functions and data types
157 in the `trace2/` directory. These symbols are prefixed with `tr2_`
158 and should only be used by functions in `trace2.c`.
160 == Conventions for Public Functions and Macros
162 The functions defined by the Trace2 API are declared and documented
163 in `trace2.h`. It defines the API functions and wrapper macros for
166 Some functions have a `_fl()` suffix to indicate that they take `file`
167 and `line-number` arguments.
169 Some functions have a `_va_fl()` suffix to indicate that they also
170 take a `va_list` argument.
172 Some functions have a `_printf_fl()` suffix to indicate that they also
173 take a varargs argument.
175 There are CPP wrapper macros and ifdefs to hide most of these details.
176 See `trace2.h` for more details. The following discussion will only
177 describe the simplified forms.
181 All Trace2 API functions send a message to all of the active
182 Trace2 Targets. This section describes the set of available
185 It helps to divide these functions into groups for discussion
188 === Basic Command Messages
190 These are concerned with the lifetime of the overall git process.
191 e.g: `void trace2_initialize_clock()`, `void trace2_initialize()`,
192 `int trace2_is_enabled()`, `void trace2_cmd_start(int argc, const char **argv)`.
194 === Command Detail Messages
196 These are concerned with describing the specific Git command
197 after the command line, config, and environment are inspected.
198 e.g: `void trace2_cmd_name(const char *name)`,
199 `void trace2_cmd_mode(const char *mode)`.
201 === Child Process Messages
203 These are concerned with the various spawned child processes,
204 including shell scripts, git commands, editors, pagers, and hooks.
206 e.g: `void trace2_child_start(struct child_process *cmd)`.
208 === Git Thread Messages
210 These messages are concerned with Git thread usage.
212 e.g: `void trace2_thread_start(const char *thread_name)`.
214 === Region and Data Messages
216 These are concerned with recording performance data
217 over regions or spans of code. e.g:
218 `void trace2_region_enter(const char *category, const char *label, const struct repository *repo)`.
220 Refer to trace2.h for details about all trace2 functions.
222 == Trace2 Target Formats
226 Events are written as lines of the form:
229 [<time> SP <filename>:<line> SP+] <event-name> [[SP] <event-message>] LF
237 is a free-form printf message intended for human consumption.
239 Note that this may contain embedded LF or CRLF characters that are
240 not escaped, so the event may spill across multiple lines.
242 If `GIT_TRACE2_BRIEF` or `trace2.normalBrief` is true, the `time`, `filename`,
243 and `line` fields are omitted.
245 This target is intended to be more of a summary (like GIT_TRACE) and
246 less detailed than the other targets. It ignores thread, region, and
247 data messages, for example.
251 Events are written as lines of the form:
254 [<time> SP <filename>:<line> SP+
256 BAR SP <thread-name> SP+
257 BAR SP <event-name> SP+
258 BAR SP [r<repo-id>] SP+
261 BAR SP [<category>] SP+
262 BAR SP DOTS* <perf-event-message>
267 is the git process depth. This is the number of parent
268 git processes. A top-level git command has depth value "d0".
269 A child of it has depth value "d1". A second level child
270 has depth value "d2" and so on.
273 is a unique name for the thread. The primary thread
274 is called "main". Other thread names are of the form "th%d:%s"
275 and include a unique number and the name of the thread-proc.
281 when present, is a number indicating the repository
282 in use. A `def_repo` event is emitted when a repository is
283 opened. This defines the repo-id and associated worktree.
284 Subsequent repo-specific events will reference this repo-id.
286 Currently, this is always "r1" for the main repository.
287 This field is in anticipation of in-proc submodules in the future.
290 when present, is the absolute time in seconds since the
294 when present, is time in seconds relative to the start of
295 the current region. For a thread-exit event, it is the elapsed
299 is present on region and data events and is used to
300 indicate a broad category, such as "index" or "status".
302 `<perf-event-message>`::
303 is a free-form printf message intended for human consumption.
306 15:33:33.532712 wt-status.c:2310 | d0 | main | region_enter | r1 | 0.126064 | | status | label:print
307 15:33:33.532712 wt-status.c:2331 | d0 | main | region_leave | r1 | 0.127568 | 0.001504 | status | label:print
310 If `GIT_TRACE2_PERF_BRIEF` or `trace2.perfBrief` is true, the `time`, `file`,
311 and `line` fields are omitted.
314 d0 | main | region_leave | r1 | 0.011717 | 0.009122 | index | label:preload
317 The PERF target is intended for interactive performance analysis
318 during development and is quite noisy.
322 Each event is a JSON-object containing multiple key/value pairs
323 written as a single line and followed by a LF.
326 '{' <key> ':' <value> [',' <key> ':' <value>]* '}' LF
329 Some key/value pairs are common to all events and some are
332 ==== Common Key/Value Pairs
334 The following key/value pairs are common to all events:
339 "sid":"20190408T191827.272759Z-H9b68c35f-P00003510",
341 "time":"2019-04-08T19:18:27.282761Z",
342 "file":"common-main.c",
352 is the session-id. This is a unique string to identify the
353 process instance to allow all events emitted by a process to
354 be identified. A session-id is used instead of a PID because
355 PIDs are recycled by the OS. For child git processes, the
356 session-id is prepended with the session-id of the parent git
357 process to allow parent-child relationships to be identified
358 during post-processing.
360 `"thread":<thread>`::
364 is the UTC time of the event.
366 `"file":<filename>`::
367 is source file generating the event.
369 `"line":<line-number>`::
370 is the integer source line number generating the event.
373 when present, is the integer repo-id as described previously.
375 If `GIT_TRACE2_EVENT_BRIEF` or `trace2.eventBrief` is true, the `file`
376 and `line` fields are omitted from all events and the `time` field is
377 only present on the "start" and "atexit" events.
379 ==== Event-Specific Key/Value Pairs
382 This event gives the version of the executable and the EVENT format. It
383 should always be the first event in a trace session. The EVENT format
384 version will be incremented if new event types are added, if existing
385 fields are removed, or if there are significant changes in
386 interpretation of existing events or fields. Smaller changes, such as
387 adding a new field to an existing event, will not require an increment
388 to the EVENT format version.
394 "evt":"2", # EVENT format version
395 "exe":"2.20.1.155.g426c96fcdb" # git version
400 This event is written to the git-trace2-discard sentinel file if there
401 are too many files in the target trace directory (see the
402 trace2.maxFiles config option).
412 This event contains the complete argv received by main().
418 "t_abs":0.001227, # elapsed time in seconds
419 "argv":["git","version"]
424 This event is emitted when git calls `exit()`.
430 "t_abs":0.001227, # elapsed time in seconds
436 This event is emitted by the Trace2 `atexit` routine during
437 final shutdown. It should be the last event emitted by the
440 (The elapsed time reported here is greater than the time reported in
441 the "exit" event because it runs after all other atexit tasks have
448 "t_abs":0.001227, # elapsed time in seconds
454 This event is emitted when the program is terminated by a user
455 signal. Depending on the platform, the signal event may
456 prevent the "atexit" event from being generated.
462 "t_abs":0.001227, # elapsed time in seconds
463 "signo":13 # SIGTERM, SIGINT, etc.
468 This event is emitted when one of the `BUG()`, `error()`, `die()`,
469 `warning()`, or `usage()` functions are called.
475 "msg":"invalid option: --cahced", # formatted error message
476 "fmt":"invalid option: %s" # error format string
480 The error event may be emitted more than once. The format string
481 allows post-processors to group errors by type without worrying
482 about specific error arguments.
485 This event contains the discovered full path of the git
486 executable (on platforms that are configured to resolve it).
492 "path":"C:/work/gfw/git.exe"
497 This event contains the text command name for the parent (and earlier
498 generations of parents) of the current process, in an array ordered from
499 nearest parent to furthest great-grandparent. It may not be implemented
504 "event":"cmd_ancestry",
506 "ancestry":["bash","tmux: server","systemd"]
511 This event contains the command name for this git process
512 and the hierarchy of commands from parent git processes.
518 "name":"pack-objects",
519 "hierarchy":"push/pack-objects"
523 Normally, the "name" field contains the canonical name of the
524 command. When a canonical name is not available, one of
525 these special values are used:
528 "_query_" # "git --html-path"
529 "_run_dashed_" # when "git foo" tries to run "git-foo"
530 "_run_shell_alias_" # alias expansion to a shell command
531 "_run_git_alias_" # alias expansion to a git command
532 "_usage_" # usage error
536 This event, when present, describes the command variant This
537 event may be emitted more than once.
547 The "name" field is an arbitrary string to describe the command mode.
548 For example, checkout can checkout a branch or an individual file.
549 And these variations typically have different performance
550 characteristics that are not comparable.
553 This event is present when an alias is expanded.
559 "alias":"l", # registered alias
560 "argv":["log","--graph"] # alias expansion
565 This event describes a child process that is about to be
570 "event":"child_start",
575 "argv":["git","rev-list","--objects","--stdin","--not","--all","--quiet"]
577 "hook_name":"<hook_name>" # present when child_class is "hook"
578 "cd":"<path>" # present when cd is required
582 The "child_id" field can be used to match this child_start with the
583 corresponding child_exit event.
585 The "child_class" field is a rough classification, such as "editor",
586 "pager", "transport/*", and "hook". Unclassified children are classified
590 This event is generated after the current process has returned
591 from the waitpid() and collected the exit information from the
596 "event":"child_exit",
599 "pid":14708, # child PID
600 "code":0, # child exit-code
601 "t_rel":0.110605 # observed run-time of child process
605 Note that the session-id of the child process is not available to
606 the current/spawning process, so the child's PID is reported here as
607 a hint for post-processing. (But it is only a hint because the child
608 process may be a shell script which doesn't have a session-id.)
610 Note that the `t_rel` field contains the observed run time in seconds
611 for the child process (starting before the fork/exec/spawn and
612 stopping after the waitpid() and includes OS process creation overhead).
613 So this time will be slightly larger than the atexit time reported by
614 the child process itself.
617 This event is generated before git attempts to `exec()`
618 another command rather than starting a child process.
626 "argv":["foo", "bar"]
630 The "exec_id" field is a command-unique id and is only useful if the
631 `exec()` fails and a corresponding exec_result event is generated.
634 This event is generated if the `exec()` fails and control
635 returns to the current git command.
639 "event":"exec_result",
642 "code":1 # error code (errno) from exec()
647 This event is generated when a thread is started. It is
648 generated from *within* the new thread's thread-proc (for TLS
653 "event":"thread_start",
655 "thread":"th02:preload_thread" # thread name
660 This event is generated when a thread exits. It is generated
661 from *within* the thread's thread-proc (for TLS reasons).
665 "event":"thread_exit",
667 "thread":"th02:preload_thread", # thread name
668 "t_rel":0.007328 # thread elapsed time
673 This event is generated to log a global parameter, such as a config
674 setting, command-line flag, or environment variable.
680 "param":"core.abbrev",
686 This event defines a repo-id and associates it with the root
694 "worktree":"/Users/jeffhost/work/gfw"
698 As stated earlier, the repo-id is currently always 1, so there will
699 only be one def_repo event. Later, if in-proc submodules are
700 supported, a def_repo event should be emitted for each submodule
704 This event is generated when entering a region.
708 "event":"region_enter",
711 "nesting":1, # current region stack depth
712 "category":"index", # optional
713 "label":"do_read_index", # optional
714 "msg":".git/index" # optional
718 The `category` field may be used in a future enhancement to
719 do category-based filtering.
721 `GIT_TRACE2_EVENT_NESTING` or `trace2.eventNesting` can be used to
722 filter deeply nested regions and data events. It defaults to "2".
725 This event is generated when leaving a region.
729 "event":"region_leave",
732 "t_rel":0.002876, # time spent in region in seconds
733 "nesting":1, # region stack depth
734 "category":"index", # optional
735 "label":"do_read_index", # optional
736 "msg":".git/index" # optional
741 This event is generated to log a thread- and region-local
749 "t_abs":0.024107, # absolute elapsed time
750 "t_rel":0.001031, # elapsed time in region/thread
751 "nesting":2, # region stack depth
753 "key":"read/cache_nr",
758 The "value" field may be an integer or a string.
761 This event is generated to log a pre-formatted JSON string
762 containing structured data.
772 "category":"process",
773 "key":"windows/ancestry",
774 "value":["bash.exe","bash.exe"]
778 == Example Trace2 API Usage
780 Here is a hypothetical usage of the Trace2 API showing the intended
781 usage (without worrying about the actual Git details).
785 Initialization happens in `main()`. Behind the scenes, an
786 `atexit` and `signal` handler are registered.
789 int main(int argc, const char **argv)
794 trace2_cmd_start(argv);
796 exit_code = cmd_main(argc, argv);
798 trace2_cmd_exit(exit_code);
806 After the basics are established, additional command
807 information can be sent to Trace2 as it is discovered.
810 int cmd_checkout(int argc, const char **argv)
812 trace2_cmd_name("checkout");
813 trace2_cmd_mode("branch");
814 trace2_def_repo(the_repository);
816 // emit "def_param" messages for "interesting" config settings.
817 trace2_cmd_list_config();
820 trace2_cmd_error("Path '%s': cannot do something", path);
828 Wrap code spawning child processes.
834 struct child_process cmd = CHILD_PROCESS_INIT;
836 cmd.trace2_child_class = "editor";
838 trace2_child_start(&cmd);
839 child_exit_code = spawn_child_and_wait_for_it();
840 trace2_child_exit(&cmd, child_exit_code);
844 For example, the following fetch command spawned ssh, index-pack,
845 rev-list, and gc. This example also shows that fetch took
846 5.199 seconds and of that 4.932 was in ssh.
849 $ export GIT_TRACE2_BRIEF=1
850 $ export GIT_TRACE2=~/log.normal
857 version 2.20.1.vfs.1.1.47.g534dbe1ad1
858 start git fetch origin
859 worktree /Users/jeffhost/work/gfw
860 cmd_name fetch (fetch)
861 child_start[0] ssh git@github.com ...
862 child_start[1] git index-pack ...
863 ... (Trace2 events from child processes omitted)
864 child_exit[1] pid:14707 code:0 elapsed:0.076353
865 child_exit[0] pid:14706 code:0 elapsed:4.931869
866 child_start[2] git rev-list ...
867 ... (Trace2 events from child process omitted)
868 child_exit[2] pid:14708 code:0 elapsed:0.110605
869 child_start[3] git gc --auto
870 ... (Trace2 events from child process omitted)
871 child_exit[3] pid:14709 code:0 elapsed:0.006240
872 exit elapsed:5.198503 code:0
873 atexit elapsed:5.198541 code:0
876 When a git process is a (direct or indirect) child of another
877 git process, it inherits Trace2 context information. This
878 allows the child to print the command hierarchy. This example
879 shows gc as child[3] of fetch. When the gc process reports
880 its name as "gc", it also reports the hierarchy as "fetch/gc".
881 (In this example, trace2 messages from the child process is
882 indented for clarity.)
885 $ export GIT_TRACE2_BRIEF=1
886 $ export GIT_TRACE2=~/log.normal
893 version 2.20.1.160.g5676107ecd.dirty
894 start git fetch official
895 worktree /Users/jeffhost/work/gfw
896 cmd_name fetch (fetch)
898 child_start[3] git gc --auto
899 version 2.20.1.160.g5676107ecd.dirty
900 start /Users/jeffhost/work/gfw/git gc --auto
901 worktree /Users/jeffhost/work/gfw
902 cmd_name gc (fetch/gc)
903 exit elapsed:0.001959 code:0
904 atexit elapsed:0.001997 code:0
905 child_exit[3] pid:20303 code:0 elapsed:0.007564
906 exit elapsed:3.868938 code:0
907 atexit elapsed:3.868970 code:0
912 Regions can be use to time an interesting section of code.
915 void wt_status_collect(struct wt_status *s)
917 trace2_region_enter("status", "worktrees", s->repo);
918 wt_status_collect_changes_worktree(s);
919 trace2_region_leave("status", "worktrees", s->repo);
921 trace2_region_enter("status", "index", s->repo);
922 wt_status_collect_changes_index(s);
923 trace2_region_leave("status", "index", s->repo);
925 trace2_region_enter("status", "untracked", s->repo);
926 wt_status_collect_untracked(s);
927 trace2_region_leave("status", "untracked", s->repo);
930 void wt_status_print(struct wt_status *s)
932 trace2_region_enter("status", "print", s->repo);
933 switch (s->status_format) {
936 trace2_region_leave("status", "print", s->repo);
940 In this example, scanning for untracked files ran from +0.012568 to
941 +0.027149 (since the process started) and took 0.014581 seconds.
944 $ export GIT_TRACE2_PERF_BRIEF=1
945 $ export GIT_TRACE2_PERF=~/log.perf
950 d0 | main | version | | | | | 2.20.1.160.g5676107ecd.dirty
951 d0 | main | start | | 0.001173 | | | git status
952 d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
953 d0 | main | cmd_name | | | | | status (status)
955 d0 | main | region_enter | r1 | 0.010988 | | status | label:worktrees
956 d0 | main | region_leave | r1 | 0.011236 | 0.000248 | status | label:worktrees
957 d0 | main | region_enter | r1 | 0.011260 | | status | label:index
958 d0 | main | region_leave | r1 | 0.012542 | 0.001282 | status | label:index
959 d0 | main | region_enter | r1 | 0.012568 | | status | label:untracked
960 d0 | main | region_leave | r1 | 0.027149 | 0.014581 | status | label:untracked
961 d0 | main | region_enter | r1 | 0.027411 | | status | label:print
962 d0 | main | region_leave | r1 | 0.028741 | 0.001330 | status | label:print
963 d0 | main | exit | | 0.028778 | | | code:0
964 d0 | main | atexit | | 0.028809 | | | code:0
967 Regions may be nested. This causes messages to be indented in the
968 PERF target, for example.
969 Elapsed times are relative to the start of the corresponding nesting
970 level as expected. For example, if we add region message to:
973 static enum path_treatment read_directory_recursive(struct dir_struct *dir,
974 struct index_state *istate, const char *base, int baselen,
975 struct untracked_cache_dir *untracked, int check_only,
976 int stop_at_first_file, const struct pathspec *pathspec)
978 enum path_treatment state, subdir_state, dir_state = path_none;
980 trace2_region_enter_printf("dir", "read_recursive", NULL, "%.*s", baselen, base);
982 trace2_region_leave_printf("dir", "read_recursive", NULL, "%.*s", baselen, base);
987 We can further investigate the time spent scanning for untracked files.
990 $ export GIT_TRACE2_PERF_BRIEF=1
991 $ export GIT_TRACE2_PERF=~/log.perf
995 d0 | main | version | | | | | 2.20.1.162.gb4ccea44db.dirty
996 d0 | main | start | | 0.001173 | | | git status
997 d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
998 d0 | main | cmd_name | | | | | status (status)
1000 d0 | main | region_enter | r1 | 0.015047 | | status | label:untracked
1001 d0 | main | region_enter | | 0.015132 | | dir | ..label:read_recursive
1002 d0 | main | region_enter | | 0.016341 | | dir | ....label:read_recursive vcs-svn/
1003 d0 | main | region_leave | | 0.016422 | 0.000081 | dir | ....label:read_recursive vcs-svn/
1004 d0 | main | region_enter | | 0.016446 | | dir | ....label:read_recursive xdiff/
1005 d0 | main | region_leave | | 0.016522 | 0.000076 | dir | ....label:read_recursive xdiff/
1006 d0 | main | region_enter | | 0.016612 | | dir | ....label:read_recursive git-gui/
1007 d0 | main | region_enter | | 0.016698 | | dir | ......label:read_recursive git-gui/po/
1008 d0 | main | region_enter | | 0.016810 | | dir | ........label:read_recursive git-gui/po/glossary/
1009 d0 | main | region_leave | | 0.016863 | 0.000053 | dir | ........label:read_recursive git-gui/po/glossary/
1011 d0 | main | region_enter | | 0.031876 | | dir | ....label:read_recursive builtin/
1012 d0 | main | region_leave | | 0.032270 | 0.000394 | dir | ....label:read_recursive builtin/
1013 d0 | main | region_leave | | 0.032414 | 0.017282 | dir | ..label:read_recursive
1014 d0 | main | region_leave | r1 | 0.032454 | 0.017407 | status | label:untracked
1016 d0 | main | exit | | 0.034279 | | | code:0
1017 d0 | main | atexit | | 0.034322 | | | code:0
1020 Trace2 regions are similar to the existing trace_performance_enter()
1021 and trace_performance_leave() routines, but are thread safe and
1022 maintain per-thread stacks of timers.
1026 Data messages added to a region.
1029 int read_index_from(struct index_state *istate, const char *path,
1032 trace2_region_enter_printf("index", "do_read_index", the_repository, "%s", path);
1036 trace2_data_intmax("index", the_repository, "read/version", istate->version);
1037 trace2_data_intmax("index", the_repository, "read/cache_nr", istate->cache_nr);
1039 trace2_region_leave_printf("index", "do_read_index", the_repository, "%s", path);
1043 This example shows that the index contained 3552 entries.
1046 $ export GIT_TRACE2_PERF_BRIEF=1
1047 $ export GIT_TRACE2_PERF=~/log.perf
1051 d0 | main | version | | | | | 2.20.1.156.gf9916ae094.dirty
1052 d0 | main | start | | 0.001173 | | | git status
1053 d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
1054 d0 | main | cmd_name | | | | | status (status)
1055 d0 | main | region_enter | r1 | 0.001791 | | index | label:do_read_index .git/index
1056 d0 | main | data | r1 | 0.002494 | 0.000703 | index | ..read/version:2
1057 d0 | main | data | r1 | 0.002520 | 0.000729 | index | ..read/cache_nr:3552
1058 d0 | main | region_leave | r1 | 0.002539 | 0.000748 | index | label:do_read_index .git/index
1064 Thread messages added to a thread-proc.
1066 For example, the multithreaded preload-index code can be
1067 instrumented with a region around the thread pool and then
1068 per-thread start and exit events within the threadproc.
1071 static void *preload_thread(void *_data)
1073 // start the per-thread clock and emit a message.
1074 trace2_thread_start("preload_thread");
1076 // report which chunk of the array this thread was assigned.
1077 trace2_data_intmax("index", the_repository, "offset", p->offset);
1078 trace2_data_intmax("index", the_repository, "count", nr);
1085 // report elapsed time taken by this thread.
1086 trace2_thread_exit();
1090 void preload_index(struct index_state *index,
1091 const struct pathspec *pathspec,
1092 unsigned int refresh_flags)
1094 trace2_region_enter("index", "preload", the_repository);
1096 for (i = 0; i < threads; i++) {
1097 ... /* create thread */
1100 for (i = 0; i < threads; i++) {
1101 ... /* join thread */
1104 trace2_region_leave("index", "preload", the_repository);
1108 In this example preload_index() was executed by the `main` thread
1109 and started the `preload` region. Seven threads, named
1110 `th01:preload_thread` through `th07:preload_thread`, were started.
1111 Events from each thread are atomically appended to the shared target
1112 stream as they occur so they may appear in random order with respect
1113 other threads. Finally, the main thread waits for the threads to
1114 finish and leaves the region.
1116 Data events are tagged with the active thread name. They are used
1117 to report the per-thread parameters.
1120 $ export GIT_TRACE2_PERF_BRIEF=1
1121 $ export GIT_TRACE2_PERF=~/log.perf
1126 d0 | main | region_enter | r1 | 0.002595 | | index | label:preload
1127 d0 | th01:preload_thread | thread_start | | 0.002699 | | |
1128 d0 | th02:preload_thread | thread_start | | 0.002721 | | |
1129 d0 | th01:preload_thread | data | r1 | 0.002736 | 0.000037 | index | offset:0
1130 d0 | th02:preload_thread | data | r1 | 0.002751 | 0.000030 | index | offset:2032
1131 d0 | th03:preload_thread | thread_start | | 0.002711 | | |
1132 d0 | th06:preload_thread | thread_start | | 0.002739 | | |
1133 d0 | th01:preload_thread | data | r1 | 0.002766 | 0.000067 | index | count:508
1134 d0 | th06:preload_thread | data | r1 | 0.002856 | 0.000117 | index | offset:2540
1135 d0 | th03:preload_thread | data | r1 | 0.002824 | 0.000113 | index | offset:1016
1136 d0 | th04:preload_thread | thread_start | | 0.002710 | | |
1137 d0 | th02:preload_thread | data | r1 | 0.002779 | 0.000058 | index | count:508
1138 d0 | th06:preload_thread | data | r1 | 0.002966 | 0.000227 | index | count:508
1139 d0 | th07:preload_thread | thread_start | | 0.002741 | | |
1140 d0 | th07:preload_thread | data | r1 | 0.003017 | 0.000276 | index | offset:3048
1141 d0 | th05:preload_thread | thread_start | | 0.002712 | | |
1142 d0 | th05:preload_thread | data | r1 | 0.003067 | 0.000355 | index | offset:1524
1143 d0 | th05:preload_thread | data | r1 | 0.003090 | 0.000378 | index | count:508
1144 d0 | th07:preload_thread | data | r1 | 0.003037 | 0.000296 | index | count:504
1145 d0 | th03:preload_thread | data | r1 | 0.002971 | 0.000260 | index | count:508
1146 d0 | th04:preload_thread | data | r1 | 0.002983 | 0.000273 | index | offset:508
1147 d0 | th04:preload_thread | data | r1 | 0.007311 | 0.004601 | index | count:508
1148 d0 | th05:preload_thread | thread_exit | | 0.008781 | 0.006069 | |
1149 d0 | th01:preload_thread | thread_exit | | 0.009561 | 0.006862 | |
1150 d0 | th03:preload_thread | thread_exit | | 0.009742 | 0.007031 | |
1151 d0 | th06:preload_thread | thread_exit | | 0.009820 | 0.007081 | |
1152 d0 | th02:preload_thread | thread_exit | | 0.010274 | 0.007553 | |
1153 d0 | th07:preload_thread | thread_exit | | 0.010477 | 0.007736 | |
1154 d0 | th04:preload_thread | thread_exit | | 0.011657 | 0.008947 | |
1155 d0 | main | region_leave | r1 | 0.011717 | 0.009122 | index | label:preload
1157 d0 | main | exit | | 0.029996 | | | code:0
1158 d0 | main | atexit | | 0.030027 | | | code:0
1161 In this example, the preload region took 0.009122 seconds. The 7 threads
1162 took between 0.006069 and 0.008947 seconds to work on their portion of
1163 the index. Thread "th01" worked on 508 items at offset 0. Thread "th02"
1164 worked on 508 items at offset 2032. Thread "th04" worked on 508 items
1167 This example also shows that thread names are assigned in a racy manner
1168 as each thread starts and allocates TLS storage.
1172 === Relationship to the Existing Trace Api (api-trace.txt)
1174 There are a few issues to resolve before we can completely
1177 * Updating existing tests that assume GIT_TRACE format messages.
1179 * How to best handle custom GIT_TRACE_<key> messages?
1181 ** The GIT_TRACE_<key> mechanism allows each <key> to write to a
1182 different file (in addition to just stderr).
1184 ** Do we want to maintain that ability or simply write to the existing
1185 Trace2 targets (and convert <key> to a "category").