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