Revert "test-lib: whitelist GIT_TR2_* in the environment"
[git/git.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_TR`
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":"1","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 If the target already exists and is a directory, the traces will be
146 written to files (one per process) underneath the given directory. They
147 will be named according to the last component of the SID (optionally
148 followed by a counter to avoid filename collisions).
149
150 == Trace2 API
151
152 All public Trace2 functions and macros are defined in `trace2.h` and
153 `trace2.c`. All public symbols are prefixed with `trace2_`.
154
155 There are no public Trace2 data structures.
156
157 The Trace2 code also defines a set of private functions and data types
158 in the `trace2/` directory. These symbols are prefixed with `tr2_`
159 and should only be used by functions in `trace2.c`.
160
161 == Conventions for Public Functions and Macros
162
163 The functions defined by the Trace2 API are declared and documented
164 in `trace2.h`. It defines the API functions and wrapper macros for
165 Trace2.
166
167 Some functions have a `_fl()` suffix to indicate that they take `file`
168 and `line-number` arguments.
169
170 Some functions have a `_va_fl()` suffix to indicate that they also
171 take a `va_list` argument.
172
173 Some functions have a `_printf_fl()` suffix to indicate that they also
174 take a varargs argument.
175
176 There are CPP wrapper macros and ifdefs to hide most of these details.
177 See `trace2.h` for more details. The following discussion will only
178 describe the simplified forms.
179
180 == Public API
181
182 All Trace2 API functions send a messsage to all of the active
183 Trace2 Targets. This section describes the set of available
184 messages.
185
186 It helps to divide these functions into groups for discussion
187 purposes.
188
189 === Basic Command Messages
190
191 These are concerned with the lifetime of the overall git process.
192
193 `void trace2_initialize_clock()`::
194
195 Initialize the Trace2 start clock and nothing else. This should
196 be called at the very top of main() to capture the process start
197 time and reduce startup order dependencies.
198
199 `void trace2_initialize()`::
200
201 Determines if any Trace2 Targets should be enabled and
202 initializes the Trace2 facility. This includes setting up the
203 Trace2 thread local storage (TLS).
204 +
205 This function emits a "version" message containing the version of git
206 and the Trace2 protocol.
207 +
208 This function should be called from `main()` as early as possible in
209 the life of the process after essential process initialization.
210
211 `int trace2_is_enabled()`::
212
213 Returns 1 if Trace2 is enabled (at least one target is
214 active).
215
216 `void trace2_cmd_start(int argc, const char **argv)`::
217
218 Emits a "start" message containing the process command line
219 arguments.
220
221 `int trace2_cmd_exit(int exit_code)`::
222
223 Emits an "exit" message containing the process exit-code and
224 elapsed time.
225 +
226 Returns the exit-code.
227
228 `void trace2_cmd_error(const char *fmt, va_list ap)`::
229
230 Emits an "error" message containing a formatted error message.
231
232 `void trace2_cmd_path(const char *pathname)`::
233
234 Emits a "cmd_path" message with the full pathname of the
235 current process.
236
237 === Command Detail Messages
238
239 These are concerned with describing the specific Git command
240 after the command line, config, and environment are inspected.
241
242 `void trace2_cmd_name(const char *name)`::
243
244 Emits a "cmd_name" message with the canonical name of the
245 command, for example "status" or "checkout".
246
247 `void trace2_cmd_mode(const char *mode)`::
248
249 Emits a "cmd_mode" message with a qualifier name to further
250 describe the current git command.
251 +
252 This message is intended to be used with git commands having multiple
253 major modes. For example, a "checkout" command can checkout a new
254 branch or it can checkout a single file, so the checkout code could
255 emit a cmd_mode message of "branch" or "file".
256
257 `void trace2_cmd_alias(const char *alias, const char **argv_expansion)`::
258
259 Emits an "alias" message containing the alias used and the
260 argument expansion.
261
262 `void trace2_def_param(const char *parameter, const char *value)`::
263
264 Emits a "def_param" message containing a key/value pair.
265 +
266 This message is intended to report some global aspect of the current
267 command, such as a configuration setting or command line switch that
268 significantly affects program performance or behavior, such as
269 `core.abbrev`, `status.showUntrackedFiles`, or `--no-ahead-behind`.
270
271 `void trace2_cmd_list_config()`::
272
273 Emits a "def_param" messages for "important" configuration
274 settings.
275 +
276 The environment variable `GIT_TRACE2_CONFIG_PARAMS` or the `trace2.configParams`
277 config value can be set to a
278 list of patterns of important configuration settings, for example:
279 `core.*,remote.*.url`. This function will iterate over all config
280 settings and emit a "def_param" message for each match.
281
282 `void trace2_cmd_set_config(const char *key, const char *value)`::
283
284 Emits a "def_param" message for a new or updated key/value
285 pair IF `key` is considered important.
286 +
287 This is used to hook into `git_config_set()` and catch any
288 configuration changes and update a value previously reported by
289 `trace2_cmd_list_config()`.
290
291 `void trace2_def_repo(struct repository *repo)`::
292
293 Registers a repository with the Trace2 layer. Assigns a
294 unique "repo-id" to `repo->trace2_repo_id`.
295 +
296 Emits a "worktree" messages containing the repo-id and the worktree
297 pathname.
298 +
299 Region and data messages (described later) may refer to this repo-id.
300 +
301 The main/top-level repository will have repo-id value 1 (aka "r1").
302 +
303 The repo-id field is in anticipation of future in-proc submodule
304 repositories.
305
306 === Child Process Messages
307
308 These are concerned with the various spawned child processes,
309 including shell scripts, git commands, editors, pagers, and hooks.
310
311 `void trace2_child_start(struct child_process *cmd)`::
312
313 Emits a "child_start" message containing the "child-id",
314 "child-argv", and "child-classification".
315 +
316 Before calling this, set `cmd->trace2_child_class` to a name
317 describing the type of child process, for example "editor".
318 +
319 This function assigns a unique "child-id" to `cmd->trace2_child_id`.
320 This field is used later during the "child_exit" message to associate
321 it with the "child_start" message.
322 +
323 This function should be called before spawning the child process.
324
325 `void trace2_child_exit(struct child_proess *cmd, int child_exit_code)`::
326
327 Emits a "child_exit" message containing the "child-id",
328 the child's elapsed time and exit-code.
329 +
330 The reported elapsed time includes the process creation overhead and
331 time spend waiting for it to exit, so it may be slightly longer than
332 the time reported by the child itself.
333 +
334 This function should be called after reaping the child process.
335
336 `int trace2_exec(const char *exe, const char **argv)`::
337
338 Emits a "exec" message containing the "exec-id" and the
339 argv of the new process.
340 +
341 This function should be called before calling one of the `exec()`
342 variants, such as `execvp()`.
343 +
344 This function returns a unique "exec-id". This value is used later
345 if the exec() fails and a "exec-result" message is necessary.
346
347 `void trace2_exec_result(int exec_id, int error_code)`::
348
349 Emits a "exec_result" message containing the "exec-id"
350 and the error code.
351 +
352 On Unix-based systems, `exec()` does not return if successful.
353 This message is used to indicate that the `exec()` failed and
354 that the current program is continuing.
355
356 === Git Thread Messages
357
358 These messages are concerned with Git thread usage.
359
360 `void trace2_thread_start(const char *thread_name)`::
361
362 Emits a "thread_start" message.
363 +
364 The `thread_name` field should be a descriptive name, such as the
365 unique name of the thread-proc. A unique "thread-id" will be added
366 to the name to uniquely identify thread instances.
367 +
368 Region and data messages (described later) may refer to this thread
369 name.
370 +
371 This function must be called by the thread-proc of the new thread
372 (so that TLS data is properly initialized) and not by the caller
373 of `pthread_create()`.
374
375 `void trace2_thread_exit()`::
376
377 Emits a "thread_exit" message containing the thread name
378 and the thread elapsed time.
379 +
380 This function must be called by the thread-proc before it returns
381 (so that the coorect TLS data is used and cleaned up. It should
382 not be called by the caller of `pthread_join()`.
383
384 === Region and Data Messages
385
386 These are concerned with recording performance data
387 over regions or spans of code.
388
389 `void trace2_region_enter(const char *category, const char *label, const struct repository *repo)`::
390
391 `void trace2_region_enter_printf(const char *category, const char *label, const struct repository *repo, const char *fmt, ...)`::
392
393 `void trace2_region_enter_printf_va(const char *category, const char *label, const struct repository *repo, const char *fmt, va_list ap)`::
394
395 Emits a thread-relative "region_enter" message with optional
396 printf string.
397 +
398 This function pushes a new region nesting stack level on the current
399 thread and starts a clock for the new stack frame.
400 +
401 The `category` field is an arbitrary category name used to classify
402 regions by feature area, such as "status" or "index". At this time
403 it is only just printed along with the rest of the message. It may
404 be used in the future to filter messages.
405 +
406 The `label` field is an arbitrary label used to describe the activity
407 being started, such as "read_recursive" or "do_read_index".
408 +
409 The `repo` field, if set, will be used to get the "repo-id", so that
410 recursive oerations can be attributed to the correct repository.
411
412 `void trace2_region_leave(const char *category, const char *label, const struct repository *repo)`::
413
414 `void trace2_region_leave_printf(const char *category, const char *label, const struct repository *repo, const char *fmt, ...)`::
415
416 `void trace2_region_leave_printf_va(const char *category, const char *label, const struct repository *repo, const char *fmt, va_list ap)`::
417
418 Emits a thread-relative "region_leave" message with optional
419 printf string.
420 +
421 This function pops the region nesting stack on the current thread
422 and reports the elapsed time of the stack frame.
423 +
424 The `category`, `label`, and `repo` fields are the same as above.
425 The `category` and `label` do not need to match the correpsonding
426 "region_enter" message, but it makes the data stream easier to
427 understand.
428
429 `void trace2_data_string(const char *category, const struct repository *repo, const char *key, const char * value)`::
430
431 `void trace2_data_intmax(const char *category, const struct repository *repo, const char *key, intmax value)`::
432
433 `void trace2_data_json(const char *category, const struct repository *repo, const char *key, const struct json_writer *jw)`::
434
435 Emits a region- and thread-relative "data" or "data_json" message.
436 +
437 This is a key/value pair message containing information about the
438 current thread, region stack, and repository. This could be used
439 to print the number of files in a directory during a multi-threaded
440 recursive tree walk.
441
442 `void trace2_printf(const char *fmt, ...)`::
443
444 `void trace2_printf_va(const char *fmt, va_list ap)`::
445
446 Emits a region- and thread-relative "printf" message.
447
448 == Trace2 Target Formats
449
450 === NORMAL Format
451
452 Events are written as lines of the form:
453
454 ------------
455 [<time> SP <filename>:<line> SP+] <event-name> [[SP] <event-message>] LF
456 ------------
457
458 `<event-name>`::
459
460 is the event name.
461
462 `<event-message>`::
463 is a free-form printf message intended for human consumption.
464 +
465 Note that this may contain embedded LF or CRLF characters that are
466 not escaped, so the event may spill across multiple lines.
467
468 If `GIT_TRACE2_BRIEF` or `trace2.normalBrief` is true, the `time`, `filename`,
469 and `line` fields are omitted.
470
471 This target is intended to be more of a summary (like GIT_TRACE) and
472 less detailed than the other targets. It ignores thread, region, and
473 data messages, for example.
474
475 === PERF Format
476
477 Events are written as lines of the form:
478
479 ------------
480 [<time> SP <filename>:<line> SP+
481 BAR SP] d<depth> SP
482 BAR SP <thread-name> SP+
483 BAR SP <event-name> SP+
484 BAR SP [r<repo-id>] SP+
485 BAR SP [<t_abs>] SP+
486 BAR SP [<t_rel>] SP+
487 BAR SP [<category>] SP+
488 BAR SP DOTS* <perf-event-message>
489 LF
490 ------------
491
492 `<depth>`::
493 is the git process depth. This is the number of parent
494 git processes. A top-level git command has depth value "d0".
495 A child of it has depth value "d1". A second level child
496 has depth value "d2" and so on.
497
498 `<thread-name>`::
499 is a unique name for the thread. The primary thread
500 is called "main". Other thread names are of the form "th%d:%s"
501 and include a unique number and the name of the thread-proc.
502
503 `<event-name>`::
504 is the event name.
505
506 `<repo-id>`::
507 when present, is a number indicating the repository
508 in use. A `def_repo` event is emitted when a repository is
509 opened. This defines the repo-id and associated worktree.
510 Subsequent repo-specific events will reference this repo-id.
511 +
512 Currently, this is always "r1" for the main repository.
513 This field is in anticipation of in-proc submodules in the future.
514
515 `<t_abs>`::
516 when present, is the absolute time in seconds since the
517 program started.
518
519 `<t_rel>`::
520 when present, is time in seconds relative to the start of
521 the current region. For a thread-exit event, it is the elapsed
522 time of the thread.
523
524 `<category>`::
525 is present on region and data events and is used to
526 indicate a broad category, such as "index" or "status".
527
528 `<perf-event-message>`::
529 is a free-form printf message intended for human consumption.
530
531 ------------
532 15:33:33.532712 wt-status.c:2310 | d0 | main | region_enter | r1 | 0.126064 | | status | label:print
533 15:33:33.532712 wt-status.c:2331 | d0 | main | region_leave | r1 | 0.127568 | 0.001504 | status | label:print
534 ------------
535
536 If `GIT_TRACE2_PERF_BRIEF` or `trace2.perfBrief` is true, the `time`, `file`,
537 and `line` fields are omitted.
538
539 ------------
540 d0 | main | region_leave | r1 | 0.011717 | 0.009122 | index | label:preload
541 ------------
542
543 The PERF target is intended for interactive performance analysis
544 during development and is quite noisy.
545
546 === EVENT Format
547
548 Each event is a JSON-object containing multiple key/value pairs
549 written as a single line and followed by a LF.
550
551 ------------
552 '{' <key> ':' <value> [',' <key> ':' <value>]* '}' LF
553 ------------
554
555 Some key/value pairs are common to all events and some are
556 event-specific.
557
558 ==== Common Key/Value Pairs
559
560 The following key/value pairs are common to all events:
561
562 ------------
563 {
564 "event":"version",
565 "sid":"20190408T191827.272759Z-H9b68c35f-P00003510",
566 "thread":"main",
567 "time":"2019-04-08T19:18:27.282761Z",
568 "file":"common-main.c",
569 "line":42,
570 ...
571 }
572 ------------
573
574 `"event":<event>`::
575 is the event name.
576
577 `"sid":<sid>`::
578 is the session-id. This is a unique string to identify the
579 process instance to allow all events emitted by a process to
580 be identified. A session-id is used instead of a PID because
581 PIDs are recycled by the OS. For child git processes, the
582 session-id is prepended with the session-id of the parent git
583 process to allow parent-child relationships to be identified
584 during post-processing.
585
586 `"thread":<thread>`::
587 is the thread name.
588
589 `"time":<time>`::
590 is the UTC time of the event.
591
592 `"file":<filename>`::
593 is source file generating the event.
594
595 `"line":<line-number>`::
596 is the integer source line number generating the event.
597
598 `"repo":<repo-id>`::
599 when present, is the integer repo-id as described previously.
600
601 If `GIT_TRACE2_EVENT_BRIEF` or `trace2.eventBrief` is true, the `file`
602 and `line` fields are omitted from all events and the `time` field is
603 only present on the "start" and "atexit" events.
604
605 ==== Event-Specific Key/Value Pairs
606
607 `"version"`::
608 This event gives the version of the executable and the EVENT format.
609 +
610 ------------
611 {
612 "event":"version",
613 ...
614 "evt":"1", # EVENT format version
615 "exe":"2.20.1.155.g426c96fcdb" # git version
616 }
617 ------------
618
619 `"start"`::
620 This event contains the complete argv received by main().
621 +
622 ------------
623 {
624 "event":"start",
625 ...
626 "t_abs":0.001227, # elapsed time in seconds
627 "argv":["git","version"]
628 }
629 ------------
630
631 `"exit"`::
632 This event is emitted when git calls `exit()`.
633 +
634 ------------
635 {
636 "event":"exit",
637 ...
638 "t_abs":0.001227, # elapsed time in seconds
639 "code":0 # exit code
640 }
641 ------------
642
643 `"atexit"`::
644 This event is emitted by the Trace2 `atexit` routine during
645 final shutdown. It should be the last event emitted by the
646 process.
647 +
648 (The elapsed time reported here is greater than the time reported in
649 the "exit" event because it runs after all other atexit tasks have
650 completed.)
651 +
652 ------------
653 {
654 "event":"atexit",
655 ...
656 "t_abs":0.001227, # elapsed time in seconds
657 "code":0 # exit code
658 }
659 ------------
660
661 `"signal"`::
662 This event is emitted when the program is terminated by a user
663 signal. Depending on the platform, the signal event may
664 prevent the "atexit" event from being generated.
665 +
666 ------------
667 {
668 "event":"signal",
669 ...
670 "t_abs":0.001227, # elapsed time in seconds
671 "signal":13 # SIGTERM, SIGINT, etc.
672 }
673 ------------
674
675 `"error"`::
676 This event is emitted when one of the `error()`, `die()`,
677 or `usage()` functions are called.
678 +
679 ------------
680 {
681 "event":"error",
682 ...
683 "msg":"invalid option: --cahced", # formatted error message
684 "fmt":"invalid option: %s" # error format string
685 }
686 ------------
687 +
688 The error event may be emitted more than once. The format string
689 allows post-processors to group errors by type without worrying
690 about specific error arguments.
691
692 `"cmd_path"`::
693 This event contains the discovered full path of the git
694 executable (on platforms that are configured to resolve it).
695 +
696 ------------
697 {
698 "event":"cmd_path",
699 ...
700 "path":"C:/work/gfw/git.exe"
701 }
702 ------------
703
704 `"cmd_name"`::
705 This event contains the command name for this git process
706 and the hierarchy of commands from parent git processes.
707 +
708 ------------
709 {
710 "event":"cmd_name",
711 ...
712 "name":"pack-objects",
713 "hierarchy":"push/pack-objects"
714 }
715 ------------
716 +
717 Normally, the "name" field contains the canonical name of the
718 command. When a canonical name is not available, one of
719 these special values are used:
720 +
721 ------------
722 "_query_" # "git --html-path"
723 "_run_dashed_" # when "git foo" tries to run "git-foo"
724 "_run_shell_alias_" # alias expansion to a shell command
725 "_run_git_alias_" # alias expansion to a git command
726 "_usage_" # usage error
727 ------------
728
729 `"cmd_mode"`::
730 This event, when present, describes the command variant This
731 event may be emitted more than once.
732 +
733 ------------
734 {
735 "event":"cmd_mode",
736 ...
737 "name":"branch"
738 }
739 ------------
740 +
741 The "name" field is an arbitrary string to describe the command mode.
742 For example, checkout can checkout a branch or an individual file.
743 And these variations typically have different performance
744 characteristics that are not comparable.
745
746 `"alias"`::
747 This event is present when an alias is expanded.
748 +
749 ------------
750 {
751 "event":"alias",
752 ...
753 "alias":"l", # registered alias
754 "argv":["log","--graph"] # alias expansion
755 }
756 ------------
757
758 `"child_start"`::
759 This event describes a child process that is about to be
760 spawned.
761 +
762 ------------
763 {
764 "event":"child_start",
765 ...
766 "child_id":2,
767 "child_class":"?",
768 "use_shell":false,
769 "argv":["git","rev-list","--objects","--stdin","--not","--all","--quiet"]
770
771 "hook_name":"<hook_name>" # present when child_class is "hook"
772 "cd":"<path>" # present when cd is required
773 }
774 ------------
775 +
776 The "child_id" field can be used to match this child_start with the
777 corresponding child_exit event.
778 +
779 The "child_class" field is a rough classification, such as "editor",
780 "pager", "transport/*", and "hook". Unclassified children are classified
781 with "?".
782
783 `"child_exit"`::
784 This event is generated after the current process has returned
785 from the waitpid() and collected the exit information from the
786 child.
787 +
788 ------------
789 {
790 "event":"child_exit",
791 ...
792 "child_id":2,
793 "pid":14708, # child PID
794 "code":0, # child exit-code
795 "t_rel":0.110605 # observed run-time of child process
796 }
797 ------------
798 +
799 Note that the session-id of the child process is not available to
800 the current/spawning process, so the child's PID is reported here as
801 a hint for post-processing. (But it is only a hint because the child
802 proces may be a shell script which doesn't have a session-id.)
803 +
804 Note that the `t_rel` field contains the observed run time in seconds
805 for the child process (starting before the fork/exec/spawn and
806 stopping after the waitpid() and includes OS process creation overhead).
807 So this time will be slightly larger than the atexit time reported by
808 the child process itself.
809
810 `"exec"`::
811 This event is generated before git attempts to `exec()`
812 another command rather than starting a child process.
813 +
814 ------------
815 {
816 "event":"exec",
817 ...
818 "exec_id":0,
819 "exe":"git",
820 "argv":["foo", "bar"]
821 }
822 ------------
823 +
824 The "exec_id" field is a command-unique id and is only useful if the
825 `exec()` fails and a corresponding exec_result event is generated.
826
827 `"exec_result"`::
828 This event is generated if the `exec()` fails and control
829 returns to the current git command.
830 +
831 ------------
832 {
833 "event":"exec_result",
834 ...
835 "exec_id":0,
836 "code":1 # error code (errno) from exec()
837 }
838 ------------
839
840 `"thread_start"`::
841 This event is generated when a thread is started. It is
842 generated from *within* the new thread's thread-proc (for TLS
843 reasons).
844 +
845 ------------
846 {
847 "event":"thread_start",
848 ...
849 "thread":"th02:preload_thread" # thread name
850 }
851 ------------
852
853 `"thread_exit"`::
854 This event is generated when a thread exits. It is generated
855 from *within* the thread's thread-proc (for TLS reasons).
856 +
857 ------------
858 {
859 "event":"thread_exit",
860 ...
861 "thread":"th02:preload_thread", # thread name
862 "t_rel":0.007328 # thread elapsed time
863 }
864 ------------
865
866 `"def_param"`::
867 This event is generated to log a global parameter.
868 +
869 ------------
870 {
871 "event":"def_param",
872 ...
873 "param":"core.abbrev",
874 "value":"7"
875 }
876 ------------
877
878 `"def_repo"`::
879 This event defines a repo-id and associates it with the root
880 of the worktree.
881 +
882 ------------
883 {
884 "event":"def_repo",
885 ...
886 "repo":1,
887 "worktree":"/Users/jeffhost/work/gfw"
888 }
889 ------------
890 +
891 As stated earlier, the repo-id is currently always 1, so there will
892 only be one def_repo event. Later, if in-proc submodules are
893 supported, a def_repo event should be emitted for each submodule
894 visited.
895
896 `"region_enter"`::
897 This event is generated when entering a region.
898 +
899 ------------
900 {
901 "event":"region_enter",
902 ...
903 "repo":1, # optional
904 "nesting":1, # current region stack depth
905 "category":"index", # optional
906 "label":"do_read_index", # optional
907 "msg":".git/index" # optional
908 }
909 ------------
910 +
911 The `category` field may be used in a future enhancement to
912 do category-based filtering.
913 +
914 `GIT_TRACE2_EVENT_NESTING` or `trace2.eventNesting` can be used to
915 filter deeply nested regions and data events. It defaults to "2".
916
917 `"region_leave"`::
918 This event is generated when leaving a region.
919 +
920 ------------
921 {
922 "event":"region_leave",
923 ...
924 "repo":1, # optional
925 "t_rel":0.002876, # time spent in region in seconds
926 "nesting":1, # region stack depth
927 "category":"index", # optional
928 "label":"do_read_index", # optional
929 "msg":".git/index" # optional
930 }
931 ------------
932
933 `"data"`::
934 This event is generated to log a thread- and region-local
935 key/value pair.
936 +
937 ------------
938 {
939 "event":"data",
940 ...
941 "repo":1, # optional
942 "t_abs":0.024107, # absolute elapsed time
943 "t_rel":0.001031, # elapsed time in region/thread
944 "nesting":2, # region stack depth
945 "category":"index",
946 "key":"read/cache_nr",
947 "value":"3552"
948 }
949 ------------
950 +
951 The "value" field may be an integer or a string.
952
953 `"data-json"`::
954 This event is generated to log a pre-formatted JSON string
955 containing structured data.
956 +
957 ------------
958 {
959 "event":"data_json",
960 ...
961 "repo":1, # optional
962 "t_abs":0.015905,
963 "t_rel":0.015905,
964 "nesting":1,
965 "category":"process",
966 "key":"windows/ancestry",
967 "value":["bash.exe","bash.exe"]
968 }
969 ------------
970
971 == Example Trace2 API Usage
972
973 Here is a hypothetical usage of the Trace2 API showing the intended
974 usage (without worrying about the actual Git details).
975
976 Initialization::
977
978 Initialization happens in `main()`. Behind the scenes, an
979 `atexit` and `signal` handler are registered.
980 +
981 ----------------
982 int main(int argc, const char **argv)
983 {
984 int exit_code;
985
986 trace2_initialize();
987 trace2_cmd_start(argv);
988
989 exit_code = cmd_main(argc, argv);
990
991 trace2_cmd_exit(exit_code);
992
993 return exit_code;
994 }
995 ----------------
996
997 Command Details::
998
999 After the basics are established, additional command
1000 information can be sent to Trace2 as it is discovered.
1001 +
1002 ----------------
1003 int cmd_checkout(int argc, const char **argv)
1004 {
1005 trace2_cmd_name("checkout");
1006 trace2_cmd_mode("branch");
1007 trace2_def_repo(the_repository);
1008
1009 // emit "def_param" messages for "interesting" config settings.
1010 trace2_cmd_list_config();
1011
1012 if (do_something())
1013 trace2_cmd_error("Path '%s': cannot do something", path);
1014
1015 return 0;
1016 }
1017 ----------------
1018
1019 Child Processes::
1020
1021 Wrap code spawning child processes.
1022 +
1023 ----------------
1024 void run_child(...)
1025 {
1026 int child_exit_code;
1027 struct child_process cmd = CHILD_PROCESS_INIT;
1028 ...
1029 cmd.trace2_child_class = "editor";
1030
1031 trace2_child_start(&cmd);
1032 child_exit_code = spawn_child_and_wait_for_it();
1033 trace2_child_exit(&cmd, child_exit_code);
1034 }
1035 ----------------
1036 +
1037 For example, the following fetch command spawned ssh, index-pack,
1038 rev-list, and gc. This example also shows that fetch took
1039 5.199 seconds and of that 4.932 was in ssh.
1040 +
1041 ----------------
1042 $ export GIT_TRACE2_BRIEF=1
1043 $ export GIT_TRACE2=~/log.normal
1044 $ git fetch origin
1045 ...
1046 ----------------
1047 +
1048 ----------------
1049 $ cat ~/log.normal
1050 version 2.20.1.vfs.1.1.47.g534dbe1ad1
1051 start git fetch origin
1052 worktree /Users/jeffhost/work/gfw
1053 cmd_name fetch (fetch)
1054 child_start[0] ssh git@github.com ...
1055 child_start[1] git index-pack ...
1056 ... (Trace2 events from child processes omitted)
1057 child_exit[1] pid:14707 code:0 elapsed:0.076353
1058 child_exit[0] pid:14706 code:0 elapsed:4.931869
1059 child_start[2] git rev-list ...
1060 ... (Trace2 events from child process omitted)
1061 child_exit[2] pid:14708 code:0 elapsed:0.110605
1062 child_start[3] git gc --auto
1063 ... (Trace2 events from child process omitted)
1064 child_exit[3] pid:14709 code:0 elapsed:0.006240
1065 exit elapsed:5.198503 code:0
1066 atexit elapsed:5.198541 code:0
1067 ----------------
1068 +
1069 When a git process is a (direct or indirect) child of another
1070 git process, it inherits Trace2 context information. This
1071 allows the child to print the command hierarchy. This example
1072 shows gc as child[3] of fetch. When the gc process reports
1073 its name as "gc", it also reports the hierarchy as "fetch/gc".
1074 (In this example, trace2 messages from the child process is
1075 indented for clarity.)
1076 +
1077 ----------------
1078 $ export GIT_TRACE2_BRIEF=1
1079 $ export GIT_TRACE2=~/log.normal
1080 $ git fetch origin
1081 ...
1082 ----------------
1083 +
1084 ----------------
1085 $ cat ~/log.normal
1086 version 2.20.1.160.g5676107ecd.dirty
1087 start git fetch official
1088 worktree /Users/jeffhost/work/gfw
1089 cmd_name fetch (fetch)
1090 ...
1091 child_start[3] git gc --auto
1092 version 2.20.1.160.g5676107ecd.dirty
1093 start /Users/jeffhost/work/gfw/git gc --auto
1094 worktree /Users/jeffhost/work/gfw
1095 cmd_name gc (fetch/gc)
1096 exit elapsed:0.001959 code:0
1097 atexit elapsed:0.001997 code:0
1098 child_exit[3] pid:20303 code:0 elapsed:0.007564
1099 exit elapsed:3.868938 code:0
1100 atexit elapsed:3.868970 code:0
1101 ----------------
1102
1103 Regions::
1104
1105 Regions can be use to time an interesting section of code.
1106 +
1107 ----------------
1108 void wt_status_collect(struct wt_status *s)
1109 {
1110 trace2_region_enter("status", "worktrees", s->repo);
1111 wt_status_collect_changes_worktree(s);
1112 trace2_region_leave("status", "worktrees", s->repo);
1113
1114 trace2_region_enter("status", "index", s->repo);
1115 wt_status_collect_changes_index(s);
1116 trace2_region_leave("status", "index", s->repo);
1117
1118 trace2_region_enter("status", "untracked", s->repo);
1119 wt_status_collect_untracked(s);
1120 trace2_region_leave("status", "untracked", s->repo);
1121 }
1122
1123 void wt_status_print(struct wt_status *s)
1124 {
1125 trace2_region_enter("status", "print", s->repo);
1126 switch (s->status_format) {
1127 ...
1128 }
1129 trace2_region_leave("status", "print", s->repo);
1130 }
1131 ----------------
1132 +
1133 In this example, scanning for untracked files ran from +0.012568 to
1134 +0.027149 (since the process started) and took 0.014581 seconds.
1135 +
1136 ----------------
1137 $ export GIT_TRACE2_PERF_BRIEF=1
1138 $ export GIT_TRACE2_PERF=~/log.perf
1139 $ git status
1140 ...
1141
1142 $ cat ~/log.perf
1143 d0 | main | version | | | | | 2.20.1.160.g5676107ecd.dirty
1144 d0 | main | start | | 0.001173 | | | git status
1145 d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
1146 d0 | main | cmd_name | | | | | status (status)
1147 ...
1148 d0 | main | region_enter | r1 | 0.010988 | | status | label:worktrees
1149 d0 | main | region_leave | r1 | 0.011236 | 0.000248 | status | label:worktrees
1150 d0 | main | region_enter | r1 | 0.011260 | | status | label:index
1151 d0 | main | region_leave | r1 | 0.012542 | 0.001282 | status | label:index
1152 d0 | main | region_enter | r1 | 0.012568 | | status | label:untracked
1153 d0 | main | region_leave | r1 | 0.027149 | 0.014581 | status | label:untracked
1154 d0 | main | region_enter | r1 | 0.027411 | | status | label:print
1155 d0 | main | region_leave | r1 | 0.028741 | 0.001330 | status | label:print
1156 d0 | main | exit | | 0.028778 | | | code:0
1157 d0 | main | atexit | | 0.028809 | | | code:0
1158 ----------------
1159 +
1160 Regions may be nested. This causes messages to be indented in the
1161 PERF target, for example.
1162 Elapsed times are relative to the start of the correpsonding nesting
1163 level as expected. For example, if we add region message to:
1164 +
1165 ----------------
1166 static enum path_treatment read_directory_recursive(struct dir_struct *dir,
1167 struct index_state *istate, const char *base, int baselen,
1168 struct untracked_cache_dir *untracked, int check_only,
1169 int stop_at_first_file, const struct pathspec *pathspec)
1170 {
1171 enum path_treatment state, subdir_state, dir_state = path_none;
1172
1173 trace2_region_enter_printf("dir", "read_recursive", NULL, "%.*s", baselen, base);
1174 ...
1175 trace2_region_leave_printf("dir", "read_recursive", NULL, "%.*s", baselen, base);
1176 return dir_state;
1177 }
1178 ----------------
1179 +
1180 We can further investigate the time spent scanning for untracked files.
1181 +
1182 ----------------
1183 $ export GIT_TRACE2_PERF_BRIEF=1
1184 $ export GIT_TRACE2_PERF=~/log.perf
1185 $ git status
1186 ...
1187 $ cat ~/log.perf
1188 d0 | main | version | | | | | 2.20.1.162.gb4ccea44db.dirty
1189 d0 | main | start | | 0.001173 | | | git status
1190 d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
1191 d0 | main | cmd_name | | | | | status (status)
1192 ...
1193 d0 | main | region_enter | r1 | 0.015047 | | status | label:untracked
1194 d0 | main | region_enter | | 0.015132 | | dir | ..label:read_recursive
1195 d0 | main | region_enter | | 0.016341 | | dir | ....label:read_recursive vcs-svn/
1196 d0 | main | region_leave | | 0.016422 | 0.000081 | dir | ....label:read_recursive vcs-svn/
1197 d0 | main | region_enter | | 0.016446 | | dir | ....label:read_recursive xdiff/
1198 d0 | main | region_leave | | 0.016522 | 0.000076 | dir | ....label:read_recursive xdiff/
1199 d0 | main | region_enter | | 0.016612 | | dir | ....label:read_recursive git-gui/
1200 d0 | main | region_enter | | 0.016698 | | dir | ......label:read_recursive git-gui/po/
1201 d0 | main | region_enter | | 0.016810 | | dir | ........label:read_recursive git-gui/po/glossary/
1202 d0 | main | region_leave | | 0.016863 | 0.000053 | dir | ........label:read_recursive git-gui/po/glossary/
1203 ...
1204 d0 | main | region_enter | | 0.031876 | | dir | ....label:read_recursive builtin/
1205 d0 | main | region_leave | | 0.032270 | 0.000394 | dir | ....label:read_recursive builtin/
1206 d0 | main | region_leave | | 0.032414 | 0.017282 | dir | ..label:read_recursive
1207 d0 | main | region_leave | r1 | 0.032454 | 0.017407 | status | label:untracked
1208 ...
1209 d0 | main | exit | | 0.034279 | | | code:0
1210 d0 | main | atexit | | 0.034322 | | | code:0
1211 ----------------
1212 +
1213 Trace2 regions are similar to the existing trace_performance_enter()
1214 and trace_performance_leave() routines, but are thread safe and
1215 maintain per-thread stacks of timers.
1216
1217 Data Messages::
1218
1219 Data messages added to a region.
1220 +
1221 ----------------
1222 int read_index_from(struct index_state *istate, const char *path,
1223 const char *gitdir)
1224 {
1225 trace2_region_enter_printf("index", "do_read_index", the_repository, "%s", path);
1226
1227 ...
1228
1229 trace2_data_intmax("index", the_repository, "read/version", istate->version);
1230 trace2_data_intmax("index", the_repository, "read/cache_nr", istate->cache_nr);
1231
1232 trace2_region_leave_printf("index", "do_read_index", the_repository, "%s", path);
1233 }
1234 ----------------
1235 +
1236 This example shows that the index contained 3552 entries.
1237 +
1238 ----------------
1239 $ export GIT_TRACE2_PERF_BRIEF=1
1240 $ export GIT_TRACE2_PERF=~/log.perf
1241 $ git status
1242 ...
1243 $ cat ~/log.perf
1244 d0 | main | version | | | | | 2.20.1.156.gf9916ae094.dirty
1245 d0 | main | start | | 0.001173 | | | git status
1246 d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
1247 d0 | main | cmd_name | | | | | status (status)
1248 d0 | main | region_enter | r1 | 0.001791 | | index | label:do_read_index .git/index
1249 d0 | main | data | r1 | 0.002494 | 0.000703 | index | ..read/version:2
1250 d0 | main | data | r1 | 0.002520 | 0.000729 | index | ..read/cache_nr:3552
1251 d0 | main | region_leave | r1 | 0.002539 | 0.000748 | index | label:do_read_index .git/index
1252 ...
1253 ----------------
1254
1255 Thread Events::
1256
1257 Thread messages added to a thread-proc.
1258 +
1259 For example, the multithreaded preload-index code can be
1260 instrumented with a region around the thread pool and then
1261 per-thread start and exit events within the threadproc.
1262 +
1263 ----------------
1264 static void *preload_thread(void *_data)
1265 {
1266 // start the per-thread clock and emit a message.
1267 trace2_thread_start("preload_thread");
1268
1269 // report which chunk of the array this thread was assigned.
1270 trace2_data_intmax("index", the_repository, "offset", p->offset);
1271 trace2_data_intmax("index", the_repository, "count", nr);
1272
1273 do {
1274 ...
1275 } while (--nr > 0);
1276 ...
1277
1278 // report elapsed time taken by this thread.
1279 trace2_thread_exit();
1280 return NULL;
1281 }
1282
1283 void preload_index(struct index_state *index,
1284 const struct pathspec *pathspec,
1285 unsigned int refresh_flags)
1286 {
1287 trace2_region_enter("index", "preload", the_repository);
1288
1289 for (i = 0; i < threads; i++) {
1290 ... /* create thread */
1291 }
1292
1293 for (i = 0; i < threads; i++) {
1294 ... /* join thread */
1295 }
1296
1297 trace2_region_leave("index", "preload", the_repository);
1298 }
1299 ----------------
1300 +
1301 In this example preload_index() was executed by the `main` thread
1302 and started the `preload` region. Seven threads, named
1303 `th01:preload_thread` through `th07:preload_thread`, were started.
1304 Events from each thread are atomically appended to the shared target
1305 stream as they occur so they may appear in random order with respect
1306 other threads. Finally, the main thread waits for the threads to
1307 finish and leaves the region.
1308 +
1309 Data events are tagged with the active thread name. They are used
1310 to report the per-thread parameters.
1311 +
1312 ----------------
1313 $ export GIT_TRACE2_PERF_BRIEF=1
1314 $ export GIT_TRACE2_PERF=~/log.perf
1315 $ git status
1316 ...
1317 $ cat ~/log.perf
1318 ...
1319 d0 | main | region_enter | r1 | 0.002595 | | index | label:preload
1320 d0 | th01:preload_thread | thread_start | | 0.002699 | | |
1321 d0 | th02:preload_thread | thread_start | | 0.002721 | | |
1322 d0 | th01:preload_thread | data | r1 | 0.002736 | 0.000037 | index | offset:0
1323 d0 | th02:preload_thread | data | r1 | 0.002751 | 0.000030 | index | offset:2032
1324 d0 | th03:preload_thread | thread_start | | 0.002711 | | |
1325 d0 | th06:preload_thread | thread_start | | 0.002739 | | |
1326 d0 | th01:preload_thread | data | r1 | 0.002766 | 0.000067 | index | count:508
1327 d0 | th06:preload_thread | data | r1 | 0.002856 | 0.000117 | index | offset:2540
1328 d0 | th03:preload_thread | data | r1 | 0.002824 | 0.000113 | index | offset:1016
1329 d0 | th04:preload_thread | thread_start | | 0.002710 | | |
1330 d0 | th02:preload_thread | data | r1 | 0.002779 | 0.000058 | index | count:508
1331 d0 | th06:preload_thread | data | r1 | 0.002966 | 0.000227 | index | count:508
1332 d0 | th07:preload_thread | thread_start | | 0.002741 | | |
1333 d0 | th07:preload_thread | data | r1 | 0.003017 | 0.000276 | index | offset:3048
1334 d0 | th05:preload_thread | thread_start | | 0.002712 | | |
1335 d0 | th05:preload_thread | data | r1 | 0.003067 | 0.000355 | index | offset:1524
1336 d0 | th05:preload_thread | data | r1 | 0.003090 | 0.000378 | index | count:508
1337 d0 | th07:preload_thread | data | r1 | 0.003037 | 0.000296 | index | count:504
1338 d0 | th03:preload_thread | data | r1 | 0.002971 | 0.000260 | index | count:508
1339 d0 | th04:preload_thread | data | r1 | 0.002983 | 0.000273 | index | offset:508
1340 d0 | th04:preload_thread | data | r1 | 0.007311 | 0.004601 | index | count:508
1341 d0 | th05:preload_thread | thread_exit | | 0.008781 | 0.006069 | |
1342 d0 | th01:preload_thread | thread_exit | | 0.009561 | 0.006862 | |
1343 d0 | th03:preload_thread | thread_exit | | 0.009742 | 0.007031 | |
1344 d0 | th06:preload_thread | thread_exit | | 0.009820 | 0.007081 | |
1345 d0 | th02:preload_thread | thread_exit | | 0.010274 | 0.007553 | |
1346 d0 | th07:preload_thread | thread_exit | | 0.010477 | 0.007736 | |
1347 d0 | th04:preload_thread | thread_exit | | 0.011657 | 0.008947 | |
1348 d0 | main | region_leave | r1 | 0.011717 | 0.009122 | index | label:preload
1349 ...
1350 d0 | main | exit | | 0.029996 | | | code:0
1351 d0 | main | atexit | | 0.030027 | | | code:0
1352 ----------------
1353 +
1354 In this example, the preload region took 0.009122 seconds. The 7 threads
1355 took between 0.006069 and 0.008947 seconds to work on their portion of
1356 the index. Thread "th01" worked on 508 items at offset 0. Thread "th02"
1357 worked on 508 items at offset 2032. Thread "th04" worked on 508 itemts
1358 at offset 508.
1359 +
1360 This example also shows that thread names are assigned in a racy manner
1361 as each thread starts and allocates TLS storage.
1362
1363 == Future Work
1364
1365 === Relationship to the Existing Trace Api (api-trace.txt)
1366
1367 There are a few issues to resolve before we can completely
1368 switch to Trace2.
1369
1370 * Updating existing tests that assume GIT_TRACE format messages.
1371
1372 * How to best handle custom GIT_TRACE_<key> messages?
1373
1374 ** The GIT_TRACE_<key> mechanism allows each <key> to write to a
1375 different file (in addition to just stderr).
1376
1377 ** Do we want to maintain that ability or simply write to the existing
1378 Trace2 targets (and convert <key> to a "category").