blob: 0bb46a5666e13702fde8fd991f1b52208dd3c9e7 [file] [log] [blame]
Junio C Hamano11f15372019-03-07 03:17:001<?xml version="1.0" encoding="UTF-8"?>
2<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.1//EN"
3 "http://www.w3.org/TR/xhtml11/DTD/xhtml11.dtd">
4<html xmlns="http://www.w3.org/1999/xhtml" xml:lang="en">
5<head>
6<meta http-equiv="Content-Type" content="application/xhtml+xml; charset=UTF-8" />
7<meta name="generator" content="AsciiDoc 8.6.10" />
8<title>Trace2 API</title>
9<style type="text/css">
10/* Shared CSS for AsciiDoc xhtml11 and html5 backends */
11
12/* Default font. */
13body {
14 font-family: Georgia,serif;
15}
16
17/* Title font. */
18h1, h2, h3, h4, h5, h6,
19div.title, caption.title,
20thead, p.table.header,
21#toctitle,
22#author, #revnumber, #revdate, #revremark,
23#footer {
24 font-family: Arial,Helvetica,sans-serif;
25}
26
27body {
28 margin: 1em 5% 1em 5%;
29}
30
31a {
32 color: blue;
33 text-decoration: underline;
34}
35a:visited {
36 color: fuchsia;
37}
38
39em {
40 font-style: italic;
41 color: navy;
42}
43
44strong {
45 font-weight: bold;
46 color: #083194;
47}
48
49h1, h2, h3, h4, h5, h6 {
50 color: #527bbd;
51 margin-top: 1.2em;
52 margin-bottom: 0.5em;
53 line-height: 1.3;
54}
55
56h1, h2, h3 {
57 border-bottom: 2px solid silver;
58}
59h2 {
60 padding-top: 0.5em;
61}
62h3 {
63 float: left;
64}
65h3 + * {
66 clear: left;
67}
68h5 {
69 font-size: 1.0em;
70}
71
72div.sectionbody {
73 margin-left: 0;
74}
75
76hr {
77 border: 1px solid silver;
78}
79
80p {
81 margin-top: 0.5em;
82 margin-bottom: 0.5em;
83}
84
85ul, ol, li > p {
86 margin-top: 0;
87}
88ul > li { color: #aaa; }
89ul > li > * { color: black; }
90
91.monospaced, code, pre {
92 font-family: "Courier New", Courier, monospace;
93 font-size: inherit;
94 color: navy;
95 padding: 0;
96 margin: 0;
97}
98pre {
99 white-space: pre-wrap;
100}
101
102#author {
103 color: #527bbd;
104 font-weight: bold;
105 font-size: 1.1em;
106}
107#email {
108}
109#revnumber, #revdate, #revremark {
110}
111
112#footer {
113 font-size: small;
114 border-top: 2px solid silver;
115 padding-top: 0.5em;
116 margin-top: 4.0em;
117}
118#footer-text {
119 float: left;
120 padding-bottom: 0.5em;
121}
122#footer-badges {
123 float: right;
124 padding-bottom: 0.5em;
125}
126
127#preamble {
128 margin-top: 1.5em;
129 margin-bottom: 1.5em;
130}
131div.imageblock, div.exampleblock, div.verseblock,
132div.quoteblock, div.literalblock, div.listingblock, div.sidebarblock,
133div.admonitionblock {
134 margin-top: 1.0em;
135 margin-bottom: 1.5em;
136}
137div.admonitionblock {
138 margin-top: 2.0em;
139 margin-bottom: 2.0em;
140 margin-right: 10%;
141 color: #606060;
142}
143
144div.content { /* Block element content. */
145 padding: 0;
146}
147
148/* Block element titles. */
149div.title, caption.title {
150 color: #527bbd;
151 font-weight: bold;
152 text-align: left;
153 margin-top: 1.0em;
154 margin-bottom: 0.5em;
155}
156div.title + * {
157 margin-top: 0;
158}
159
160td div.title:first-child {
161 margin-top: 0.0em;
162}
163div.content div.title:first-child {
164 margin-top: 0.0em;
165}
166div.content + div.title {
167 margin-top: 0.0em;
168}
169
170div.sidebarblock > div.content {
171 background: #ffffee;
172 border: 1px solid #dddddd;
173 border-left: 4px solid #f0f0f0;
174 padding: 0.5em;
175}
176
177div.listingblock > div.content {
178 border: 1px solid #dddddd;
179 border-left: 5px solid #f0f0f0;
180 background: #f8f8f8;
181 padding: 0.5em;
182}
183
184div.quoteblock, div.verseblock {
185 padding-left: 1.0em;
186 margin-left: 1.0em;
187 margin-right: 10%;
188 border-left: 5px solid #f0f0f0;
189 color: #888;
190}
191
192div.quoteblock > div.attribution {
193 padding-top: 0.5em;
194 text-align: right;
195}
196
197div.verseblock > pre.content {
198 font-family: inherit;
199 font-size: inherit;
200}
201div.verseblock > div.attribution {
202 padding-top: 0.75em;
203 text-align: left;
204}
205/* DEPRECATED: Pre version 8.2.7 verse style literal block. */
206div.verseblock + div.attribution {
207 text-align: left;
208}
209
210div.admonitionblock .icon {
211 vertical-align: top;
212 font-size: 1.1em;
213 font-weight: bold;
214 text-decoration: underline;
215 color: #527bbd;
216 padding-right: 0.5em;
217}
218div.admonitionblock td.content {
219 padding-left: 0.5em;
220 border-left: 3px solid #dddddd;
221}
222
223div.exampleblock > div.content {
224 border-left: 3px solid #dddddd;
225 padding-left: 0.5em;
226}
227
228div.imageblock div.content { padding-left: 0; }
229span.image img { border-style: none; vertical-align: text-bottom; }
230a.image:visited { color: white; }
231
232dl {
233 margin-top: 0.8em;
234 margin-bottom: 0.8em;
235}
236dt {
237 margin-top: 0.5em;
238 margin-bottom: 0;
239 font-style: normal;
240 color: navy;
241}
242dd > *:first-child {
243 margin-top: 0.1em;
244}
245
246ul, ol {
247 list-style-position: outside;
248}
249ol.arabic {
250 list-style-type: decimal;
251}
252ol.loweralpha {
253 list-style-type: lower-alpha;
254}
255ol.upperalpha {
256 list-style-type: upper-alpha;
257}
258ol.lowerroman {
259 list-style-type: lower-roman;
260}
261ol.upperroman {
262 list-style-type: upper-roman;
263}
264
265div.compact ul, div.compact ol,
266div.compact p, div.compact p,
267div.compact div, div.compact div {
268 margin-top: 0.1em;
269 margin-bottom: 0.1em;
270}
271
272tfoot {
273 font-weight: bold;
274}
275td > div.verse {
276 white-space: pre;
277}
278
279div.hdlist {
280 margin-top: 0.8em;
281 margin-bottom: 0.8em;
282}
283div.hdlist tr {
284 padding-bottom: 15px;
285}
286dt.hdlist1.strong, td.hdlist1.strong {
287 font-weight: bold;
288}
289td.hdlist1 {
290 vertical-align: top;
291 font-style: normal;
292 padding-right: 0.8em;
293 color: navy;
294}
295td.hdlist2 {
296 vertical-align: top;
297}
298div.hdlist.compact tr {
299 margin: 0;
300 padding-bottom: 0;
301}
302
303.comment {
304 background: yellow;
305}
306
307.footnote, .footnoteref {
308 font-size: 0.8em;
309}
310
311span.footnote, span.footnoteref {
312 vertical-align: super;
313}
314
315#footnotes {
316 margin: 20px 0 20px 0;
317 padding: 7px 0 0 0;
318}
319
320#footnotes div.footnote {
321 margin: 0 0 5px 0;
322}
323
324#footnotes hr {
325 border: none;
326 border-top: 1px solid silver;
327 height: 1px;
328 text-align: left;
329 margin-left: 0;
330 width: 20%;
331 min-width: 100px;
332}
333
334div.colist td {
335 padding-right: 0.5em;
336 padding-bottom: 0.3em;
337 vertical-align: top;
338}
339div.colist td img {
340 margin-top: 0.3em;
341}
342
343@media print {
344 #footer-badges { display: none; }
345}
346
347#toc {
348 margin-bottom: 2.5em;
349}
350
351#toctitle {
352 color: #527bbd;
353 font-size: 1.1em;
354 font-weight: bold;
355 margin-top: 1.0em;
356 margin-bottom: 0.1em;
357}
358
359div.toclevel0, div.toclevel1, div.toclevel2, div.toclevel3, div.toclevel4 {
360 margin-top: 0;
361 margin-bottom: 0;
362}
363div.toclevel2 {
364 margin-left: 2em;
365 font-size: 0.9em;
366}
367div.toclevel3 {
368 margin-left: 4em;
369 font-size: 0.9em;
370}
371div.toclevel4 {
372 margin-left: 6em;
373 font-size: 0.9em;
374}
375
376span.aqua { color: aqua; }
377span.black { color: black; }
378span.blue { color: blue; }
379span.fuchsia { color: fuchsia; }
380span.gray { color: gray; }
381span.green { color: green; }
382span.lime { color: lime; }
383span.maroon { color: maroon; }
384span.navy { color: navy; }
385span.olive { color: olive; }
386span.purple { color: purple; }
387span.red { color: red; }
388span.silver { color: silver; }
389span.teal { color: teal; }
390span.white { color: white; }
391span.yellow { color: yellow; }
392
393span.aqua-background { background: aqua; }
394span.black-background { background: black; }
395span.blue-background { background: blue; }
396span.fuchsia-background { background: fuchsia; }
397span.gray-background { background: gray; }
398span.green-background { background: green; }
399span.lime-background { background: lime; }
400span.maroon-background { background: maroon; }
401span.navy-background { background: navy; }
402span.olive-background { background: olive; }
403span.purple-background { background: purple; }
404span.red-background { background: red; }
405span.silver-background { background: silver; }
406span.teal-background { background: teal; }
407span.white-background { background: white; }
408span.yellow-background { background: yellow; }
409
410span.big { font-size: 2em; }
411span.small { font-size: 0.6em; }
412
413span.underline { text-decoration: underline; }
414span.overline { text-decoration: overline; }
415span.line-through { text-decoration: line-through; }
416
417div.unbreakable { page-break-inside: avoid; }
418
419
420/*
421 * xhtml11 specific
422 *
423 * */
424
425div.tableblock {
426 margin-top: 1.0em;
427 margin-bottom: 1.5em;
428}
429div.tableblock > table {
430 border: 3px solid #527bbd;
431}
432thead, p.table.header {
433 font-weight: bold;
434 color: #527bbd;
435}
436p.table {
437 margin-top: 0;
438}
439/* Because the table frame attribute is overriden by CSS in most browsers. */
440div.tableblock > table[frame="void"] {
441 border-style: none;
442}
443div.tableblock > table[frame="hsides"] {
444 border-left-style: none;
445 border-right-style: none;
446}
447div.tableblock > table[frame="vsides"] {
448 border-top-style: none;
449 border-bottom-style: none;
450}
451
452
453/*
454 * html5 specific
455 *
456 * */
457
458table.tableblock {
459 margin-top: 1.0em;
460 margin-bottom: 1.5em;
461}
462thead, p.tableblock.header {
463 font-weight: bold;
464 color: #527bbd;
465}
466p.tableblock {
467 margin-top: 0;
468}
469table.tableblock {
470 border-width: 3px;
471 border-spacing: 0px;
472 border-style: solid;
473 border-color: #527bbd;
474 border-collapse: collapse;
475}
476th.tableblock, td.tableblock {
477 border-width: 1px;
478 padding: 4px;
479 border-style: solid;
480 border-color: #527bbd;
481}
482
483table.tableblock.frame-topbot {
484 border-left-style: hidden;
485 border-right-style: hidden;
486}
487table.tableblock.frame-sides {
488 border-top-style: hidden;
489 border-bottom-style: hidden;
490}
491table.tableblock.frame-none {
492 border-style: hidden;
493}
494
495th.tableblock.halign-left, td.tableblock.halign-left {
496 text-align: left;
497}
498th.tableblock.halign-center, td.tableblock.halign-center {
499 text-align: center;
500}
501th.tableblock.halign-right, td.tableblock.halign-right {
502 text-align: right;
503}
504
505th.tableblock.valign-top, td.tableblock.valign-top {
506 vertical-align: top;
507}
508th.tableblock.valign-middle, td.tableblock.valign-middle {
509 vertical-align: middle;
510}
511th.tableblock.valign-bottom, td.tableblock.valign-bottom {
512 vertical-align: bottom;
513}
514
515
516/*
517 * manpage specific
518 *
519 * */
520
521body.manpage h1 {
522 padding-top: 0.5em;
523 padding-bottom: 0.5em;
524 border-top: 2px solid silver;
525 border-bottom: 2px solid silver;
526}
527body.manpage h2 {
528 border-style: none;
529}
530body.manpage div.sectionbody {
531 margin-left: 3em;
532}
533
534@media print {
535 body.manpage div#toc { display: none; }
536}
537
538
539</style>
540<script type="text/javascript">
541/*<![CDATA[*/
542var asciidoc = { // Namespace.
543
544/////////////////////////////////////////////////////////////////////
545// Table Of Contents generator
546/////////////////////////////////////////////////////////////////////
547
548/* Author: Mihai Bazon, September 2002
549 * http://students.infoiasi.ro/~mishoo
550 *
551 * Table Of Content generator
552 * Version: 0.4
553 *
554 * Feel free to use this script under the terms of the GNU General Public
555 * License, as long as you do not remove or alter this notice.
556 */
557
558 /* modified by Troy D. Hanson, September 2006. License: GPL */
559 /* modified by Stuart Rackham, 2006, 2009. License: GPL */
560
561// toclevels = 1..4.
562toc: function (toclevels) {
563
564 function getText(el) {
565 var text = "";
566 for (var i = el.firstChild; i != null; i = i.nextSibling) {
567 if (i.nodeType == 3 /* Node.TEXT_NODE */) // IE doesn't speak constants.
568 text += i.data;
569 else if (i.firstChild != null)
570 text += getText(i);
571 }
572 return text;
573 }
574
575 function TocEntry(el, text, toclevel) {
576 this.element = el;
577 this.text = text;
578 this.toclevel = toclevel;
579 }
580
581 function tocEntries(el, toclevels) {
582 var result = new Array;
583 var re = new RegExp('[hH]([1-'+(toclevels+1)+'])');
584 // Function that scans the DOM tree for header elements (the DOM2
585 // nodeIterator API would be a better technique but not supported by all
586 // browsers).
587 var iterate = function (el) {
588 for (var i = el.firstChild; i != null; i = i.nextSibling) {
589 if (i.nodeType == 1 /* Node.ELEMENT_NODE */) {
590 var mo = re.exec(i.tagName);
591 if (mo && (i.getAttribute("class") || i.getAttribute("className")) != "float") {
592 result[result.length] = new TocEntry(i, getText(i), mo[1]-1);
593 }
594 iterate(i);
595 }
596 }
597 }
598 iterate(el);
599 return result;
600 }
601
602 var toc = document.getElementById("toc");
603 if (!toc) {
604 return;
605 }
606
607 // Delete existing TOC entries in case we're reloading the TOC.
608 var tocEntriesToRemove = [];
609 var i;
610 for (i = 0; i < toc.childNodes.length; i++) {
611 var entry = toc.childNodes[i];
612 if (entry.nodeName.toLowerCase() == 'div'
613 && entry.getAttribute("class")
614 && entry.getAttribute("class").match(/^toclevel/))
615 tocEntriesToRemove.push(entry);
616 }
617 for (i = 0; i < tocEntriesToRemove.length; i++) {
618 toc.removeChild(tocEntriesToRemove[i]);
619 }
620
621 // Rebuild TOC entries.
622 var entries = tocEntries(document.getElementById("content"), toclevels);
623 for (var i = 0; i < entries.length; ++i) {
624 var entry = entries[i];
625 if (entry.element.id == "")
626 entry.element.id = "_toc_" + i;
627 var a = document.createElement("a");
628 a.href = "#" + entry.element.id;
629 a.appendChild(document.createTextNode(entry.text));
630 var div = document.createElement("div");
631 div.appendChild(a);
632 div.className = "toclevel" + entry.toclevel;
633 toc.appendChild(div);
634 }
635 if (entries.length == 0)
636 toc.parentNode.removeChild(toc);
637},
638
639
640/////////////////////////////////////////////////////////////////////
641// Footnotes generator
642/////////////////////////////////////////////////////////////////////
643
644/* Based on footnote generation code from:
645 * http://www.brandspankingnew.net/archive/2005/07/format_footnote.html
646 */
647
648footnotes: function () {
649 // Delete existing footnote entries in case we're reloading the footnodes.
650 var i;
651 var noteholder = document.getElementById("footnotes");
652 if (!noteholder) {
653 return;
654 }
655 var entriesToRemove = [];
656 for (i = 0; i < noteholder.childNodes.length; i++) {
657 var entry = noteholder.childNodes[i];
658 if (entry.nodeName.toLowerCase() == 'div' && entry.getAttribute("class") == "footnote")
659 entriesToRemove.push(entry);
660 }
661 for (i = 0; i < entriesToRemove.length; i++) {
662 noteholder.removeChild(entriesToRemove[i]);
663 }
664
665 // Rebuild footnote entries.
666 var cont = document.getElementById("content");
667 var spans = cont.getElementsByTagName("span");
668 var refs = {};
669 var n = 0;
670 for (i=0; i<spans.length; i++) {
671 if (spans[i].className == "footnote") {
672 n++;
673 var note = spans[i].getAttribute("data-note");
674 if (!note) {
675 // Use [\s\S] in place of . so multi-line matches work.
676 // Because JavaScript has no s (dotall) regex flag.
677 note = spans[i].innerHTML.match(/\s*\[([\s\S]*)]\s*/)[1];
678 spans[i].innerHTML =
679 "[<a id='_footnoteref_" + n + "' href='#_footnote_" + n +
680 "' title='View footnote' class='footnote'>" + n + "</a>]";
681 spans[i].setAttribute("data-note", note);
682 }
683 noteholder.innerHTML +=
684 "<div class='footnote' id='_footnote_" + n + "'>" +
685 "<a href='#_footnoteref_" + n + "' title='Return to text'>" +
686 n + "</a>. " + note + "</div>";
687 var id =spans[i].getAttribute("id");
688 if (id != null) refs["#"+id] = n;
689 }
690 }
691 if (n == 0)
692 noteholder.parentNode.removeChild(noteholder);
693 else {
694 // Process footnoterefs.
695 for (i=0; i<spans.length; i++) {
696 if (spans[i].className == "footnoteref") {
697 var href = spans[i].getElementsByTagName("a")[0].getAttribute("href");
698 href = href.match(/#.*/)[0]; // Because IE return full URL.
699 n = refs[href];
700 spans[i].innerHTML =
701 "[<a href='#_footnote_" + n +
702 "' title='View footnote' class='footnote'>" + n + "</a>]";
703 }
704 }
705 }
706},
707
708install: function(toclevels) {
709 var timerId;
710
711 function reinstall() {
712 asciidoc.footnotes();
713 if (toclevels) {
714 asciidoc.toc(toclevels);
715 }
716 }
717
718 function reinstallAndRemoveTimer() {
719 clearInterval(timerId);
720 reinstall();
721 }
722
723 timerId = setInterval(reinstall, 500);
724 if (document.addEventListener)
725 document.addEventListener("DOMContentLoaded", reinstallAndRemoveTimer, false);
726 else
727 window.onload = reinstallAndRemoveTimer;
728}
729
730}
731asciidoc.install();
732/*]]>*/
733</script>
734</head>
735<body class="article">
736<div id="header">
737<h1>Trace2 API</h1>
738</div>
739<div id="content">
740<div id="preamble">
741<div class="sectionbody">
742<div class="paragraph"><p>The Trace2 API can be used to print debug, performance, and telemetry
743information to stderr or a file. The Trace2 feature is inactive unless
744explicitly enabled by enabling one or more Trace2 Targets.</p></div>
745<div class="paragraph"><p>The Trace2 API is intended to replace the existing (Trace1)
746printf-style tracing provided by the existing <code>GIT_TRACE</code> and
747<code>GIT_TRACE_PERFORMANCE</code> facilities. During initial implementation,
748Trace2 and Trace1 may operate in parallel.</p></div>
749<div class="paragraph"><p>The Trace2 API defines a set of high-level messages with known fields,
750such as (<code>start</code>: <code>argv</code>) and (<code>exit</code>: {<code>exit-code</code>, <code>elapsed-time</code>}).</p></div>
751<div class="paragraph"><p>Trace2 instrumentation throughout the Git code base sends Trace2
752messages to the enabled Trace2 Targets. Targets transform these
753messages content into purpose-specific formats and write events to
754their data streams. In this manner, the Trace2 API can drive
755many different types of analysis.</p></div>
756<div class="paragraph"><p>Targets are defined using a VTable allowing easy extension to other
757formats in the future. This might be used to define a binary format,
758for example.</p></div>
759</div>
760</div>
761<div class="sect1">
762<h2 id="_trace2_targets">Trace2 Targets</h2>
763<div class="sectionbody">
764<div class="paragraph"><p>Trace2 defines the following set of Trace2 Targets.
765Format details are given in a later section.</p></div>
766<div class="dlist"><dl>
767<dt class="hdlist1">
768<code>GIT_TR2</code> (NORMAL)
769</dt>
770<dd>
771<p>
772 a simple printf format like GIT_TRACE.
773</p>
774<div class="listingblock">
775<div class="content">
776<pre><code>$ export GIT_TR2=~/log.normal
777$ git version
778git version 2.20.1.155.g426c96fcdb</code></pre>
779</div></div>
780<div class="listingblock">
781<div class="content">
782<pre><code>$ cat ~/log.normal
78312:28:42.620009 common-main.c:38 version 2.20.1.155.g426c96fcdb
78412:28:42.620989 common-main.c:39 start git version
78512:28:42.621101 git.c:432 cmd_name version (version)
78612:28:42.621215 git.c:662 exit elapsed:0.001227 code:0
78712:28:42.621250 trace2/tr2_tgt_normal.c:124 atexit elapsed:0.001265 code:0</code></pre>
788</div></div>
789</dd>
790<dt class="hdlist1">
791<code>GIT_TR2_PERF</code> (PERF)
792</dt>
793<dd>
794<p>
795 a column-based format to replace GIT_TRACE_PERFORMANCE suitable for
796 development and testing, possibly to complement tools like gprof.
797</p>
798<div class="listingblock">
799<div class="content">
800<pre><code>$ export GIT_TR2_PERF=~/log.perf
801$ git version
802git version 2.20.1.155.g426c96fcdb</code></pre>
803</div></div>
804<div class="listingblock">
805<div class="content">
806<pre><code>$ cat ~/log.perf
80712:28:42.620675 common-main.c:38 | d0 | main | version | | | | | 2.20.1.155.g426c96fcdb
80812:28:42.621001 common-main.c:39 | d0 | main | start | | | | | git version
80912:28:42.621111 git.c:432 | d0 | main | cmd_name | | | | | version (version)
81012:28:42.621225 git.c:662 | d0 | main | exit | | 0.001227 | | | code:0
81112:28:42.621259 trace2/tr2_tgt_perf.c:211 | d0 | main | atexit | | 0.001265 | | | code:0</code></pre>
812</div></div>
813</dd>
814<dt class="hdlist1">
815<code>GIT_TR2_EVENT</code> (EVENT)
816</dt>
817<dd>
818<p>
819 a JSON-based format of event data suitable for telemetry analysis.
820</p>
821<div class="listingblock">
822<div class="content">
823<pre><code>$ export GIT_TR2_EVENT=~/log.event
824$ git version
825git version 2.20.1.155.g426c96fcdb</code></pre>
826</div></div>
827<div class="listingblock">
828<div class="content">
829<pre><code>$ cat ~/log.event
830{"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"}
831{"event":"start","sid":"1547659722619736-11614","thread":"main","time":"2019-01-16 17:28:42.621027","file":"common-main.c","line":39,"argv":["git","version"]}
832{"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"}
833{"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}
834{"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}</code></pre>
835</div></div>
836</dd>
837</dl></div>
838</div>
839</div>
840<div class="sect1">
841<h2 id="_enabling_a_target">Enabling a Target</h2>
842<div class="sectionbody">
843<div class="paragraph"><p>A Trace2 Target is enabled when the corresponding environment variable
844(<code>GIT_TR2</code>, <code>GIT_TR2_PERF</code>, or <code>GIT_TR2_EVENT</code>) is set. The following
845values are recognized.</p></div>
846<div class="dlist"><dl>
847<dt class="hdlist1">
848<code>0</code>
849</dt>
850<dt class="hdlist1">
851<code>false</code>
852</dt>
853<dd>
854<p>
855 Disables the target.
856</p>
857</dd>
858<dt class="hdlist1">
859<code>1</code>
860</dt>
861<dt class="hdlist1">
862<code>true</code>
863</dt>
864<dd>
865<p>
866 Enables the target and writes stream to <code>STDERR</code>.
867</p>
868</dd>
869<dt class="hdlist1">
870<code>[2-9]</code>
871</dt>
872<dd>
873<p>
874 Enables the target and writes to the already opened file descriptor.
875</p>
876</dd>
877<dt class="hdlist1">
878<code>&lt;absolute-pathname&gt;</code>
879</dt>
880<dd>
881<p>
882 Enables the target, opens and writes to the file in append mode.
883</p>
884</dd>
885<dt class="hdlist1">
886<code>af_unix:[&lt;socket_type&gt;:]&lt;absolute-pathname&gt;</code>
887</dt>
888<dd>
889<p>
890 Enables the target, opens and writes to a Unix Domain Socket
891 (on platforms that support them).
892</p>
893<div class="paragraph"><p>Socket type can be either <code>stream</code> or <code>dgram</code>. If the socket type is
894omitted, Git will try both.</p></div>
895</dd>
896</dl></div>
897</div>
898</div>
899<div class="sect1">
900<h2 id="_trace2_api">Trace2 API</h2>
901<div class="sectionbody">
902<div class="paragraph"><p>All public Trace2 functions and macros are defined in <code>trace2.h</code> and
903<code>trace2.c</code>. All public symbols are prefixed with <code>trace2_</code>.</p></div>
904<div class="paragraph"><p>There are no public Trace2 data structures.</p></div>
905<div class="paragraph"><p>The Trace2 code also defines a set of private functions and data types
906in the <code>trace2/</code> directory. These symbols are prefixed with <code>tr2_</code>
907and should only be used by functions in <code>trace2.c</code>.</p></div>
908</div>
909</div>
910<div class="sect1">
911<h2 id="_conventions_for_public_functions_and_macros">Conventions for Public Functions and Macros</h2>
912<div class="sectionbody">
913<div class="paragraph"><p>The functions defined by the Trace2 API are declared and documented
914in <code>trace2.h</code>. It defines the API functions and wrapper macros for
915Trace2.</p></div>
916<div class="paragraph"><p>Some functions have a <code>_fl()</code> suffix to indicate that they take <code>file</code>
917and <code>line-number</code> arguments.</p></div>
918<div class="paragraph"><p>Some functions have a <code>_va_fl()</code> suffix to indicate that they also
919take a <code>va_list</code> argument.</p></div>
920<div class="paragraph"><p>Some functions have a <code>_printf_fl()</code> suffix to indicate that they also
921take a varargs argument.</p></div>
922<div class="paragraph"><p>There are CPP wrapper macros and ifdefs to hide most of these details.
923See <code>trace2.h</code> for more details. The following discussion will only
924describe the simplified forms.</p></div>
925</div>
926</div>
927<div class="sect1">
928<h2 id="_public_api">Public API</h2>
929<div class="sectionbody">
930<div class="paragraph"><p>All Trace2 API functions send a messsage to all of the active
931Trace2 Targets. This section describes the set of available
932messages.</p></div>
933<div class="paragraph"><p>It helps to divide these functions into groups for discussion
934purposes.</p></div>
935<div class="sect2">
936<h3 id="_basic_command_messages">Basic Command Messages</h3>
937<div class="paragraph"><p>These are concerned with the lifetime of the overall git process.</p></div>
938<div class="dlist"><dl>
939<dt class="hdlist1">
940<code>void trace2_initialize()</code>
941</dt>
942<dd>
943<p>
944 Determines if any Trace2 Targets should be enabled and
945 initializes the Trace2 facility. This includes starting the
946 elapsed time clocks and thread local storage (TLS).
947</p>
948<div class="paragraph"><p>This function emits a "version" message containing the version of git
949and the Trace2 protocol.</p></div>
950<div class="paragraph"><p>This function should be called from <code>main()</code> as early as possible in
951the life of the process.</p></div>
952</dd>
953<dt class="hdlist1">
954<code>int trace2_is_enabled()</code>
955</dt>
956<dd>
957<p>
958 Returns 1 if Trace2 is enabled (at least one target is
959 active).
960</p>
961</dd>
962<dt class="hdlist1">
963<code>void trace2_cmd_start(int argc, const char **argv)</code>
964</dt>
965<dd>
966<p>
967 Emits a "start" message containing the process command line
968 arguments.
969</p>
970</dd>
971<dt class="hdlist1">
972<code>int trace2_cmd_exit(int exit_code)</code>
973</dt>
974<dd>
975<p>
976 Emits an "exit" message containing the process exit-code and
977 elapsed time.
978</p>
979<div class="paragraph"><p>Returns the exit-code.</p></div>
980</dd>
981<dt class="hdlist1">
982<code>void trace2_cmd_error(const char *fmt, va_list ap)</code>
983</dt>
984<dd>
985<p>
986 Emits an "error" message containing a formatted error message.
987</p>
988</dd>
989<dt class="hdlist1">
990<code>void trace2_cmd_path(const char *pathname)</code>
991</dt>
992<dd>
993<p>
994 Emits a "cmd_path" message with the full pathname of the
995 current process.
996</p>
997</dd>
998</dl></div>
999</div>
1000<div class="sect2">
1001<h3 id="_command_detail_messages">Command Detail Messages</h3>
1002<div class="paragraph"><p>These are concerned with describing the specific Git command
1003after the command line, config, and environment are inspected.</p></div>
1004<div class="dlist"><dl>
1005<dt class="hdlist1">
1006<code>void trace2_cmd_name(const char *name)</code>
1007</dt>
1008<dd>
1009<p>
1010 Emits a "cmd_name" message with the canonical name of the
1011 command, for example "status" or "checkout".
1012</p>
1013</dd>
1014<dt class="hdlist1">
1015<code>void trace2_cmd_mode(const char *mode)</code>
1016</dt>
1017<dd>
1018<p>
1019 Emits a "cmd_mode" message with a qualifier name to further
1020 describe the current git command.
1021</p>
1022<div class="paragraph"><p>This message is intended to be used with git commands having multiple
1023major modes. For example, a "checkout" command can checkout a new
1024branch or it can checkout a single file, so the checkout code could
1025emit a cmd_mode message of "branch" or "file".</p></div>
1026</dd>
1027<dt class="hdlist1">
1028<code>void trace2_cmd_alias(const char *alias, const char **argv_expansion)</code>
1029</dt>
1030<dd>
1031<p>
1032 Emits an "alias" message containing the alias used and the
1033 argument expansion.
1034</p>
1035</dd>
1036<dt class="hdlist1">
1037<code>void trace2_def_param(const char *parameter, const char *value)</code>
1038</dt>
1039<dd>
1040<p>
1041 Emits a "def_param" message containing a key/value pair.
1042</p>
1043<div class="paragraph"><p>This message is intended to report some global aspect of the current
1044command, such as a configuration setting or command line switch that
1045significantly affects program performance or behavior, such as
1046<code>core.abbrev</code>, <code>status.showUntrackedFiles</code>, or <code>--no-ahead-behind</code>.</p></div>
1047</dd>
1048<dt class="hdlist1">
1049<code>void trace2_cmd_list_config()</code>
1050</dt>
1051<dd>
1052<p>
1053 Emits a "def_param" messages for "important" configuration
1054 settings.
1055</p>
1056<div class="paragraph"><p>The environment variable <code>GIT_TR2_CONFIG_PARAMS</code> can be set to a
1057list of patterns of important configuration settings, for example:
1058<code>core.*,remote.*.url</code>. This function will iterate over all config
1059settings and emit a "def_param" message for each match.</p></div>
1060</dd>
1061<dt class="hdlist1">
1062<code>void trace2_cmd_set_config(const char *key, const char *value)</code>
1063</dt>
1064<dd>
1065<p>
1066 Emits a "def_param" message for a specific configuration
1067 setting IFF it matches the <code>GIT_TR2_CONFIG_PARAMS</code> pattern.
1068</p>
1069<div class="paragraph"><p>This is used to hook into <code>git_config_set()</code> and catch any
1070configuration changes and update a value previously reported by
1071<code>trace2_cmd_list_config()</code>.</p></div>
1072</dd>
1073<dt class="hdlist1">
1074<code>void trace2_def_repo(struct repository *repo)</code>
1075</dt>
1076<dd>
1077<p>
1078 Registers a repository with the Trace2 layer. Assigns a
1079 unique "repo-id" to <code>repo-&gt;trace2_repo_id</code>.
1080</p>
1081<div class="paragraph"><p>Emits a "worktree" messages containing the repo-id and the worktree
1082pathname.</p></div>
1083<div class="paragraph"><p>Region and data messages (described later) may refer to this repo-id.</p></div>
1084<div class="paragraph"><p>The main/top-level repository will have repo-id value 1 (aka "r1").</p></div>
1085<div class="paragraph"><p>The repo-id field is in anticipation of future in-proc submodule
1086repositories.</p></div>
1087</dd>
1088</dl></div>
1089</div>
1090<div class="sect2">
1091<h3 id="_child_process_messages">Child Process Messages</h3>
1092<div class="paragraph"><p>These are concerned with the various spawned child processes,
1093including shell scripts, git commands, editors, pagers, and hooks.</p></div>
1094<div class="dlist"><dl>
1095<dt class="hdlist1">
1096<code>void trace2_child_start(struct child_process *cmd)</code>
1097</dt>
1098<dd>
1099<p>
1100 Emits a "child_start" message containing the "child-id",
1101 "child-argv", and "child-classification".
1102</p>
1103<div class="paragraph"><p>Before calling this, set <code>cmd-&gt;trace2_child_class</code> to a name
1104describing the type of child process, for example "editor".</p></div>
1105<div class="paragraph"><p>This function assigns a unique "child-id" to <code>cmd-&gt;trace2_child_id</code>.
1106This field is used later during the "child_exit" message to associate
1107it with the "child_start" message.</p></div>
1108<div class="paragraph"><p>This function should be called before spawning the child process.</p></div>
1109</dd>
1110<dt class="hdlist1">
1111<code>void trace2_child_exit(struct child_proess *cmd, int child_exit_code)</code>
1112</dt>
1113<dd>
1114<p>
1115 Emits a "child_exit" message containing the "child-id",
1116 the child&#8217;s elapsed time and exit-code.
1117</p>
1118<div class="paragraph"><p>The reported elapsed time includes the process creation overhead and
1119time spend waiting for it to exit, so it may be slightly longer than
1120the time reported by the child itself.</p></div>
1121<div class="paragraph"><p>This function should be called after reaping the child process.</p></div>
1122</dd>
1123<dt class="hdlist1">
1124<code>int trace2_exec(const char *exe, const char **argv)</code>
1125</dt>
1126<dd>
1127<p>
1128 Emits a "exec" message containing the "exec-id" and the
1129 argv of the new process.
1130</p>
1131<div class="paragraph"><p>This function should be called before calling one of the <code>exec()</code>
1132variants, such as <code>execvp()</code>.</p></div>
1133<div class="paragraph"><p>This function returns a unique "exec-id". This value is used later
1134if the exec() fails and a "exec-result" message is necessary.</p></div>
1135</dd>
1136<dt class="hdlist1">
1137<code>void trace2_exec_result(int exec_id, int error_code)</code>
1138</dt>
1139<dd>
1140<p>
1141 Emits a "exec_result" message containing the "exec-id"
1142 and the error code.
1143</p>
1144<div class="paragraph"><p>On Unix-based systems, <code>exec()</code> does not return if successful.
1145This message is used to indicate that the <code>exec()</code> failed and
1146that the current program is continuing.</p></div>
1147</dd>
1148</dl></div>
1149</div>
1150<div class="sect2">
1151<h3 id="_git_thread_messages">Git Thread Messages</h3>
1152<div class="paragraph"><p>These messages are concerned with Git thread usage.</p></div>
1153<div class="dlist"><dl>
1154<dt class="hdlist1">
1155<code>void trace2_thread_start(const char *thread_name)</code>
1156</dt>
1157<dd>
1158<p>
1159 Emits a "thread_start" message.
1160</p>
1161<div class="paragraph"><p>The <code>thread_name</code> field should be a descriptive name, such as the
1162unique name of the thread-proc. A unique "thread-id" will be added
1163to the name to uniquely identify thread instances.</p></div>
1164<div class="paragraph"><p>Region and data messages (described later) may refer to this thread
1165name.</p></div>
1166<div class="paragraph"><p>This function must be called by the thread-proc of the new thread
1167(so that TLS data is properly initialized) and not by the caller
1168of <code>pthread_create()</code>.</p></div>
1169</dd>
1170<dt class="hdlist1">
1171<code>void trace2_thread_exit()</code>
1172</dt>
1173<dd>
1174<p>
1175 Emits a "thread_exit" message containing the thread name
1176 and the thread elapsed time.
1177</p>
1178<div class="paragraph"><p>This function must be called by the thread-proc before it returns
1179(so that the coorect TLS data is used and cleaned up. It should
1180not be called by the caller of <code>pthread_join()</code>.</p></div>
1181</dd>
1182</dl></div>
1183</div>
1184<div class="sect2">
1185<h3 id="_region_and_data_messages">Region and Data Messages</h3>
1186<div class="paragraph"><p>These are concerned with recording performance data
1187over regions or spans of code.</p></div>
1188<div class="dlist"><dl>
1189<dt class="hdlist1">
1190<code>void trace2_region_enter(const char *category, const char *label, const struct repository *repo)</code>
1191</dt>
1192<dt class="hdlist1">
1193<code>void trace2_region_enter_printf(const char *category, const char *label, const struct repository *repo, const char *fmt, ...)</code>
1194</dt>
1195<dt class="hdlist1">
1196<code>void trace2_region_enter_printf_va(const char *category, const char *label, const struct repository *repo, const char *fmt, va_list ap)</code>
1197</dt>
1198<dd>
1199<p>
1200 Emits a thread-relative "region_enter" message with optional
1201 printf string.
1202</p>
1203<div class="paragraph"><p>This function pushes a new region nesting stack level on the current
1204thread and starts a clock for the new stack frame.</p></div>
1205<div class="paragraph"><p>The <code>category</code> field is an arbitrary category name used to classify
1206regions by feature area, such as "status" or "index". At this time
1207it is only just printed along with the rest of the message. It may
1208be used in the future to filter messages.</p></div>
1209<div class="paragraph"><p>The <code>label</code> field is an arbitrary label used to describe the activity
1210being started, such as "read_recursive" or "do_read_index".</p></div>
1211<div class="paragraph"><p>The <code>repo</code> field, if set, will be used to get the "repo-id", so that
1212recursive oerations can be attributed to the correct repository.</p></div>
1213</dd>
1214<dt class="hdlist1">
1215<code>void trace2_region_leave(const char *category, const char *label, const struct repository *repo)</code>
1216</dt>
1217<dt class="hdlist1">
1218<code>void trace2_region_leave_printf(const char *category, const char *label, const struct repository *repo, const char *fmt, ...)</code>
1219</dt>
1220<dt class="hdlist1">
1221<code>void trace2_region_leave_printf_va(const char *category, const char *label, const struct repository *repo, const char *fmt, va_list ap)</code>
1222</dt>
1223<dd>
1224<p>
1225 Emits a thread-relative "region_leave" message with optional
1226 printf string.
1227</p>
1228<div class="paragraph"><p>This function pops the region nesting stack on the current thread
1229and reports the elapsed time of the stack frame.</p></div>
1230<div class="paragraph"><p>The <code>category</code>, <code>label</code>, and <code>repo</code> fields are the same as above.
1231The <code>category</code> and <code>label</code> do not need to match the correpsonding
1232"region_enter" message, but it makes the data stream easier to
1233understand.</p></div>
1234</dd>
1235<dt class="hdlist1">
1236<code>void trace2_data_string(const char *category, const struct repository *repo, const char *key, const char * value)</code>
1237</dt>
1238<dt class="hdlist1">
1239<code>void trace2_data_intmax(const char *category, const struct repository *repo, const char *key, intmax value)</code>
1240</dt>
1241<dt class="hdlist1">
1242<code>void trace2_data_json(const char *category, const struct repository *repo, const char *key, const struct json_writer *jw)</code>
1243</dt>
1244<dd>
1245<p>
1246 Emits a region- and thread-relative "data" or "data_json" message.
1247</p>
1248<div class="paragraph"><p>This is a key/value pair message containing information about the
1249current thread, region stack, and repository. This could be used
1250to print the number of files in a directory during a multi-threaded
1251recursive tree walk.</p></div>
1252</dd>
1253<dt class="hdlist1">
1254<code>void trace2_printf(const char *fmt, ...)</code>
1255</dt>
1256<dt class="hdlist1">
1257<code>void trace2_printf_va(const char *fmt, va_list ap)</code>
1258</dt>
1259<dd>
1260<p>
1261 Emits a region- and thread-relative "printf" message.
1262</p>
1263</dd>
1264</dl></div>
1265</div>
1266</div>
1267</div>
1268<div class="sect1">
1269<h2 id="_trace2_target_formats">Trace2 Target Formats</h2>
1270<div class="sectionbody">
1271<div class="sect2">
1272<h3 id="_normal_format">NORMAL Format</h3>
1273<div class="paragraph"><p>NORMAL format is enabled when the <code>GIT_TR2</code> environment variable is
1274set.</p></div>
1275<div class="paragraph"><p>Events are written as lines of the form:</p></div>
1276<div class="listingblock">
1277<div class="content">
1278<pre><code>[&lt;time&gt; SP &lt;filename&gt;:&lt;line&gt; SP+] &lt;event-name&gt; [[SP] &lt;event-message&gt;] LF</code></pre>
1279</div></div>
1280<div class="dlist"><dl>
1281<dt class="hdlist1">
1282<code>&lt;event-name&gt;</code>
1283</dt>
1284<dd>
1285<p>
1286 is the event name.
1287</p>
1288</dd>
1289<dt class="hdlist1">
1290<code>&lt;event-message&gt;</code>
1291</dt>
1292<dd>
1293<p>
1294 is a free-form printf message intended for human consumption.
1295</p>
1296<div class="paragraph"><p>Note that this may contain embedded LF or CRLF characters that are
1297not escaped, so the event may spill across multiple lines.</p></div>
1298</dd>
1299</dl></div>
1300<div class="paragraph"><p>If <code>GIT_TR2_BRIEF</code> is true, the <code>time</code>, <code>filename</code>, and <code>line</code> fields
1301are omitted.</p></div>
1302<div class="paragraph"><p>This target is intended to be more of a summary (like GIT_TRACE) and
1303less detailed than the other targets. It ignores thread, region, and
1304data messages, for example.</p></div>
1305</div>
1306<div class="sect2">
1307<h3 id="_perf_format">PERF Format</h3>
1308<div class="paragraph"><p>PERF format is enabled when the <code>GIT_TR2_PERF</code> environment variable
1309is set.</p></div>
1310<div class="paragraph"><p>Events are written as lines of the form:</p></div>
1311<div class="listingblock">
1312<div class="content">
1313<pre><code>[&lt;time&gt; SP &lt;filename&gt;:&lt;line&gt; SP+
1314 BAR SP] d&lt;depth&gt; SP
1315 BAR SP &lt;thread-name&gt; SP+
1316 BAR SP &lt;event-name&gt; SP+
1317 BAR SP [r&lt;repo-id&gt;] SP+
1318 BAR SP [&lt;t_abs&gt;] SP+
1319 BAR SP [&lt;t_rel&gt;] SP+
1320 BAR SP [&lt;category&gt;] SP+
1321 BAR SP DOTS* &lt;perf-event-message&gt;
1322 LF</code></pre>
1323</div></div>
1324<div class="dlist"><dl>
1325<dt class="hdlist1">
1326<code>&lt;depth&gt;</code>
1327</dt>
1328<dd>
1329<p>
1330 is the git process depth. This is the number of parent
1331 git processes. A top-level git command has depth value "d0".
1332 A child of it has depth value "d1". A second level child
1333 has depth value "d2" and so on.
1334</p>
1335</dd>
1336<dt class="hdlist1">
1337<code>&lt;thread-name&gt;</code>
1338</dt>
1339<dd>
1340<p>
1341 is a unique name for the thread. The primary thread
1342 is called "main". Other thread names are of the form "th%d:%s"
1343 and include a unique number and the name of the thread-proc.
1344</p>
1345</dd>
1346<dt class="hdlist1">
1347<code>&lt;event-name&gt;</code>
1348</dt>
1349<dd>
1350<p>
1351 is the event name.
1352</p>
1353</dd>
1354<dt class="hdlist1">
1355<code>&lt;repo-id&gt;</code>
1356</dt>
1357<dd>
1358<p>
1359 when present, is a number indicating the repository
1360 in use. A <code>def_repo</code> event is emitted when a repository is
1361 opened. This defines the repo-id and associated worktree.
1362 Subsequent repo-specific events will reference this repo-id.
1363</p>
1364<div class="paragraph"><p>Currently, this is always "r1" for the main repository.
1365This field is in anticipation of in-proc submodules in the future.</p></div>
1366</dd>
1367<dt class="hdlist1">
1368<code>&lt;t_abs&gt;</code>
1369</dt>
1370<dd>
1371<p>
1372 when present, is the absolute time in seconds since the
1373 program started.
1374</p>
1375</dd>
1376<dt class="hdlist1">
1377<code>&lt;t_rel&gt;</code>
1378</dt>
1379<dd>
1380<p>
1381 when present, is time in seconds relative to the start of
1382 the current region. For a thread-exit event, it is the elapsed
1383 time of the thread.
1384</p>
1385</dd>
1386<dt class="hdlist1">
1387<code>&lt;category&gt;</code>
1388</dt>
1389<dd>
1390<p>
1391 is present on region and data events and is used to
1392 indicate a broad category, such as "index" or "status".
1393</p>
1394</dd>
1395<dt class="hdlist1">
1396<code>&lt;perf-event-message&gt;</code>
1397</dt>
1398<dd>
1399<p>
1400 is a free-form printf message intended for human consumption.
1401</p>
1402</dd>
1403</dl></div>
1404<div class="listingblock">
1405<div class="content">
1406<pre><code>15:33:33.532712 wt-status.c:2310 | d0 | main | region_enter | r1 | 0.126064 | | status | label:print
140715:33:33.532712 wt-status.c:2331 | d0 | main | region_leave | r1 | 0.127568 | 0.001504 | status | label:print</code></pre>
1408</div></div>
1409<div class="paragraph"><p>If <code>GIT_TR2_PERF_BRIEF</code> is true, the <code>time</code>, <code>file</code>, and <code>line</code>
1410fields are omitted.</p></div>
1411<div class="listingblock">
1412<div class="content">
1413<pre><code>d0 | main | region_leave | r1 | 0.011717 | 0.009122 | index | label:preload</code></pre>
1414</div></div>
1415<div class="paragraph"><p>The PERF target is intended for interactive performance analysis
1416during development and is quite noisy.</p></div>
1417</div>
1418<div class="sect2">
1419<h3 id="_event_format">EVENT Format</h3>
1420<div class="paragraph"><p>EVENT format is enabled when the <code>GIT_TR2_EVENT</code> environment
1421variable is set.</p></div>
1422<div class="paragraph"><p>Each event is a JSON-object containing multiple key/value pairs
1423written as a single line and followed by a LF.</p></div>
1424<div class="listingblock">
1425<div class="content">
1426<pre><code>'{' &lt;key&gt; ':' &lt;value&gt; [',' &lt;key&gt; ':' &lt;value&gt;]* '}' LF</code></pre>
1427</div></div>
1428<div class="paragraph"><p>Some key/value pairs are common to all events and some are
1429event-specific.</p></div>
1430<div class="sect3">
1431<h4 id="_common_key_value_pairs">Common Key/Value Pairs</h4>
1432<div class="paragraph"><p>The following key/value pairs are common to all events:</p></div>
1433<div class="listingblock">
1434<div class="content">
1435<pre><code>{
1436 "event":"version",
1437 "sid":"1547659722619736-11614",
1438 "thread":"main",
1439 "time":"2019-01-16 17:28:42.620713",
1440 "file":"common-main.c",
1441 "line":38,
1442 ...
1443}</code></pre>
1444</div></div>
1445<div class="dlist"><dl>
1446<dt class="hdlist1">
1447<code>"event":&lt;event&gt;</code>
1448</dt>
1449<dd>
1450<p>
1451 is the event name.
1452</p>
1453</dd>
1454<dt class="hdlist1">
1455<code>"sid":&lt;sid&gt;</code>
1456</dt>
1457<dd>
1458<p>
1459 is the session-id. This is a unique string to identify the
1460 process instance to allow all events emitted by a process to
1461 be identified. A session-id is used instead of a PID because
1462 PIDs are recycled by the OS. For child git processes, the
1463 session-id is prepended with the session-id of the parent git
1464 process to allow parent-child relationships to be identified
1465 during post-processing.
1466</p>
1467</dd>
1468<dt class="hdlist1">
1469<code>"thread":&lt;thread&gt;</code>
1470</dt>
1471<dd>
1472<p>
1473 is the thread name.
1474</p>
1475</dd>
1476<dt class="hdlist1">
1477<code>"time":&lt;time&gt;</code>
1478</dt>
1479<dd>
1480<p>
1481 is the UTC time of the event.
1482</p>
1483</dd>
1484<dt class="hdlist1">
1485<code>"file":&lt;filename&gt;</code>
1486</dt>
1487<dd>
1488<p>
1489 is source file generating the event.
1490</p>
1491</dd>
1492<dt class="hdlist1">
1493<code>"line":&lt;line-number&gt;</code>
1494</dt>
1495<dd>
1496<p>
1497 is the integer source line number generating the event.
1498</p>
1499</dd>
1500<dt class="hdlist1">
1501<code>"repo":&lt;repo-id&gt;</code>
1502</dt>
1503<dd>
1504<p>
1505 when present, is the integer repo-id as described previously.
1506</p>
1507</dd>
1508</dl></div>
1509<div class="paragraph"><p>If <code>GIT_TR2_EVENT_BRIEF</code> is true, the <code>file</code> and <code>line</code> fields are omitted
1510from all events and the <code>time</code> field is only present on the "start" and
1511"atexit" events.</p></div>
1512</div>
1513<div class="sect3">
1514<h4 id="_event_specific_key_value_pairs">Event-Specific Key/Value Pairs</h4>
1515<div class="dlist"><dl>
1516<dt class="hdlist1">
1517<code>"version"</code>
1518</dt>
1519<dd>
1520<p>
1521 This event gives the version of the executable and the EVENT format.
1522</p>
1523<div class="listingblock">
1524<div class="content">
1525<pre><code>{
1526 "event":"version",
1527 ...
1528 "evt":"1", # EVENT format version
1529 "exe":"2.20.1.155.g426c96fcdb" # git version
1530}</code></pre>
1531</div></div>
1532</dd>
1533<dt class="hdlist1">
1534<code>"start"</code>
1535</dt>
1536<dd>
1537<p>
1538 This event contains the complete argv received by main().
1539</p>
1540<div class="listingblock">
1541<div class="content">
1542<pre><code>{
1543 "event":"start",
1544 ...
1545 "argv":["git","version"]
1546}</code></pre>
1547</div></div>
1548</dd>
1549<dt class="hdlist1">
1550<code>"exit"</code>
1551</dt>
1552<dd>
1553<p>
1554 This event is emitted when git calls <code>exit()</code>.
1555</p>
1556<div class="listingblock">
1557<div class="content">
1558<pre><code>{
1559 "event":"exit",
1560 ...
1561 "t_abs":0.001227, # elapsed time in seconds
1562 "code":0 # exit code
1563}</code></pre>
1564</div></div>
1565</dd>
1566<dt class="hdlist1">
1567<code>"atexit"</code>
1568</dt>
1569<dd>
1570<p>
1571 This event is emitted by the Trace2 <code>atexit</code> routine during
1572 final shutdown. It should be the last event emitted by the
1573 process.
1574</p>
1575<div class="paragraph"><p>(The elapsed time reported here is greater than the time reported in
1576the "exit" event because it runs after all other atexit tasks have
1577completed.)</p></div>
1578<div class="listingblock">
1579<div class="content">
1580<pre><code>{
1581 "event":"atexit",
1582 ...
1583 "t_abs":0.001227, # elapsed time in seconds
1584 "code":0 # exit code
1585}</code></pre>
1586</div></div>
1587</dd>
1588<dt class="hdlist1">
1589<code>"signal"</code>
1590</dt>
1591<dd>
1592<p>
1593 This event is emitted when the program is terminated by a user
1594 signal. Depending on the platform, the signal event may
1595 prevent the "atexit" event from being generated.
1596</p>
1597<div class="listingblock">
1598<div class="content">
1599<pre><code>{
1600 "event":"signal",
1601 ...
1602 "t_abs":0.001227, # elapsed time in seconds
1603 "signal":13 # SIGTERM, SIGINT, etc.
1604}</code></pre>
1605</div></div>
1606</dd>
1607<dt class="hdlist1">
1608<code>"error"</code>
1609</dt>
1610<dd>
1611<p>
1612 This event is emitted when one of the <code>error()</code>, <code>die()</code>,
1613 or <code>usage()</code> functions are called.
1614</p>
1615<div class="listingblock">
1616<div class="content">
1617<pre><code>{
1618 "event":"error",
1619 ...
1620 "msg":"invalid option: --cahced", # formatted error message
1621 "fmt":"invalid option: %s" # error format string
1622}</code></pre>
1623</div></div>
1624<div class="paragraph"><p>The error event may be emitted more than once. The format string
1625allows post-processors to group errors by type without worrying
1626about specific error arguments.</p></div>
1627</dd>
1628<dt class="hdlist1">
1629<code>"cmd_path"</code>
1630</dt>
1631<dd>
1632<p>
1633 This event contains the discovered full path of the git
1634 executable (on platforms that are configured to resolve it).
1635</p>
1636<div class="listingblock">
1637<div class="content">
1638<pre><code>{
1639 "event":"cmd_path",
1640 ...
1641 "path":"C:/work/gfw/git.exe"
1642}</code></pre>
1643</div></div>
1644</dd>
1645<dt class="hdlist1">
1646<code>"cmd_name"</code>
1647</dt>
1648<dd>
1649<p>
1650 This event contains the command name for this git process
1651 and the hierarchy of commands from parent git processes.
1652</p>
1653<div class="listingblock">
1654<div class="content">
1655<pre><code>{
1656 "event":"cmd_name",
1657 ...
1658 "name":"pack-objects",
1659 "hierarchy":"push/pack-objects"
1660}</code></pre>
1661</div></div>
1662<div class="paragraph"><p>Normally, the "name" field contains the canonical name of the
1663command. When a canonical name is not available, one of
1664these special values are used:</p></div>
1665<div class="listingblock">
1666<div class="content">
1667<pre><code>"_query_" # "git --html-path"
1668"_run_dashed_" # when "git foo" tries to run "git-foo"
1669"_run_shell_alias_" # alias expansion to a shell command
1670"_run_git_alias_" # alias expansion to a git command
1671"_usage_" # usage error</code></pre>
1672</div></div>
1673</dd>
1674<dt class="hdlist1">
1675<code>"cmd_mode"</code>
1676</dt>
1677<dd>
1678<p>
1679 This event, when present, describes the command variant This
1680 event may be emitted more than once.
1681</p>
1682<div class="listingblock">
1683<div class="content">
1684<pre><code>{
1685 "event":"cmd_mode",
1686 ...
1687 "name":"branch"
1688}</code></pre>
1689</div></div>
1690<div class="paragraph"><p>The "name" field is an arbitrary string to describe the command mode.
1691For example, checkout can checkout a branch or an individual file.
1692And these variations typically have different performance
1693characteristics that are not comparable.</p></div>
1694</dd>
1695<dt class="hdlist1">
1696<code>"alias"</code>
1697</dt>
1698<dd>
1699<p>
1700 This event is present when an alias is expanded.
1701</p>
1702<div class="listingblock">
1703<div class="content">
1704<pre><code>{
1705 "event":"alias",
1706 ...
1707 "alias":"l", # registered alias
1708 "argv":["log","--graph"] # alias expansion
1709}</code></pre>
1710</div></div>
1711</dd>
1712<dt class="hdlist1">
1713<code>"child_start"</code>
1714</dt>
1715<dd>
1716<p>
1717 This event describes a child process that is about to be
1718 spawned.
1719</p>
1720<div class="listingblock">
1721<div class="content">
1722<pre><code>{
1723 "event":"child_start",
1724 ...
1725 "child_id":2,
1726 "child_class":"?",
1727 "use_shell":false,
1728 "argv":["git","rev-list","--objects","--stdin","--not","--all","--quiet"]
1729
1730 "hook_name":"&lt;hook_name&gt;" # present when child_class is "hook"
1731 "cd":"&lt;path&gt;" # present when cd is required
1732}</code></pre>
1733</div></div>
1734<div class="paragraph"><p>The "child_id" field can be used to match this child_start with the
1735corresponding child_exit event.</p></div>
1736<div class="paragraph"><p>The "child_class" field is a rough classification, such as "editor",
1737"pager", "transport/*", and "hook". Unclassified children are classified
1738with "?".</p></div>
1739</dd>
1740<dt class="hdlist1">
1741<code>"child_exit"</code>
1742</dt>
1743<dd>
1744<p>
1745 This event is generated after the current process has returned
1746 from the waitpid() and collected the exit information from the
1747 child.
1748</p>
1749<div class="listingblock">
1750<div class="content">
1751<pre><code>{
1752 "event":"child_exit",
1753 ...
1754 "child_id":2,
1755 "pid":14708, # child PID
1756 "code":0, # child exit-code
1757 "t_rel":0.110605 # observed run-time of child process
1758}</code></pre>
1759</div></div>
1760<div class="paragraph"><p>Note that the session-id of the child process is not available to
1761the current/spawning process, so the child&#8217;s PID is reported here as
1762a hint for post-processing. (But it is only a hint because the child
1763proces may be a shell script which doesn&#8217;t have a session-id.)</p></div>
1764<div class="paragraph"><p>Note that the <code>t_rel</code> field contains the observed run time in seconds
1765for the child process (starting before the fork/exec/spawn and
1766stopping after the waitpid() and includes OS process creation overhead).
1767So this time will be slightly larger than the atexit time reported by
1768the child process itself.</p></div>
1769</dd>
1770<dt class="hdlist1">
1771<code>"exec"</code>
1772</dt>
1773<dd>
1774<p>
1775 This event is generated before git attempts to <code>exec()</code>
1776 another command rather than starting a child process.
1777</p>
1778<div class="listingblock">
1779<div class="content">
1780<pre><code>{
1781 "event":"exec",
1782 ...
1783 "exec_id":0,
1784 "exe":"git",
1785 "argv":["foo", "bar"]
1786}</code></pre>
1787</div></div>
1788<div class="paragraph"><p>The "exec_id" field is a command-unique id and is only useful if the
1789<code>exec()</code> fails and a corresponding exec_result event is generated.</p></div>
1790</dd>
1791<dt class="hdlist1">
1792<code>"exec_result"</code>
1793</dt>
1794<dd>
1795<p>
1796 This event is generated if the <code>exec()</code> fails and control
1797 returns to the current git command.
1798</p>
1799<div class="listingblock">
1800<div class="content">
1801<pre><code>{
1802 "event":"exec_result",
1803 ...
1804 "exec_id":0,
1805 "code":1 # error code (errno) from exec()
1806}</code></pre>
1807</div></div>
1808</dd>
1809<dt class="hdlist1">
1810<code>"thread_start"</code>
1811</dt>
1812<dd>
1813<p>
1814 This event is generated when a thread is started. It is
1815 generated from <strong>within</strong> the new thread&#8217;s thread-proc (for TLS
1816 reasons).
1817</p>
1818<div class="listingblock">
1819<div class="content">
1820<pre><code>{
1821 "event":"thread_start",
1822 ...
1823 "thread":"th02:preload_thread" # thread name
1824}</code></pre>
1825</div></div>
1826</dd>
1827<dt class="hdlist1">
1828<code>"thread_exit"</code>
1829</dt>
1830<dd>
1831<p>
1832 This event is generated when a thread exits. It is generated
1833 from <strong>within</strong> the thread&#8217;s thread-proc (for TLS reasons).
1834</p>
1835<div class="listingblock">
1836<div class="content">
1837<pre><code>{
1838 "event":"thread_exit",
1839 ...
1840 "thread":"th02:preload_thread", # thread name
1841 "t_rel":0.007328 # thread elapsed time
1842}</code></pre>
1843</div></div>
1844</dd>
1845<dt class="hdlist1">
1846<code>"def_param"</code>
1847</dt>
1848<dd>
1849<p>
1850 This event is generated to log a global parameter.
1851</p>
1852<div class="listingblock">
1853<div class="content">
1854<pre><code>{
1855 "event":"def_param",
1856 ...
1857 "param":"core.abbrev",
1858 "value":"7"
1859}</code></pre>
1860</div></div>
1861</dd>
1862<dt class="hdlist1">
1863<code>"def_repo"</code>
1864</dt>
1865<dd>
1866<p>
1867 This event defines a repo-id and associates it with the root
1868 of the worktree.
1869</p>
1870<div class="listingblock">
1871<div class="content">
1872<pre><code>{
1873 "event":"def_repo",
1874 ...
1875 "repo":1,
1876 "worktree":"/Users/jeffhost/work/gfw"
1877}</code></pre>
1878</div></div>
1879<div class="paragraph"><p>As stated earlier, the repo-id is currently always 1, so there will
1880only be one def_repo event. Later, if in-proc submodules are
1881supported, a def_repo event should be emitted for each submodule
1882visited.</p></div>
1883</dd>
1884<dt class="hdlist1">
1885<code>"region_enter"</code>
1886</dt>
1887<dd>
1888<p>
1889 This event is generated when entering a region.
1890</p>
1891<div class="listingblock">
1892<div class="content">
1893<pre><code>{
1894 "event":"region_enter",
1895 ...
1896 "repo":1, # optional
1897 "nesting":1, # current region stack depth
1898 "category":"index", # optional
1899 "label":"do_read_index", # optional
1900 "msg":".git/index" # optional
1901}</code></pre>
1902</div></div>
1903<div class="paragraph"><p>The <code>category</code> field may be used in a future enhancement to
1904do category-based filtering.</p></div>
1905<div class="paragraph"><p>The <code>GIT_TR2_EVENT_NESTING</code> environment variable can be used to
1906filter deeply nested regions and data events. It defaults to "2".</p></div>
1907</dd>
1908<dt class="hdlist1">
1909<code>"region_leave"</code>
1910</dt>
1911<dd>
1912<p>
1913 This event is generated when leaving a region.
1914</p>
1915<div class="listingblock">
1916<div class="content">
1917<pre><code>{
1918 "event":"region_leave",
1919 ...
1920 "repo":1, # optional
1921 "t_rel":0.002876, # time spent in region in seconds
1922 "nesting":1, # region stack depth
1923 "category":"index", # optional
1924 "label":"do_read_index", # optional
1925 "msg":".git/index" # optional
1926}</code></pre>
1927</div></div>
1928</dd>
1929<dt class="hdlist1">
1930<code>"data"</code>
1931</dt>
1932<dd>
1933<p>
1934 This event is generated to log a thread- and region-local
1935 key/value pair.
1936</p>
1937<div class="listingblock">
1938<div class="content">
1939<pre><code>{
1940 "event":"data",
1941 ...
1942 "repo":1, # optional
1943 "t_abs":0.024107, # absolute elapsed time
1944 "t_rel":0.001031, # elapsed time in region/thread
1945 "nesting":2, # region stack depth
1946 "category":"index",
1947 "key":"read/cache_nr",
1948 "value":"3552"
1949}</code></pre>
1950</div></div>
1951<div class="paragraph"><p>The "value" field may be an integer or a string.</p></div>
1952</dd>
1953<dt class="hdlist1">
1954<code>"data-json"</code>
1955</dt>
1956<dd>
1957<p>
1958 This event is generated to log a pre-formatted JSON string
1959 containing structured data.
1960</p>
1961<div class="listingblock">
1962<div class="content">
1963<pre><code>{
1964 "event":"data_json",
1965 ...
1966 "repo":1, # optional
1967 "t_abs":0.015905,
1968 "t_rel":0.015905,
1969 "nesting":1,
1970 "category":"process",
1971 "key":"windows/ancestry",
1972 "value":["bash.exe","bash.exe"]
1973}</code></pre>
1974</div></div>
1975</dd>
1976</dl></div>
1977</div>
1978</div>
1979</div>
1980</div>
1981<div class="sect1">
1982<h2 id="_example_trace2_api_usage">Example Trace2 API Usage</h2>
1983<div class="sectionbody">
1984<div class="paragraph"><p>Here is a hypothetical usage of the Trace2 API showing the intended
1985usage (without worrying about the actual Git details).</p></div>
1986<div class="dlist"><dl>
1987<dt class="hdlist1">
1988Initialization
1989</dt>
1990<dd>
1991<p>
1992 Initialization happens in <code>main()</code>. Behind the scenes, an
1993 <code>atexit</code> and <code>signal</code> handler are registered.
1994</p>
1995<div class="listingblock">
1996<div class="content">
1997<pre><code>int main(int argc, const char **argv)
1998{
1999 int exit_code;
2000
2001 trace2_initialize();
2002 trace2_cmd_start(argv);
2003
2004 exit_code = cmd_main(argc, argv);
2005
2006 trace2_cmd_exit(exit_code);
2007
2008 return exit_code;
2009}</code></pre>
2010</div></div>
2011</dd>
2012<dt class="hdlist1">
2013Command Details
2014</dt>
2015<dd>
2016<p>
2017 After the basics are established, additional command
2018 information can be sent to Trace2 as it is discovered.
2019</p>
2020<div class="listingblock">
2021<div class="content">
2022<pre><code>int cmd_checkout(int argc, const char **argv)
2023{
2024 trace2_cmd_name("checkout");
2025 trace2_cmd_mode("branch");
2026 trace2_def_repo(the_repository);
2027
2028 // emit "def_param" messages for "interesting" config settings.
2029 trace2_cmd_list_config();
2030
2031 if (do_something())
2032 trace2_cmd_error("Path '%s': cannot do something", path);
2033
2034 return 0;
2035}</code></pre>
2036</div></div>
2037</dd>
2038<dt class="hdlist1">
2039Child Processes
2040</dt>
2041<dd>
2042<p>
2043 Wrap code spawning child processes.
2044</p>
2045<div class="listingblock">
2046<div class="content">
2047<pre><code>void run_child(...)
2048{
2049 int child_exit_code;
2050 struct child_process cmd = CHILD_PROCESS_INIT;
2051 ...
2052 cmd.trace2_child_class = "editor";
2053
2054 trace2_child_start(&amp;cmd);
2055 child_exit_code = spawn_child_and_wait_for_it();
2056 trace2_child_exit(&amp;cmd, child_exit_code);
2057}</code></pre>
2058</div></div>
2059<div class="paragraph"><p>For example, the following fetch command spawned ssh, index-pack,
2060rev-list, and gc. This example also shows that fetch took
20615.199 seconds and of that 4.932 was in ssh.</p></div>
2062<div class="listingblock">
2063<div class="content">
2064<pre><code>$ export GIT_TR2_BRIEF=1
2065$ export GIT_TR2=~/log.normal
2066$ git fetch origin
2067...</code></pre>
2068</div></div>
2069<div class="listingblock">
2070<div class="content">
2071<pre><code>$ cat ~/log.normal
2072version 2.20.1.vfs.1.1.47.g534dbe1ad1
2073start git fetch origin
2074worktree /Users/jeffhost/work/gfw
2075cmd_name fetch (fetch)
2076child_start[0] ssh git@github.com ...
2077child_start[1] git index-pack ...
2078... (Trace2 events from child processes omitted)
2079child_exit[1] pid:14707 code:0 elapsed:0.076353
2080child_exit[0] pid:14706 code:0 elapsed:4.931869
2081child_start[2] git rev-list ...
2082... (Trace2 events from child process omitted)
2083child_exit[2] pid:14708 code:0 elapsed:0.110605
2084child_start[3] git gc --auto
2085... (Trace2 events from child process omitted)
2086child_exit[3] pid:14709 code:0 elapsed:0.006240
2087exit elapsed:5.198503 code:0
2088atexit elapsed:5.198541 code:0</code></pre>
2089</div></div>
2090<div class="paragraph"><p>When a git process is a (direct or indirect) child of another
2091git process, it inherits Trace2 context information. This
2092allows the child to print the command hierarchy. This example
2093shows gc as child[3] of fetch. When the gc process reports
2094its name as "gc", it also reports the hierarchy as "fetch/gc".
2095(In this example, trace2 messages from the child process is
2096indented for clarity.)</p></div>
2097<div class="listingblock">
2098<div class="content">
2099<pre><code>$ export GIT_TR2_BRIEF=1
2100$ export GIT_TR2=~/log.normal
2101$ git fetch origin
2102...</code></pre>
2103</div></div>
2104<div class="listingblock">
2105<div class="content">
2106<pre><code>$ cat ~/log.normal
2107version 2.20.1.160.g5676107ecd.dirty
2108start git fetch official
2109worktree /Users/jeffhost/work/gfw
2110cmd_name fetch (fetch)
2111...
2112child_start[3] git gc --auto
2113 version 2.20.1.160.g5676107ecd.dirty
2114 start /Users/jeffhost/work/gfw/git gc --auto
2115 worktree /Users/jeffhost/work/gfw
2116 cmd_name gc (fetch/gc)
2117 exit elapsed:0.001959 code:0
2118 atexit elapsed:0.001997 code:0
2119child_exit[3] pid:20303 code:0 elapsed:0.007564
2120exit elapsed:3.868938 code:0
2121atexit elapsed:3.868970 code:0</code></pre>
2122</div></div>
2123</dd>
2124<dt class="hdlist1">
2125Regions
2126</dt>
2127<dd>
2128<p>
2129 Regions can be use to time an interesting section of code.
2130</p>
2131<div class="listingblock">
2132<div class="content">
2133<pre><code>void wt_status_collect(struct wt_status *s)
2134{
2135 trace2_region_enter("status", "worktrees", s-&gt;repo);
2136 wt_status_collect_changes_worktree(s);
2137 trace2_region_leave("status", "worktrees", s-&gt;repo);
2138
2139 trace2_region_enter("status", "index", s-&gt;repo);
2140 wt_status_collect_changes_index(s);
2141 trace2_region_leave("status", "index", s-&gt;repo);
2142
2143 trace2_region_enter("status", "untracked", s-&gt;repo);
2144 wt_status_collect_untracked(s);
2145 trace2_region_leave("status", "untracked", s-&gt;repo);
2146}
2147
2148void wt_status_print(struct wt_status *s)
2149{
2150 trace2_region_enter("status", "print", s-&gt;repo);
2151 switch (s-&gt;status_format) {
2152 ...
2153 }
2154 trace2_region_leave("status", "print", s-&gt;repo);
2155}</code></pre>
2156</div></div>
2157<div class="paragraph"><p>In this example, scanning for untracked files ran from +0.012568 to
2158+0.027149 (since the process started) and took 0.014581 seconds.</p></div>
2159<div class="listingblock">
2160<div class="content">
2161<pre><code>$ export GIT_TR2_PERF_BRIEF=1
2162$ export GIT_TR2_PERF=~/log.perf
2163$ git status
2164...
2165
2166$ cat ~/log.perf
2167d0 | main | version | | | | | 2.20.1.160.g5676107ecd.dirty
2168d0 | main | start | | | | | git status
2169d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
2170d0 | main | cmd_name | | | | | status (status)
2171...
2172d0 | main | region_enter | r1 | 0.010988 | | status | label:worktrees
2173d0 | main | region_leave | r1 | 0.011236 | 0.000248 | status | label:worktrees
2174d0 | main | region_enter | r1 | 0.011260 | | status | label:index
2175d0 | main | region_leave | r1 | 0.012542 | 0.001282 | status | label:index
2176d0 | main | region_enter | r1 | 0.012568 | | status | label:untracked
2177d0 | main | region_leave | r1 | 0.027149 | 0.014581 | status | label:untracked
2178d0 | main | region_enter | r1 | 0.027411 | | status | label:print
2179d0 | main | region_leave | r1 | 0.028741 | 0.001330 | status | label:print
2180d0 | main | exit | | 0.028778 | | | code:0
2181d0 | main | atexit | | 0.028809 | | | code:0</code></pre>
2182</div></div>
2183<div class="paragraph"><p>Regions may be nested. This causes messages to be indented in the
2184PERF target, for example.
2185Elapsed times are relative to the start of the correpsonding nesting
2186level as expected. For example, if we add region message to:</p></div>
2187<div class="listingblock">
2188<div class="content">
2189<pre><code>static enum path_treatment read_directory_recursive(struct dir_struct *dir,
2190 struct index_state *istate, const char *base, int baselen,
2191 struct untracked_cache_dir *untracked, int check_only,
2192 int stop_at_first_file, const struct pathspec *pathspec)
2193{
2194 enum path_treatment state, subdir_state, dir_state = path_none;
2195
2196 trace2_region_enter_printf("dir", "read_recursive", NULL, "%.*s", baselen, base);
2197 ...
2198 trace2_region_leave_printf("dir", "read_recursive", NULL, "%.*s", baselen, base);
2199 return dir_state;
2200}</code></pre>
2201</div></div>
2202<div class="paragraph"><p>We can further investigate the time spent scanning for untracked files.</p></div>
2203<div class="listingblock">
2204<div class="content">
2205<pre><code>$ export GIT_TR2_PERF_BRIEF=1
2206$ export GIT_TR2_PERF=~/log.perf
2207$ git status
2208...
2209$ cat ~/log.perf
2210d0 | main | version | | | | | 2.20.1.162.gb4ccea44db.dirty
2211d0 | main | start | | | | | git status
2212d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
2213d0 | main | cmd_name | | | | | status (status)
2214...
2215d0 | main | region_enter | r1 | 0.015047 | | status | label:untracked
2216d0 | main | region_enter | | 0.015132 | | dir | ..label:read_recursive
2217d0 | main | region_enter | | 0.016341 | | dir | ....label:read_recursive vcs-svn/
2218d0 | main | region_leave | | 0.016422 | 0.000081 | dir | ....label:read_recursive vcs-svn/
2219d0 | main | region_enter | | 0.016446 | | dir | ....label:read_recursive xdiff/
2220d0 | main | region_leave | | 0.016522 | 0.000076 | dir | ....label:read_recursive xdiff/
2221d0 | main | region_enter | | 0.016612 | | dir | ....label:read_recursive git-gui/
2222d0 | main | region_enter | | 0.016698 | | dir | ......label:read_recursive git-gui/po/
2223d0 | main | region_enter | | 0.016810 | | dir | ........label:read_recursive git-gui/po/glossary/
2224d0 | main | region_leave | | 0.016863 | 0.000053 | dir | ........label:read_recursive git-gui/po/glossary/
2225...
2226d0 | main | region_enter | | 0.031876 | | dir | ....label:read_recursive builtin/
2227d0 | main | region_leave | | 0.032270 | 0.000394 | dir | ....label:read_recursive builtin/
2228d0 | main | region_leave | | 0.032414 | 0.017282 | dir | ..label:read_recursive
2229d0 | main | region_leave | r1 | 0.032454 | 0.017407 | status | label:untracked
2230...
2231d0 | main | exit | | 0.034279 | | | code:0
2232d0 | main | atexit | | 0.034322 | | | code:0</code></pre>
2233</div></div>
2234<div class="paragraph"><p>Trace2 regions are similar to the existing trace_performance_enter()
2235and trace_performance_leave() routines, but are thread safe and
2236maintain per-thread stacks of timers.</p></div>
2237</dd>
2238<dt class="hdlist1">
2239Data Messages
2240</dt>
2241<dd>
2242<p>
2243 Data messages added to a region.
2244</p>
2245<div class="listingblock">
2246<div class="content">
2247<pre><code>int read_index_from(struct index_state *istate, const char *path,
2248 const char *gitdir)
2249{
2250 trace2_region_enter_printf("index", "do_read_index", the_repository, "%s", path);
2251
2252 ...
2253
2254 trace2_data_intmax("index", the_repository, "read/version", istate-&gt;version);
2255 trace2_data_intmax("index", the_repository, "read/cache_nr", istate-&gt;cache_nr);
2256
2257 trace2_region_leave_printf("index", "do_read_index", the_repository, "%s", path);
2258}</code></pre>
2259</div></div>
2260<div class="paragraph"><p>This example shows that the index contained 3552 entries.</p></div>
2261<div class="listingblock">
2262<div class="content">
2263<pre><code>$ export GIT_TR2_PERF_BRIEF=1
2264$ export GIT_TR2_PERF=~/log.perf
2265$ git status
2266...
2267$ cat ~/log.perf
2268d0 | main | version | | | | | 2.20.1.156.gf9916ae094.dirty
2269d0 | main | start | | | | | git status
2270d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
2271d0 | main | cmd_name | | | | | status (status)
2272d0 | main | region_enter | r1 | 0.001791 | | index | label:do_read_index .git/index
2273d0 | main | data | r1 | 0.002494 | 0.000703 | index | ..read/version:2
2274d0 | main | data | r1 | 0.002520 | 0.000729 | index | ..read/cache_nr:3552
2275d0 | main | region_leave | r1 | 0.002539 | 0.000748 | index | label:do_read_index .git/index
2276...</code></pre>
2277</div></div>
2278</dd>
2279<dt class="hdlist1">
2280Thread Events
2281</dt>
2282<dd>
2283<p>
2284 Thread messages added to a thread-proc.
2285</p>
2286<div class="paragraph"><p>For example, the multithreaded preload-index code can be
2287instrumented with a region around the thread pool and then
2288per-thread start and exit events within the threadproc.</p></div>
2289<div class="listingblock">
2290<div class="content">
2291<pre><code>static void *preload_thread(void *_data)
2292{
2293 // start the per-thread clock and emit a message.
2294 trace2_thread_start("preload_thread");
2295
2296 // report which chunk of the array this thread was assigned.
2297 trace2_data_intmax("index", the_repository, "offset", p-&gt;offset);
2298 trace2_data_intmax("index", the_repository, "count", nr);
2299
2300 do {
2301 ...
2302 } while (--nr &gt; 0);
2303 ...
2304
2305 // report elapsed time taken by this thread.
2306 trace2_thread_exit();
2307 return NULL;
2308}
2309
2310void preload_index(struct index_state *index,
2311 const struct pathspec *pathspec,
2312 unsigned int refresh_flags)
2313{
2314 trace2_region_enter("index", "preload", the_repository);
2315
2316 for (i = 0; i &lt; threads; i++) {
2317 ... /* create thread */
2318 }
2319
2320 for (i = 0; i &lt; threads; i++) {
2321 ... /* join thread */
2322 }
2323
2324 trace2_region_leave("index", "preload", the_repository);
2325}</code></pre>
2326</div></div>
2327<div class="paragraph"><p>In this example preload_index() was executed by the <code>main</code> thread
2328and started the <code>preload</code> region. Seven threads, named
2329<code>th01:preload_thread</code> through <code>th07:preload_thread</code>, were started.
2330Events from each thread are atomically appended to the shared target
2331stream as they occur so they may appear in random order with respect
2332other threads. Finally, the main thread waits for the threads to
2333finish and leaves the region.</p></div>
2334<div class="paragraph"><p>Data events are tagged with the active thread name. They are used
2335to report the per-thread parameters.</p></div>
2336<div class="listingblock">
2337<div class="content">
2338<pre><code>$ export GIT_TR2_PERF_BRIEF=1
2339$ export GIT_TR2_PERF=~/log.perf
2340$ git status
2341...
2342$ cat ~/log.perf
2343...
2344d0 | main | region_enter | r1 | 0.002595 | | index | label:preload
2345d0 | th01:preload_thread | thread_start | | 0.002699 | | |
2346d0 | th02:preload_thread | thread_start | | 0.002721 | | |
2347d0 | th01:preload_thread | data | r1 | 0.002736 | 0.000037 | index | offset:0
2348d0 | th02:preload_thread | data | r1 | 0.002751 | 0.000030 | index | offset:2032
2349d0 | th03:preload_thread | thread_start | | 0.002711 | | |
2350d0 | th06:preload_thread | thread_start | | 0.002739 | | |
2351d0 | th01:preload_thread | data | r1 | 0.002766 | 0.000067 | index | count:508
2352d0 | th06:preload_thread | data | r1 | 0.002856 | 0.000117 | index | offset:2540
2353d0 | th03:preload_thread | data | r1 | 0.002824 | 0.000113 | index | offset:1016
2354d0 | th04:preload_thread | thread_start | | 0.002710 | | |
2355d0 | th02:preload_thread | data | r1 | 0.002779 | 0.000058 | index | count:508
2356d0 | th06:preload_thread | data | r1 | 0.002966 | 0.000227 | index | count:508
2357d0 | th07:preload_thread | thread_start | | 0.002741 | | |
2358d0 | th07:preload_thread | data | r1 | 0.003017 | 0.000276 | index | offset:3048
2359d0 | th05:preload_thread | thread_start | | 0.002712 | | |
2360d0 | th05:preload_thread | data | r1 | 0.003067 | 0.000355 | index | offset:1524
2361d0 | th05:preload_thread | data | r1 | 0.003090 | 0.000378 | index | count:508
2362d0 | th07:preload_thread | data | r1 | 0.003037 | 0.000296 | index | count:504
2363d0 | th03:preload_thread | data | r1 | 0.002971 | 0.000260 | index | count:508
2364d0 | th04:preload_thread | data | r1 | 0.002983 | 0.000273 | index | offset:508
2365d0 | th04:preload_thread | data | r1 | 0.007311 | 0.004601 | index | count:508
2366d0 | th05:preload_thread | thread_exit | | 0.008781 | 0.006069 | |
2367d0 | th01:preload_thread | thread_exit | | 0.009561 | 0.006862 | |
2368d0 | th03:preload_thread | thread_exit | | 0.009742 | 0.007031 | |
2369d0 | th06:preload_thread | thread_exit | | 0.009820 | 0.007081 | |
2370d0 | th02:preload_thread | thread_exit | | 0.010274 | 0.007553 | |
2371d0 | th07:preload_thread | thread_exit | | 0.010477 | 0.007736 | |
2372d0 | th04:preload_thread | thread_exit | | 0.011657 | 0.008947 | |
2373d0 | main | region_leave | r1 | 0.011717 | 0.009122 | index | label:preload
2374...
2375d0 | main | exit | | 0.029996 | | | code:0
2376d0 | main | atexit | | 0.030027 | | | code:0</code></pre>
2377</div></div>
2378<div class="paragraph"><p>In this example, the preload region took 0.009122 seconds. The 7 threads
2379took between 0.006069 and 0.008947 seconds to work on their portion of
2380the index. Thread "th01" worked on 508 items at offset 0. Thread "th02"
2381worked on 508 items at offset 2032. Thread "th04" worked on 508 itemts
2382at offset 508.</p></div>
2383<div class="paragraph"><p>This example also shows that thread names are assigned in a racy manner
2384as each thread starts and allocates TLS storage.</p></div>
2385</dd>
2386</dl></div>
2387</div>
2388</div>
2389<div class="sect1">
2390<h2 id="_future_work">Future Work</h2>
2391<div class="sectionbody">
2392<div class="sect2">
2393<h3 id="_relationship_to_the_existing_trace_api_api_trace_txt">Relationship to the Existing Trace Api (api-trace.txt)</h3>
2394<div class="paragraph"><p>There are a few issues to resolve before we can completely
2395switch to Trace2.</p></div>
2396<div class="ulist"><ul>
2397<li>
2398<p>
2399Updating existing tests that assume GIT_TRACE format messages.
2400</p>
2401</li>
2402<li>
2403<p>
2404How to best handle custom GIT_TRACE_&lt;key&gt; messages?
2405</p>
2406<div class="ulist"><ul>
2407<li>
2408<p>
2409The GIT_TRACE_&lt;key&gt; mechanism allows each &lt;key&gt; to write to a
2410different file (in addition to just stderr).
2411</p>
2412</li>
2413<li>
2414<p>
2415Do we want to maintain that ability or simply write to the existing
2416Trace2 targets (and convert &lt;key&gt; to a "category").
2417</p>
2418</li>
2419</ul></div>
2420</li>
2421</ul></div>
2422</div>
2423</div>
2424</div>
2425</div>
2426<div id="footnotes"><hr /></div>
2427<div id="footer">
2428<div id="footer-text">
2429Last updated
2430 2019-03-07 12:16:20 JST
2431</div>
2432</div>
2433</body>
2434</html>