freshlybakedca.ke
Git fork
1= Trace2 API
2
3The Trace2 API can be used to print debug, performance, and telemetry
4information to stderr or a file. The Trace2 feature is inactive unless
5explicitly enabled by enabling one or more Trace2 Targets.
6
7The 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,
10Trace2 and Trace1 may operate in parallel.
11
12The Trace2 API defines a set of high-level messages with known fields,
13such as (`start`: `argv`) and (`exit`: {`exit-code`, `elapsed-time`}).
14
15Trace2 instrumentation throughout the Git code base sends Trace2
16messages to the enabled Trace2 Targets. Targets transform these
17messages content into purpose-specific formats and write events to
18their data streams. In this manner, the Trace2 API can drive
19many different types of analysis.
20
21Targets are defined using a VTable allowing easy extension to other
22formats in the future. This might be used to define a binary format,
23for example.
24
25Trace2 is controlled using `trace2.*` config values in the system and
26global config files and `GIT_TRACE2*` environment variables. Trace2 does
27not read from repo local or worktree config files, nor does it respect
28`-c` command line config settings.
29
30== Trace2 Targets
31
32Trace2 defines the following set of Trace2 Targets.
33Format details are given in a later section.
34
35=== The Normal Format Target
36
37The normal format target is a traditional `printf()` format and similar
38to the `GIT_TRACE` format. This format is enabled with the `GIT_TRACE2`
39environment variable or the `trace2.normalTarget` system or global
40config setting.
41
42For example
43
44------------
45$ export GIT_TRACE2=~/log.normal
46$ git version
47git version 2.20.1.155.g426c96fcdb
48------------
49
50or
51
52------------
53$ git config --global trace2.normalTarget ~/log.normal
54$ git version
55git version 2.20.1.155.g426c96fcdb
56------------
57
58yields
59
60------------
61$ cat ~/log.normal
6212:28:42.620009 common-main.c:38 version 2.20.1.155.g426c96fcdb
6312:28:42.620989 common-main.c:39 start git version
6412:28:42.621101 git.c:432 cmd_name version (version)
6512:28:42.621215 git.c:662 exit elapsed:0.001227 code:0
6612:28:42.621250 trace2/tr2_tgt_normal.c:124 atexit elapsed:0.001265 code:0
67------------
68
69=== The Performance Format Target
70
71The performance format target (PERF) is a column-based format to
72replace `GIT_TRACE_PERFORMANCE` and is suitable for development and
73testing, possibly to complement tools like `gprof`. This format is
74enabled with the `GIT_TRACE2_PERF` environment variable or the
75`trace2.perfTarget` system or global config setting.
76
77For example
78
79------------
80$ export GIT_TRACE2_PERF=~/log.perf
81$ git version
82git version 2.20.1.155.g426c96fcdb
83------------
84
85or
86
87------------
88$ git config --global trace2.perfTarget ~/log.perf
89$ git version
90git version 2.20.1.155.g426c96fcdb
91------------
92
93yields
94
95------------
96$ cat ~/log.perf
9712:28:42.620675 common-main.c:38 | d0 | main | version | | | | | 2.20.1.155.g426c96fcdb
9812:28:42.621001 common-main.c:39 | d0 | main | start | | 0.001173 | | | git version
9912:28:42.621111 git.c:432 | d0 | main | cmd_name | | | | | version (version)
10012:28:42.621225 git.c:662 | d0 | main | exit | | 0.001227 | | | code:0
10112:28:42.621259 trace2/tr2_tgt_perf.c:211 | d0 | main | atexit | | 0.001265 | | | code:0
102------------
103
104=== The Event Format Target
105
106The event format target is a JSON-based format of event data suitable
107for telemetry analysis. This format is enabled with the `GIT_TRACE2_EVENT`
108environment variable or the `trace2.eventTarget` system or global config
109setting.
110
111For example
112
113------------
114$ export GIT_TRACE2_EVENT=~/log.event
115$ git version
116git version 2.20.1.155.g426c96fcdb
117------------
118
119or
120
121------------
122$ git config --global trace2.eventTarget ~/log.event
123$ git version
124git version 2.20.1.155.g426c96fcdb
125------------
126
127yields
128
129------------
130$ cat ~/log.event
131{"event":"version","sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.620713Z","file":"common-main.c","line":38,"evt":"4","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}
136------------
137
138=== Enabling a Target
139
140To enable a target, set the corresponding environment variable or
141system or global config value to one of the following:
142
143include::../trace2-target-values.adoc[]
144
145When trace files are written to a target directory, they will be named according
146to the last component of the SID (optionally followed by a counter to avoid
147filename collisions).
148
149== Trace2 API
150
151The Trace2 public API is defined and documented in `trace2.h`; refer to it for
152more information. All public functions and macros are prefixed
153with `trace2_` and are implemented in `trace2.c`.
154
155There are no public Trace2 data structures.
156
157The Trace2 code also defines a set of private functions and data types
158in the `trace2/` directory. These symbols are prefixed with `tr2_`
159and should only be used by functions in `trace2.c` (or other private
160source files in `trace2/`).
161
162=== Conventions for Public Functions and Macros
163
164Some functions have a `_fl()` suffix to indicate that they take `file`
165and `line-number` arguments.
166
167Some functions have a `_va_fl()` suffix to indicate that they also
168take a `va_list` argument.
169
170Some functions have a `_printf_fl()` suffix to indicate that they also
171take a `printf()` style format with a variable number of arguments.
172
173CPP wrapper macros are defined to hide most of these details.
174
175== Trace2 Target Formats
176
177=== NORMAL Format
178
179Events are written as lines of the form:
180
181------------
182[<time> SP <filename>:<line> SP+] <event-name> [[SP] <event-message>] LF
183------------
184
185`<event-name>`::
186
187 is the event name.
188
189`<event-message>`::
190 is a free-form `printf()` message intended for human consumption.
191+
192Note that this may contain embedded LF or CRLF characters that are
193not escaped, so the event may spill across multiple lines.
194
195If `GIT_TRACE2_BRIEF` or `trace2.normalBrief` is true, the `time`, `filename`,
196and `line` fields are omitted.
197
198This target is intended to be more of a summary (like GIT_TRACE) and
199less detailed than the other targets. It ignores thread, region, and
200data messages, for example.
201
202=== PERF Format
203
204Events are written as lines of the form:
205
206------------
207[<time> SP <filename>:<line> SP+
208 BAR SP] d<depth> SP
209 BAR SP <thread-name> SP+
210 BAR SP <event-name> SP+
211 BAR SP [r<repo-id>] SP+
212 BAR SP [<t_abs>] SP+
213 BAR SP [<t_rel>] SP+
214 BAR SP [<category>] SP+
215 BAR SP DOTS* <perf-event-message>
216 LF
217------------
218
219`<depth>`::
220 is the git process depth. This is the number of parent
221 git processes. A top-level git command has depth value "d0".
222 A child of it has depth value "d1". A second level child
223 has depth value "d2" and so on.
224
225`<thread-name>`::
226 is a unique name for the thread. The primary thread
227 is called "main". Other thread names are of the form "th%d:%s"
228 and include a unique number and the name of the thread-proc.
229
230`<event-name>`::
231 is the event name.
232
233`<repo-id>`::
234 when present, is a number indicating the repository
235 in use. A `def_repo` event is emitted when a repository is
236 opened. This defines the repo-id and associated worktree.
237 Subsequent repo-specific events will reference this repo-id.
238+
239Currently, this is always "r1" for the main repository.
240This field is in anticipation of in-proc submodules in the future.
241
242`<t_abs>`::
243 when present, is the absolute time in seconds since the
244 program started.
245
246`<t_rel>`::
247 when present, is time in seconds relative to the start of
248 the current region. For a thread-exit event, it is the elapsed
249 time of the thread.
250
251`<category>`::
252 is present on region and data events and is used to
253 indicate a broad category, such as "index" or "status".
254
255`<perf-event-message>`::
256 is a free-form `printf()` message intended for human consumption.
257
258------------
25915:33:33.532712 wt-status.c:2310 | d0 | main | region_enter | r1 | 0.126064 | | status | label:print
26015:33:33.532712 wt-status.c:2331 | d0 | main | region_leave | r1 | 0.127568 | 0.001504 | status | label:print
261------------
262
263If `GIT_TRACE2_PERF_BRIEF` or `trace2.perfBrief` is true, the `time`, `file`,
264and `line` fields are omitted.
265
266------------
267d0 | main | region_leave | r1 | 0.011717 | 0.009122 | index | label:preload
268------------
269
270The PERF target is intended for interactive performance analysis
271during development and is quite noisy.
272
273=== EVENT Format
274
275Each event is a JSON-object containing multiple key/value pairs
276written as a single line and followed by a LF.
277
278------------
279'{' <key> ':' <value> [',' <key> ':' <value>]* '}' LF
280------------
281
282Some key/value pairs are common to all events and some are
283event-specific.
284
285==== Common Key/Value Pairs
286
287The following key/value pairs are common to all events:
288
289------------
290{
291 "event":"version",
292 "sid":"20190408T191827.272759Z-H9b68c35f-P00003510",
293 "thread":"main",
294 "time":"2019-04-08T19:18:27.282761Z",
295 "file":"common-main.c",
296 "line":42,
297 ...
298}
299------------
300
301`"event":<event>`::
302 is the event name.
303
304`"sid":<sid>`::
305 is the session-id. This is a unique string to identify the
306 process instance to allow all events emitted by a process to
307 be identified. A session-id is used instead of a PID because
308 PIDs are recycled by the OS. For child git processes, the
309 session-id is prepended with the session-id of the parent git
310 process to allow parent-child relationships to be identified
311 during post-processing.
312
313`"thread":<thread>`::
314 is the thread name.
315
316`"time":<time>`::
317 is the UTC time of the event.
318
319`"file":<filename>`::
320 is source file generating the event.
321
322`"line":<line-number>`::
323 is the integer source line number generating the event.
324
325`"repo":<repo-id>`::
326 when present, is the integer repo-id as described previously.
327
328If `GIT_TRACE2_EVENT_BRIEF` or `trace2.eventBrief` is true, the `file`
329and `line` fields are omitted from all events and the `time` field is
330only present on the "start" and "atexit" events.
331
332==== Event-Specific Key/Value Pairs
333
334`"version"`::
335 This event gives the version of the executable and the EVENT format. It
336 should always be the first event in a trace session. The EVENT format
337 version will be incremented if new event types are added, if existing
338 fields are removed, or if there are significant changes in
339 interpretation of existing events or fields. Smaller changes, such as
340 adding a new field to an existing event, will not require an increment
341 to the EVENT format version.
342+
343------------
344{
345 "event":"version",
346 ...
347 "evt":"4", # EVENT format version
348 "exe":"2.20.1.155.g426c96fcdb" # git version
349}
350------------
351
352`"too_many_files"`::
353 This event is written to the git-trace2-discard sentinel file if there
354 are too many files in the target trace directory (see the
355 trace2.maxFiles config option).
356+
357------------
358{
359 "event":"too_many_files",
360 ...
361}
362------------
363
364`"start"`::
365 This event contains the complete argv received by main().
366+
367------------
368{
369 "event":"start",
370 ...
371 "t_abs":0.001227, # elapsed time in seconds
372 "argv":["git","version"]
373}
374------------
375
376`"exit"`::
377 This event is emitted when git calls `exit()`.
378+
379------------
380{
381 "event":"exit",
382 ...
383 "t_abs":0.001227, # elapsed time in seconds
384 "code":0 # exit code
385}
386------------
387
388`"atexit"`::
389 This event is emitted by the Trace2 `atexit` routine during
390 final shutdown. It should be the last event emitted by the
391 process.
392+
393(The elapsed time reported here is greater than the time reported in
394the "exit" event because it runs after all other atexit tasks have
395completed.)
396+
397------------
398{
399 "event":"atexit",
400 ...
401 "t_abs":0.001227, # elapsed time in seconds
402 "code":0 # exit code
403}
404------------
405
406`"signal"`::
407 This event is emitted when the program is terminated by a user
408 signal. Depending on the platform, the signal event may
409 prevent the "atexit" event from being generated.
410+
411------------
412{
413 "event":"signal",
414 ...
415 "t_abs":0.001227, # elapsed time in seconds
416 "signo":13 # SIGTERM, SIGINT, etc.
417}
418------------
419
420`"error"`::
421 This event is emitted when one of the `BUG()`, `bug()`, `error()`,
422 `die()`, `warning()`, or `usage()` functions are called.
423+
424------------
425{
426 "event":"error",
427 ...
428 "msg":"invalid option: --cahced", # formatted error message
429 "fmt":"invalid option: %s" # error format string
430}
431------------
432+
433The error event may be emitted more than once. The format string
434allows post-processors to group errors by type without worrying
435about specific error arguments.
436
437`"cmd_path"`::
438 This event contains the discovered full path of the git
439 executable (on platforms that are configured to resolve it).
440+
441------------
442{
443 "event":"cmd_path",
444 ...
445 "path":"C:/work/gfw/git.exe"
446}
447------------
448
449`"cmd_ancestry"`::
450 This event contains the text command name for the parent (and earlier
451 generations of parents) of the current process, in an array ordered from
452 nearest parent to furthest great-grandparent. It may not be implemented
453 on all platforms.
454+
455------------
456{
457 "event":"cmd_ancestry",
458 ...
459 "ancestry":["bash","tmux: server","systemd"]
460}
461------------
462
463`"cmd_name"`::
464 This event contains the command name for this git process
465 and the hierarchy of commands from parent git processes.
466+
467------------
468{
469 "event":"cmd_name",
470 ...
471 "name":"pack-objects",
472 "hierarchy":"push/pack-objects"
473}
474------------
475+
476Normally, the "name" field contains the canonical name of the
477command. When a canonical name is not available, one of
478these special values are used:
479+
480------------
481"_query_" # "git --html-path"
482"_run_dashed_" # when "git foo" tries to run "git-foo"
483"_run_shell_alias_" # alias expansion to a shell command
484"_run_git_alias_" # alias expansion to a git command
485"_usage_" # usage error
486------------
487
488`"cmd_mode"`::
489 This event, when present, describes the command variant. This
490 event may be emitted more than once.
491+
492------------
493{
494 "event":"cmd_mode",
495 ...
496 "name":"branch"
497}
498------------
499+
500The "name" field is an arbitrary string to describe the command mode.
501For example, checkout can checkout a branch or an individual file.
502And these variations typically have different performance
503characteristics that are not comparable.
504
505`"alias"`::
506 This event is present when an alias is expanded.
507+
508------------
509{
510 "event":"alias",
511 ...
512 "alias":"l", # registered alias
513 "argv":["log","--graph"] # alias expansion
514}
515------------
516
517`"child_start"`::
518 This event describes a child process that is about to be
519 spawned.
520+
521------------
522{
523 "event":"child_start",
524 ...
525 "child_id":2,
526 "child_class":"?",
527 "use_shell":false,
528 "argv":["git","rev-list","--objects","--stdin","--not","--all","--quiet"]
529
530 "hook_name":"<hook_name>" # present when child_class is "hook"
531 "cd":"<path>" # present when cd is required
532}
533------------
534+
535The "child_id" field can be used to match this child_start with the
536corresponding child_exit event.
537+
538The "child_class" field is a rough classification, such as "editor",
539"pager", "transport/*", and "hook". Unclassified children are classified
540with "?".
541
542`"child_exit"`::
543 This event is generated after the current process has returned
544 from the `waitpid()` and collected the exit information from the
545 child.
546+
547------------
548{
549 "event":"child_exit",
550 ...
551 "child_id":2,
552 "pid":14708, # child PID
553 "code":0, # child exit-code
554 "t_rel":0.110605 # observed run-time of child process
555}
556------------
557+
558Note that the session-id of the child process is not available to
559the current/spawning process, so the child's PID is reported here as
560a hint for post-processing. (But it is only a hint because the child
561process may be a shell script which doesn't have a session-id.)
562+
563Note that the `t_rel` field contains the observed run time in seconds
564for the child process (starting before the fork/exec/spawn and
565stopping after the `waitpid()` and includes OS process creation overhead).
566So this time will be slightly larger than the atexit time reported by
567the child process itself.
568
569`"child_ready"`::
570 This event is generated after the current process has started
571 a background process and released all handles to it.
572+
573------------
574{
575 "event":"child_ready",
576 ...
577 "child_id":2,
578 "pid":14708, # child PID
579 "ready":"ready", # child ready state
580 "t_rel":0.110605 # observed run-time of child process
581}
582------------
583+
584Note that the session-id of the child process is not available to
585the current/spawning process, so the child's PID is reported here as
586a hint for post-processing. (But it is only a hint because the child
587process may be a shell script which doesn't have a session-id.)
588+
589This event is generated after the child is started in the background
590and given a little time to boot up and start working. If the child
591starts up normally while the parent is still waiting, the "ready"
592field will have the value "ready".
593If the child is too slow to start and the parent times out, the field
594will have the value "timeout".
595If the child starts but the parent is unable to probe it, the field
596will have the value "error".
597+
598After the parent process emits this event, it will release all of its
599handles to the child process and treat the child as a background
600daemon. So even if the child does eventually finish booting up,
601the parent will not emit an updated event.
602+
603Note that the `t_rel` field contains the observed run time in seconds
604when the parent released the child process into the background.
605The child is assumed to be a long-running daemon process and may
606outlive the parent process. So the parent's child event times should
607not be compared to the child's atexit times.
608
609`"exec"`::
610 This event is generated before git attempts to `exec()`
611 another command rather than starting a child process.
612+
613------------
614{
615 "event":"exec",
616 ...
617 "exec_id":0,
618 "exe":"git",
619 "argv":["foo", "bar"]
620}
621------------
622+
623The "exec_id" field is a command-unique id and is only useful if the
624`exec()` fails and a corresponding exec_result event is generated.
625
626`"exec_result"`::
627 This event is generated if the `exec()` fails and control
628 returns to the current git command.
629+
630------------
631{
632 "event":"exec_result",
633 ...
634 "exec_id":0,
635 "code":1 # error code (errno) from exec()
636}
637------------
638
639`"thread_start"`::
640 This event is generated when a thread is started. It is
641 generated from *within* the new thread's thread-proc (because
642 it needs to access data in the thread's thread-local storage).
643+
644------------
645{
646 "event":"thread_start",
647 ...
648 "thread":"th02:preload_thread" # thread name
649}
650------------
651
652`"thread_exit"`::
653 This event is generated when a thread exits. It is generated
654 from *within* the thread's thread-proc.
655+
656------------
657{
658 "event":"thread_exit",
659 ...
660 "thread":"th02:preload_thread", # thread name
661 "t_rel":0.007328 # thread elapsed time
662}
663------------
664
665`"def_param"`::
666 This event is generated to log a global parameter, such as a config
667 setting, command-line flag, or environment variable.
668+
669------------
670{
671 "event":"def_param",
672 ...
673 "scope":"global",
674 "param":"core.abbrev",
675 "value":"7"
676}
677------------
678
679`"def_repo"`::
680 This event defines a repo-id and associates it with the root
681 of the worktree.
682+
683------------
684{
685 "event":"def_repo",
686 ...
687 "repo":1,
688 "worktree":"/Users/jeffhost/work/gfw"
689}
690------------
691+
692As stated earlier, the repo-id is currently always 1, so there will
693only be one def_repo event. Later, if in-proc submodules are
694supported, a def_repo event should be emitted for each submodule
695visited.
696
697`"region_enter"`::
698 This event is generated when entering a region.
699+
700------------
701{
702 "event":"region_enter",
703 ...
704 "repo":1, # optional
705 "nesting":1, # current region stack depth
706 "category":"index", # optional
707 "label":"do_read_index", # optional
708 "msg":".git/index" # optional
709}
710------------
711+
712The `category` field may be used in a future enhancement to
713do category-based filtering.
714+
715`GIT_TRACE2_EVENT_NESTING` or `trace2.eventNesting` can be used to
716filter deeply nested regions and data events. It defaults to "2".
717
718`"region_leave"`::
719 This event is generated when leaving a region.
720+
721------------
722{
723 "event":"region_leave",
724 ...
725 "repo":1, # optional
726 "t_rel":0.002876, # time spent in region in seconds
727 "nesting":1, # region stack depth
728 "category":"index", # optional
729 "label":"do_read_index", # optional
730 "msg":".git/index" # optional
731}
732------------
733
734`"data"`::
735 This event is generated to log a thread- and region-local
736 key/value pair.
737+
738------------
739{
740 "event":"data",
741 ...
742 "repo":1, # optional
743 "t_abs":0.024107, # absolute elapsed time
744 "t_rel":0.001031, # elapsed time in region/thread
745 "nesting":2, # region stack depth
746 "category":"index",
747 "key":"read/cache_nr",
748 "value":"3552"
749}
750------------
751+
752The "value" field may be an integer or a string.
753
754`"data-json"`::
755 This event is generated to log a pre-formatted JSON string
756 containing structured data.
757+
758------------
759{
760 "event":"data_json",
761 ...
762 "repo":1, # optional
763 "t_abs":0.015905,
764 "t_rel":0.015905,
765 "nesting":1,
766 "category":"process",
767 "key":"windows/ancestry",
768 "value":["bash.exe","bash.exe"]
769}
770------------
771
772`"th_timer"`::
773 This event logs the amount of time that a stopwatch timer was
774 running in the thread. This event is generated when a thread
775 exits for timers that requested per-thread events.
776+
777------------
778{
779 "event":"th_timer",
780 ...
781 "category":"my_category",
782 "name":"my_timer",
783 "intervals":5, # number of time it was started/stopped
784 "t_total":0.052741, # total time in seconds it was running
785 "t_min":0.010061, # shortest interval
786 "t_max":0.011648 # longest interval
787}
788------------
789
790`"timer"`::
791 This event logs the amount of time that a stopwatch timer was
792 running aggregated across all threads. This event is generated
793 when the process exits.
794+
795------------
796{
797 "event":"timer",
798 ...
799 "category":"my_category",
800 "name":"my_timer",
801 "intervals":5, # number of time it was started/stopped
802 "t_total":0.052741, # total time in seconds it was running
803 "t_min":0.010061, # shortest interval
804 "t_max":0.011648 # longest interval
805}
806------------
807
808`"th_counter"`::
809 This event logs the value of a counter variable in a thread.
810 This event is generated when a thread exits for counters that
811 requested per-thread events.
812+
813------------
814{
815 "event":"th_counter",
816 ...
817 "category":"my_category",
818 "name":"my_counter",
819 "count":23
820}
821------------
822
823`"counter"`::
824 This event logs the value of a counter variable across all threads.
825 This event is generated when the process exits. The total value
826 reported here is the sum across all threads.
827+
828------------
829{
830 "event":"counter",
831 ...
832 "category":"my_category",
833 "name":"my_counter",
834 "count":23
835}
836------------
837
838`"printf"`::
839 This event logs a human-readable message with no particular formatting
840 guidelines.
841+
842------------
843{
844 "event":"printf",
845 ...
846 "t_abs":0.015905, # elapsed time in seconds
847 "msg":"Hello world" # optional
848}
849------------
850
851
852== Example Trace2 API Usage
853
854Here is a hypothetical usage of the Trace2 API showing the intended
855usage (without worrying about the actual Git details).
856
857Initialization::
858
859 Initialization happens in `main()`. Behind the scenes, an
860 `atexit` and `signal` handler are registered.
861+
862----------------
863int main(int argc, const char **argv)
864{
865 int exit_code;
866
867 trace2_initialize();
868 trace2_cmd_start(argv);
869
870 exit_code = cmd_main(argc, argv);
871
872 trace2_cmd_exit(exit_code);
873
874 return exit_code;
875}
876----------------
877
878Command Details::
879
880 After the basics are established, additional command
881 information can be sent to Trace2 as it is discovered.
882+
883----------------
884int cmd_checkout(int argc, const char **argv)
885{
886 trace2_cmd_name("checkout");
887 trace2_cmd_mode("branch");
888 trace2_def_repo(the_repository);
889
890 // emit "def_param" messages for "interesting" config settings.
891 trace2_cmd_list_config();
892
893 if (do_something())
894 trace2_cmd_error("Path '%s': cannot do something", path);
895
896 return 0;
897}
898----------------
899
900Child Processes::
901
902 Wrap code spawning child processes.
903+
904----------------
905void run_child(...)
906{
907 int child_exit_code;
908 struct child_process cmd = CHILD_PROCESS_INIT;
909 ...
910 cmd.trace2_child_class = "editor";
911
912 trace2_child_start(&cmd);
913 child_exit_code = spawn_child_and_wait_for_it();
914 trace2_child_exit(&cmd, child_exit_code);
915}
916----------------
917+
918For example, the following fetch command spawned ssh, index-pack,
919rev-list, and gc. This example also shows that fetch took
9205.199 seconds and of that 4.932 was in ssh.
921+
922----------------
923$ export GIT_TRACE2_BRIEF=1
924$ export GIT_TRACE2=~/log.normal
925$ git fetch origin
926...
927----------------
928+
929----------------
930$ cat ~/log.normal
931version 2.20.1.vfs.1.1.47.g534dbe1ad1
932start git fetch origin
933worktree /Users/jeffhost/work/gfw
934cmd_name fetch (fetch)
935child_start[0] ssh git@github.com ...
936child_start[1] git index-pack ...
937... (Trace2 events from child processes omitted)
938child_exit[1] pid:14707 code:0 elapsed:0.076353
939child_exit[0] pid:14706 code:0 elapsed:4.931869
940child_start[2] git rev-list ...
941... (Trace2 events from child process omitted)
942child_exit[2] pid:14708 code:0 elapsed:0.110605
943child_start[3] git gc --auto
944... (Trace2 events from child process omitted)
945child_exit[3] pid:14709 code:0 elapsed:0.006240
946exit elapsed:5.198503 code:0
947atexit elapsed:5.198541 code:0
948----------------
949+
950When a git process is a (direct or indirect) child of another
951git process, it inherits Trace2 context information. This
952allows the child to print the command hierarchy. This example
953shows gc as child[3] of fetch. When the gc process reports
954its name as "gc", it also reports the hierarchy as "fetch/gc".
955(In this example, trace2 messages from the child process is
956indented for clarity.)
957+
958----------------
959$ export GIT_TRACE2_BRIEF=1
960$ export GIT_TRACE2=~/log.normal
961$ git fetch origin
962...
963----------------
964+
965----------------
966$ cat ~/log.normal
967version 2.20.1.160.g5676107ecd.dirty
968start git fetch official
969worktree /Users/jeffhost/work/gfw
970cmd_name fetch (fetch)
971...
972child_start[3] git gc --auto
973 version 2.20.1.160.g5676107ecd.dirty
974 start /Users/jeffhost/work/gfw/git gc --auto
975 worktree /Users/jeffhost/work/gfw
976 cmd_name gc (fetch/gc)
977 exit elapsed:0.001959 code:0
978 atexit elapsed:0.001997 code:0
979child_exit[3] pid:20303 code:0 elapsed:0.007564
980exit elapsed:3.868938 code:0
981atexit elapsed:3.868970 code:0
982----------------
983
984Regions::
985
986 Regions can be used to time an interesting section of code.
987+
988----------------
989void wt_status_collect(struct wt_status *s)
990{
991 trace2_region_enter("status", "worktrees", s->repo);
992 wt_status_collect_changes_worktree(s);
993 trace2_region_leave("status", "worktrees", s->repo);
994
995 trace2_region_enter("status", "index", s->repo);
996 wt_status_collect_changes_index(s);
997 trace2_region_leave("status", "index", s->repo);
998
999 trace2_region_enter("status", "untracked", s->repo);
1000 wt_status_collect_untracked(s);
1001 trace2_region_leave("status", "untracked", s->repo);
1002}
1003
1004void wt_status_print(struct wt_status *s)
1005{
1006 trace2_region_enter("status", "print", s->repo);
1007 switch (s->status_format) {
1008 ...
1009 }
1010 trace2_region_leave("status", "print", s->repo);
1011}
1012----------------
1013+
1014In this example, scanning for untracked files ran from +0.012568 to
1015+0.027149 (since the process started) and took 0.014581 seconds.
1016+
1017----------------
1018$ export GIT_TRACE2_PERF_BRIEF=1
1019$ export GIT_TRACE2_PERF=~/log.perf
1020$ git status
1021...
1022
1023$ cat ~/log.perf
1024d0 | main | version | | | | | 2.20.1.160.g5676107ecd.dirty
1025d0 | main | start | | 0.001173 | | | git status
1026d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
1027d0 | main | cmd_name | | | | | status (status)
1028...
1029d0 | main | region_enter | r1 | 0.010988 | | status | label:worktrees
1030d0 | main | region_leave | r1 | 0.011236 | 0.000248 | status | label:worktrees
1031d0 | main | region_enter | r1 | 0.011260 | | status | label:index
1032d0 | main | region_leave | r1 | 0.012542 | 0.001282 | status | label:index
1033d0 | main | region_enter | r1 | 0.012568 | | status | label:untracked
1034d0 | main | region_leave | r1 | 0.027149 | 0.014581 | status | label:untracked
1035d0 | main | region_enter | r1 | 0.027411 | | status | label:print
1036d0 | main | region_leave | r1 | 0.028741 | 0.001330 | status | label:print
1037d0 | main | exit | | 0.028778 | | | code:0
1038d0 | main | atexit | | 0.028809 | | | code:0
1039----------------
1040+
1041Regions may be nested. This causes messages to be indented in the
1042PERF target, for example.
1043Elapsed times are relative to the start of the corresponding nesting
1044level as expected. For example, if we add region message to:
1045+
1046----------------
1047static enum path_treatment read_directory_recursive(struct dir_struct *dir,
1048 struct index_state *istate, const char *base, int baselen,
1049 struct untracked_cache_dir *untracked, int check_only,
1050 int stop_at_first_file, const struct pathspec *pathspec)
1051{
1052 enum path_treatment state, subdir_state, dir_state = path_none;
1053
1054 trace2_region_enter_printf("dir", "read_recursive", NULL, "%.*s", baselen, base);
1055 ...
1056 trace2_region_leave_printf("dir", "read_recursive", NULL, "%.*s", baselen, base);
1057 return dir_state;
1058}
1059----------------
1060+
1061We can further investigate the time spent scanning for untracked files.
1062+
1063----------------
1064$ export GIT_TRACE2_PERF_BRIEF=1
1065$ export GIT_TRACE2_PERF=~/log.perf
1066$ git status
1067...
1068$ cat ~/log.perf
1069d0 | main | version | | | | | 2.20.1.162.gb4ccea44db.dirty
1070d0 | main | start | | 0.001173 | | | git status
1071d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
1072d0 | main | cmd_name | | | | | status (status)
1073...
1074d0 | main | region_enter | r1 | 0.015047 | | status | label:untracked
1075d0 | main | region_enter | | 0.015132 | | dir | ..label:read_recursive
1076d0 | main | region_enter | | 0.016341 | | dir | ....label:read_recursive vcs-svn/
1077d0 | main | region_leave | | 0.016422 | 0.000081 | dir | ....label:read_recursive vcs-svn/
1078d0 | main | region_enter | | 0.016446 | | dir | ....label:read_recursive xdiff/
1079d0 | main | region_leave | | 0.016522 | 0.000076 | dir | ....label:read_recursive xdiff/
1080d0 | main | region_enter | | 0.016612 | | dir | ....label:read_recursive git-gui/
1081d0 | main | region_enter | | 0.016698 | | dir | ......label:read_recursive git-gui/po/
1082d0 | main | region_enter | | 0.016810 | | dir | ........label:read_recursive git-gui/po/glossary/
1083d0 | main | region_leave | | 0.016863 | 0.000053 | dir | ........label:read_recursive git-gui/po/glossary/
1084...
1085d0 | main | region_enter | | 0.031876 | | dir | ....label:read_recursive builtin/
1086d0 | main | region_leave | | 0.032270 | 0.000394 | dir | ....label:read_recursive builtin/
1087d0 | main | region_leave | | 0.032414 | 0.017282 | dir | ..label:read_recursive
1088d0 | main | region_leave | r1 | 0.032454 | 0.017407 | status | label:untracked
1089...
1090d0 | main | exit | | 0.034279 | | | code:0
1091d0 | main | atexit | | 0.034322 | | | code:0
1092----------------
1093+
1094Trace2 regions are similar to the existing trace_performance_enter()
1095and trace_performance_leave() routines, but are thread safe and
1096maintain per-thread stacks of timers.
1097
1098Data Messages::
1099
1100 Data messages added to a region.
1101+
1102----------------
1103int read_index_from(struct index_state *istate, const char *path,
1104 const char *gitdir)
1105{
1106 trace2_region_enter_printf("index", "do_read_index", the_repository, "%s", path);
1107
1108 ...
1109
1110 trace2_data_intmax("index", the_repository, "read/version", istate->version);
1111 trace2_data_intmax("index", the_repository, "read/cache_nr", istate->cache_nr);
1112
1113 trace2_region_leave_printf("index", "do_read_index", the_repository, "%s", path);
1114}
1115----------------
1116+
1117This example shows that the index contained 3552 entries.
1118+
1119----------------
1120$ export GIT_TRACE2_PERF_BRIEF=1
1121$ export GIT_TRACE2_PERF=~/log.perf
1122$ git status
1123...
1124$ cat ~/log.perf
1125d0 | main | version | | | | | 2.20.1.156.gf9916ae094.dirty
1126d0 | main | start | | 0.001173 | | | git status
1127d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
1128d0 | main | cmd_name | | | | | status (status)
1129d0 | main | region_enter | r1 | 0.001791 | | index | label:do_read_index .git/index
1130d0 | main | data | r1 | 0.002494 | 0.000703 | index | ..read/version:2
1131d0 | main | data | r1 | 0.002520 | 0.000729 | index | ..read/cache_nr:3552
1132d0 | main | region_leave | r1 | 0.002539 | 0.000748 | index | label:do_read_index .git/index
1133...
1134----------------
1135
1136Thread Events::
1137
1138 Thread messages added to a thread-proc.
1139+
1140For example, the multi-threaded preload-index code can be
1141instrumented with a region around the thread pool and then
1142per-thread start and exit events within the thread-proc.
1143+
1144----------------
1145static void *preload_thread(void *_data)
1146{
1147 // start the per-thread clock and emit a message.
1148 trace2_thread_start("preload_thread");
1149
1150 // report which chunk of the array this thread was assigned.
1151 trace2_data_intmax("index", the_repository, "offset", p->offset);
1152 trace2_data_intmax("index", the_repository, "count", nr);
1153
1154 do {
1155 ...
1156 } while (--nr > 0);
1157 ...
1158
1159 // report elapsed time taken by this thread.
1160 trace2_thread_exit();
1161 return NULL;
1162}
1163
1164void preload_index(struct index_state *index,
1165 const struct pathspec *pathspec,
1166 unsigned int refresh_flags)
1167{
1168 trace2_region_enter("index", "preload", the_repository);
1169
1170 for (i = 0; i < threads; i++) {
1171 ... /* create thread */
1172 }
1173
1174 for (i = 0; i < threads; i++) {
1175 ... /* join thread */
1176 }
1177
1178 trace2_region_leave("index", "preload", the_repository);
1179}
1180----------------
1181+
1182In this example preload_index() was executed by the `main` thread
1183and started the `preload` region. Seven threads, named
1184`th01:preload_thread` through `th07:preload_thread`, were started.
1185Events from each thread are atomically appended to the shared target
1186stream as they occur so they may appear in random order with respect
1187other threads. Finally, the main thread waits for the threads to
1188finish and leaves the region.
1189+
1190Data events are tagged with the active thread name. They are used
1191to report the per-thread parameters.
1192+
1193----------------
1194$ export GIT_TRACE2_PERF_BRIEF=1
1195$ export GIT_TRACE2_PERF=~/log.perf
1196$ git status
1197...
1198$ cat ~/log.perf
1199...
1200d0 | main | region_enter | r1 | 0.002595 | | index | label:preload
1201d0 | th01:preload_thread | thread_start | | 0.002699 | | |
1202d0 | th02:preload_thread | thread_start | | 0.002721 | | |
1203d0 | th01:preload_thread | data | r1 | 0.002736 | 0.000037 | index | offset:0
1204d0 | th02:preload_thread | data | r1 | 0.002751 | 0.000030 | index | offset:2032
1205d0 | th03:preload_thread | thread_start | | 0.002711 | | |
1206d0 | th06:preload_thread | thread_start | | 0.002739 | | |
1207d0 | th01:preload_thread | data | r1 | 0.002766 | 0.000067 | index | count:508
1208d0 | th06:preload_thread | data | r1 | 0.002856 | 0.000117 | index | offset:2540
1209d0 | th03:preload_thread | data | r1 | 0.002824 | 0.000113 | index | offset:1016
1210d0 | th04:preload_thread | thread_start | | 0.002710 | | |
1211d0 | th02:preload_thread | data | r1 | 0.002779 | 0.000058 | index | count:508
1212d0 | th06:preload_thread | data | r1 | 0.002966 | 0.000227 | index | count:508
1213d0 | th07:preload_thread | thread_start | | 0.002741 | | |
1214d0 | th07:preload_thread | data | r1 | 0.003017 | 0.000276 | index | offset:3048
1215d0 | th05:preload_thread | thread_start | | 0.002712 | | |
1216d0 | th05:preload_thread | data | r1 | 0.003067 | 0.000355 | index | offset:1524
1217d0 | th05:preload_thread | data | r1 | 0.003090 | 0.000378 | index | count:508
1218d0 | th07:preload_thread | data | r1 | 0.003037 | 0.000296 | index | count:504
1219d0 | th03:preload_thread | data | r1 | 0.002971 | 0.000260 | index | count:508
1220d0 | th04:preload_thread | data | r1 | 0.002983 | 0.000273 | index | offset:508
1221d0 | th04:preload_thread | data | r1 | 0.007311 | 0.004601 | index | count:508
1222d0 | th05:preload_thread | thread_exit | | 0.008781 | 0.006069 | |
1223d0 | th01:preload_thread | thread_exit | | 0.009561 | 0.006862 | |
1224d0 | th03:preload_thread | thread_exit | | 0.009742 | 0.007031 | |
1225d0 | th06:preload_thread | thread_exit | | 0.009820 | 0.007081 | |
1226d0 | th02:preload_thread | thread_exit | | 0.010274 | 0.007553 | |
1227d0 | th07:preload_thread | thread_exit | | 0.010477 | 0.007736 | |
1228d0 | th04:preload_thread | thread_exit | | 0.011657 | 0.008947 | |
1229d0 | main | region_leave | r1 | 0.011717 | 0.009122 | index | label:preload
1230...
1231d0 | main | exit | | 0.029996 | | | code:0
1232d0 | main | atexit | | 0.030027 | | | code:0
1233----------------
1234+
1235In this example, the preload region took 0.009122 seconds. The 7 threads
1236took between 0.006069 and 0.008947 seconds to work on their portion of
1237the index. Thread "th01" worked on 508 items at offset 0. Thread "th02"
1238worked on 508 items at offset 2032. Thread "th04" worked on 508 items
1239at offset 508.
1240+
1241This example also shows that thread names are assigned in a racy manner
1242as each thread starts.
1243
1244Config (def param) Events::
1245
1246 Dump "interesting" config values to trace2 log.
1247+
1248We can optionally emit configuration events, see
1249`trace2.configparams` in linkgit:git-config[1] for how to enable
1250it.
1251+
1252----------------
1253$ git config --system color.ui never
1254$ git config --global color.ui always
1255$ git config --local color.ui auto
1256$ git config --list --show-scope | grep 'color.ui'
1257system color.ui=never
1258global color.ui=always
1259local color.ui=auto
1260----------------
1261+
1262Then, mark the config `color.ui` as "interesting" config with
1263`GIT_TRACE2_CONFIG_PARAMS`:
1264+
1265----------------
1266$ export GIT_TRACE2_PERF_BRIEF=1
1267$ export GIT_TRACE2_PERF=~/log.perf
1268$ export GIT_TRACE2_CONFIG_PARAMS=color.ui
1269$ git version
1270...
1271$ cat ~/log.perf
1272d0 | main | version | | | | | ...
1273d0 | main | start | | 0.001642 | | | /usr/local/bin/git version
1274d0 | main | cmd_name | | | | | version (version)
1275d0 | main | def_param | | | | scope:system | color.ui:never
1276d0 | main | def_param | | | | scope:global | color.ui:always
1277d0 | main | def_param | | | | scope:local | color.ui:auto
1278d0 | main | data | r0 | 0.002100 | 0.002100 | fsync | fsync/writeout-only:0
1279d0 | main | data | r0 | 0.002126 | 0.002126 | fsync | fsync/hardware-flush:0
1280d0 | main | exit | | 0.000470 | | | code:0
1281d0 | main | atexit | | 0.000477 | | | code:0
1282----------------
1283
1284Stopwatch Timer Events::
1285
1286 Measure the time spent in a function call or span of code
1287 that might be called from many places within the code
1288 throughout the life of the process.
1289+
1290----------------
1291static void expensive_function(void)
1292{
1293 trace2_timer_start(TRACE2_TIMER_ID_TEST1);
1294 ...
1295 sleep_millisec(1000); // Do something expensive
1296 ...
1297 trace2_timer_stop(TRACE2_TIMER_ID_TEST1);
1298}
1299
1300static int ut_100timer(int argc, const char **argv)
1301{
1302 ...
1303
1304 expensive_function();
1305
1306 // Do something else 1...
1307
1308 expensive_function();
1309
1310 // Do something else 2...
1311
1312 expensive_function();
1313
1314 return 0;
1315}
1316----------------
1317+
1318In this example, we measure the total time spent in
1319`expensive_function()` regardless of when it is called
1320in the overall flow of the program.
1321+
1322----------------
1323$ export GIT_TRACE2_PERF_BRIEF=1
1324$ export GIT_TRACE2_PERF=~/log.perf
1325$ t/helper/test-tool trace2 100timer 3 1000
1326...
1327$ cat ~/log.perf
1328d0 | main | version | | | | | ...
1329d0 | main | start | | 0.001453 | | | t/helper/test-tool trace2 100timer 3 1000
1330d0 | main | cmd_name | | | | | trace2 (trace2)
1331d0 | main | exit | | 3.003667 | | | code:0
1332d0 | main | timer | | | | test | name:test1 intervals:3 total:3.001686 min:1.000254 max:1.000929
1333d0 | main | atexit | | 3.003796 | | | code:0
1334----------------
1335
1336
1337== Future Work
1338
1339=== Relationship to the Existing Trace Api (api-trace.txt)
1340
1341There are a few issues to resolve before we can completely
1342switch to Trace2.
1343
1344* Updating existing tests that assume `GIT_TRACE` format messages.
1345
1346* How to best handle custom `GIT_TRACE_<key>` messages?
1347
1348** The `GIT_TRACE_<key>` mechanism allows each <key> to write to a
1349different file (in addition to just stderr).
1350
1351** Do we want to maintain that ability or simply write to the existing
1352Trace2 targets (and convert <key> to a "category").