-
Notifications
You must be signed in to change notification settings - Fork 25.2k
/
api-trace2.txt
1185 lines (1014 loc) · 38.1 KB
/
api-trace2.txt
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
477
478
479
480
481
482
483
484
485
486
487
488
489
490
491
492
493
494
495
496
497
498
499
500
501
502
503
504
505
506
507
508
509
510
511
512
513
514
515
516
517
518
519
520
521
522
523
524
525
526
527
528
529
530
531
532
533
534
535
536
537
538
539
540
541
542
543
544
545
546
547
548
549
550
551
552
553
554
555
556
557
558
559
560
561
562
563
564
565
566
567
568
569
570
571
572
573
574
575
576
577
578
579
580
581
582
583
584
585
586
587
588
589
590
591
592
593
594
595
596
597
598
599
600
601
602
603
604
605
606
607
608
609
610
611
612
613
614
615
616
617
618
619
620
621
622
623
624
625
626
627
628
629
630
631
632
633
634
635
636
637
638
639
640
641
642
643
644
645
646
647
648
649
650
651
652
653
654
655
656
657
658
659
660
661
662
663
664
665
666
667
668
669
670
671
672
673
674
675
676
677
678
679
680
681
682
683
684
685
686
687
688
689
690
691
692
693
694
695
696
697
698
699
700
701
702
703
704
705
706
707
708
709
710
711
712
713
714
715
716
717
718
719
720
721
722
723
724
725
726
727
728
729
730
731
732
733
734
735
736
737
738
739
740
741
742
743
744
745
746
747
748
749
750
751
752
753
754
755
756
757
758
759
760
761
762
763
764
765
766
767
768
769
770
771
772
773
774
775
776
777
778
779
780
781
782
783
784
785
786
787
788
789
790
791
792
793
794
795
796
797
798
799
800
801
802
803
804
805
806
807
808
809
810
811
812
813
814
815
816
817
818
819
820
821
822
823
824
825
826
827
828
829
830
831
832
833
834
835
836
837
838
839
840
841
842
843
844
845
846
847
848
849
850
851
852
853
854
855
856
857
858
859
860
861
862
863
864
865
866
867
868
869
870
871
872
873
874
875
876
877
878
879
880
881
882
883
884
885
886
887
888
889
890
891
892
893
894
895
896
897
898
899
900
901
902
903
904
905
906
907
908
909
910
911
912
913
914
915
916
917
918
919
920
921
922
923
924
925
926
927
928
929
930
931
932
933
934
935
936
937
938
939
940
941
942
943
944
945
946
947
948
949
950
951
952
953
954
955
956
957
958
959
960
961
962
963
964
965
966
967
968
969
970
971
972
973
974
975
976
977
978
979
980
981
982
983
984
985
986
987
988
989
990
991
992
993
994
995
996
997
998
999
1000
= Trace2 API
The Trace2 API can be used to print debug, performance, and telemetry
information to stderr or a file. The Trace2 feature is inactive unless
explicitly enabled by enabling one or more Trace2 Targets.
The Trace2 API is intended to replace the existing (Trace1)
printf-style tracing provided by the existing `GIT_TRACE` and
`GIT_TRACE_PERFORMANCE` facilities. During initial implementation,
Trace2 and Trace1 may operate in parallel.
The Trace2 API defines a set of high-level messages with known fields,
such as (`start`: `argv`) and (`exit`: {`exit-code`, `elapsed-time`}).
Trace2 instrumentation throughout the Git code base sends Trace2
messages to the enabled Trace2 Targets. Targets transform these
messages content into purpose-specific formats and write events to
their data streams. In this manner, the Trace2 API can drive
many different types of analysis.
Targets are defined using a VTable allowing easy extension to other
formats in the future. This might be used to define a binary format,
for example.
Trace2 is controlled using `trace2.*` config values in the system and
global config files and `GIT_TRACE2*` environment variables. Trace2 does
not read from repo local or worktree config files or respect `-c`
command line config settings.
== Trace2 Targets
Trace2 defines the following set of Trace2 Targets.
Format details are given in a later section.
=== The Normal Format Target
The normal format target is a tradition printf format and similar
to GIT_TRACE format. This format is enabled with the `GIT_TRACE2`
environment variable or the `trace2.normalTarget` system or global
config setting.
For example
------------
$ export GIT_TRACE2=~/log.normal
$ git version
git version 2.20.1.155.g426c96fcdb
------------
or
------------
$ git config --global trace2.normalTarget ~/log.normal
$ git version
git version 2.20.1.155.g426c96fcdb
------------
yields
------------
$ cat ~/log.normal
12:28:42.620009 common-main.c:38 version 2.20.1.155.g426c96fcdb
12:28:42.620989 common-main.c:39 start git version
12:28:42.621101 git.c:432 cmd_name version (version)
12:28:42.621215 git.c:662 exit elapsed:0.001227 code:0
12:28:42.621250 trace2/tr2_tgt_normal.c:124 atexit elapsed:0.001265 code:0
------------
=== The Performance Format Target
The performance format target (PERF) is a column-based format to
replace GIT_TRACE_PERFORMANCE and is suitable for development and
testing, possibly to complement tools like gprof. This format is
enabled with the `GIT_TRACE2_PERF` environment variable or the
`trace2.perfTarget` system or global config setting.
For example
------------
$ export GIT_TRACE2_PERF=~/log.perf
$ git version
git version 2.20.1.155.g426c96fcdb
------------
or
------------
$ git config --global trace2.perfTarget ~/log.perf
$ git version
git version 2.20.1.155.g426c96fcdb
------------
yields
------------
$ cat ~/log.perf
12:28:42.620675 common-main.c:38 | d0 | main | version | | | | | 2.20.1.155.g426c96fcdb
12:28:42.621001 common-main.c:39 | d0 | main | start | | 0.001173 | | | git version
12:28:42.621111 git.c:432 | d0 | main | cmd_name | | | | | version (version)
12:28:42.621225 git.c:662 | d0 | main | exit | | 0.001227 | | | code:0
12:28:42.621259 trace2/tr2_tgt_perf.c:211 | d0 | main | atexit | | 0.001265 | | | code:0
------------
=== The Event Format Target
The event format target is a JSON-based format of event data suitable
for telemetry analysis. This format is enabled with the `GIT_TRACE2_EVENT`
environment variable or the `trace2.eventTarget` system or global config
setting.
For example
------------
$ export GIT_TRACE2_EVENT=~/log.event
$ git version
git version 2.20.1.155.g426c96fcdb
------------
or
------------
$ git config --global trace2.eventTarget ~/log.event
$ git version
git version 2.20.1.155.g426c96fcdb
------------
yields
------------
$ cat ~/log.event
{"event":"version","sid":"sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.620713Z","file":"common-main.c","line":38,"evt":"2","exe":"2.20.1.155.g426c96fcdb"}
{"event":"start","sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.621027Z","file":"common-main.c","line":39,"t_abs":0.001173,"argv":["git","version"]}
{"event":"cmd_name","sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.621122Z","file":"git.c","line":432,"name":"version","hierarchy":"version"}
{"event":"exit","sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.621236Z","file":"git.c","line":662,"t_abs":0.001227,"code":0}
{"event":"atexit","sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.621268Z","file":"trace2/tr2_tgt_event.c","line":163,"t_abs":0.001265,"code":0}
------------
=== Enabling a Target
To enable a target, set the corresponding environment variable or
system or global config value to one of the following:
include::../trace2-target-values.txt[]
When trace files are written to a target directory, they will be named according
to the last component of the SID (optionally followed by a counter to avoid
filename collisions).
== Trace2 API
All public Trace2 functions and macros are defined in `trace2.h` and
`trace2.c`. All public symbols are prefixed with `trace2_`.
There are no public Trace2 data structures.
The Trace2 code also defines a set of private functions and data types
in the `trace2/` directory. These symbols are prefixed with `tr2_`
and should only be used by functions in `trace2.c`.
== Conventions for Public Functions and Macros
The functions defined by the Trace2 API are declared and documented
in `trace2.h`. It defines the API functions and wrapper macros for
Trace2.
Some functions have a `_fl()` suffix to indicate that they take `file`
and `line-number` arguments.
Some functions have a `_va_fl()` suffix to indicate that they also
take a `va_list` argument.
Some functions have a `_printf_fl()` suffix to indicate that they also
take a varargs argument.
There are CPP wrapper macros and ifdefs to hide most of these details.
See `trace2.h` for more details. The following discussion will only
describe the simplified forms.
== Public API
All Trace2 API functions send a message to all of the active
Trace2 Targets. This section describes the set of available
messages.
It helps to divide these functions into groups for discussion
purposes.
=== Basic Command Messages
These are concerned with the lifetime of the overall git process.
e.g: `void trace2_initialize_clock()`, `void trace2_initialize()`,
`int trace2_is_enabled()`, `void trace2_cmd_start(int argc, const char **argv)`.
=== Command Detail Messages
These are concerned with describing the specific Git command
after the command line, config, and environment are inspected.
e.g: `void trace2_cmd_name(const char *name)`,
`void trace2_cmd_mode(const char *mode)`.
=== Child Process Messages
These are concerned with the various spawned child processes,
including shell scripts, git commands, editors, pagers, and hooks.
e.g: `void trace2_child_start(struct child_process *cmd)`.
=== Git Thread Messages
These messages are concerned with Git thread usage.
e.g: `void trace2_thread_start(const char *thread_name)`.
=== Region and Data Messages
These are concerned with recording performance data
over regions or spans of code. e.g:
`void trace2_region_enter(const char *category, const char *label, const struct repository *repo)`.
Refer to trace2.h for details about all trace2 functions.
== Trace2 Target Formats
=== NORMAL Format
Events are written as lines of the form:
------------
[<time> SP <filename>:<line> SP+] <event-name> [[SP] <event-message>] LF
------------
`<event-name>`::
is the event name.
`<event-message>`::
is a free-form printf message intended for human consumption.
+
Note that this may contain embedded LF or CRLF characters that are
not escaped, so the event may spill across multiple lines.
If `GIT_TRACE2_BRIEF` or `trace2.normalBrief` is true, the `time`, `filename`,
and `line` fields are omitted.
This target is intended to be more of a summary (like GIT_TRACE) and
less detailed than the other targets. It ignores thread, region, and
data messages, for example.
=== PERF Format
Events are written as lines of the form:
------------
[<time> SP <filename>:<line> SP+
BAR SP] d<depth> SP
BAR SP <thread-name> SP+
BAR SP <event-name> SP+
BAR SP [r<repo-id>] SP+
BAR SP [<t_abs>] SP+
BAR SP [<t_rel>] SP+
BAR SP [<category>] SP+
BAR SP DOTS* <perf-event-message>
LF
------------
`<depth>`::
is the git process depth. This is the number of parent
git processes. A top-level git command has depth value "d0".
A child of it has depth value "d1". A second level child
has depth value "d2" and so on.
`<thread-name>`::
is a unique name for the thread. The primary thread
is called "main". Other thread names are of the form "th%d:%s"
and include a unique number and the name of the thread-proc.
`<event-name>`::
is the event name.
`<repo-id>`::
when present, is a number indicating the repository
in use. A `def_repo` event is emitted when a repository is
opened. This defines the repo-id and associated worktree.
Subsequent repo-specific events will reference this repo-id.
+
Currently, this is always "r1" for the main repository.
This field is in anticipation of in-proc submodules in the future.
`<t_abs>`::
when present, is the absolute time in seconds since the
program started.
`<t_rel>`::
when present, is time in seconds relative to the start of
the current region. For a thread-exit event, it is the elapsed
time of the thread.
`<category>`::
is present on region and data events and is used to
indicate a broad category, such as "index" or "status".
`<perf-event-message>`::
is a free-form printf message intended for human consumption.
------------
15:33:33.532712 wt-status.c:2310 | d0 | main | region_enter | r1 | 0.126064 | | status | label:print
15:33:33.532712 wt-status.c:2331 | d0 | main | region_leave | r1 | 0.127568 | 0.001504 | status | label:print
------------
If `GIT_TRACE2_PERF_BRIEF` or `trace2.perfBrief` is true, the `time`, `file`,
and `line` fields are omitted.
------------
d0 | main | region_leave | r1 | 0.011717 | 0.009122 | index | label:preload
------------
The PERF target is intended for interactive performance analysis
during development and is quite noisy.
=== EVENT Format
Each event is a JSON-object containing multiple key/value pairs
written as a single line and followed by a LF.
------------
'{' <key> ':' <value> [',' <key> ':' <value>]* '}' LF
------------
Some key/value pairs are common to all events and some are
event-specific.
==== Common Key/Value Pairs
The following key/value pairs are common to all events:
------------
{
"event":"version",
"sid":"20190408T191827.272759Z-H9b68c35f-P00003510",
"thread":"main",
"time":"2019-04-08T19:18:27.282761Z",
"file":"common-main.c",
"line":42,
...
}
------------
`"event":<event>`::
is the event name.
`"sid":<sid>`::
is the session-id. This is a unique string to identify the
process instance to allow all events emitted by a process to
be identified. A session-id is used instead of a PID because
PIDs are recycled by the OS. For child git processes, the
session-id is prepended with the session-id of the parent git
process to allow parent-child relationships to be identified
during post-processing.
`"thread":<thread>`::
is the thread name.
`"time":<time>`::
is the UTC time of the event.
`"file":<filename>`::
is source file generating the event.
`"line":<line-number>`::
is the integer source line number generating the event.
`"repo":<repo-id>`::
when present, is the integer repo-id as described previously.
If `GIT_TRACE2_EVENT_BRIEF` or `trace2.eventBrief` is true, the `file`
and `line` fields are omitted from all events and the `time` field is
only present on the "start" and "atexit" events.
==== Event-Specific Key/Value Pairs
`"version"`::
This event gives the version of the executable and the EVENT format. It
should always be the first event in a trace session. The EVENT format
version will be incremented if new event types are added, if existing
fields are removed, or if there are significant changes in
interpretation of existing events or fields. Smaller changes, such as
adding a new field to an existing event, will not require an increment
to the EVENT format version.
+
------------
{
"event":"version",
...
"evt":"2", # EVENT format version
"exe":"2.20.1.155.g426c96fcdb" # git version
}
------------
`"discard"`::
This event is written to the git-trace2-discard sentinel file if there
are too many files in the target trace directory (see the
trace2.maxFiles config option).
+
------------
{
"event":"discard",
...
}
------------
`"start"`::
This event contains the complete argv received by main().
+
------------
{
"event":"start",
...
"t_abs":0.001227, # elapsed time in seconds
"argv":["git","version"]
}
------------
`"exit"`::
This event is emitted when git calls `exit()`.
+
------------
{
"event":"exit",
...
"t_abs":0.001227, # elapsed time in seconds
"code":0 # exit code
}
------------
`"atexit"`::
This event is emitted by the Trace2 `atexit` routine during
final shutdown. It should be the last event emitted by the
process.
+
(The elapsed time reported here is greater than the time reported in
the "exit" event because it runs after all other atexit tasks have
completed.)
+
------------
{
"event":"atexit",
...
"t_abs":0.001227, # elapsed time in seconds
"code":0 # exit code
}
------------
`"signal"`::
This event is emitted when the program is terminated by a user
signal. Depending on the platform, the signal event may
prevent the "atexit" event from being generated.
+
------------
{
"event":"signal",
...
"t_abs":0.001227, # elapsed time in seconds
"signo":13 # SIGTERM, SIGINT, etc.
}
------------
`"error"`::
This event is emitted when one of the `BUG()`, `error()`, `die()`,
`warning()`, or `usage()` functions are called.
+
------------
{
"event":"error",
...
"msg":"invalid option: --cahced", # formatted error message
"fmt":"invalid option: %s" # error format string
}
------------
+
The error event may be emitted more than once. The format string
allows post-processors to group errors by type without worrying
about specific error arguments.
`"cmd_path"`::
This event contains the discovered full path of the git
executable (on platforms that are configured to resolve it).
+
------------
{
"event":"cmd_path",
...
"path":"C:/work/gfw/git.exe"
}
------------
`"cmd_ancestry"`::
This event contains the text command name for the parent (and earlier
generations of parents) of the current process, in an array ordered from
nearest parent to furthest great-grandparent. It may not be implemented
on all platforms.
+
------------
{
"event":"cmd_ancestry",
...
"ancestry":["bash","tmux: server","systemd"]
}
------------
`"cmd_name"`::
This event contains the command name for this git process
and the hierarchy of commands from parent git processes.
+
------------
{
"event":"cmd_name",
...
"name":"pack-objects",
"hierarchy":"push/pack-objects"
}
------------
+
Normally, the "name" field contains the canonical name of the
command. When a canonical name is not available, one of
these special values are used:
+
------------
"_query_" # "git --html-path"
"_run_dashed_" # when "git foo" tries to run "git-foo"
"_run_shell_alias_" # alias expansion to a shell command
"_run_git_alias_" # alias expansion to a git command
"_usage_" # usage error
------------
`"cmd_mode"`::
This event, when present, describes the command variant This
event may be emitted more than once.
+
------------
{
"event":"cmd_mode",
...
"name":"branch"
}
------------
+
The "name" field is an arbitrary string to describe the command mode.
For example, checkout can checkout a branch or an individual file.
And these variations typically have different performance
characteristics that are not comparable.
`"alias"`::
This event is present when an alias is expanded.
+
------------
{
"event":"alias",
...
"alias":"l", # registered alias
"argv":["log","--graph"] # alias expansion
}
------------
`"child_start"`::
This event describes a child process that is about to be
spawned.
+
------------
{
"event":"child_start",
...
"child_id":2,
"child_class":"?",
"use_shell":false,
"argv":["git","rev-list","--objects","--stdin","--not","--all","--quiet"]
"hook_name":"<hook_name>" # present when child_class is "hook"
"cd":"<path>" # present when cd is required
}
------------
+
The "child_id" field can be used to match this child_start with the
corresponding child_exit event.
+
The "child_class" field is a rough classification, such as "editor",
"pager", "transport/*", and "hook". Unclassified children are classified
with "?".
`"child_exit"`::
This event is generated after the current process has returned
from the waitpid() and collected the exit information from the
child.
+
------------
{
"event":"child_exit",
...
"child_id":2,
"pid":14708, # child PID
"code":0, # child exit-code
"t_rel":0.110605 # observed run-time of child process
}
------------
+
Note that the session-id of the child process is not available to
the current/spawning process, so the child's PID is reported here as
a hint for post-processing. (But it is only a hint because the child
process may be a shell script which doesn't have a session-id.)
+
Note that the `t_rel` field contains the observed run time in seconds
for the child process (starting before the fork/exec/spawn and
stopping after the waitpid() and includes OS process creation overhead).
So this time will be slightly larger than the atexit time reported by
the child process itself.
`"exec"`::
This event is generated before git attempts to `exec()`
another command rather than starting a child process.
+
------------
{
"event":"exec",
...
"exec_id":0,
"exe":"git",
"argv":["foo", "bar"]
}
------------
+
The "exec_id" field is a command-unique id and is only useful if the
`exec()` fails and a corresponding exec_result event is generated.
`"exec_result"`::
This event is generated if the `exec()` fails and control
returns to the current git command.
+
------------
{
"event":"exec_result",
...
"exec_id":0,
"code":1 # error code (errno) from exec()
}
------------
`"thread_start"`::
This event is generated when a thread is started. It is
generated from *within* the new thread's thread-proc (for TLS
reasons).
+
------------
{
"event":"thread_start",
...
"thread":"th02:preload_thread" # thread name
}
------------
`"thread_exit"`::
This event is generated when a thread exits. It is generated
from *within* the thread's thread-proc (for TLS reasons).
+
------------
{
"event":"thread_exit",
...
"thread":"th02:preload_thread", # thread name
"t_rel":0.007328 # thread elapsed time
}
------------
`"def_param"`::
This event is generated to log a global parameter, such as a config
setting, command-line flag, or environment variable.
+
------------
{
"event":"def_param",
...
"param":"core.abbrev",
"value":"7"
}
------------
`"def_repo"`::
This event defines a repo-id and associates it with the root
of the worktree.
+
------------
{
"event":"def_repo",
...
"repo":1,
"worktree":"/Users/jeffhost/work/gfw"
}
------------
+
As stated earlier, the repo-id is currently always 1, so there will
only be one def_repo event. Later, if in-proc submodules are
supported, a def_repo event should be emitted for each submodule
visited.
`"region_enter"`::
This event is generated when entering a region.
+
------------
{
"event":"region_enter",
...
"repo":1, # optional
"nesting":1, # current region stack depth
"category":"index", # optional
"label":"do_read_index", # optional
"msg":".git/index" # optional
}
------------
+
The `category` field may be used in a future enhancement to
do category-based filtering.
+
`GIT_TRACE2_EVENT_NESTING` or `trace2.eventNesting` can be used to
filter deeply nested regions and data events. It defaults to "2".
`"region_leave"`::
This event is generated when leaving a region.
+
------------
{
"event":"region_leave",
...
"repo":1, # optional
"t_rel":0.002876, # time spent in region in seconds
"nesting":1, # region stack depth
"category":"index", # optional
"label":"do_read_index", # optional
"msg":".git/index" # optional
}
------------
`"data"`::
This event is generated to log a thread- and region-local
key/value pair.
+
------------
{
"event":"data",
...
"repo":1, # optional
"t_abs":0.024107, # absolute elapsed time
"t_rel":0.001031, # elapsed time in region/thread
"nesting":2, # region stack depth
"category":"index",
"key":"read/cache_nr",
"value":"3552"
}
------------
+
The "value" field may be an integer or a string.
`"data-json"`::
This event is generated to log a pre-formatted JSON string
containing structured data.
+
------------
{
"event":"data_json",
...
"repo":1, # optional
"t_abs":0.015905,
"t_rel":0.015905,
"nesting":1,
"category":"process",
"key":"windows/ancestry",
"value":["bash.exe","bash.exe"]
}
------------
== Example Trace2 API Usage
Here is a hypothetical usage of the Trace2 API showing the intended
usage (without worrying about the actual Git details).
Initialization::
Initialization happens in `main()`. Behind the scenes, an
`atexit` and `signal` handler are registered.
+
----------------
int main(int argc, const char **argv)
{
int exit_code;
trace2_initialize();
trace2_cmd_start(argv);
exit_code = cmd_main(argc, argv);
trace2_cmd_exit(exit_code);
return exit_code;
}
----------------
Command Details::
After the basics are established, additional command
information can be sent to Trace2 as it is discovered.
+
----------------
int cmd_checkout(int argc, const char **argv)
{
trace2_cmd_name("checkout");
trace2_cmd_mode("branch");
trace2_def_repo(the_repository);
// emit "def_param" messages for "interesting" config settings.
trace2_cmd_list_config();
if (do_something())
trace2_cmd_error("Path '%s': cannot do something", path);
return 0;
}
----------------
Child Processes::
Wrap code spawning child processes.
+
----------------
void run_child(...)
{
int child_exit_code;
struct child_process cmd = CHILD_PROCESS_INIT;
...
cmd.trace2_child_class = "editor";
trace2_child_start(&cmd);
child_exit_code = spawn_child_and_wait_for_it();
trace2_child_exit(&cmd, child_exit_code);
}
----------------
+
For example, the following fetch command spawned ssh, index-pack,
rev-list, and gc. This example also shows that fetch took
5.199 seconds and of that 4.932 was in ssh.
+
----------------
$ export GIT_TRACE2_BRIEF=1
$ export GIT_TRACE2=~/log.normal
$ git fetch origin
...
----------------
+
----------------
$ cat ~/log.normal
version 2.20.1.vfs.1.1.47.g534dbe1ad1
start git fetch origin
worktree /Users/jeffhost/work/gfw
cmd_name fetch (fetch)
child_start[0] ssh git@github.com ...
child_start[1] git index-pack ...
... (Trace2 events from child processes omitted)
child_exit[1] pid:14707 code:0 elapsed:0.076353
child_exit[0] pid:14706 code:0 elapsed:4.931869
child_start[2] git rev-list ...
... (Trace2 events from child process omitted)
child_exit[2] pid:14708 code:0 elapsed:0.110605
child_start[3] git gc --auto
... (Trace2 events from child process omitted)
child_exit[3] pid:14709 code:0 elapsed:0.006240
exit elapsed:5.198503 code:0
atexit elapsed:5.198541 code:0
----------------
+
When a git process is a (direct or indirect) child of another
git process, it inherits Trace2 context information. This
allows the child to print the command hierarchy. This example
shows gc as child[3] of fetch. When the gc process reports
its name as "gc", it also reports the hierarchy as "fetch/gc".
(In this example, trace2 messages from the child process is
indented for clarity.)
+
----------------
$ export GIT_TRACE2_BRIEF=1
$ export GIT_TRACE2=~/log.normal
$ git fetch origin
...
----------------
+
----------------
$ cat ~/log.normal
version 2.20.1.160.g5676107ecd.dirty
start git fetch official
worktree /Users/jeffhost/work/gfw
cmd_name fetch (fetch)
...
child_start[3] git gc --auto
version 2.20.1.160.g5676107ecd.dirty
start /Users/jeffhost/work/gfw/git gc --auto
worktree /Users/jeffhost/work/gfw
cmd_name gc (fetch/gc)
exit elapsed:0.001959 code:0
atexit elapsed:0.001997 code:0
child_exit[3] pid:20303 code:0 elapsed:0.007564
exit elapsed:3.868938 code:0
atexit elapsed:3.868970 code:0
----------------
Regions::
Regions can be use to time an interesting section of code.
+
----------------
void wt_status_collect(struct wt_status *s)
{
trace2_region_enter("status", "worktrees", s->repo);
wt_status_collect_changes_worktree(s);
trace2_region_leave("status", "worktrees", s->repo);
trace2_region_enter("status", "index", s->repo);
wt_status_collect_changes_index(s);
trace2_region_leave("status", "index", s->repo);
trace2_region_enter("status", "untracked", s->repo);
wt_status_collect_untracked(s);
trace2_region_leave("status", "untracked", s->repo);
}
void wt_status_print(struct wt_status *s)
{
trace2_region_enter("status", "print", s->repo);
switch (s->status_format) {
...
}
trace2_region_leave("status", "print", s->repo);
}
----------------
+
In this example, scanning for untracked files ran from +0.012568 to
+0.027149 (since the process started) and took 0.014581 seconds.
+
----------------
$ export GIT_TRACE2_PERF_BRIEF=1
$ export GIT_TRACE2_PERF=~/log.perf
$ git status
...
$ cat ~/log.perf
d0 | main | version | | | | | 2.20.1.160.g5676107ecd.dirty
d0 | main | start | | 0.001173 | | | git status
d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
d0 | main | cmd_name | | | | | status (status)
...
d0 | main | region_enter | r1 | 0.010988 | | status | label:worktrees
d0 | main | region_leave | r1 | 0.011236 | 0.000248 | status | label:worktrees
d0 | main | region_enter | r1 | 0.011260 | | status | label:index
d0 | main | region_leave | r1 | 0.012542 | 0.001282 | status | label:index
d0 | main | region_enter | r1 | 0.012568 | | status | label:untracked
d0 | main | region_leave | r1 | 0.027149 | 0.014581 | status | label:untracked
d0 | main | region_enter | r1 | 0.027411 | | status | label:print
d0 | main | region_leave | r1 | 0.028741 | 0.001330 | status | label:print
d0 | main | exit | | 0.028778 | | | code:0
d0 | main | atexit | | 0.028809 | | | code:0
----------------
+
Regions may be nested. This causes messages to be indented in the
PERF target, for example.
Elapsed times are relative to the start of the corresponding nesting
level as expected. For example, if we add region message to:
+
----------------
static enum path_treatment read_directory_recursive(struct dir_struct *dir,
struct index_state *istate, const char *base, int baselen,
struct untracked_cache_dir *untracked, int check_only,
int stop_at_first_file, const struct pathspec *pathspec)
{
enum path_treatment state, subdir_state, dir_state = path_none;
trace2_region_enter_printf("dir", "read_recursive", NULL, "%.*s", baselen, base);
...
trace2_region_leave_printf("dir", "read_recursive", NULL, "%.*s", baselen, base);
return dir_state;
}
----------------
+
We can further investigate the time spent scanning for untracked files.
+
----------------
$ export GIT_TRACE2_PERF_BRIEF=1
$ export GIT_TRACE2_PERF=~/log.perf
$ git status
...
$ cat ~/log.perf
d0 | main | version | | | | | 2.20.1.162.gb4ccea44db.dirty
d0 | main | start | | 0.001173 | | | git status
d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
d0 | main | cmd_name | | | | | status (status)
...
d0 | main | region_enter | r1 | 0.015047 | | status | label:untracked