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