Google Git
Sign in
chromium / external / gitster / git-htmldocs / d1063b1b2e658ecbb78ae560ecb80d543e8c78c5 / . / technical / api-trace2.html
blob: dbfe5517c714ac1dc7ded57e03db3af32a146104 [file] [log] [blame]
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1<?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>
Junio C Hamanod1063b12019-05-08 17:18:07[diff] [blame^]884<div class="literalblock">
885<div class="content">
886<pre><code>If the target already exists and is a directory, the traces will be
887written to files (one per process) underneath the given directory. They
888will be named according to the last component of the SID (optionally
889followed by a counter to avoid filename collisions).</code></pre>
890</div></div>
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]891</dd>
892<dt class="hdlist1">
893<code>af_unix:[&lt;socket_type&gt;:]&lt;absolute-pathname&gt;</code>
894</dt>
895<dd>
896<p>
897 Enables the target, opens and writes to a Unix Domain Socket
898 (on platforms that support them).
899</p>
900<div class="paragraph"><p>Socket type can be either <code>stream</code> or <code>dgram</code>. If the socket type is
901omitted, Git will try both.</p></div>
902</dd>
903</dl></div>
904</div>
905</div>
906<div class="sect1">
907<h2 id="_trace2_api">Trace2 API</h2>
908<div class="sectionbody">
909<div class="paragraph"><p>All public Trace2 functions and macros are defined in <code>trace2.h</code> and
910<code>trace2.c</code>. All public symbols are prefixed with <code>trace2_</code>.</p></div>
911<div class="paragraph"><p>There are no public Trace2 data structures.</p></div>
912<div class="paragraph"><p>The Trace2 code also defines a set of private functions and data types
913in the <code>trace2/</code> directory. These symbols are prefixed with <code>tr2_</code>
914and should only be used by functions in <code>trace2.c</code>.</p></div>
915</div>
916</div>
917<div class="sect1">
918<h2 id="_conventions_for_public_functions_and_macros">Conventions for Public Functions and Macros</h2>
919<div class="sectionbody">
920<div class="paragraph"><p>The functions defined by the Trace2 API are declared and documented
921in <code>trace2.h</code>. It defines the API functions and wrapper macros for
922Trace2.</p></div>
923<div class="paragraph"><p>Some functions have a <code>_fl()</code> suffix to indicate that they take <code>file</code>
924and <code>line-number</code> arguments.</p></div>
925<div class="paragraph"><p>Some functions have a <code>_va_fl()</code> suffix to indicate that they also
926take a <code>va_list</code> argument.</p></div>
927<div class="paragraph"><p>Some functions have a <code>_printf_fl()</code> suffix to indicate that they also
928take a varargs argument.</p></div>
929<div class="paragraph"><p>There are CPP wrapper macros and ifdefs to hide most of these details.
930See <code>trace2.h</code> for more details. The following discussion will only
931describe the simplified forms.</p></div>
932</div>
933</div>
934<div class="sect1">
935<h2 id="_public_api">Public API</h2>
936<div class="sectionbody">
937<div class="paragraph"><p>All Trace2 API functions send a messsage to all of the active
938Trace2 Targets. This section describes the set of available
939messages.</p></div>
940<div class="paragraph"><p>It helps to divide these functions into groups for discussion
941purposes.</p></div>
942<div class="sect2">
943<h3 id="_basic_command_messages">Basic Command Messages</h3>
944<div class="paragraph"><p>These are concerned with the lifetime of the overall git process.</p></div>
945<div class="dlist"><dl>
946<dt class="hdlist1">
947<code>void trace2_initialize()</code>
948</dt>
949<dd>
950<p>
951 Determines if any Trace2 Targets should be enabled and
952 initializes the Trace2 facility. This includes starting the
953 elapsed time clocks and thread local storage (TLS).
954</p>
955<div class="paragraph"><p>This function emits a "version" message containing the version of git
956and the Trace2 protocol.</p></div>
957<div class="paragraph"><p>This function should be called from <code>main()</code> as early as possible in
958the life of the process.</p></div>
959</dd>
960<dt class="hdlist1">
961<code>int trace2_is_enabled()</code>
962</dt>
963<dd>
964<p>
965 Returns 1 if Trace2 is enabled (at least one target is
966 active).
967</p>
968</dd>
969<dt class="hdlist1">
970<code>void trace2_cmd_start(int argc, const char **argv)</code>
971</dt>
972<dd>
973<p>
974 Emits a "start" message containing the process command line
975 arguments.
976</p>
977</dd>
978<dt class="hdlist1">
979<code>int trace2_cmd_exit(int exit_code)</code>
980</dt>
981<dd>
982<p>
983 Emits an "exit" message containing the process exit-code and
984 elapsed time.
985</p>
986<div class="paragraph"><p>Returns the exit-code.</p></div>
987</dd>
988<dt class="hdlist1">
989<code>void trace2_cmd_error(const char *fmt, va_list ap)</code>
990</dt>
991<dd>
992<p>
993 Emits an "error" message containing a formatted error message.
994</p>
995</dd>
996<dt class="hdlist1">
997<code>void trace2_cmd_path(const char *pathname)</code>
998</dt>
999<dd>
1000<p>
1001 Emits a "cmd_path" message with the full pathname of the
1002 current process.
1003</p>
1004</dd>
1005</dl></div>
1006</div>
1007<div class="sect2">
1008<h3 id="_command_detail_messages">Command Detail Messages</h3>
1009<div class="paragraph"><p>These are concerned with describing the specific Git command
1010after the command line, config, and environment are inspected.</p></div>
1011<div class="dlist"><dl>
1012<dt class="hdlist1">
1013<code>void trace2_cmd_name(const char *name)</code>
1014</dt>
1015<dd>
1016<p>
1017 Emits a "cmd_name" message with the canonical name of the
1018 command, for example "status" or "checkout".
1019</p>
1020</dd>
1021<dt class="hdlist1">
1022<code>void trace2_cmd_mode(const char *mode)</code>
1023</dt>
1024<dd>
1025<p>
1026 Emits a "cmd_mode" message with a qualifier name to further
1027 describe the current git command.
1028</p>
1029<div class="paragraph"><p>This message is intended to be used with git commands having multiple
1030major modes. For example, a "checkout" command can checkout a new
1031branch or it can checkout a single file, so the checkout code could
1032emit a cmd_mode message of "branch" or "file".</p></div>
1033</dd>
1034<dt class="hdlist1">
1035<code>void trace2_cmd_alias(const char *alias, const char **argv_expansion)</code>
1036</dt>
1037<dd>
1038<p>
1039 Emits an "alias" message containing the alias used and the
1040 argument expansion.
1041</p>
1042</dd>
1043<dt class="hdlist1">
1044<code>void trace2_def_param(const char *parameter, const char *value)</code>
1045</dt>
1046<dd>
1047<p>
1048 Emits a "def_param" message containing a key/value pair.
1049</p>
1050<div class="paragraph"><p>This message is intended to report some global aspect of the current
1051command, such as a configuration setting or command line switch that
1052significantly affects program performance or behavior, such as
1053<code>core.abbrev</code>, <code>status.showUntrackedFiles</code>, or <code>--no-ahead-behind</code>.</p></div>
1054</dd>
1055<dt class="hdlist1">
1056<code>void trace2_cmd_list_config()</code>
1057</dt>
1058<dd>
1059<p>
1060 Emits a "def_param" messages for "important" configuration
1061 settings.
1062</p>
1063<div class="paragraph"><p>The environment variable <code>GIT_TR2_CONFIG_PARAMS</code> can be set to a
1064list of patterns of important configuration settings, for example:
1065<code>core.*,remote.*.url</code>. This function will iterate over all config
1066settings and emit a "def_param" message for each match.</p></div>
1067</dd>
1068<dt class="hdlist1">
1069<code>void trace2_cmd_set_config(const char *key, const char *value)</code>
1070</dt>
1071<dd>
1072<p>
1073 Emits a "def_param" message for a specific configuration
1074 setting IFF it matches the <code>GIT_TR2_CONFIG_PARAMS</code> pattern.
1075</p>
1076<div class="paragraph"><p>This is used to hook into <code>git_config_set()</code> and catch any
1077configuration changes and update a value previously reported by
1078<code>trace2_cmd_list_config()</code>.</p></div>
1079</dd>
1080<dt class="hdlist1">
1081<code>void trace2_def_repo(struct repository *repo)</code>
1082</dt>
1083<dd>
1084<p>
1085 Registers a repository with the Trace2 layer. Assigns a
1086 unique "repo-id" to <code>repo-&gt;trace2_repo_id</code>.
1087</p>
1088<div class="paragraph"><p>Emits a "worktree" messages containing the repo-id and the worktree
1089pathname.</p></div>
1090<div class="paragraph"><p>Region and data messages (described later) may refer to this repo-id.</p></div>
1091<div class="paragraph"><p>The main/top-level repository will have repo-id value 1 (aka "r1").</p></div>
1092<div class="paragraph"><p>The repo-id field is in anticipation of future in-proc submodule
1093repositories.</p></div>
1094</dd>
1095</dl></div>
1096</div>
1097<div class="sect2">
1098<h3 id="_child_process_messages">Child Process Messages</h3>
1099<div class="paragraph"><p>These are concerned with the various spawned child processes,
1100including shell scripts, git commands, editors, pagers, and hooks.</p></div>
1101<div class="dlist"><dl>
1102<dt class="hdlist1">
1103<code>void trace2_child_start(struct child_process *cmd)</code>
1104</dt>
1105<dd>
1106<p>
1107 Emits a "child_start" message containing the "child-id",
1108 "child-argv", and "child-classification".
1109</p>
1110<div class="paragraph"><p>Before calling this, set <code>cmd-&gt;trace2_child_class</code> to a name
1111describing the type of child process, for example "editor".</p></div>
1112<div class="paragraph"><p>This function assigns a unique "child-id" to <code>cmd-&gt;trace2_child_id</code>.
1113This field is used later during the "child_exit" message to associate
1114it with the "child_start" message.</p></div>
1115<div class="paragraph"><p>This function should be called before spawning the child process.</p></div>
1116</dd>
1117<dt class="hdlist1">
1118<code>void trace2_child_exit(struct child_proess *cmd, int child_exit_code)</code>
1119</dt>
1120<dd>
1121<p>
1122 Emits a "child_exit" message containing the "child-id",
1123 the child&#8217;s elapsed time and exit-code.
1124</p>
1125<div class="paragraph"><p>The reported elapsed time includes the process creation overhead and
1126time spend waiting for it to exit, so it may be slightly longer than
1127the time reported by the child itself.</p></div>
1128<div class="paragraph"><p>This function should be called after reaping the child process.</p></div>
1129</dd>
1130<dt class="hdlist1">
1131<code>int trace2_exec(const char *exe, const char **argv)</code>
1132</dt>
1133<dd>
1134<p>
1135 Emits a "exec" message containing the "exec-id" and the
1136 argv of the new process.
1137</p>
1138<div class="paragraph"><p>This function should be called before calling one of the <code>exec()</code>
1139variants, such as <code>execvp()</code>.</p></div>
1140<div class="paragraph"><p>This function returns a unique "exec-id". This value is used later
1141if the exec() fails and a "exec-result" message is necessary.</p></div>
1142</dd>
1143<dt class="hdlist1">
1144<code>void trace2_exec_result(int exec_id, int error_code)</code>
1145</dt>
1146<dd>
1147<p>
1148 Emits a "exec_result" message containing the "exec-id"
1149 and the error code.
1150</p>
1151<div class="paragraph"><p>On Unix-based systems, <code>exec()</code> does not return if successful.
1152This message is used to indicate that the <code>exec()</code> failed and
1153that the current program is continuing.</p></div>
1154</dd>
1155</dl></div>
1156</div>
1157<div class="sect2">
1158<h3 id="_git_thread_messages">Git Thread Messages</h3>
1159<div class="paragraph"><p>These messages are concerned with Git thread usage.</p></div>
1160<div class="dlist"><dl>
1161<dt class="hdlist1">
1162<code>void trace2_thread_start(const char *thread_name)</code>
1163</dt>
1164<dd>
1165<p>
1166 Emits a "thread_start" message.
1167</p>
1168<div class="paragraph"><p>The <code>thread_name</code> field should be a descriptive name, such as the
1169unique name of the thread-proc. A unique "thread-id" will be added
1170to the name to uniquely identify thread instances.</p></div>
1171<div class="paragraph"><p>Region and data messages (described later) may refer to this thread
1172name.</p></div>
1173<div class="paragraph"><p>This function must be called by the thread-proc of the new thread
1174(so that TLS data is properly initialized) and not by the caller
1175of <code>pthread_create()</code>.</p></div>
1176</dd>
1177<dt class="hdlist1">
1178<code>void trace2_thread_exit()</code>
1179</dt>
1180<dd>
1181<p>
1182 Emits a "thread_exit" message containing the thread name
1183 and the thread elapsed time.
1184</p>
1185<div class="paragraph"><p>This function must be called by the thread-proc before it returns
1186(so that the coorect TLS data is used and cleaned up. It should
1187not be called by the caller of <code>pthread_join()</code>.</p></div>
1188</dd>
1189</dl></div>
1190</div>
1191<div class="sect2">
1192<h3 id="_region_and_data_messages">Region and Data Messages</h3>
1193<div class="paragraph"><p>These are concerned with recording performance data
1194over regions or spans of code.</p></div>
1195<div class="dlist"><dl>
1196<dt class="hdlist1">
1197<code>void trace2_region_enter(const char *category, const char *label, const struct repository *repo)</code>
1198</dt>
1199<dt class="hdlist1">
1200<code>void trace2_region_enter_printf(const char *category, const char *label, const struct repository *repo, const char *fmt, ...)</code>
1201</dt>
1202<dt class="hdlist1">
1203<code>void trace2_region_enter_printf_va(const char *category, const char *label, const struct repository *repo, const char *fmt, va_list ap)</code>
1204</dt>
1205<dd>
1206<p>
1207 Emits a thread-relative "region_enter" message with optional
1208 printf string.
1209</p>
1210<div class="paragraph"><p>This function pushes a new region nesting stack level on the current
1211thread and starts a clock for the new stack frame.</p></div>
1212<div class="paragraph"><p>The <code>category</code> field is an arbitrary category name used to classify
1213regions by feature area, such as "status" or "index". At this time
1214it is only just printed along with the rest of the message. It may
1215be used in the future to filter messages.</p></div>
1216<div class="paragraph"><p>The <code>label</code> field is an arbitrary label used to describe the activity
1217being started, such as "read_recursive" or "do_read_index".</p></div>
1218<div class="paragraph"><p>The <code>repo</code> field, if set, will be used to get the "repo-id", so that
1219recursive oerations can be attributed to the correct repository.</p></div>
1220</dd>
1221<dt class="hdlist1">
1222<code>void trace2_region_leave(const char *category, const char *label, const struct repository *repo)</code>
1223</dt>
1224<dt class="hdlist1">
1225<code>void trace2_region_leave_printf(const char *category, const char *label, const struct repository *repo, const char *fmt, ...)</code>
1226</dt>
1227<dt class="hdlist1">
1228<code>void trace2_region_leave_printf_va(const char *category, const char *label, const struct repository *repo, const char *fmt, va_list ap)</code>
1229</dt>
1230<dd>
1231<p>
1232 Emits a thread-relative "region_leave" message with optional
1233 printf string.
1234</p>
1235<div class="paragraph"><p>This function pops the region nesting stack on the current thread
1236and reports the elapsed time of the stack frame.</p></div>
1237<div class="paragraph"><p>The <code>category</code>, <code>label</code>, and <code>repo</code> fields are the same as above.
1238The <code>category</code> and <code>label</code> do not need to match the correpsonding
1239"region_enter" message, but it makes the data stream easier to
1240understand.</p></div>
1241</dd>
1242<dt class="hdlist1">
1243<code>void trace2_data_string(const char *category, const struct repository *repo, const char *key, const char * value)</code>
1244</dt>
1245<dt class="hdlist1">
1246<code>void trace2_data_intmax(const char *category, const struct repository *repo, const char *key, intmax value)</code>
1247</dt>
1248<dt class="hdlist1">
1249<code>void trace2_data_json(const char *category, const struct repository *repo, const char *key, const struct json_writer *jw)</code>
1250</dt>
1251<dd>
1252<p>
1253 Emits a region- and thread-relative "data" or "data_json" message.
1254</p>
1255<div class="paragraph"><p>This is a key/value pair message containing information about the
1256current thread, region stack, and repository. This could be used
1257to print the number of files in a directory during a multi-threaded
1258recursive tree walk.</p></div>
1259</dd>
1260<dt class="hdlist1">
1261<code>void trace2_printf(const char *fmt, ...)</code>
1262</dt>
1263<dt class="hdlist1">
1264<code>void trace2_printf_va(const char *fmt, va_list ap)</code>
1265</dt>
1266<dd>
1267<p>
1268 Emits a region- and thread-relative "printf" message.
1269</p>
1270</dd>
1271</dl></div>
1272</div>
1273</div>
1274</div>
1275<div class="sect1">
1276<h2 id="_trace2_target_formats">Trace2 Target Formats</h2>
1277<div class="sectionbody">
1278<div class="sect2">
1279<h3 id="_normal_format">NORMAL Format</h3>
1280<div class="paragraph"><p>NORMAL format is enabled when the <code>GIT_TR2</code> environment variable is
1281set.</p></div>
1282<div class="paragraph"><p>Events are written as lines of the form:</p></div>
1283<div class="listingblock">
1284<div class="content">
1285<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>
1286</div></div>
1287<div class="dlist"><dl>
1288<dt class="hdlist1">
1289<code>&lt;event-name&gt;</code>
1290</dt>
1291<dd>
1292<p>
1293 is the event name.
1294</p>
1295</dd>
1296<dt class="hdlist1">
1297<code>&lt;event-message&gt;</code>
1298</dt>
1299<dd>
1300<p>
1301 is a free-form printf message intended for human consumption.
1302</p>
1303<div class="paragraph"><p>Note that this may contain embedded LF or CRLF characters that are
1304not escaped, so the event may spill across multiple lines.</p></div>
1305</dd>
1306</dl></div>
1307<div class="paragraph"><p>If <code>GIT_TR2_BRIEF</code> is true, the <code>time</code>, <code>filename</code>, and <code>line</code> fields
1308are omitted.</p></div>
1309<div class="paragraph"><p>This target is intended to be more of a summary (like GIT_TRACE) and
1310less detailed than the other targets. It ignores thread, region, and
1311data messages, for example.</p></div>
1312</div>
1313<div class="sect2">
1314<h3 id="_perf_format">PERF Format</h3>
1315<div class="paragraph"><p>PERF format is enabled when the <code>GIT_TR2_PERF</code> environment variable
1316is set.</p></div>
1317<div class="paragraph"><p>Events are written as lines of the form:</p></div>
1318<div class="listingblock">
1319<div class="content">
1320<pre><code>[&lt;time&gt; SP &lt;filename&gt;:&lt;line&gt; SP+
1321 BAR SP] d&lt;depth&gt; SP
1322 BAR SP &lt;thread-name&gt; SP+
1323 BAR SP &lt;event-name&gt; SP+
1324 BAR SP [r&lt;repo-id&gt;] SP+
1325 BAR SP [&lt;t_abs&gt;] SP+
1326 BAR SP [&lt;t_rel&gt;] SP+
1327 BAR SP [&lt;category&gt;] SP+
1328 BAR SP DOTS* &lt;perf-event-message&gt;
1329 LF</code></pre>
1330</div></div>
1331<div class="dlist"><dl>
1332<dt class="hdlist1">
1333<code>&lt;depth&gt;</code>
1334</dt>
1335<dd>
1336<p>
1337 is the git process depth. This is the number of parent
1338 git processes. A top-level git command has depth value "d0".
1339 A child of it has depth value "d1". A second level child
1340 has depth value "d2" and so on.
1341</p>
1342</dd>
1343<dt class="hdlist1">
1344<code>&lt;thread-name&gt;</code>
1345</dt>
1346<dd>
1347<p>
1348 is a unique name for the thread. The primary thread
1349 is called "main". Other thread names are of the form "th%d:%s"
1350 and include a unique number and the name of the thread-proc.
1351</p>
1352</dd>
1353<dt class="hdlist1">
1354<code>&lt;event-name&gt;</code>
1355</dt>
1356<dd>
1357<p>
1358 is the event name.
1359</p>
1360</dd>
1361<dt class="hdlist1">
1362<code>&lt;repo-id&gt;</code>
1363</dt>
1364<dd>
1365<p>
1366 when present, is a number indicating the repository
1367 in use. A <code>def_repo</code> event is emitted when a repository is
1368 opened. This defines the repo-id and associated worktree.
1369 Subsequent repo-specific events will reference this repo-id.
1370</p>
1371<div class="paragraph"><p>Currently, this is always "r1" for the main repository.
1372This field is in anticipation of in-proc submodules in the future.</p></div>
1373</dd>
1374<dt class="hdlist1">
1375<code>&lt;t_abs&gt;</code>
1376</dt>
1377<dd>
1378<p>
1379 when present, is the absolute time in seconds since the
1380 program started.
1381</p>
1382</dd>
1383<dt class="hdlist1">
1384<code>&lt;t_rel&gt;</code>
1385</dt>
1386<dd>
1387<p>
1388 when present, is time in seconds relative to the start of
1389 the current region. For a thread-exit event, it is the elapsed
1390 time of the thread.
1391</p>
1392</dd>
1393<dt class="hdlist1">
1394<code>&lt;category&gt;</code>
1395</dt>
1396<dd>
1397<p>
1398 is present on region and data events and is used to
1399 indicate a broad category, such as "index" or "status".
1400</p>
1401</dd>
1402<dt class="hdlist1">
1403<code>&lt;perf-event-message&gt;</code>
1404</dt>
1405<dd>
1406<p>
1407 is a free-form printf message intended for human consumption.
1408</p>
1409</dd>
1410</dl></div>
1411<div class="listingblock">
1412<div class="content">
1413<pre><code>15:33:33.532712 wt-status.c:2310 | d0 | main | region_enter | r1 | 0.126064 | | status | label:print
141415:33:33.532712 wt-status.c:2331 | d0 | main | region_leave | r1 | 0.127568 | 0.001504 | status | label:print</code></pre>
1415</div></div>
1416<div class="paragraph"><p>If <code>GIT_TR2_PERF_BRIEF</code> is true, the <code>time</code>, <code>file</code>, and <code>line</code>
1417fields are omitted.</p></div>
1418<div class="listingblock">
1419<div class="content">
1420<pre><code>d0 | main | region_leave | r1 | 0.011717 | 0.009122 | index | label:preload</code></pre>
1421</div></div>
1422<div class="paragraph"><p>The PERF target is intended for interactive performance analysis
1423during development and is quite noisy.</p></div>
1424</div>
1425<div class="sect2">
1426<h3 id="_event_format">EVENT Format</h3>
1427<div class="paragraph"><p>EVENT format is enabled when the <code>GIT_TR2_EVENT</code> environment
1428variable is set.</p></div>
1429<div class="paragraph"><p>Each event is a JSON-object containing multiple key/value pairs
1430written as a single line and followed by a LF.</p></div>
1431<div class="listingblock">
1432<div class="content">
1433<pre><code>'{' &lt;key&gt; ':' &lt;value&gt; [',' &lt;key&gt; ':' &lt;value&gt;]* '}' LF</code></pre>
1434</div></div>
1435<div class="paragraph"><p>Some key/value pairs are common to all events and some are
1436event-specific.</p></div>
1437<div class="sect3">
1438<h4 id="_common_key_value_pairs">Common Key/Value Pairs</h4>
1439<div class="paragraph"><p>The following key/value pairs are common to all events:</p></div>
1440<div class="listingblock">
1441<div class="content">
1442<pre><code>{
1443 "event":"version",
1444 "sid":"1547659722619736-11614",
1445 "thread":"main",
1446 "time":"2019-01-16 17:28:42.620713",
1447 "file":"common-main.c",
1448 "line":38,
1449 ...
1450}</code></pre>
1451</div></div>
1452<div class="dlist"><dl>
1453<dt class="hdlist1">
1454<code>"event":&lt;event&gt;</code>
1455</dt>
1456<dd>
1457<p>
1458 is the event name.
1459</p>
1460</dd>
1461<dt class="hdlist1">
1462<code>"sid":&lt;sid&gt;</code>
1463</dt>
1464<dd>
1465<p>
1466 is the session-id. This is a unique string to identify the
1467 process instance to allow all events emitted by a process to
1468 be identified. A session-id is used instead of a PID because
1469 PIDs are recycled by the OS. For child git processes, the
1470 session-id is prepended with the session-id of the parent git
1471 process to allow parent-child relationships to be identified
1472 during post-processing.
1473</p>
1474</dd>
1475<dt class="hdlist1">
1476<code>"thread":&lt;thread&gt;</code>
1477</dt>
1478<dd>
1479<p>
1480 is the thread name.
1481</p>
1482</dd>
1483<dt class="hdlist1">
1484<code>"time":&lt;time&gt;</code>
1485</dt>
1486<dd>
1487<p>
1488 is the UTC time of the event.
1489</p>
1490</dd>
1491<dt class="hdlist1">
1492<code>"file":&lt;filename&gt;</code>
1493</dt>
1494<dd>
1495<p>
1496 is source file generating the event.
1497</p>
1498</dd>
1499<dt class="hdlist1">
1500<code>"line":&lt;line-number&gt;</code>
1501</dt>
1502<dd>
1503<p>
1504 is the integer source line number generating the event.
1505</p>
1506</dd>
1507<dt class="hdlist1">
1508<code>"repo":&lt;repo-id&gt;</code>
1509</dt>
1510<dd>
1511<p>
1512 when present, is the integer repo-id as described previously.
1513</p>
1514</dd>
1515</dl></div>
1516<div class="paragraph"><p>If <code>GIT_TR2_EVENT_BRIEF</code> is true, the <code>file</code> and <code>line</code> fields are omitted
1517from all events and the <code>time</code> field is only present on the "start" and
1518"atexit" events.</p></div>
1519</div>
1520<div class="sect3">
1521<h4 id="_event_specific_key_value_pairs">Event-Specific Key/Value Pairs</h4>
1522<div class="dlist"><dl>
1523<dt class="hdlist1">
1524<code>"version"</code>
1525</dt>
1526<dd>
1527<p>
1528 This event gives the version of the executable and the EVENT format.
1529</p>
1530<div class="listingblock">
1531<div class="content">
1532<pre><code>{
1533 "event":"version",
1534 ...
1535 "evt":"1", # EVENT format version
1536 "exe":"2.20.1.155.g426c96fcdb" # git version
1537}</code></pre>
1538</div></div>
1539</dd>
1540<dt class="hdlist1">
1541<code>"start"</code>
1542</dt>
1543<dd>
1544<p>
1545 This event contains the complete argv received by main().
1546</p>
1547<div class="listingblock">
1548<div class="content">
1549<pre><code>{
1550 "event":"start",
1551 ...
1552 "argv":["git","version"]
1553}</code></pre>
1554</div></div>
1555</dd>
1556<dt class="hdlist1">
1557<code>"exit"</code>
1558</dt>
1559<dd>
1560<p>
1561 This event is emitted when git calls <code>exit()</code>.
1562</p>
1563<div class="listingblock">
1564<div class="content">
1565<pre><code>{
1566 "event":"exit",
1567 ...
1568 "t_abs":0.001227, # elapsed time in seconds
1569 "code":0 # exit code
1570}</code></pre>
1571</div></div>
1572</dd>
1573<dt class="hdlist1">
1574<code>"atexit"</code>
1575</dt>
1576<dd>
1577<p>
1578 This event is emitted by the Trace2 <code>atexit</code> routine during
1579 final shutdown. It should be the last event emitted by the
1580 process.
1581</p>
1582<div class="paragraph"><p>(The elapsed time reported here is greater than the time reported in
1583the "exit" event because it runs after all other atexit tasks have
1584completed.)</p></div>
1585<div class="listingblock">
1586<div class="content">
1587<pre><code>{
1588 "event":"atexit",
1589 ...
1590 "t_abs":0.001227, # elapsed time in seconds
1591 "code":0 # exit code
1592}</code></pre>
1593</div></div>
1594</dd>
1595<dt class="hdlist1">
1596<code>"signal"</code>
1597</dt>
1598<dd>
1599<p>
1600 This event is emitted when the program is terminated by a user
1601 signal. Depending on the platform, the signal event may
1602 prevent the "atexit" event from being generated.
1603</p>
1604<div class="listingblock">
1605<div class="content">
1606<pre><code>{
1607 "event":"signal",
1608 ...
1609 "t_abs":0.001227, # elapsed time in seconds
1610 "signal":13 # SIGTERM, SIGINT, etc.
1611}</code></pre>
1612</div></div>
1613</dd>
1614<dt class="hdlist1">
1615<code>"error"</code>
1616</dt>
1617<dd>
1618<p>
1619 This event is emitted when one of the <code>error()</code>, <code>die()</code>,
1620 or <code>usage()</code> functions are called.
1621</p>
1622<div class="listingblock">
1623<div class="content">
1624<pre><code>{
1625 "event":"error",
1626 ...
1627 "msg":"invalid option: --cahced", # formatted error message
1628 "fmt":"invalid option: %s" # error format string
1629}</code></pre>
1630</div></div>
1631<div class="paragraph"><p>The error event may be emitted more than once. The format string
1632allows post-processors to group errors by type without worrying
1633about specific error arguments.</p></div>
1634</dd>
1635<dt class="hdlist1">
1636<code>"cmd_path"</code>
1637</dt>
1638<dd>
1639<p>
1640 This event contains the discovered full path of the git
1641 executable (on platforms that are configured to resolve it).
1642</p>
1643<div class="listingblock">
1644<div class="content">
1645<pre><code>{
1646 "event":"cmd_path",
1647 ...
1648 "path":"C:/work/gfw/git.exe"
1649}</code></pre>
1650</div></div>
1651</dd>
1652<dt class="hdlist1">
1653<code>"cmd_name"</code>
1654</dt>
1655<dd>
1656<p>
1657 This event contains the command name for this git process
1658 and the hierarchy of commands from parent git processes.
1659</p>
1660<div class="listingblock">
1661<div class="content">
1662<pre><code>{
1663 "event":"cmd_name",
1664 ...
1665 "name":"pack-objects",
1666 "hierarchy":"push/pack-objects"
1667}</code></pre>
1668</div></div>
1669<div class="paragraph"><p>Normally, the "name" field contains the canonical name of the
1670command. When a canonical name is not available, one of
1671these special values are used:</p></div>
1672<div class="listingblock">
1673<div class="content">
1674<pre><code>"_query_" # "git --html-path"
1675"_run_dashed_" # when "git foo" tries to run "git-foo"
1676"_run_shell_alias_" # alias expansion to a shell command
1677"_run_git_alias_" # alias expansion to a git command
1678"_usage_" # usage error</code></pre>
1679</div></div>
1680</dd>
1681<dt class="hdlist1">
1682<code>"cmd_mode"</code>
1683</dt>
1684<dd>
1685<p>
1686 This event, when present, describes the command variant This
1687 event may be emitted more than once.
1688</p>
1689<div class="listingblock">
1690<div class="content">
1691<pre><code>{
1692 "event":"cmd_mode",
1693 ...
1694 "name":"branch"
1695}</code></pre>
1696</div></div>
1697<div class="paragraph"><p>The "name" field is an arbitrary string to describe the command mode.
1698For example, checkout can checkout a branch or an individual file.
1699And these variations typically have different performance
1700characteristics that are not comparable.</p></div>
1701</dd>
1702<dt class="hdlist1">
1703<code>"alias"</code>
1704</dt>
1705<dd>
1706<p>
1707 This event is present when an alias is expanded.
1708</p>
1709<div class="listingblock">
1710<div class="content">
1711<pre><code>{
1712 "event":"alias",
1713 ...
1714 "alias":"l", # registered alias
1715 "argv":["log","--graph"] # alias expansion
1716}</code></pre>
1717</div></div>
1718</dd>
1719<dt class="hdlist1">
1720<code>"child_start"</code>
1721</dt>
1722<dd>
1723<p>
1724 This event describes a child process that is about to be
1725 spawned.
1726</p>
1727<div class="listingblock">
1728<div class="content">
1729<pre><code>{
1730 "event":"child_start",
1731 ...
1732 "child_id":2,
1733 "child_class":"?",
1734 "use_shell":false,
1735 "argv":["git","rev-list","--objects","--stdin","--not","--all","--quiet"]
1736
1737 "hook_name":"&lt;hook_name&gt;" # present when child_class is "hook"
1738 "cd":"&lt;path&gt;" # present when cd is required
1739}</code></pre>
1740</div></div>
1741<div class="paragraph"><p>The "child_id" field can be used to match this child_start with the
1742corresponding child_exit event.</p></div>
1743<div class="paragraph"><p>The "child_class" field is a rough classification, such as "editor",
1744"pager", "transport/*", and "hook". Unclassified children are classified
1745with "?".</p></div>
1746</dd>
1747<dt class="hdlist1">
1748<code>"child_exit"</code>
1749</dt>
1750<dd>
1751<p>
1752 This event is generated after the current process has returned
1753 from the waitpid() and collected the exit information from the
1754 child.
1755</p>
1756<div class="listingblock">
1757<div class="content">
1758<pre><code>{
1759 "event":"child_exit",
1760 ...
1761 "child_id":2,
1762 "pid":14708, # child PID
1763 "code":0, # child exit-code
1764 "t_rel":0.110605 # observed run-time of child process
1765}</code></pre>
1766</div></div>
1767<div class="paragraph"><p>Note that the session-id of the child process is not available to
1768the current/spawning process, so the child&#8217;s PID is reported here as
1769a hint for post-processing. (But it is only a hint because the child
1770proces may be a shell script which doesn&#8217;t have a session-id.)</p></div>
1771<div class="paragraph"><p>Note that the <code>t_rel</code> field contains the observed run time in seconds
1772for the child process (starting before the fork/exec/spawn and
1773stopping after the waitpid() and includes OS process creation overhead).
1774So this time will be slightly larger than the atexit time reported by
1775the child process itself.</p></div>
1776</dd>
1777<dt class="hdlist1">
1778<code>"exec"</code>
1779</dt>
1780<dd>
1781<p>
1782 This event is generated before git attempts to <code>exec()</code>
1783 another command rather than starting a child process.
1784</p>
1785<div class="listingblock">
1786<div class="content">
1787<pre><code>{
1788 "event":"exec",
1789 ...
1790 "exec_id":0,
1791 "exe":"git",
1792 "argv":["foo", "bar"]
1793}</code></pre>
1794</div></div>
1795<div class="paragraph"><p>The "exec_id" field is a command-unique id and is only useful if the
1796<code>exec()</code> fails and a corresponding exec_result event is generated.</p></div>
1797</dd>
1798<dt class="hdlist1">
1799<code>"exec_result"</code>
1800</dt>
1801<dd>
1802<p>
1803 This event is generated if the <code>exec()</code> fails and control
1804 returns to the current git command.
1805</p>
1806<div class="listingblock">
1807<div class="content">
1808<pre><code>{
1809 "event":"exec_result",
1810 ...
1811 "exec_id":0,
1812 "code":1 # error code (errno) from exec()
1813}</code></pre>
1814</div></div>
1815</dd>
1816<dt class="hdlist1">
1817<code>"thread_start"</code>
1818</dt>
1819<dd>
1820<p>
1821 This event is generated when a thread is started. It is
1822 generated from <strong>within</strong> the new thread&#8217;s thread-proc (for TLS
1823 reasons).
1824</p>
1825<div class="listingblock">
1826<div class="content">
1827<pre><code>{
1828 "event":"thread_start",
1829 ...
1830 "thread":"th02:preload_thread" # thread name
1831}</code></pre>
1832</div></div>
1833</dd>
1834<dt class="hdlist1">
1835<code>"thread_exit"</code>
1836</dt>
1837<dd>
1838<p>
1839 This event is generated when a thread exits. It is generated
1840 from <strong>within</strong> the thread&#8217;s thread-proc (for TLS reasons).
1841</p>
1842<div class="listingblock">
1843<div class="content">
1844<pre><code>{
1845 "event":"thread_exit",
1846 ...
1847 "thread":"th02:preload_thread", # thread name
1848 "t_rel":0.007328 # thread elapsed time
1849}</code></pre>
1850</div></div>
1851</dd>
1852<dt class="hdlist1">
1853<code>"def_param"</code>
1854</dt>
1855<dd>
1856<p>
1857 This event is generated to log a global parameter.
1858</p>
1859<div class="listingblock">
1860<div class="content">
1861<pre><code>{
1862 "event":"def_param",
1863 ...
1864 "param":"core.abbrev",
1865 "value":"7"
1866}</code></pre>
1867</div></div>
1868</dd>
1869<dt class="hdlist1">
1870<code>"def_repo"</code>
1871</dt>
1872<dd>
1873<p>
1874 This event defines a repo-id and associates it with the root
1875 of the worktree.
1876</p>
1877<div class="listingblock">
1878<div class="content">
1879<pre><code>{
1880 "event":"def_repo",
1881 ...
1882 "repo":1,
1883 "worktree":"/Users/jeffhost/work/gfw"
1884}</code></pre>
1885</div></div>
1886<div class="paragraph"><p>As stated earlier, the repo-id is currently always 1, so there will
1887only be one def_repo event. Later, if in-proc submodules are
1888supported, a def_repo event should be emitted for each submodule
1889visited.</p></div>
1890</dd>
1891<dt class="hdlist1">
1892<code>"region_enter"</code>
1893</dt>
1894<dd>
1895<p>
1896 This event is generated when entering a region.
1897</p>
1898<div class="listingblock">
1899<div class="content">
1900<pre><code>{
1901 "event":"region_enter",
1902 ...
1903 "repo":1, # optional
1904 "nesting":1, # current region stack depth
1905 "category":"index", # optional
1906 "label":"do_read_index", # optional
1907 "msg":".git/index" # optional
1908}</code></pre>
1909</div></div>
1910<div class="paragraph"><p>The <code>category</code> field may be used in a future enhancement to
1911do category-based filtering.</p></div>
1912<div class="paragraph"><p>The <code>GIT_TR2_EVENT_NESTING</code> environment variable can be used to
1913filter deeply nested regions and data events. It defaults to "2".</p></div>
1914</dd>
1915<dt class="hdlist1">
1916<code>"region_leave"</code>
1917</dt>
1918<dd>
1919<p>
1920 This event is generated when leaving a region.
1921</p>
1922<div class="listingblock">
1923<div class="content">
1924<pre><code>{
1925 "event":"region_leave",
1926 ...
1927 "repo":1, # optional
1928 "t_rel":0.002876, # time spent in region in seconds
1929 "nesting":1, # region stack depth
1930 "category":"index", # optional
1931 "label":"do_read_index", # optional
1932 "msg":".git/index" # optional
1933}</code></pre>
1934</div></div>
1935</dd>
1936<dt class="hdlist1">
1937<code>"data"</code>
1938</dt>
1939<dd>
1940<p>
1941 This event is generated to log a thread- and region-local
1942 key/value pair.
1943</p>
1944<div class="listingblock">
1945<div class="content">
1946<pre><code>{
1947 "event":"data",
1948 ...
1949 "repo":1, # optional
1950 "t_abs":0.024107, # absolute elapsed time
1951 "t_rel":0.001031, # elapsed time in region/thread
1952 "nesting":2, # region stack depth
1953 "category":"index",
1954 "key":"read/cache_nr",
1955 "value":"3552"
1956}</code></pre>
1957</div></div>
1958<div class="paragraph"><p>The "value" field may be an integer or a string.</p></div>
1959</dd>
1960<dt class="hdlist1">
1961<code>"data-json"</code>
1962</dt>
1963<dd>
1964<p>
1965 This event is generated to log a pre-formatted JSON string
1966 containing structured data.
1967</p>
1968<div class="listingblock">
1969<div class="content">
1970<pre><code>{
1971 "event":"data_json",
1972 ...
1973 "repo":1, # optional
1974 "t_abs":0.015905,
1975 "t_rel":0.015905,
1976 "nesting":1,
1977 "category":"process",
1978 "key":"windows/ancestry",
1979 "value":["bash.exe","bash.exe"]
1980}</code></pre>
1981</div></div>
1982</dd>
1983</dl></div>
1984</div>
1985</div>
1986</div>
1987</div>
1988<div class="sect1">
1989<h2 id="_example_trace2_api_usage">Example Trace2 API Usage</h2>
1990<div class="sectionbody">
1991<div class="paragraph"><p>Here is a hypothetical usage of the Trace2 API showing the intended
1992usage (without worrying about the actual Git details).</p></div>
1993<div class="dlist"><dl>
1994<dt class="hdlist1">
1995Initialization
1996</dt>
1997<dd>
1998<p>
1999 Initialization happens in <code>main()</code>. Behind the scenes, an
2000 <code>atexit</code> and <code>signal</code> handler are registered.
2001</p>
2002<div class="listingblock">
2003<div class="content">
2004<pre><code>int main(int argc, const char **argv)
2005{
2006 int exit_code;
2007
2008 trace2_initialize();
2009 trace2_cmd_start(argv);
2010
2011 exit_code = cmd_main(argc, argv);
2012
2013 trace2_cmd_exit(exit_code);
2014
2015 return exit_code;
2016}</code></pre>
2017</div></div>
2018</dd>
2019<dt class="hdlist1">
2020Command Details
2021</dt>
2022<dd>
2023<p>
2024 After the basics are established, additional command
2025 information can be sent to Trace2 as it is discovered.
2026</p>
2027<div class="listingblock">
2028<div class="content">
2029<pre><code>int cmd_checkout(int argc, const char **argv)
2030{
2031 trace2_cmd_name("checkout");
2032 trace2_cmd_mode("branch");
2033 trace2_def_repo(the_repository);
2034
2035 // emit "def_param" messages for "interesting" config settings.
2036 trace2_cmd_list_config();
2037
2038 if (do_something())
2039 trace2_cmd_error("Path '%s': cannot do something", path);
2040
2041 return 0;
2042}</code></pre>
2043</div></div>
2044</dd>
2045<dt class="hdlist1">
2046Child Processes
2047</dt>
2048<dd>
2049<p>
2050 Wrap code spawning child processes.
2051</p>
2052<div class="listingblock">
2053<div class="content">
2054<pre><code>void run_child(...)
2055{
2056 int child_exit_code;
2057 struct child_process cmd = CHILD_PROCESS_INIT;
2058 ...
2059 cmd.trace2_child_class = "editor";
2060
2061 trace2_child_start(&amp;cmd);
2062 child_exit_code = spawn_child_and_wait_for_it();
2063 trace2_child_exit(&amp;cmd, child_exit_code);
2064}</code></pre>
2065</div></div>
2066<div class="paragraph"><p>For example, the following fetch command spawned ssh, index-pack,
2067rev-list, and gc. This example also shows that fetch took
20685.199 seconds and of that 4.932 was in ssh.</p></div>
2069<div class="listingblock">
2070<div class="content">
2071<pre><code>$ export GIT_TR2_BRIEF=1
2072$ export GIT_TR2=~/log.normal
2073$ git fetch origin
2074...</code></pre>
2075</div></div>
2076<div class="listingblock">
2077<div class="content">
2078<pre><code>$ cat ~/log.normal
2079version 2.20.1.vfs.1.1.47.g534dbe1ad1
2080start git fetch origin
2081worktree /Users/jeffhost/work/gfw
2082cmd_name fetch (fetch)
2083child_start[0] ssh git@github.com ...
2084child_start[1] git index-pack ...
2085... (Trace2 events from child processes omitted)
2086child_exit[1] pid:14707 code:0 elapsed:0.076353
2087child_exit[0] pid:14706 code:0 elapsed:4.931869
2088child_start[2] git rev-list ...
2089... (Trace2 events from child process omitted)
2090child_exit[2] pid:14708 code:0 elapsed:0.110605
2091child_start[3] git gc --auto
2092... (Trace2 events from child process omitted)
2093child_exit[3] pid:14709 code:0 elapsed:0.006240
2094exit elapsed:5.198503 code:0
2095atexit elapsed:5.198541 code:0</code></pre>
2096</div></div>
2097<div class="paragraph"><p>When a git process is a (direct or indirect) child of another
2098git process, it inherits Trace2 context information. This
2099allows the child to print the command hierarchy. This example
2100shows gc as child[3] of fetch. When the gc process reports
2101its name as "gc", it also reports the hierarchy as "fetch/gc".
2102(In this example, trace2 messages from the child process is
2103indented for clarity.)</p></div>
2104<div class="listingblock">
2105<div class="content">
2106<pre><code>$ export GIT_TR2_BRIEF=1
2107$ export GIT_TR2=~/log.normal
2108$ git fetch origin
2109...</code></pre>
2110</div></div>
2111<div class="listingblock">
2112<div class="content">
2113<pre><code>$ cat ~/log.normal
2114version 2.20.1.160.g5676107ecd.dirty
2115start git fetch official
2116worktree /Users/jeffhost/work/gfw
2117cmd_name fetch (fetch)
2118...
2119child_start[3] git gc --auto
2120 version 2.20.1.160.g5676107ecd.dirty
2121 start /Users/jeffhost/work/gfw/git gc --auto
2122 worktree /Users/jeffhost/work/gfw
2123 cmd_name gc (fetch/gc)
2124 exit elapsed:0.001959 code:0
2125 atexit elapsed:0.001997 code:0
2126child_exit[3] pid:20303 code:0 elapsed:0.007564
2127exit elapsed:3.868938 code:0
2128atexit elapsed:3.868970 code:0</code></pre>
2129</div></div>
2130</dd>
2131<dt class="hdlist1">
2132Regions
2133</dt>
2134<dd>
2135<p>
2136 Regions can be use to time an interesting section of code.
2137</p>
2138<div class="listingblock">
2139<div class="content">
2140<pre><code>void wt_status_collect(struct wt_status *s)
2141{
2142 trace2_region_enter("status", "worktrees", s-&gt;repo);
2143 wt_status_collect_changes_worktree(s);
2144 trace2_region_leave("status", "worktrees", s-&gt;repo);
2145
2146 trace2_region_enter("status", "index", s-&gt;repo);
2147 wt_status_collect_changes_index(s);
2148 trace2_region_leave("status", "index", s-&gt;repo);
2149
2150 trace2_region_enter("status", "untracked", s-&gt;repo);
2151 wt_status_collect_untracked(s);
2152 trace2_region_leave("status", "untracked", s-&gt;repo);
2153}
2154
2155void wt_status_print(struct wt_status *s)
2156{
2157 trace2_region_enter("status", "print", s-&gt;repo);
2158 switch (s-&gt;status_format) {
2159 ...
2160 }
2161 trace2_region_leave("status", "print", s-&gt;repo);
2162}</code></pre>
2163</div></div>
2164<div class="paragraph"><p>In this example, scanning for untracked files ran from +0.012568 to
2165+0.027149 (since the process started) and took 0.014581 seconds.</p></div>
2166<div class="listingblock">
2167<div class="content">
2168<pre><code>$ export GIT_TR2_PERF_BRIEF=1
2169$ export GIT_TR2_PERF=~/log.perf
2170$ git status
2171...
2172
2173$ cat ~/log.perf
2174d0 | main | version | | | | | 2.20.1.160.g5676107ecd.dirty
2175d0 | main | start | | | | | git status
2176d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
2177d0 | main | cmd_name | | | | | status (status)
2178...
2179d0 | main | region_enter | r1 | 0.010988 | | status | label:worktrees
2180d0 | main | region_leave | r1 | 0.011236 | 0.000248 | status | label:worktrees
2181d0 | main | region_enter | r1 | 0.011260 | | status | label:index
2182d0 | main | region_leave | r1 | 0.012542 | 0.001282 | status | label:index
2183d0 | main | region_enter | r1 | 0.012568 | | status | label:untracked
2184d0 | main | region_leave | r1 | 0.027149 | 0.014581 | status | label:untracked
2185d0 | main | region_enter | r1 | 0.027411 | | status | label:print
2186d0 | main | region_leave | r1 | 0.028741 | 0.001330 | status | label:print
2187d0 | main | exit | | 0.028778 | | | code:0
2188d0 | main | atexit | | 0.028809 | | | code:0</code></pre>
2189</div></div>
2190<div class="paragraph"><p>Regions may be nested. This causes messages to be indented in the
2191PERF target, for example.
2192Elapsed times are relative to the start of the correpsonding nesting
2193level as expected. For example, if we add region message to:</p></div>
2194<div class="listingblock">
2195<div class="content">
2196<pre><code>static enum path_treatment read_directory_recursive(struct dir_struct *dir,
2197 struct index_state *istate, const char *base, int baselen,
2198 struct untracked_cache_dir *untracked, int check_only,
2199 int stop_at_first_file, const struct pathspec *pathspec)
2200{
2201 enum path_treatment state, subdir_state, dir_state = path_none;
2202
2203 trace2_region_enter_printf("dir", "read_recursive", NULL, "%.*s", baselen, base);
2204 ...
2205 trace2_region_leave_printf("dir", "read_recursive", NULL, "%.*s", baselen, base);
2206 return dir_state;
2207}</code></pre>
2208</div></div>
2209<div class="paragraph"><p>We can further investigate the time spent scanning for untracked files.</p></div>
2210<div class="listingblock">
2211<div class="content">
2212<pre><code>$ export GIT_TR2_PERF_BRIEF=1
2213$ export GIT_TR2_PERF=~/log.perf
2214$ git status
2215...
2216$ cat ~/log.perf
2217d0 | main | version | | | | | 2.20.1.162.gb4ccea44db.dirty
2218d0 | main | start | | | | | git status
2219d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
2220d0 | main | cmd_name | | | | | status (status)
2221...
2222d0 | main | region_enter | r1 | 0.015047 | | status | label:untracked
2223d0 | main | region_enter | | 0.015132 | | dir | ..label:read_recursive
2224d0 | main | region_enter | | 0.016341 | | dir | ....label:read_recursive vcs-svn/
2225d0 | main | region_leave | | 0.016422 | 0.000081 | dir | ....label:read_recursive vcs-svn/
2226d0 | main | region_enter | | 0.016446 | | dir | ....label:read_recursive xdiff/
2227d0 | main | region_leave | | 0.016522 | 0.000076 | dir | ....label:read_recursive xdiff/
2228d0 | main | region_enter | | 0.016612 | | dir | ....label:read_recursive git-gui/
2229d0 | main | region_enter | | 0.016698 | | dir | ......label:read_recursive git-gui/po/
2230d0 | main | region_enter | | 0.016810 | | dir | ........label:read_recursive git-gui/po/glossary/
2231d0 | main | region_leave | | 0.016863 | 0.000053 | dir | ........label:read_recursive git-gui/po/glossary/
2232...
2233d0 | main | region_enter | | 0.031876 | | dir | ....label:read_recursive builtin/
2234d0 | main | region_leave | | 0.032270 | 0.000394 | dir | ....label:read_recursive builtin/
2235d0 | main | region_leave | | 0.032414 | 0.017282 | dir | ..label:read_recursive
2236d0 | main | region_leave | r1 | 0.032454 | 0.017407 | status | label:untracked
2237...
2238d0 | main | exit | | 0.034279 | | | code:0
2239d0 | main | atexit | | 0.034322 | | | code:0</code></pre>
2240</div></div>
2241<div class="paragraph"><p>Trace2 regions are similar to the existing trace_performance_enter()
2242and trace_performance_leave() routines, but are thread safe and
2243maintain per-thread stacks of timers.</p></div>
2244</dd>
2245<dt class="hdlist1">
2246Data Messages
2247</dt>
2248<dd>
2249<p>
2250 Data messages added to a region.
2251</p>
2252<div class="listingblock">
2253<div class="content">
2254<pre><code>int read_index_from(struct index_state *istate, const char *path,
2255 const char *gitdir)
2256{
2257 trace2_region_enter_printf("index", "do_read_index", the_repository, "%s", path);
2258
2259 ...
2260
2261 trace2_data_intmax("index", the_repository, "read/version", istate-&gt;version);
2262 trace2_data_intmax("index", the_repository, "read/cache_nr", istate-&gt;cache_nr);
2263
2264 trace2_region_leave_printf("index", "do_read_index", the_repository, "%s", path);
2265}</code></pre>
2266</div></div>
2267<div class="paragraph"><p>This example shows that the index contained 3552 entries.</p></div>
2268<div class="listingblock">
2269<div class="content">
2270<pre><code>$ export GIT_TR2_PERF_BRIEF=1
2271$ export GIT_TR2_PERF=~/log.perf
2272$ git status
2273...
2274$ cat ~/log.perf
2275d0 | main | version | | | | | 2.20.1.156.gf9916ae094.dirty
2276d0 | main | start | | | | | git status
2277d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
2278d0 | main | cmd_name | | | | | status (status)
2279d0 | main | region_enter | r1 | 0.001791 | | index | label:do_read_index .git/index
2280d0 | main | data | r1 | 0.002494 | 0.000703 | index | ..read/version:2
2281d0 | main | data | r1 | 0.002520 | 0.000729 | index | ..read/cache_nr:3552
2282d0 | main | region_leave | r1 | 0.002539 | 0.000748 | index | label:do_read_index .git/index
2283...</code></pre>
2284</div></div>
2285</dd>
2286<dt class="hdlist1">
2287Thread Events
2288</dt>
2289<dd>
2290<p>
2291 Thread messages added to a thread-proc.
2292</p>
2293<div class="paragraph"><p>For example, the multithreaded preload-index code can be
2294instrumented with a region around the thread pool and then
2295per-thread start and exit events within the threadproc.</p></div>
2296<div class="listingblock">
2297<div class="content">
2298<pre><code>static void *preload_thread(void *_data)
2299{
2300 // start the per-thread clock and emit a message.
2301 trace2_thread_start("preload_thread");
2302
2303 // report which chunk of the array this thread was assigned.
2304 trace2_data_intmax("index", the_repository, "offset", p-&gt;offset);
2305 trace2_data_intmax("index", the_repository, "count", nr);
2306
2307 do {
2308 ...
2309 } while (--nr &gt; 0);
2310 ...
2311
2312 // report elapsed time taken by this thread.
2313 trace2_thread_exit();
2314 return NULL;
2315}
2316
2317void preload_index(struct index_state *index,
2318 const struct pathspec *pathspec,
2319 unsigned int refresh_flags)
2320{
2321 trace2_region_enter("index", "preload", the_repository);
2322
2323 for (i = 0; i &lt; threads; i++) {
2324 ... /* create thread */
2325 }
2326
2327 for (i = 0; i &lt; threads; i++) {
2328 ... /* join thread */
2329 }
2330
2331 trace2_region_leave("index", "preload", the_repository);
2332}</code></pre>
2333</div></div>
2334<div class="paragraph"><p>In this example preload_index() was executed by the <code>main</code> thread
2335and started the <code>preload</code> region. Seven threads, named
2336<code>th01:preload_thread</code> through <code>th07:preload_thread</code>, were started.
2337Events from each thread are atomically appended to the shared target
2338stream as they occur so they may appear in random order with respect
2339other threads. Finally, the main thread waits for the threads to
2340finish and leaves the region.</p></div>
2341<div class="paragraph"><p>Data events are tagged with the active thread name. They are used
2342to report the per-thread parameters.</p></div>
2343<div class="listingblock">
2344<div class="content">
2345<pre><code>$ export GIT_TR2_PERF_BRIEF=1
2346$ export GIT_TR2_PERF=~/log.perf
2347$ git status
2348...
2349$ cat ~/log.perf
2350...
2351d0 | main | region_enter | r1 | 0.002595 | | index | label:preload
2352d0 | th01:preload_thread | thread_start | | 0.002699 | | |
2353d0 | th02:preload_thread | thread_start | | 0.002721 | | |
2354d0 | th01:preload_thread | data | r1 | 0.002736 | 0.000037 | index | offset:0
2355d0 | th02:preload_thread | data | r1 | 0.002751 | 0.000030 | index | offset:2032
2356d0 | th03:preload_thread | thread_start | | 0.002711 | | |
2357d0 | th06:preload_thread | thread_start | | 0.002739 | | |
2358d0 | th01:preload_thread | data | r1 | 0.002766 | 0.000067 | index | count:508
2359d0 | th06:preload_thread | data | r1 | 0.002856 | 0.000117 | index | offset:2540
2360d0 | th03:preload_thread | data | r1 | 0.002824 | 0.000113 | index | offset:1016
2361d0 | th04:preload_thread | thread_start | | 0.002710 | | |
2362d0 | th02:preload_thread | data | r1 | 0.002779 | 0.000058 | index | count:508
2363d0 | th06:preload_thread | data | r1 | 0.002966 | 0.000227 | index | count:508
2364d0 | th07:preload_thread | thread_start | | 0.002741 | | |
2365d0 | th07:preload_thread | data | r1 | 0.003017 | 0.000276 | index | offset:3048
2366d0 | th05:preload_thread | thread_start | | 0.002712 | | |
2367d0 | th05:preload_thread | data | r1 | 0.003067 | 0.000355 | index | offset:1524
2368d0 | th05:preload_thread | data | r1 | 0.003090 | 0.000378 | index | count:508
2369d0 | th07:preload_thread | data | r1 | 0.003037 | 0.000296 | index | count:504
2370d0 | th03:preload_thread | data | r1 | 0.002971 | 0.000260 | index | count:508
2371d0 | th04:preload_thread | data | r1 | 0.002983 | 0.000273 | index | offset:508
2372d0 | th04:preload_thread | data | r1 | 0.007311 | 0.004601 | index | count:508
2373d0 | th05:preload_thread | thread_exit | | 0.008781 | 0.006069 | |
2374d0 | th01:preload_thread | thread_exit | | 0.009561 | 0.006862 | |
2375d0 | th03:preload_thread | thread_exit | | 0.009742 | 0.007031 | |
2376d0 | th06:preload_thread | thread_exit | | 0.009820 | 0.007081 | |
2377d0 | th02:preload_thread | thread_exit | | 0.010274 | 0.007553 | |
2378d0 | th07:preload_thread | thread_exit | | 0.010477 | 0.007736 | |
2379d0 | th04:preload_thread | thread_exit | | 0.011657 | 0.008947 | |
2380d0 | main | region_leave | r1 | 0.011717 | 0.009122 | index | label:preload
2381...
2382d0 | main | exit | | 0.029996 | | | code:0
2383d0 | main | atexit | | 0.030027 | | | code:0</code></pre>
2384</div></div>
2385<div class="paragraph"><p>In this example, the preload region took 0.009122 seconds. The 7 threads
2386took between 0.006069 and 0.008947 seconds to work on their portion of
2387the index. Thread "th01" worked on 508 items at offset 0. Thread "th02"
2388worked on 508 items at offset 2032. Thread "th04" worked on 508 itemts
2389at offset 508.</p></div>
2390<div class="paragraph"><p>This example also shows that thread names are assigned in a racy manner
2391as each thread starts and allocates TLS storage.</p></div>
2392</dd>
2393</dl></div>
2394</div>
2395</div>
2396<div class="sect1">
2397<h2 id="_future_work">Future Work</h2>
2398<div class="sectionbody">
2399<div class="sect2">
2400<h3 id="_relationship_to_the_existing_trace_api_api_trace_txt">Relationship to the Existing Trace Api (api-trace.txt)</h3>
2401<div class="paragraph"><p>There are a few issues to resolve before we can completely
2402switch to Trace2.</p></div>
2403<div class="ulist"><ul>
2404<li>
2405<p>
2406Updating existing tests that assume GIT_TRACE format messages.
2407</p>
2408</li>
2409<li>
2410<p>
2411How to best handle custom GIT_TRACE_&lt;key&gt; messages?
2412</p>
2413<div class="ulist"><ul>
2414<li>
2415<p>
2416The GIT_TRACE_&lt;key&gt; mechanism allows each &lt;key&gt; to write to a
2417different file (in addition to just stderr).
2418</p>
2419</li>
2420<li>
2421<p>
2422Do we want to maintain that ability or simply write to the existing
2423Trace2 targets (and convert &lt;key&gt; to a "category").
2424</p>
2425</li>
2426</ul></div>
2427</li>
2428</ul></div>
2429</div>
2430</div>
2431</div>
2432</div>
2433<div id="footnotes"><hr /></div>
2434<div id="footer">
2435<div id="footer-text">
2436Last updated
Junio C Hamanod1063b12019-05-08 17:18:07[diff] [blame^]2437 2019-05-09 02:15:17 JST
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]2438</div>
2439</div>
2440</body>
2441</html>