Merge branch 'jk/oid-array-cleanup'
[git] / Documentation / technical / api-trace2.txt
1 = Trace2 API
2
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.
6
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.
11
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`}).
14
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.
20
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,
23 for example.
24
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.
29
30 == Trace2 Targets
31
32 Trace2 defines the following set of Trace2 Targets.
33 Format details are given in a later section.
34
35 === The Normal Format Target
36
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
40 config setting.
41
42 For example
43
44 ------------
45 $ export GIT_TRACE2=~/log.normal
46 $ git version
47 git version 2.20.1.155.g426c96fcdb
48 ------------
49
50 or
51
52 ------------
53 $ git config --global trace2.normalTarget ~/log.normal
54 $ git version
55 git version 2.20.1.155.g426c96fcdb
56 ------------
57
58 yields
59
60 ------------
61 $ cat ~/log.normal
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
67 ------------
68
69 === The Performance Format Target
70
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.
76
77 For example
78
79 ------------
80 $ export GIT_TRACE2_PERF=~/log.perf
81 $ git version
82 git version 2.20.1.155.g426c96fcdb
83 ------------
84
85 or
86
87 ------------
88 $ git config --global trace2.perfTarget ~/log.perf
89 $ git version
90 git version 2.20.1.155.g426c96fcdb
91 ------------
92
93 yields
94
95 ------------
96 $ cat ~/log.perf
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
102 ------------
103
104 === The Event Format Target
105
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
109 setting.
110
111 For example
112
113 ------------
114 $ export GIT_TRACE2_EVENT=~/log.event
115 $ git version
116 git version 2.20.1.155.g426c96fcdb
117 ------------
118
119 or
120
121 ------------
122 $ git config --global trace2.eventTarget ~/log.event
123 $ git version
124 git version 2.20.1.155.g426c96fcdb
125 ------------
126
127 yields
128
129 ------------
130 $ cat ~/log.event
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}
136 ------------
137
138 === Enabling a Target
139
140 To enable a target, set the corresponding environment variable or
141 system or global config value to one of the following:
142
143 include::../trace2-target-values.txt[]
144
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).
148
149 == Trace2 API
150
151 All public Trace2 functions and macros are defined in `trace2.h` and
152 `trace2.c`.  All public symbols are prefixed with `trace2_`.
153
154 There are no public Trace2 data structures.
155
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`.
159
160 == Conventions for Public Functions and Macros
161
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
164 Trace2.
165
166 Some functions have a `_fl()` suffix to indicate that they take `file`
167 and `line-number` arguments.
168
169 Some functions have a `_va_fl()` suffix to indicate that they also
170 take a `va_list` argument.
171
172 Some functions have a `_printf_fl()` suffix to indicate that they also
173 take a varargs argument.
174
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.
178
179 == Public API
180
181 All Trace2 API functions send a message to all of the active
182 Trace2 Targets.  This section describes the set of available
183 messages.
184
185 It helps to divide these functions into groups for discussion
186 purposes.
187
188 === Basic Command Messages
189
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)`.
193
194 === Command Detail Messages
195
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)`.
200
201 === Child Process Messages
202
203 These are concerned with the various spawned child processes,
204 including shell scripts, git commands, editors, pagers, and hooks.
205
206 e.g: `void trace2_child_start(struct child_process *cmd)`.
207
208 === Git Thread Messages
209
210 These messages are concerned with Git thread usage.
211
212 e.g: `void trace2_thread_start(const char *thread_name)`.
213
214 === Region and Data Messages
215
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)`.
219
220 Refer to trace2.h for details about all trace2 functions.
221
222 == Trace2 Target Formats
223
224 === NORMAL Format
225
226 Events are written as lines of the form:
227
228 ------------
229 [<time> SP <filename>:<line> SP+] <event-name> [[SP] <event-message>] LF
230 ------------
231
232 `<event-name>`::
233
234         is the event name.
235
236 `<event-message>`::
237         is a free-form printf message intended for human consumption.
238 +
239 Note that this may contain embedded LF or CRLF characters that are
240 not escaped, so the event may spill across multiple lines.
241
242 If `GIT_TRACE2_BRIEF` or `trace2.normalBrief` is true, the `time`, `filename`,
243 and `line` fields are omitted.
244
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.
248
249 === PERF Format
250
251 Events are written as lines of the form:
252
253 ------------
254 [<time> SP <filename>:<line> SP+
255     BAR SP] d<depth> SP
256     BAR SP <thread-name> SP+
257     BAR SP <event-name> SP+
258     BAR SP [r<repo-id>] SP+
259     BAR SP [<t_abs>] SP+
260     BAR SP [<t_rel>] SP+
261     BAR SP [<category>] SP+
262     BAR SP DOTS* <perf-event-message>
263     LF
264 ------------
265
266 `<depth>`::
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.
271
272 `<thread-name>`::
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.
276
277 `<event-name>`::
278         is the event name.
279
280 `<repo-id>`::
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.
285 +
286 Currently, this is always "r1" for the main repository.
287 This field is in anticipation of in-proc submodules in the future.
288
289 `<t_abs>`::
290         when present, is the absolute time in seconds since the
291         program started.
292
293 `<t_rel>`::
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
296         time of the thread.
297
298 `<category>`::
299         is present on region and data events and is used to
300         indicate a broad category, such as "index" or "status".
301
302 `<perf-event-message>`::
303         is a free-form printf message intended for human consumption.
304
305 ------------
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
308 ------------
309
310 If `GIT_TRACE2_PERF_BRIEF` or `trace2.perfBrief` is true, the `time`, `file`,
311 and `line` fields are omitted.
312
313 ------------
314 d0 | main                     | region_leave | r1  |  0.011717 |  0.009122 | index      | label:preload
315 ------------
316
317 The PERF target is intended for interactive performance analysis
318 during development and is quite noisy.
319
320 === EVENT Format
321
322 Each event is a JSON-object containing multiple key/value pairs
323 written as a single line and followed by a LF.
324
325 ------------
326 '{' <key> ':' <value> [',' <key> ':' <value>]* '}' LF
327 ------------
328
329 Some key/value pairs are common to all events and some are
330 event-specific.
331
332 ==== Common Key/Value Pairs
333
334 The following key/value pairs are common to all events:
335
336 ------------
337 {
338         "event":"version",
339         "sid":"20190408T191827.272759Z-H9b68c35f-P00003510",
340         "thread":"main",
341         "time":"2019-04-08T19:18:27.282761Z",
342         "file":"common-main.c",
343         "line":42,
344         ...
345 }
346 ------------
347
348 `"event":<event>`::
349         is the event name.
350
351 `"sid":<sid>`::
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.
359
360 `"thread":<thread>`::
361         is the thread name.
362
363 `"time":<time>`::
364         is the UTC time of the event.
365
366 `"file":<filename>`::
367         is source file generating the event.
368
369 `"line":<line-number>`::
370         is the integer source line number generating the event.
371
372 `"repo":<repo-id>`::
373         when present, is the integer repo-id as described previously.
374
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.
378
379 ==== Event-Specific Key/Value Pairs
380
381 `"version"`::
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.
389 +
390 ------------
391 {
392         "event":"version",
393         ...
394         "evt":"2",                     # EVENT format version
395         "exe":"2.20.1.155.g426c96fcdb" # git version
396 }
397 ------------
398
399 `"discard"`::
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).
403 +
404 ------------
405 {
406         "event":"discard",
407         ...
408 }
409 ------------
410
411 `"start"`::
412         This event contains the complete argv received by main().
413 +
414 ------------
415 {
416         "event":"start",
417         ...
418         "t_abs":0.001227, # elapsed time in seconds
419         "argv":["git","version"]
420 }
421 ------------
422
423 `"exit"`::
424         This event is emitted when git calls `exit()`.
425 +
426 ------------
427 {
428         "event":"exit",
429         ...
430         "t_abs":0.001227, # elapsed time in seconds
431         "code":0          # exit code
432 }
433 ------------
434
435 `"atexit"`::
436         This event is emitted by the Trace2 `atexit` routine during
437         final shutdown.  It should be the last event emitted by the
438         process.
439 +
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
442 completed.)
443 +
444 ------------
445 {
446         "event":"atexit",
447         ...
448         "t_abs":0.001227, # elapsed time in seconds
449         "code":0          # exit code
450 }
451 ------------
452
453 `"signal"`::
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.
457 +
458 ------------
459 {
460         "event":"signal",
461         ...
462         "t_abs":0.001227,  # elapsed time in seconds
463         "signo":13         # SIGTERM, SIGINT, etc.
464 }
465 ------------
466
467 `"error"`::
468         This event is emitted when one of the `error()`, `die()`,
469         `warning()`, or `usage()` functions are called.
470 +
471 ------------
472 {
473         "event":"error",
474         ...
475         "msg":"invalid option: --cahced", # formatted error message
476         "fmt":"invalid option: %s"        # error format string
477 }
478 ------------
479 +
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.
483
484 `"cmd_path"`::
485         This event contains the discovered full path of the git
486         executable (on platforms that are configured to resolve it).
487 +
488 ------------
489 {
490         "event":"cmd_path",
491         ...
492         "path":"C:/work/gfw/git.exe"
493 }
494 ------------
495
496 `"cmd_name"`::
497         This event contains the command name for this git process
498         and the hierarchy of commands from parent git processes.
499 +
500 ------------
501 {
502         "event":"cmd_name",
503         ...
504         "name":"pack-objects",
505         "hierarchy":"push/pack-objects"
506 }
507 ------------
508 +
509 Normally, the "name" field contains the canonical name of the
510 command.  When a canonical name is not available, one of
511 these special values are used:
512 +
513 ------------
514 "_query_"            # "git --html-path"
515 "_run_dashed_"       # when "git foo" tries to run "git-foo"
516 "_run_shell_alias_"  # alias expansion to a shell command
517 "_run_git_alias_"    # alias expansion to a git command
518 "_usage_"            # usage error
519 ------------
520
521 `"cmd_mode"`::
522         This event, when present, describes the command variant This
523         event may be emitted more than once.
524 +
525 ------------
526 {
527         "event":"cmd_mode",
528         ...
529         "name":"branch"
530 }
531 ------------
532 +
533 The "name" field is an arbitrary string to describe the command mode.
534 For example, checkout can checkout a branch or an individual file.
535 And these variations typically have different performance
536 characteristics that are not comparable.
537
538 `"alias"`::
539         This event is present when an alias is expanded.
540 +
541 ------------
542 {
543         "event":"alias",
544         ...
545         "alias":"l",             # registered alias
546         "argv":["log","--graph"] # alias expansion
547 }
548 ------------
549
550 `"child_start"`::
551         This event describes a child process that is about to be
552         spawned.
553 +
554 ------------
555 {
556         "event":"child_start",
557         ...
558         "child_id":2,
559         "child_class":"?",
560         "use_shell":false,
561         "argv":["git","rev-list","--objects","--stdin","--not","--all","--quiet"]
562
563         "hook_name":"<hook_name>"  # present when child_class is "hook"
564         "cd":"<path>"              # present when cd is required
565 }
566 ------------
567 +
568 The "child_id" field can be used to match this child_start with the
569 corresponding child_exit event.
570 +
571 The "child_class" field is a rough classification, such as "editor",
572 "pager", "transport/*", and "hook".  Unclassified children are classified
573 with "?".
574
575 `"child_exit"`::
576         This event is generated after the current process has returned
577         from the waitpid() and collected the exit information from the
578         child.
579 +
580 ------------
581 {
582         "event":"child_exit",
583         ...
584         "child_id":2,
585         "pid":14708,     # child PID
586         "code":0,        # child exit-code
587         "t_rel":0.110605 # observed run-time of child process
588 }
589 ------------
590 +
591 Note that the session-id of the child process is not available to
592 the current/spawning process, so the child's PID is reported here as
593 a hint for post-processing.  (But it is only a hint because the child
594 process may be a shell script which doesn't have a session-id.)
595 +
596 Note that the `t_rel` field contains the observed run time in seconds
597 for the child process (starting before the fork/exec/spawn and
598 stopping after the waitpid() and includes OS process creation overhead).
599 So this time will be slightly larger than the atexit time reported by
600 the child process itself.
601
602 `"exec"`::
603         This event is generated before git attempts to `exec()`
604         another command rather than starting a child process.
605 +
606 ------------
607 {
608         "event":"exec",
609         ...
610         "exec_id":0,
611         "exe":"git",
612         "argv":["foo", "bar"]
613 }
614 ------------
615 +
616 The "exec_id" field is a command-unique id and is only useful if the
617 `exec()` fails and a corresponding exec_result event is generated.
618
619 `"exec_result"`::
620         This event is generated if the `exec()` fails and control
621         returns to the current git command.
622 +
623 ------------
624 {
625         "event":"exec_result",
626         ...
627         "exec_id":0,
628         "code":1      # error code (errno) from exec()
629 }
630 ------------
631
632 `"thread_start"`::
633         This event is generated when a thread is started.  It is
634         generated from *within* the new thread's thread-proc (for TLS
635         reasons).
636 +
637 ------------
638 {
639         "event":"thread_start",
640         ...
641         "thread":"th02:preload_thread" # thread name
642 }
643 ------------
644
645 `"thread_exit"`::
646         This event is generated when a thread exits.  It is generated
647         from *within* the thread's thread-proc (for TLS reasons).
648 +
649 ------------
650 {
651         "event":"thread_exit",
652         ...
653         "thread":"th02:preload_thread", # thread name
654         "t_rel":0.007328                # thread elapsed time
655 }
656 ------------
657
658 `"def_param"`::
659         This event is generated to log a global parameter, such as a config
660         setting, command-line flag, or environment variable.
661 +
662 ------------
663 {
664         "event":"def_param",
665         ...
666         "param":"core.abbrev",
667         "value":"7"
668 }
669 ------------
670
671 `"def_repo"`::
672         This event defines a repo-id and associates it with the root
673         of the worktree.
674 +
675 ------------
676 {
677         "event":"def_repo",
678         ...
679         "repo":1,
680         "worktree":"/Users/jeffhost/work/gfw"
681 }
682 ------------
683 +
684 As stated earlier, the repo-id is currently always 1, so there will
685 only be one def_repo event.  Later, if in-proc submodules are
686 supported, a def_repo event should be emitted for each submodule
687 visited.
688
689 `"region_enter"`::
690         This event is generated when entering a region.
691 +
692 ------------
693 {
694         "event":"region_enter",
695         ...
696         "repo":1,                # optional
697         "nesting":1,             # current region stack depth
698         "category":"index",      # optional
699         "label":"do_read_index", # optional
700         "msg":".git/index"       # optional
701 }
702 ------------
703 +
704 The `category` field may be used in a future enhancement to
705 do category-based filtering.
706 +
707 `GIT_TRACE2_EVENT_NESTING` or `trace2.eventNesting` can be used to
708 filter deeply nested regions and data events.  It defaults to "2".
709
710 `"region_leave"`::
711         This event is generated when leaving a region.
712 +
713 ------------
714 {
715         "event":"region_leave",
716         ...
717         "repo":1,                # optional
718         "t_rel":0.002876,        # time spent in region in seconds
719         "nesting":1,             # region stack depth
720         "category":"index",      # optional
721         "label":"do_read_index", # optional
722         "msg":".git/index"       # optional
723 }
724 ------------
725
726 `"data"`::
727         This event is generated to log a thread- and region-local
728         key/value pair.
729 +
730 ------------
731 {
732         "event":"data",
733         ...
734         "repo":1,              # optional
735         "t_abs":0.024107,      # absolute elapsed time
736         "t_rel":0.001031,      # elapsed time in region/thread
737         "nesting":2,           # region stack depth
738         "category":"index",
739         "key":"read/cache_nr",
740         "value":"3552"
741 }
742 ------------
743 +
744 The "value" field may be an integer or a string.
745
746 `"data-json"`::
747         This event is generated to log a pre-formatted JSON string
748         containing structured data.
749 +
750 ------------
751 {
752         "event":"data_json",
753         ...
754         "repo":1,              # optional
755         "t_abs":0.015905,
756         "t_rel":0.015905,
757         "nesting":1,
758         "category":"process",
759         "key":"windows/ancestry",
760         "value":["bash.exe","bash.exe"]
761 }
762 ------------
763
764 == Example Trace2 API Usage
765
766 Here is a hypothetical usage of the Trace2 API showing the intended
767 usage (without worrying about the actual Git details).
768
769 Initialization::
770
771         Initialization happens in `main()`.  Behind the scenes, an
772         `atexit` and `signal` handler are registered.
773 +
774 ----------------
775 int main(int argc, const char **argv)
776 {
777         int exit_code;
778
779         trace2_initialize();
780         trace2_cmd_start(argv);
781
782         exit_code = cmd_main(argc, argv);
783
784         trace2_cmd_exit(exit_code);
785
786         return exit_code;
787 }
788 ----------------
789
790 Command Details::
791
792         After the basics are established, additional command
793         information can be sent to Trace2 as it is discovered.
794 +
795 ----------------
796 int cmd_checkout(int argc, const char **argv)
797 {
798         trace2_cmd_name("checkout");
799         trace2_cmd_mode("branch");
800         trace2_def_repo(the_repository);
801
802         // emit "def_param" messages for "interesting" config settings.
803         trace2_cmd_list_config();
804
805         if (do_something())
806             trace2_cmd_error("Path '%s': cannot do something", path);
807
808         return 0;
809 }
810 ----------------
811
812 Child Processes::
813
814         Wrap code spawning child processes.
815 +
816 ----------------
817 void run_child(...)
818 {
819         int child_exit_code;
820         struct child_process cmd = CHILD_PROCESS_INIT;
821         ...
822         cmd.trace2_child_class = "editor";
823
824         trace2_child_start(&cmd);
825         child_exit_code = spawn_child_and_wait_for_it();
826         trace2_child_exit(&cmd, child_exit_code);
827 }
828 ----------------
829 +
830 For example, the following fetch command spawned ssh, index-pack,
831 rev-list, and gc.  This example also shows that fetch took
832 5.199 seconds and of that 4.932 was in ssh.
833 +
834 ----------------
835 $ export GIT_TRACE2_BRIEF=1
836 $ export GIT_TRACE2=~/log.normal
837 $ git fetch origin
838 ...
839 ----------------
840 +
841 ----------------
842 $ cat ~/log.normal
843 version 2.20.1.vfs.1.1.47.g534dbe1ad1
844 start git fetch origin
845 worktree /Users/jeffhost/work/gfw
846 cmd_name fetch (fetch)
847 child_start[0] ssh git@github.com ...
848 child_start[1] git index-pack ...
849 ... (Trace2 events from child processes omitted)
850 child_exit[1] pid:14707 code:0 elapsed:0.076353
851 child_exit[0] pid:14706 code:0 elapsed:4.931869
852 child_start[2] git rev-list ...
853 ... (Trace2 events from child process omitted)
854 child_exit[2] pid:14708 code:0 elapsed:0.110605
855 child_start[3] git gc --auto
856 ... (Trace2 events from child process omitted)
857 child_exit[3] pid:14709 code:0 elapsed:0.006240
858 exit elapsed:5.198503 code:0
859 atexit elapsed:5.198541 code:0
860 ----------------
861 +
862 When a git process is a (direct or indirect) child of another
863 git process, it inherits Trace2 context information.  This
864 allows the child to print the command hierarchy.  This example
865 shows gc as child[3] of fetch.  When the gc process reports
866 its name as "gc", it also reports the hierarchy as "fetch/gc".
867 (In this example, trace2 messages from the child process is
868 indented for clarity.)
869 +
870 ----------------
871 $ export GIT_TRACE2_BRIEF=1
872 $ export GIT_TRACE2=~/log.normal
873 $ git fetch origin
874 ...
875 ----------------
876 +
877 ----------------
878 $ cat ~/log.normal
879 version 2.20.1.160.g5676107ecd.dirty
880 start git fetch official
881 worktree /Users/jeffhost/work/gfw
882 cmd_name fetch (fetch)
883 ...
884 child_start[3] git gc --auto
885     version 2.20.1.160.g5676107ecd.dirty
886     start /Users/jeffhost/work/gfw/git gc --auto
887     worktree /Users/jeffhost/work/gfw
888     cmd_name gc (fetch/gc)
889     exit elapsed:0.001959 code:0
890     atexit elapsed:0.001997 code:0
891 child_exit[3] pid:20303 code:0 elapsed:0.007564
892 exit elapsed:3.868938 code:0
893 atexit elapsed:3.868970 code:0
894 ----------------
895
896 Regions::
897
898         Regions can be use to time an interesting section of code.
899 +
900 ----------------
901 void wt_status_collect(struct wt_status *s)
902 {
903         trace2_region_enter("status", "worktrees", s->repo);
904         wt_status_collect_changes_worktree(s);
905         trace2_region_leave("status", "worktrees", s->repo);
906
907         trace2_region_enter("status", "index", s->repo);
908         wt_status_collect_changes_index(s);
909         trace2_region_leave("status", "index", s->repo);
910
911         trace2_region_enter("status", "untracked", s->repo);
912         wt_status_collect_untracked(s);
913         trace2_region_leave("status", "untracked", s->repo);
914 }
915
916 void wt_status_print(struct wt_status *s)
917 {
918         trace2_region_enter("status", "print", s->repo);
919         switch (s->status_format) {
920             ...
921         }
922         trace2_region_leave("status", "print", s->repo);
923 }
924 ----------------
925 +
926 In this example, scanning for untracked files ran from +0.012568 to
927 +0.027149 (since the process started) and took 0.014581 seconds.
928 +
929 ----------------
930 $ export GIT_TRACE2_PERF_BRIEF=1
931 $ export GIT_TRACE2_PERF=~/log.perf
932 $ git status
933 ...
934
935 $ cat ~/log.perf
936 d0 | main                     | version      |     |           |           |            | 2.20.1.160.g5676107ecd.dirty
937 d0 | main                     | start        |     |  0.001173 |           |            | git status
938 d0 | main                     | def_repo     | r1  |           |           |            | worktree:/Users/jeffhost/work/gfw
939 d0 | main                     | cmd_name     |     |           |           |            | status (status)
940 ...
941 d0 | main                     | region_enter | r1  |  0.010988 |           | status     | label:worktrees
942 d0 | main                     | region_leave | r1  |  0.011236 |  0.000248 | status     | label:worktrees
943 d0 | main                     | region_enter | r1  |  0.011260 |           | status     | label:index
944 d0 | main                     | region_leave | r1  |  0.012542 |  0.001282 | status     | label:index
945 d0 | main                     | region_enter | r1  |  0.012568 |           | status     | label:untracked
946 d0 | main                     | region_leave | r1  |  0.027149 |  0.014581 | status     | label:untracked
947 d0 | main                     | region_enter | r1  |  0.027411 |           | status     | label:print
948 d0 | main                     | region_leave | r1  |  0.028741 |  0.001330 | status     | label:print
949 d0 | main                     | exit         |     |  0.028778 |           |            | code:0
950 d0 | main                     | atexit       |     |  0.028809 |           |            | code:0
951 ----------------
952 +
953 Regions may be nested.  This causes messages to be indented in the
954 PERF target, for example.
955 Elapsed times are relative to the start of the corresponding nesting
956 level as expected.  For example, if we add region message to:
957 +
958 ----------------
959 static enum path_treatment read_directory_recursive(struct dir_struct *dir,
960         struct index_state *istate, const char *base, int baselen,
961         struct untracked_cache_dir *untracked, int check_only,
962         int stop_at_first_file, const struct pathspec *pathspec)
963 {
964         enum path_treatment state, subdir_state, dir_state = path_none;
965
966         trace2_region_enter_printf("dir", "read_recursive", NULL, "%.*s", baselen, base);
967         ...
968         trace2_region_leave_printf("dir", "read_recursive", NULL, "%.*s", baselen, base);
969         return dir_state;
970 }
971 ----------------
972 +
973 We can further investigate the time spent scanning for untracked files.
974 +
975 ----------------
976 $ export GIT_TRACE2_PERF_BRIEF=1
977 $ export GIT_TRACE2_PERF=~/log.perf
978 $ git status
979 ...
980 $ cat ~/log.perf
981 d0 | main                     | version      |     |           |           |            | 2.20.1.162.gb4ccea44db.dirty
982 d0 | main                     | start        |     |  0.001173 |           |            | git status
983 d0 | main                     | def_repo     | r1  |           |           |            | worktree:/Users/jeffhost/work/gfw
984 d0 | main                     | cmd_name     |     |           |           |            | status (status)
985 ...
986 d0 | main                     | region_enter | r1  |  0.015047 |           | status     | label:untracked
987 d0 | main                     | region_enter |     |  0.015132 |           | dir        | ..label:read_recursive
988 d0 | main                     | region_enter |     |  0.016341 |           | dir        | ....label:read_recursive vcs-svn/
989 d0 | main                     | region_leave |     |  0.016422 |  0.000081 | dir        | ....label:read_recursive vcs-svn/
990 d0 | main                     | region_enter |     |  0.016446 |           | dir        | ....label:read_recursive xdiff/
991 d0 | main                     | region_leave |     |  0.016522 |  0.000076 | dir        | ....label:read_recursive xdiff/
992 d0 | main                     | region_enter |     |  0.016612 |           | dir        | ....label:read_recursive git-gui/
993 d0 | main                     | region_enter |     |  0.016698 |           | dir        | ......label:read_recursive git-gui/po/
994 d0 | main                     | region_enter |     |  0.016810 |           | dir        | ........label:read_recursive git-gui/po/glossary/
995 d0 | main                     | region_leave |     |  0.016863 |  0.000053 | dir        | ........label:read_recursive git-gui/po/glossary/
996 ...
997 d0 | main                     | region_enter |     |  0.031876 |           | dir        | ....label:read_recursive builtin/
998 d0 | main                     | region_leave |     |  0.032270 |  0.000394 | dir        | ....label:read_recursive builtin/
999 d0 | main                     | region_leave |     |  0.032414 |  0.017282 | dir        | ..label:read_recursive
1000 d0 | main                     | region_leave | r1  |  0.032454 |  0.017407 | status     | label:untracked
1001 ...
1002 d0 | main                     | exit         |     |  0.034279 |           |            | code:0
1003 d0 | main                     | atexit       |     |  0.034322 |           |            | code:0
1004 ----------------
1005 +
1006 Trace2 regions are similar to the existing trace_performance_enter()
1007 and trace_performance_leave() routines, but are thread safe and
1008 maintain per-thread stacks of timers.
1009
1010 Data Messages::
1011
1012         Data messages added to a region.
1013 +
1014 ----------------
1015 int read_index_from(struct index_state *istate, const char *path,
1016         const char *gitdir)
1017 {
1018         trace2_region_enter_printf("index", "do_read_index", the_repository, "%s", path);
1019
1020         ...
1021
1022         trace2_data_intmax("index", the_repository, "read/version", istate->version);
1023         trace2_data_intmax("index", the_repository, "read/cache_nr", istate->cache_nr);
1024
1025         trace2_region_leave_printf("index", "do_read_index", the_repository, "%s", path);
1026 }
1027 ----------------
1028 +
1029 This example shows that the index contained 3552 entries.
1030 +
1031 ----------------
1032 $ export GIT_TRACE2_PERF_BRIEF=1
1033 $ export GIT_TRACE2_PERF=~/log.perf
1034 $ git status
1035 ...
1036 $ cat ~/log.perf
1037 d0 | main                     | version      |     |           |           |            | 2.20.1.156.gf9916ae094.dirty
1038 d0 | main                     | start        |     |  0.001173 |           |            | git status
1039 d0 | main                     | def_repo     | r1  |           |           |            | worktree:/Users/jeffhost/work/gfw
1040 d0 | main                     | cmd_name     |     |           |           |            | status (status)
1041 d0 | main                     | region_enter | r1  |  0.001791 |           | index      | label:do_read_index .git/index
1042 d0 | main                     | data         | r1  |  0.002494 |  0.000703 | index      | ..read/version:2
1043 d0 | main                     | data         | r1  |  0.002520 |  0.000729 | index      | ..read/cache_nr:3552
1044 d0 | main                     | region_leave | r1  |  0.002539 |  0.000748 | index      | label:do_read_index .git/index
1045 ...
1046 ----------------
1047
1048 Thread Events::
1049
1050         Thread messages added to a thread-proc.
1051 +
1052 For example, the multithreaded preload-index code can be
1053 instrumented with a region around the thread pool and then
1054 per-thread start and exit events within the threadproc.
1055 +
1056 ----------------
1057 static void *preload_thread(void *_data)
1058 {
1059         // start the per-thread clock and emit a message.
1060         trace2_thread_start("preload_thread");
1061
1062         // report which chunk of the array this thread was assigned.
1063         trace2_data_intmax("index", the_repository, "offset", p->offset);
1064         trace2_data_intmax("index", the_repository, "count", nr);
1065
1066         do {
1067             ...
1068         } while (--nr > 0);
1069         ...
1070
1071         // report elapsed time taken by this thread.
1072         trace2_thread_exit();
1073         return NULL;
1074 }
1075
1076 void preload_index(struct index_state *index,
1077         const struct pathspec *pathspec,
1078         unsigned int refresh_flags)
1079 {
1080         trace2_region_enter("index", "preload", the_repository);
1081
1082         for (i = 0; i < threads; i++) {
1083             ... /* create thread */
1084         }
1085
1086         for (i = 0; i < threads; i++) {
1087             ... /* join thread */
1088         }
1089
1090         trace2_region_leave("index", "preload", the_repository);
1091 }
1092 ----------------
1093 +
1094 In this example preload_index() was executed by the `main` thread
1095 and started the `preload` region.  Seven threads, named
1096 `th01:preload_thread` through `th07:preload_thread`, were started.
1097 Events from each thread are atomically appended to the shared target
1098 stream as they occur so they may appear in random order with respect
1099 other threads. Finally, the main thread waits for the threads to
1100 finish and leaves the region.
1101 +
1102 Data events are tagged with the active thread name.  They are used
1103 to report the per-thread parameters.
1104 +
1105 ----------------
1106 $ export GIT_TRACE2_PERF_BRIEF=1
1107 $ export GIT_TRACE2_PERF=~/log.perf
1108 $ git status
1109 ...
1110 $ cat ~/log.perf
1111 ...
1112 d0 | main                     | region_enter | r1  |  0.002595 |           | index      | label:preload
1113 d0 | th01:preload_thread      | thread_start |     |  0.002699 |           |            |
1114 d0 | th02:preload_thread      | thread_start |     |  0.002721 |           |            |
1115 d0 | th01:preload_thread      | data         | r1  |  0.002736 |  0.000037 | index      | offset:0
1116 d0 | th02:preload_thread      | data         | r1  |  0.002751 |  0.000030 | index      | offset:2032
1117 d0 | th03:preload_thread      | thread_start |     |  0.002711 |           |            |
1118 d0 | th06:preload_thread      | thread_start |     |  0.002739 |           |            |
1119 d0 | th01:preload_thread      | data         | r1  |  0.002766 |  0.000067 | index      | count:508
1120 d0 | th06:preload_thread      | data         | r1  |  0.002856 |  0.000117 | index      | offset:2540
1121 d0 | th03:preload_thread      | data         | r1  |  0.002824 |  0.000113 | index      | offset:1016
1122 d0 | th04:preload_thread      | thread_start |     |  0.002710 |           |            |
1123 d0 | th02:preload_thread      | data         | r1  |  0.002779 |  0.000058 | index      | count:508
1124 d0 | th06:preload_thread      | data         | r1  |  0.002966 |  0.000227 | index      | count:508
1125 d0 | th07:preload_thread      | thread_start |     |  0.002741 |           |            |
1126 d0 | th07:preload_thread      | data         | r1  |  0.003017 |  0.000276 | index      | offset:3048
1127 d0 | th05:preload_thread      | thread_start |     |  0.002712 |           |            |
1128 d0 | th05:preload_thread      | data         | r1  |  0.003067 |  0.000355 | index      | offset:1524
1129 d0 | th05:preload_thread      | data         | r1  |  0.003090 |  0.000378 | index      | count:508
1130 d0 | th07:preload_thread      | data         | r1  |  0.003037 |  0.000296 | index      | count:504
1131 d0 | th03:preload_thread      | data         | r1  |  0.002971 |  0.000260 | index      | count:508
1132 d0 | th04:preload_thread      | data         | r1  |  0.002983 |  0.000273 | index      | offset:508
1133 d0 | th04:preload_thread      | data         | r1  |  0.007311 |  0.004601 | index      | count:508
1134 d0 | th05:preload_thread      | thread_exit  |     |  0.008781 |  0.006069 |            |
1135 d0 | th01:preload_thread      | thread_exit  |     |  0.009561 |  0.006862 |            |
1136 d0 | th03:preload_thread      | thread_exit  |     |  0.009742 |  0.007031 |            |
1137 d0 | th06:preload_thread      | thread_exit  |     |  0.009820 |  0.007081 |            |
1138 d0 | th02:preload_thread      | thread_exit  |     |  0.010274 |  0.007553 |            |
1139 d0 | th07:preload_thread      | thread_exit  |     |  0.010477 |  0.007736 |            |
1140 d0 | th04:preload_thread      | thread_exit  |     |  0.011657 |  0.008947 |            |
1141 d0 | main                     | region_leave | r1  |  0.011717 |  0.009122 | index      | label:preload
1142 ...
1143 d0 | main                     | exit         |     |  0.029996 |           |            | code:0
1144 d0 | main                     | atexit       |     |  0.030027 |           |            | code:0
1145 ----------------
1146 +
1147 In this example, the preload region took 0.009122 seconds.  The 7 threads
1148 took between 0.006069 and 0.008947 seconds to work on their portion of
1149 the index.  Thread "th01" worked on 508 items at offset 0.  Thread "th02"
1150 worked on 508 items at offset 2032.  Thread "th04" worked on 508 items
1151 at offset 508.
1152 +
1153 This example also shows that thread names are assigned in a racy manner
1154 as each thread starts and allocates TLS storage.
1155
1156 == Future Work
1157
1158 === Relationship to the Existing Trace Api (api-trace.txt)
1159
1160 There are a few issues to resolve before we can completely
1161 switch to Trace2.
1162
1163 * Updating existing tests that assume GIT_TRACE format messages.
1164
1165 * How to best handle custom GIT_TRACE_<key> messages?
1166
1167 ** The GIT_TRACE_<key> mechanism allows each <key> to write to a
1168 different file (in addition to just stderr).
1169
1170 ** Do we want to maintain that ability or simply write to the existing
1171 Trace2 targets (and convert <key> to a "category").