Google Git
Sign in
chromium / external / gitster / git-htmldocs / 09e83a384d91ee3b9bf63610714713e840e1a1a8 / . / technical / api-trace2.html
blob: 5044b0c54287faa16346eb4cba44f793a26d78af [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" />
Junio C Hamano98c882d2020-08-13 22:06:57[diff] [blame]7<meta name="generator" content="AsciiDoc 9.0.0rc2" />
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]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}
Junio C Hamano725b0da2020-01-22 22:02:40[diff] [blame]439/* Because the table frame attribute is overridden by CSS in most browsers. */
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]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>
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]759<div class="paragraph"><p>Trace2 is controlled using <code>trace2.*</code> config values in the system and
Junio C Hamanoc01eecf2019-05-30 18:17:47[diff] [blame]760global config files and <code>GIT_TRACE2*</code> environment variables. Trace2 does
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]761not read from repo local or worktree config files or respect <code>-c</code>
762command line config settings.</p></div>
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]763</div>
764</div>
765<div class="sect1">
766<h2 id="_trace2_targets">Trace2 Targets</h2>
767<div class="sectionbody">
768<div class="paragraph"><p>Trace2 defines the following set of Trace2 Targets.
769Format details are given in a later section.</p></div>
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]770<div class="sect2">
771<h3 id="_the_normal_format_target">The Normal Format Target</h3>
772<div class="paragraph"><p>The normal format target is a tradition printf format and similar
Junio C Hamanoc9f11c22019-07-10 02:54:04[diff] [blame]773to GIT_TRACE format. This format is enabled with the <code>GIT_TRACE2</code>
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]774environment variable or the <code>trace2.normalTarget</code> system or global
775config setting.</p></div>
776<div class="paragraph"><p>For example</p></div>
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]777<div class="listingblock">
778<div class="content">
Junio C Hamanoc01eecf2019-05-30 18:17:47[diff] [blame]779<pre><code>$ export GIT_TRACE2=~/log.normal
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]780$ git version
781git version 2.20.1.155.g426c96fcdb</code></pre>
782</div></div>
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]783<div class="paragraph"><p>or</p></div>
784<div class="listingblock">
785<div class="content">
786<pre><code>$ git config --global trace2.normalTarget ~/log.normal
787$ git version
788git version 2.20.1.155.g426c96fcdb</code></pre>
789</div></div>
790<div class="paragraph"><p>yields</p></div>
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]791<div class="listingblock">
792<div class="content">
793<pre><code>$ cat ~/log.normal
79412:28:42.620009 common-main.c:38 version 2.20.1.155.g426c96fcdb
79512:28:42.620989 common-main.c:39 start git version
79612:28:42.621101 git.c:432 cmd_name version (version)
79712:28:42.621215 git.c:662 exit elapsed:0.001227 code:0
79812:28:42.621250 trace2/tr2_tgt_normal.c:124 atexit elapsed:0.001265 code:0</code></pre>
799</div></div>
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]800</div>
801<div class="sect2">
802<h3 id="_the_performance_format_target">The Performance Format Target</h3>
803<div class="paragraph"><p>The performance format target (PERF) is a column-based format to
804replace GIT_TRACE_PERFORMANCE and is suitable for development and
805testing, possibly to complement tools like gprof. This format is
Junio C Hamanoc01eecf2019-05-30 18:17:47[diff] [blame]806enabled with the <code>GIT_TRACE2_PERF</code> environment variable or the
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]807<code>trace2.perfTarget</code> system or global config setting.</p></div>
808<div class="paragraph"><p>For example</p></div>
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]809<div class="listingblock">
810<div class="content">
Junio C Hamanoc01eecf2019-05-30 18:17:47[diff] [blame]811<pre><code>$ export GIT_TRACE2_PERF=~/log.perf
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]812$ git version
813git version 2.20.1.155.g426c96fcdb</code></pre>
814</div></div>
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]815<div class="paragraph"><p>or</p></div>
816<div class="listingblock">
817<div class="content">
818<pre><code>$ git config --global trace2.perfTarget ~/log.perf
819$ git version
820git version 2.20.1.155.g426c96fcdb</code></pre>
821</div></div>
822<div class="paragraph"><p>yields</p></div>
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]823<div class="listingblock">
824<div class="content">
825<pre><code>$ cat ~/log.perf
82612:28:42.620675 common-main.c:38 | d0 | main | version | | | | | 2.20.1.155.g426c96fcdb
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]82712:28:42.621001 common-main.c:39 | d0 | main | start | | 0.001173 | | | git version
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]82812:28:42.621111 git.c:432 | d0 | main | cmd_name | | | | | version (version)
82912:28:42.621225 git.c:662 | d0 | main | exit | | 0.001227 | | | code:0
83012:28:42.621259 trace2/tr2_tgt_perf.c:211 | d0 | main | atexit | | 0.001265 | | | code:0</code></pre>
831</div></div>
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]832</div>
833<div class="sect2">
834<h3 id="_the_event_format_target">The Event Format Target</h3>
835<div class="paragraph"><p>The event format target is a JSON-based format of event data suitable
Junio C Hamanoc01eecf2019-05-30 18:17:47[diff] [blame]836for telemetry analysis. This format is enabled with the <code>GIT_TRACE2_EVENT</code>
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]837environment variable or the <code>trace2.eventTarget</code> system or global config
838setting.</p></div>
839<div class="paragraph"><p>For example</p></div>
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]840<div class="listingblock">
841<div class="content">
Junio C Hamanoc01eecf2019-05-30 18:17:47[diff] [blame]842<pre><code>$ export GIT_TRACE2_EVENT=~/log.event
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]843$ git version
844git version 2.20.1.155.g426c96fcdb</code></pre>
845</div></div>
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]846<div class="paragraph"><p>or</p></div>
847<div class="listingblock">
848<div class="content">
849<pre><code>$ git config --global trace2.eventTarget ~/log.event
850$ git version
851git version 2.20.1.155.g426c96fcdb</code></pre>
852</div></div>
853<div class="paragraph"><p>yields</p></div>
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]854<div class="listingblock">
855<div class="content">
856<pre><code>$ cat ~/log.event
Junio C Hamanofa2a48b2019-10-15 05:24:40[diff] [blame]857{"event":"version","sid":"sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.620713Z","file":"common-main.c","line":38,"evt":"2","exe":"2.20.1.155.g426c96fcdb"}
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]858{"event":"start","sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.621027Z","file":"common-main.c","line":39,"t_abs":0.001173,"argv":["git","version"]}
859{"event":"cmd_name","sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.621122Z","file":"git.c","line":432,"name":"version","hierarchy":"version"}
860{"event":"exit","sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.621236Z","file":"git.c","line":662,"t_abs":0.001227,"code":0}
861{"event":"atexit","sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.621268Z","file":"trace2/tr2_tgt_event.c","line":163,"t_abs":0.001265,"code":0}</code></pre>
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]862</div></div>
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]863</div>
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]864<div class="sect2">
865<h3 id="_enabling_a_target">Enabling a Target</h3>
866<div class="paragraph"><p>To enable a target, set the corresponding environment variable or
867system or global config value to one of the following:</p></div>
868<div class="openblock">
Junio C Hamanod1063b12019-05-08 17:18:07[diff] [blame]869<div class="content">
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]870<div class="ulist"><ul>
871<li>
872<p>
873<code>0</code> or <code>false</code> - Disables the target.
874</p>
875</li>
876<li>
877<p>
878<code>1</code> or <code>true</code> - Writes to <code>STDERR</code>.
879</p>
880</li>
881<li>
882<p>
883<code>[2-9]</code> - Writes to the already opened file descriptor.
884</p>
885</li>
886<li>
887<p>
Junio C Hamanofa2a48b2019-10-15 05:24:40[diff] [blame]888<code>&lt;absolute-pathname&gt;</code> - Writes to the file in append mode. If the target
889already exists and is a directory, the traces will be written to files (one
890per process) underneath the given directory.
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]891</p>
892</li>
893<li>
894<p>
895<code>af_unix:[&lt;socket_type&gt;:]&lt;absolute-pathname&gt;</code> - Write to a
896Unix DomainSocket (on platforms that support them). Socket
897type can be either <code>stream</code> or <code>dgram</code>; if omitted Git will
898try both.
899</p>
900</li>
901</ul></div>
902</div></div>
Junio C Hamanofa2a48b2019-10-15 05:24:40[diff] [blame]903<div class="paragraph"><p>When trace files are written to a target directory, they will be named according
904to the last component of the SID (optionally followed by a counter to avoid
905filename collisions).</p></div>
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]906</div>
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]907</div>
908</div>
909<div class="sect1">
910<h2 id="_trace2_api">Trace2 API</h2>
911<div class="sectionbody">
912<div class="paragraph"><p>All public Trace2 functions and macros are defined in <code>trace2.h</code> and
913<code>trace2.c</code>. All public symbols are prefixed with <code>trace2_</code>.</p></div>
914<div class="paragraph"><p>There are no public Trace2 data structures.</p></div>
915<div class="paragraph"><p>The Trace2 code also defines a set of private functions and data types
916in the <code>trace2/</code> directory. These symbols are prefixed with <code>tr2_</code>
917and should only be used by functions in <code>trace2.c</code>.</p></div>
918</div>
919</div>
920<div class="sect1">
921<h2 id="_conventions_for_public_functions_and_macros">Conventions for Public Functions and Macros</h2>
922<div class="sectionbody">
923<div class="paragraph"><p>The functions defined by the Trace2 API are declared and documented
924in <code>trace2.h</code>. It defines the API functions and wrapper macros for
925Trace2.</p></div>
926<div class="paragraph"><p>Some functions have a <code>_fl()</code> suffix to indicate that they take <code>file</code>
927and <code>line-number</code> arguments.</p></div>
928<div class="paragraph"><p>Some functions have a <code>_va_fl()</code> suffix to indicate that they also
929take a <code>va_list</code> argument.</p></div>
930<div class="paragraph"><p>Some functions have a <code>_printf_fl()</code> suffix to indicate that they also
931take a varargs argument.</p></div>
932<div class="paragraph"><p>There are CPP wrapper macros and ifdefs to hide most of these details.
933See <code>trace2.h</code> for more details. The following discussion will only
934describe the simplified forms.</p></div>
935</div>
936</div>
937<div class="sect1">
938<h2 id="_public_api">Public API</h2>
939<div class="sectionbody">
Junio C Hamano8ef91f32019-12-01 22:58:27[diff] [blame]940<div class="paragraph"><p>All Trace2 API functions send a message to all of the active
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]941Trace2 Targets. This section describes the set of available
942messages.</p></div>
943<div class="paragraph"><p>It helps to divide these functions into groups for discussion
944purposes.</p></div>
945<div class="sect2">
946<h3 id="_basic_command_messages">Basic Command Messages</h3>
Junio C Hamano2267da52019-12-18 23:09:43[diff] [blame]947<div class="paragraph"><p>These are concerned with the lifetime of the overall git process.
948e.g: <code>void trace2_initialize_clock()</code>, <code>void trace2_initialize()</code>,
949<code>int trace2_is_enabled()</code>, <code>void trace2_cmd_start(int argc, const char **argv)</code>.</p></div>
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]950</div>
951<div class="sect2">
952<h3 id="_command_detail_messages">Command Detail Messages</h3>
953<div class="paragraph"><p>These are concerned with describing the specific Git command
Junio C Hamano2267da52019-12-18 23:09:43[diff] [blame]954after the command line, config, and environment are inspected.
955e.g: <code>void trace2_cmd_name(const char *name)</code>,
956<code>void trace2_cmd_mode(const char *mode)</code>.</p></div>
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]957</div>
958<div class="sect2">
959<h3 id="_child_process_messages">Child Process Messages</h3>
960<div class="paragraph"><p>These are concerned with the various spawned child processes,
961including shell scripts, git commands, editors, pagers, and hooks.</p></div>
Junio C Hamano2267da52019-12-18 23:09:43[diff] [blame]962<div class="paragraph"><p>e.g: <code>void trace2_child_start(struct child_process *cmd)</code>.</p></div>
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]963</div>
964<div class="sect2">
965<h3 id="_git_thread_messages">Git Thread Messages</h3>
966<div class="paragraph"><p>These messages are concerned with Git thread usage.</p></div>
Junio C Hamano2267da52019-12-18 23:09:43[diff] [blame]967<div class="paragraph"><p>e.g: <code>void trace2_thread_start(const char *thread_name)</code>.</p></div>
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]968</div>
969<div class="sect2">
970<h3 id="_region_and_data_messages">Region and Data Messages</h3>
971<div class="paragraph"><p>These are concerned with recording performance data
Junio C Hamano2267da52019-12-18 23:09:43[diff] [blame]972over regions or spans of code. e.g:
973<code>void trace2_region_enter(const char *category, const char *label, const struct repository *repo)</code>.</p></div>
974<div class="paragraph"><p>Refer to trace2.h for details about all trace2 functions.</p></div>
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]975</div>
976</div>
977</div>
978<div class="sect1">
979<h2 id="_trace2_target_formats">Trace2 Target Formats</h2>
980<div class="sectionbody">
981<div class="sect2">
982<h3 id="_normal_format">NORMAL Format</h3>
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]983<div class="paragraph"><p>Events are written as lines of the form:</p></div>
984<div class="listingblock">
985<div class="content">
986<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>
987</div></div>
988<div class="dlist"><dl>
989<dt class="hdlist1">
990<code>&lt;event-name&gt;</code>
991</dt>
992<dd>
993<p>
994 is the event name.
995</p>
996</dd>
997<dt class="hdlist1">
998<code>&lt;event-message&gt;</code>
999</dt>
1000<dd>
1001<p>
1002 is a free-form printf message intended for human consumption.
1003</p>
1004<div class="paragraph"><p>Note that this may contain embedded LF or CRLF characters that are
1005not escaped, so the event may spill across multiple lines.</p></div>
1006</dd>
1007</dl></div>
Junio C Hamanoc01eecf2019-05-30 18:17:47[diff] [blame]1008<div class="paragraph"><p>If <code>GIT_TRACE2_BRIEF</code> or <code>trace2.normalBrief</code> is true, the <code>time</code>, <code>filename</code>,
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]1009and <code>line</code> fields are omitted.</p></div>
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1010<div class="paragraph"><p>This target is intended to be more of a summary (like GIT_TRACE) and
1011less detailed than the other targets. It ignores thread, region, and
1012data messages, for example.</p></div>
1013</div>
1014<div class="sect2">
1015<h3 id="_perf_format">PERF Format</h3>
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1016<div class="paragraph"><p>Events are written as lines of the form:</p></div>
1017<div class="listingblock">
1018<div class="content">
1019<pre><code>[&lt;time&gt; SP &lt;filename&gt;:&lt;line&gt; SP+
1020 BAR SP] d&lt;depth&gt; SP
1021 BAR SP &lt;thread-name&gt; SP+
1022 BAR SP &lt;event-name&gt; SP+
1023 BAR SP [r&lt;repo-id&gt;] SP+
1024 BAR SP [&lt;t_abs&gt;] SP+
1025 BAR SP [&lt;t_rel&gt;] SP+
1026 BAR SP [&lt;category&gt;] SP+
1027 BAR SP DOTS* &lt;perf-event-message&gt;
1028 LF</code></pre>
1029</div></div>
1030<div class="dlist"><dl>
1031<dt class="hdlist1">
1032<code>&lt;depth&gt;</code>
1033</dt>
1034<dd>
1035<p>
1036 is the git process depth. This is the number of parent
1037 git processes. A top-level git command has depth value "d0".
1038 A child of it has depth value "d1". A second level child
1039 has depth value "d2" and so on.
1040</p>
1041</dd>
1042<dt class="hdlist1">
1043<code>&lt;thread-name&gt;</code>
1044</dt>
1045<dd>
1046<p>
1047 is a unique name for the thread. The primary thread
1048 is called "main". Other thread names are of the form "th%d:%s"
1049 and include a unique number and the name of the thread-proc.
1050</p>
1051</dd>
1052<dt class="hdlist1">
1053<code>&lt;event-name&gt;</code>
1054</dt>
1055<dd>
1056<p>
1057 is the event name.
1058</p>
1059</dd>
1060<dt class="hdlist1">
1061<code>&lt;repo-id&gt;</code>
1062</dt>
1063<dd>
1064<p>
1065 when present, is a number indicating the repository
1066 in use. A <code>def_repo</code> event is emitted when a repository is
1067 opened. This defines the repo-id and associated worktree.
1068 Subsequent repo-specific events will reference this repo-id.
1069</p>
1070<div class="paragraph"><p>Currently, this is always "r1" for the main repository.
1071This field is in anticipation of in-proc submodules in the future.</p></div>
1072</dd>
1073<dt class="hdlist1">
1074<code>&lt;t_abs&gt;</code>
1075</dt>
1076<dd>
1077<p>
1078 when present, is the absolute time in seconds since the
1079 program started.
1080</p>
1081</dd>
1082<dt class="hdlist1">
1083<code>&lt;t_rel&gt;</code>
1084</dt>
1085<dd>
1086<p>
1087 when present, is time in seconds relative to the start of
1088 the current region. For a thread-exit event, it is the elapsed
1089 time of the thread.
1090</p>
1091</dd>
1092<dt class="hdlist1">
1093<code>&lt;category&gt;</code>
1094</dt>
1095<dd>
1096<p>
1097 is present on region and data events and is used to
1098 indicate a broad category, such as "index" or "status".
1099</p>
1100</dd>
1101<dt class="hdlist1">
1102<code>&lt;perf-event-message&gt;</code>
1103</dt>
1104<dd>
1105<p>
1106 is a free-form printf message intended for human consumption.
1107</p>
1108</dd>
1109</dl></div>
1110<div class="listingblock">
1111<div class="content">
1112<pre><code>15:33:33.532712 wt-status.c:2310 | d0 | main | region_enter | r1 | 0.126064 | | status | label:print
111315:33:33.532712 wt-status.c:2331 | d0 | main | region_leave | r1 | 0.127568 | 0.001504 | status | label:print</code></pre>
1114</div></div>
Junio C Hamanoc01eecf2019-05-30 18:17:47[diff] [blame]1115<div class="paragraph"><p>If <code>GIT_TRACE2_PERF_BRIEF</code> or <code>trace2.perfBrief</code> is true, the <code>time</code>, <code>file</code>,
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]1116and <code>line</code> fields are omitted.</p></div>
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1117<div class="listingblock">
1118<div class="content">
1119<pre><code>d0 | main | region_leave | r1 | 0.011717 | 0.009122 | index | label:preload</code></pre>
1120</div></div>
1121<div class="paragraph"><p>The PERF target is intended for interactive performance analysis
1122during development and is quite noisy.</p></div>
1123</div>
1124<div class="sect2">
1125<h3 id="_event_format">EVENT Format</h3>
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1126<div class="paragraph"><p>Each event is a JSON-object containing multiple key/value pairs
1127written as a single line and followed by a LF.</p></div>
1128<div class="listingblock">
1129<div class="content">
1130<pre><code>'{' &lt;key&gt; ':' &lt;value&gt; [',' &lt;key&gt; ':' &lt;value&gt;]* '}' LF</code></pre>
1131</div></div>
1132<div class="paragraph"><p>Some key/value pairs are common to all events and some are
1133event-specific.</p></div>
1134<div class="sect3">
1135<h4 id="_common_key_value_pairs">Common Key/Value Pairs</h4>
1136<div class="paragraph"><p>The following key/value pairs are common to all events:</p></div>
1137<div class="listingblock">
1138<div class="content">
1139<pre><code>{
1140 "event":"version",
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]1141 "sid":"20190408T191827.272759Z-H9b68c35f-P00003510",
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1142 "thread":"main",
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]1143 "time":"2019-04-08T19:18:27.282761Z",
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1144 "file":"common-main.c",
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]1145 "line":42,
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1146 ...
1147}</code></pre>
1148</div></div>
1149<div class="dlist"><dl>
1150<dt class="hdlist1">
1151<code>"event":&lt;event&gt;</code>
1152</dt>
1153<dd>
1154<p>
1155 is the event name.
1156</p>
1157</dd>
1158<dt class="hdlist1">
1159<code>"sid":&lt;sid&gt;</code>
1160</dt>
1161<dd>
1162<p>
1163 is the session-id. This is a unique string to identify the
1164 process instance to allow all events emitted by a process to
1165 be identified. A session-id is used instead of a PID because
1166 PIDs are recycled by the OS. For child git processes, the
1167 session-id is prepended with the session-id of the parent git
1168 process to allow parent-child relationships to be identified
1169 during post-processing.
1170</p>
1171</dd>
1172<dt class="hdlist1">
1173<code>"thread":&lt;thread&gt;</code>
1174</dt>
1175<dd>
1176<p>
1177 is the thread name.
1178</p>
1179</dd>
1180<dt class="hdlist1">
1181<code>"time":&lt;time&gt;</code>
1182</dt>
1183<dd>
1184<p>
1185 is the UTC time of the event.
1186</p>
1187</dd>
1188<dt class="hdlist1">
1189<code>"file":&lt;filename&gt;</code>
1190</dt>
1191<dd>
1192<p>
1193 is source file generating the event.
1194</p>
1195</dd>
1196<dt class="hdlist1">
1197<code>"line":&lt;line-number&gt;</code>
1198</dt>
1199<dd>
1200<p>
1201 is the integer source line number generating the event.
1202</p>
1203</dd>
1204<dt class="hdlist1">
1205<code>"repo":&lt;repo-id&gt;</code>
1206</dt>
1207<dd>
1208<p>
1209 when present, is the integer repo-id as described previously.
1210</p>
1211</dd>
1212</dl></div>
Junio C Hamanoc01eecf2019-05-30 18:17:47[diff] [blame]1213<div class="paragraph"><p>If <code>GIT_TRACE2_EVENT_BRIEF</code> or <code>trace2.eventBrief</code> is true, the <code>file</code>
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]1214and <code>line</code> fields are omitted from all events and the <code>time</code> field is
1215only present on the "start" and "atexit" events.</p></div>
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1216</div>
1217<div class="sect3">
1218<h4 id="_event_specific_key_value_pairs">Event-Specific Key/Value Pairs</h4>
1219<div class="dlist"><dl>
1220<dt class="hdlist1">
1221<code>"version"</code>
1222</dt>
1223<dd>
1224<p>
Junio C Hamanofa2a48b2019-10-15 05:24:40[diff] [blame]1225 This event gives the version of the executable and the EVENT format. It
1226 should always be the first event in a trace session. The EVENT format
1227 version will be incremented if new event types are added, if existing
1228 fields are removed, or if there are significant changes in
1229 interpretation of existing events or fields. Smaller changes, such as
1230 adding a new field to an existing event, will not require an increment
1231 to the EVENT format version.
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1232</p>
1233<div class="listingblock">
1234<div class="content">
1235<pre><code>{
1236 "event":"version",
1237 ...
Junio C Hamanofa2a48b2019-10-15 05:24:40[diff] [blame]1238 "evt":"2", # EVENT format version
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1239 "exe":"2.20.1.155.g426c96fcdb" # git version
1240}</code></pre>
1241</div></div>
1242</dd>
1243<dt class="hdlist1">
Junio C Hamanofa2a48b2019-10-15 05:24:40[diff] [blame]1244<code>"discard"</code>
1245</dt>
1246<dd>
1247<p>
1248 This event is written to the git-trace2-discard sentinel file if there
1249 are too many files in the target trace directory (see the
1250 trace2.maxFiles config option).
1251</p>
1252<div class="listingblock">
1253<div class="content">
1254<pre><code>{
1255 "event":"discard",
1256 ...
1257}</code></pre>
1258</div></div>
1259</dd>
1260<dt class="hdlist1">
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1261<code>"start"</code>
1262</dt>
1263<dd>
1264<p>
1265 This event contains the complete argv received by main().
1266</p>
1267<div class="listingblock">
1268<div class="content">
1269<pre><code>{
1270 "event":"start",
1271 ...
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]1272 "t_abs":0.001227, # elapsed time in seconds
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1273 "argv":["git","version"]
1274}</code></pre>
1275</div></div>
1276</dd>
1277<dt class="hdlist1">
1278<code>"exit"</code>
1279</dt>
1280<dd>
1281<p>
1282 This event is emitted when git calls <code>exit()</code>.
1283</p>
1284<div class="listingblock">
1285<div class="content">
1286<pre><code>{
1287 "event":"exit",
1288 ...
1289 "t_abs":0.001227, # elapsed time in seconds
1290 "code":0 # exit code
1291}</code></pre>
1292</div></div>
1293</dd>
1294<dt class="hdlist1">
1295<code>"atexit"</code>
1296</dt>
1297<dd>
1298<p>
1299 This event is emitted by the Trace2 <code>atexit</code> routine during
1300 final shutdown. It should be the last event emitted by the
1301 process.
1302</p>
1303<div class="paragraph"><p>(The elapsed time reported here is greater than the time reported in
1304the "exit" event because it runs after all other atexit tasks have
1305completed.)</p></div>
1306<div class="listingblock">
1307<div class="content">
1308<pre><code>{
1309 "event":"atexit",
1310 ...
1311 "t_abs":0.001227, # elapsed time in seconds
1312 "code":0 # exit code
1313}</code></pre>
1314</div></div>
1315</dd>
1316<dt class="hdlist1">
1317<code>"signal"</code>
1318</dt>
1319<dd>
1320<p>
1321 This event is emitted when the program is terminated by a user
1322 signal. Depending on the platform, the signal event may
1323 prevent the "atexit" event from being generated.
1324</p>
1325<div class="listingblock">
1326<div class="content">
1327<pre><code>{
1328 "event":"signal",
1329 ...
1330 "t_abs":0.001227, # elapsed time in seconds
Junio C Hamanoa42e0332019-07-19 19:49:37[diff] [blame]1331 "signo":13 # SIGTERM, SIGINT, etc.
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1332}</code></pre>
1333</div></div>
1334</dd>
1335<dt class="hdlist1">
1336<code>"error"</code>
1337</dt>
1338<dd>
1339<p>
Junio C Hamano4078a552021-04-30 06:08:10[diff] [blame]1340 This event is emitted when one of the <code>BUG()</code>, <code>error()</code>, <code>die()</code>,
Junio C Hamano992fbdc2020-12-09 00:14:29[diff] [blame]1341 <code>warning()</code>, or <code>usage()</code> functions are called.
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1342</p>
1343<div class="listingblock">
1344<div class="content">
1345<pre><code>{
1346 "event":"error",
1347 ...
1348 "msg":"invalid option: --cahced", # formatted error message
1349 "fmt":"invalid option: %s" # error format string
1350}</code></pre>
1351</div></div>
1352<div class="paragraph"><p>The error event may be emitted more than once. The format string
1353allows post-processors to group errors by type without worrying
1354about specific error arguments.</p></div>
1355</dd>
1356<dt class="hdlist1">
1357<code>"cmd_path"</code>
1358</dt>
1359<dd>
1360<p>
1361 This event contains the discovered full path of the git
1362 executable (on platforms that are configured to resolve it).
1363</p>
1364<div class="listingblock">
1365<div class="content">
1366<pre><code>{
1367 "event":"cmd_path",
1368 ...
1369 "path":"C:/work/gfw/git.exe"
1370}</code></pre>
1371</div></div>
1372</dd>
1373<dt class="hdlist1">
1374<code>"cmd_name"</code>
1375</dt>
1376<dd>
1377<p>
1378 This event contains the command name for this git process
1379 and the hierarchy of commands from parent git processes.
1380</p>
1381<div class="listingblock">
1382<div class="content">
1383<pre><code>{
1384 "event":"cmd_name",
1385 ...
1386 "name":"pack-objects",
1387 "hierarchy":"push/pack-objects"
1388}</code></pre>
1389</div></div>
1390<div class="paragraph"><p>Normally, the "name" field contains the canonical name of the
1391command. When a canonical name is not available, one of
1392these special values are used:</p></div>
1393<div class="listingblock">
1394<div class="content">
1395<pre><code>"_query_" # "git --html-path"
1396"_run_dashed_" # when "git foo" tries to run "git-foo"
1397"_run_shell_alias_" # alias expansion to a shell command
1398"_run_git_alias_" # alias expansion to a git command
1399"_usage_" # usage error</code></pre>
1400</div></div>
1401</dd>
1402<dt class="hdlist1">
1403<code>"cmd_mode"</code>
1404</dt>
1405<dd>
1406<p>
1407 This event, when present, describes the command variant This
1408 event may be emitted more than once.
1409</p>
1410<div class="listingblock">
1411<div class="content">
1412<pre><code>{
1413 "event":"cmd_mode",
1414 ...
1415 "name":"branch"
1416}</code></pre>
1417</div></div>
1418<div class="paragraph"><p>The "name" field is an arbitrary string to describe the command mode.
1419For example, checkout can checkout a branch or an individual file.
1420And these variations typically have different performance
1421characteristics that are not comparable.</p></div>
1422</dd>
1423<dt class="hdlist1">
1424<code>"alias"</code>
1425</dt>
1426<dd>
1427<p>
1428 This event is present when an alias is expanded.
1429</p>
1430<div class="listingblock">
1431<div class="content">
1432<pre><code>{
1433 "event":"alias",
1434 ...
1435 "alias":"l", # registered alias
1436 "argv":["log","--graph"] # alias expansion
1437}</code></pre>
1438</div></div>
1439</dd>
1440<dt class="hdlist1">
1441<code>"child_start"</code>
1442</dt>
1443<dd>
1444<p>
1445 This event describes a child process that is about to be
1446 spawned.
1447</p>
1448<div class="listingblock">
1449<div class="content">
1450<pre><code>{
1451 "event":"child_start",
1452 ...
1453 "child_id":2,
1454 "child_class":"?",
1455 "use_shell":false,
1456 "argv":["git","rev-list","--objects","--stdin","--not","--all","--quiet"]
1457
1458 "hook_name":"&lt;hook_name&gt;" # present when child_class is "hook"
1459 "cd":"&lt;path&gt;" # present when cd is required
1460}</code></pre>
1461</div></div>
1462<div class="paragraph"><p>The "child_id" field can be used to match this child_start with the
1463corresponding child_exit event.</p></div>
1464<div class="paragraph"><p>The "child_class" field is a rough classification, such as "editor",
1465"pager", "transport/*", and "hook". Unclassified children are classified
1466with "?".</p></div>
1467</dd>
1468<dt class="hdlist1">
1469<code>"child_exit"</code>
1470</dt>
1471<dd>
1472<p>
1473 This event is generated after the current process has returned
1474 from the waitpid() and collected the exit information from the
1475 child.
1476</p>
1477<div class="listingblock">
1478<div class="content">
1479<pre><code>{
1480 "event":"child_exit",
1481 ...
1482 "child_id":2,
1483 "pid":14708, # child PID
1484 "code":0, # child exit-code
1485 "t_rel":0.110605 # observed run-time of child process
1486}</code></pre>
1487</div></div>
1488<div class="paragraph"><p>Note that the session-id of the child process is not available to
1489the current/spawning process, so the child&#8217;s PID is reported here as
1490a hint for post-processing. (But it is only a hint because the child
Junio C Hamano8ef91f32019-12-01 22:58:27[diff] [blame]1491process may be a shell script which doesn&#8217;t have a session-id.)</p></div>
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1492<div class="paragraph"><p>Note that the <code>t_rel</code> field contains the observed run time in seconds
1493for the child process (starting before the fork/exec/spawn and
1494stopping after the waitpid() and includes OS process creation overhead).
1495So this time will be slightly larger than the atexit time reported by
1496the child process itself.</p></div>
1497</dd>
1498<dt class="hdlist1">
1499<code>"exec"</code>
1500</dt>
1501<dd>
1502<p>
1503 This event is generated before git attempts to <code>exec()</code>
1504 another command rather than starting a child process.
1505</p>
1506<div class="listingblock">
1507<div class="content">
1508<pre><code>{
1509 "event":"exec",
1510 ...
1511 "exec_id":0,
1512 "exe":"git",
1513 "argv":["foo", "bar"]
1514}</code></pre>
1515</div></div>
1516<div class="paragraph"><p>The "exec_id" field is a command-unique id and is only useful if the
1517<code>exec()</code> fails and a corresponding exec_result event is generated.</p></div>
1518</dd>
1519<dt class="hdlist1">
1520<code>"exec_result"</code>
1521</dt>
1522<dd>
1523<p>
1524 This event is generated if the <code>exec()</code> fails and control
1525 returns to the current git command.
1526</p>
1527<div class="listingblock">
1528<div class="content">
1529<pre><code>{
1530 "event":"exec_result",
1531 ...
1532 "exec_id":0,
1533 "code":1 # error code (errno) from exec()
1534}</code></pre>
1535</div></div>
1536</dd>
1537<dt class="hdlist1">
1538<code>"thread_start"</code>
1539</dt>
1540<dd>
1541<p>
1542 This event is generated when a thread is started. It is
1543 generated from <strong>within</strong> the new thread&#8217;s thread-proc (for TLS
1544 reasons).
1545</p>
1546<div class="listingblock">
1547<div class="content">
1548<pre><code>{
1549 "event":"thread_start",
1550 ...
1551 "thread":"th02:preload_thread" # thread name
1552}</code></pre>
1553</div></div>
1554</dd>
1555<dt class="hdlist1">
1556<code>"thread_exit"</code>
1557</dt>
1558<dd>
1559<p>
1560 This event is generated when a thread exits. It is generated
1561 from <strong>within</strong> the thread&#8217;s thread-proc (for TLS reasons).
1562</p>
1563<div class="listingblock">
1564<div class="content">
1565<pre><code>{
1566 "event":"thread_exit",
1567 ...
1568 "thread":"th02:preload_thread", # thread name
1569 "t_rel":0.007328 # thread elapsed time
1570}</code></pre>
1571</div></div>
1572</dd>
1573<dt class="hdlist1">
1574<code>"def_param"</code>
1575</dt>
1576<dd>
1577<p>
Junio C Hamano67bf2242020-04-22 21:41:44[diff] [blame]1578 This event is generated to log a global parameter, such as a config
1579 setting, command-line flag, or environment variable.
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1580</p>
1581<div class="listingblock">
1582<div class="content">
1583<pre><code>{
1584 "event":"def_param",
1585 ...
1586 "param":"core.abbrev",
1587 "value":"7"
1588}</code></pre>
1589</div></div>
1590</dd>
1591<dt class="hdlist1">
1592<code>"def_repo"</code>
1593</dt>
1594<dd>
1595<p>
1596 This event defines a repo-id and associates it with the root
1597 of the worktree.
1598</p>
1599<div class="listingblock">
1600<div class="content">
1601<pre><code>{
1602 "event":"def_repo",
1603 ...
1604 "repo":1,
1605 "worktree":"/Users/jeffhost/work/gfw"
1606}</code></pre>
1607</div></div>
1608<div class="paragraph"><p>As stated earlier, the repo-id is currently always 1, so there will
1609only be one def_repo event. Later, if in-proc submodules are
1610supported, a def_repo event should be emitted for each submodule
1611visited.</p></div>
1612</dd>
1613<dt class="hdlist1">
1614<code>"region_enter"</code>
1615</dt>
1616<dd>
1617<p>
1618 This event is generated when entering a region.
1619</p>
1620<div class="listingblock">
1621<div class="content">
1622<pre><code>{
1623 "event":"region_enter",
1624 ...
1625 "repo":1, # optional
1626 "nesting":1, # current region stack depth
1627 "category":"index", # optional
1628 "label":"do_read_index", # optional
1629 "msg":".git/index" # optional
1630}</code></pre>
1631</div></div>
1632<div class="paragraph"><p>The <code>category</code> field may be used in a future enhancement to
1633do category-based filtering.</p></div>
Junio C Hamanoc01eecf2019-05-30 18:17:47[diff] [blame]1634<div class="paragraph"><p><code>GIT_TRACE2_EVENT_NESTING</code> or <code>trace2.eventNesting</code> can be used to
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1635filter deeply nested regions and data events. It defaults to "2".</p></div>
1636</dd>
1637<dt class="hdlist1">
1638<code>"region_leave"</code>
1639</dt>
1640<dd>
1641<p>
1642 This event is generated when leaving a region.
1643</p>
1644<div class="listingblock">
1645<div class="content">
1646<pre><code>{
1647 "event":"region_leave",
1648 ...
1649 "repo":1, # optional
1650 "t_rel":0.002876, # time spent in region in seconds
1651 "nesting":1, # region stack depth
1652 "category":"index", # optional
1653 "label":"do_read_index", # optional
1654 "msg":".git/index" # optional
1655}</code></pre>
1656</div></div>
1657</dd>
1658<dt class="hdlist1">
1659<code>"data"</code>
1660</dt>
1661<dd>
1662<p>
1663 This event is generated to log a thread- and region-local
1664 key/value pair.
1665</p>
1666<div class="listingblock">
1667<div class="content">
1668<pre><code>{
1669 "event":"data",
1670 ...
1671 "repo":1, # optional
1672 "t_abs":0.024107, # absolute elapsed time
1673 "t_rel":0.001031, # elapsed time in region/thread
1674 "nesting":2, # region stack depth
1675 "category":"index",
1676 "key":"read/cache_nr",
1677 "value":"3552"
1678}</code></pre>
1679</div></div>
1680<div class="paragraph"><p>The "value" field may be an integer or a string.</p></div>
1681</dd>
1682<dt class="hdlist1">
1683<code>"data-json"</code>
1684</dt>
1685<dd>
1686<p>
1687 This event is generated to log a pre-formatted JSON string
1688 containing structured data.
1689</p>
1690<div class="listingblock">
1691<div class="content">
1692<pre><code>{
1693 "event":"data_json",
1694 ...
1695 "repo":1, # optional
1696 "t_abs":0.015905,
1697 "t_rel":0.015905,
1698 "nesting":1,
1699 "category":"process",
1700 "key":"windows/ancestry",
1701 "value":["bash.exe","bash.exe"]
1702}</code></pre>
1703</div></div>
1704</dd>
1705</dl></div>
1706</div>
1707</div>
1708</div>
1709</div>
1710<div class="sect1">
1711<h2 id="_example_trace2_api_usage">Example Trace2 API Usage</h2>
1712<div class="sectionbody">
1713<div class="paragraph"><p>Here is a hypothetical usage of the Trace2 API showing the intended
1714usage (without worrying about the actual Git details).</p></div>
1715<div class="dlist"><dl>
1716<dt class="hdlist1">
1717Initialization
1718</dt>
1719<dd>
1720<p>
1721 Initialization happens in <code>main()</code>. Behind the scenes, an
1722 <code>atexit</code> and <code>signal</code> handler are registered.
1723</p>
1724<div class="listingblock">
1725<div class="content">
1726<pre><code>int main(int argc, const char **argv)
1727{
1728 int exit_code;
1729
1730 trace2_initialize();
1731 trace2_cmd_start(argv);
1732
1733 exit_code = cmd_main(argc, argv);
1734
1735 trace2_cmd_exit(exit_code);
1736
1737 return exit_code;
1738}</code></pre>
1739</div></div>
1740</dd>
1741<dt class="hdlist1">
1742Command Details
1743</dt>
1744<dd>
1745<p>
1746 After the basics are established, additional command
1747 information can be sent to Trace2 as it is discovered.
1748</p>
1749<div class="listingblock">
1750<div class="content">
1751<pre><code>int cmd_checkout(int argc, const char **argv)
1752{
1753 trace2_cmd_name("checkout");
1754 trace2_cmd_mode("branch");
1755 trace2_def_repo(the_repository);
1756
1757 // emit "def_param" messages for "interesting" config settings.
1758 trace2_cmd_list_config();
1759
1760 if (do_something())
1761 trace2_cmd_error("Path '%s': cannot do something", path);
1762
1763 return 0;
1764}</code></pre>
1765</div></div>
1766</dd>
1767<dt class="hdlist1">
1768Child Processes
1769</dt>
1770<dd>
1771<p>
1772 Wrap code spawning child processes.
1773</p>
1774<div class="listingblock">
1775<div class="content">
1776<pre><code>void run_child(...)
1777{
1778 int child_exit_code;
1779 struct child_process cmd = CHILD_PROCESS_INIT;
1780 ...
1781 cmd.trace2_child_class = "editor";
1782
1783 trace2_child_start(&amp;cmd);
1784 child_exit_code = spawn_child_and_wait_for_it();
1785 trace2_child_exit(&amp;cmd, child_exit_code);
1786}</code></pre>
1787</div></div>
1788<div class="paragraph"><p>For example, the following fetch command spawned ssh, index-pack,
1789rev-list, and gc. This example also shows that fetch took
17905.199 seconds and of that 4.932 was in ssh.</p></div>
1791<div class="listingblock">
1792<div class="content">
Junio C Hamanoc01eecf2019-05-30 18:17:47[diff] [blame]1793<pre><code>$ export GIT_TRACE2_BRIEF=1
1794$ export GIT_TRACE2=~/log.normal
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1795$ git fetch origin
1796...</code></pre>
1797</div></div>
1798<div class="listingblock">
1799<div class="content">
1800<pre><code>$ cat ~/log.normal
1801version 2.20.1.vfs.1.1.47.g534dbe1ad1
1802start git fetch origin
1803worktree /Users/jeffhost/work/gfw
1804cmd_name fetch (fetch)
1805child_start[0] ssh git@github.com ...
1806child_start[1] git index-pack ...
1807... (Trace2 events from child processes omitted)
1808child_exit[1] pid:14707 code:0 elapsed:0.076353
1809child_exit[0] pid:14706 code:0 elapsed:4.931869
1810child_start[2] git rev-list ...
1811... (Trace2 events from child process omitted)
1812child_exit[2] pid:14708 code:0 elapsed:0.110605
1813child_start[3] git gc --auto
1814... (Trace2 events from child process omitted)
1815child_exit[3] pid:14709 code:0 elapsed:0.006240
1816exit elapsed:5.198503 code:0
1817atexit elapsed:5.198541 code:0</code></pre>
1818</div></div>
1819<div class="paragraph"><p>When a git process is a (direct or indirect) child of another
1820git process, it inherits Trace2 context information. This
1821allows the child to print the command hierarchy. This example
1822shows gc as child[3] of fetch. When the gc process reports
1823its name as "gc", it also reports the hierarchy as "fetch/gc".
1824(In this example, trace2 messages from the child process is
1825indented for clarity.)</p></div>
1826<div class="listingblock">
1827<div class="content">
Junio C Hamanoc01eecf2019-05-30 18:17:47[diff] [blame]1828<pre><code>$ export GIT_TRACE2_BRIEF=1
1829$ export GIT_TRACE2=~/log.normal
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1830$ git fetch origin
1831...</code></pre>
1832</div></div>
1833<div class="listingblock">
1834<div class="content">
1835<pre><code>$ cat ~/log.normal
1836version 2.20.1.160.g5676107ecd.dirty
1837start git fetch official
1838worktree /Users/jeffhost/work/gfw
1839cmd_name fetch (fetch)
1840...
1841child_start[3] git gc --auto
1842 version 2.20.1.160.g5676107ecd.dirty
1843 start /Users/jeffhost/work/gfw/git gc --auto
1844 worktree /Users/jeffhost/work/gfw
1845 cmd_name gc (fetch/gc)
1846 exit elapsed:0.001959 code:0
1847 atexit elapsed:0.001997 code:0
1848child_exit[3] pid:20303 code:0 elapsed:0.007564
1849exit elapsed:3.868938 code:0
1850atexit elapsed:3.868970 code:0</code></pre>
1851</div></div>
1852</dd>
1853<dt class="hdlist1">
1854Regions
1855</dt>
1856<dd>
1857<p>
1858 Regions can be use to time an interesting section of code.
1859</p>
1860<div class="listingblock">
1861<div class="content">
1862<pre><code>void wt_status_collect(struct wt_status *s)
1863{
1864 trace2_region_enter("status", "worktrees", s-&gt;repo);
1865 wt_status_collect_changes_worktree(s);
1866 trace2_region_leave("status", "worktrees", s-&gt;repo);
1867
1868 trace2_region_enter("status", "index", s-&gt;repo);
1869 wt_status_collect_changes_index(s);
1870 trace2_region_leave("status", "index", s-&gt;repo);
1871
1872 trace2_region_enter("status", "untracked", s-&gt;repo);
1873 wt_status_collect_untracked(s);
1874 trace2_region_leave("status", "untracked", s-&gt;repo);
1875}
1876
1877void wt_status_print(struct wt_status *s)
1878{
1879 trace2_region_enter("status", "print", s-&gt;repo);
1880 switch (s-&gt;status_format) {
1881 ...
1882 }
1883 trace2_region_leave("status", "print", s-&gt;repo);
1884}</code></pre>
1885</div></div>
1886<div class="paragraph"><p>In this example, scanning for untracked files ran from +0.012568 to
1887+0.027149 (since the process started) and took 0.014581 seconds.</p></div>
1888<div class="listingblock">
1889<div class="content">
Junio C Hamanoc01eecf2019-05-30 18:17:47[diff] [blame]1890<pre><code>$ export GIT_TRACE2_PERF_BRIEF=1
1891$ export GIT_TRACE2_PERF=~/log.perf
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1892$ git status
1893...
1894
1895$ cat ~/log.perf
1896d0 | main | version | | | | | 2.20.1.160.g5676107ecd.dirty
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]1897d0 | main | start | | 0.001173 | | | git status
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1898d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
1899d0 | main | cmd_name | | | | | status (status)
1900...
1901d0 | main | region_enter | r1 | 0.010988 | | status | label:worktrees
1902d0 | main | region_leave | r1 | 0.011236 | 0.000248 | status | label:worktrees
1903d0 | main | region_enter | r1 | 0.011260 | | status | label:index
1904d0 | main | region_leave | r1 | 0.012542 | 0.001282 | status | label:index
1905d0 | main | region_enter | r1 | 0.012568 | | status | label:untracked
1906d0 | main | region_leave | r1 | 0.027149 | 0.014581 | status | label:untracked
1907d0 | main | region_enter | r1 | 0.027411 | | status | label:print
1908d0 | main | region_leave | r1 | 0.028741 | 0.001330 | status | label:print
1909d0 | main | exit | | 0.028778 | | | code:0
1910d0 | main | atexit | | 0.028809 | | | code:0</code></pre>
1911</div></div>
1912<div class="paragraph"><p>Regions may be nested. This causes messages to be indented in the
1913PERF target, for example.
Junio C Hamano8ef91f32019-12-01 22:58:27[diff] [blame]1914Elapsed times are relative to the start of the corresponding nesting
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1915level as expected. For example, if we add region message to:</p></div>
1916<div class="listingblock">
1917<div class="content">
1918<pre><code>static enum path_treatment read_directory_recursive(struct dir_struct *dir,
1919 struct index_state *istate, const char *base, int baselen,
1920 struct untracked_cache_dir *untracked, int check_only,
1921 int stop_at_first_file, const struct pathspec *pathspec)
1922{
1923 enum path_treatment state, subdir_state, dir_state = path_none;
1924
1925 trace2_region_enter_printf("dir", "read_recursive", NULL, "%.*s", baselen, base);
1926 ...
1927 trace2_region_leave_printf("dir", "read_recursive", NULL, "%.*s", baselen, base);
1928 return dir_state;
1929}</code></pre>
1930</div></div>
1931<div class="paragraph"><p>We can further investigate the time spent scanning for untracked files.</p></div>
1932<div class="listingblock">
1933<div class="content">
Junio C Hamanoc01eecf2019-05-30 18:17:47[diff] [blame]1934<pre><code>$ export GIT_TRACE2_PERF_BRIEF=1
1935$ export GIT_TRACE2_PERF=~/log.perf
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1936$ git status
1937...
1938$ cat ~/log.perf
1939d0 | main | version | | | | | 2.20.1.162.gb4ccea44db.dirty
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]1940d0 | main | start | | 0.001173 | | | git status
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1941d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
1942d0 | main | cmd_name | | | | | status (status)
1943...
1944d0 | main | region_enter | r1 | 0.015047 | | status | label:untracked
1945d0 | main | region_enter | | 0.015132 | | dir | ..label:read_recursive
1946d0 | main | region_enter | | 0.016341 | | dir | ....label:read_recursive vcs-svn/
1947d0 | main | region_leave | | 0.016422 | 0.000081 | dir | ....label:read_recursive vcs-svn/
1948d0 | main | region_enter | | 0.016446 | | dir | ....label:read_recursive xdiff/
1949d0 | main | region_leave | | 0.016522 | 0.000076 | dir | ....label:read_recursive xdiff/
1950d0 | main | region_enter | | 0.016612 | | dir | ....label:read_recursive git-gui/
1951d0 | main | region_enter | | 0.016698 | | dir | ......label:read_recursive git-gui/po/
1952d0 | main | region_enter | | 0.016810 | | dir | ........label:read_recursive git-gui/po/glossary/
1953d0 | main | region_leave | | 0.016863 | 0.000053 | dir | ........label:read_recursive git-gui/po/glossary/
1954...
1955d0 | main | region_enter | | 0.031876 | | dir | ....label:read_recursive builtin/
1956d0 | main | region_leave | | 0.032270 | 0.000394 | dir | ....label:read_recursive builtin/
1957d0 | main | region_leave | | 0.032414 | 0.017282 | dir | ..label:read_recursive
1958d0 | main | region_leave | r1 | 0.032454 | 0.017407 | status | label:untracked
1959...
1960d0 | main | exit | | 0.034279 | | | code:0
1961d0 | main | atexit | | 0.034322 | | | code:0</code></pre>
1962</div></div>
1963<div class="paragraph"><p>Trace2 regions are similar to the existing trace_performance_enter()
1964and trace_performance_leave() routines, but are thread safe and
1965maintain per-thread stacks of timers.</p></div>
1966</dd>
1967<dt class="hdlist1">
1968Data Messages
1969</dt>
1970<dd>
1971<p>
1972 Data messages added to a region.
1973</p>
1974<div class="listingblock">
1975<div class="content">
1976<pre><code>int read_index_from(struct index_state *istate, const char *path,
1977 const char *gitdir)
1978{
1979 trace2_region_enter_printf("index", "do_read_index", the_repository, "%s", path);
1980
1981 ...
1982
1983 trace2_data_intmax("index", the_repository, "read/version", istate-&gt;version);
1984 trace2_data_intmax("index", the_repository, "read/cache_nr", istate-&gt;cache_nr);
1985
1986 trace2_region_leave_printf("index", "do_read_index", the_repository, "%s", path);
1987}</code></pre>
1988</div></div>
1989<div class="paragraph"><p>This example shows that the index contained 3552 entries.</p></div>
1990<div class="listingblock">
1991<div class="content">
Junio C Hamanoc01eecf2019-05-30 18:17:47[diff] [blame]1992<pre><code>$ export GIT_TRACE2_PERF_BRIEF=1
1993$ export GIT_TRACE2_PERF=~/log.perf
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1994$ git status
1995...
1996$ cat ~/log.perf
1997d0 | main | version | | | | | 2.20.1.156.gf9916ae094.dirty
Junio C Hamano792b6092019-05-13 16:03:59[diff] [blame]1998d0 | main | start | | 0.001173 | | | git status
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]1999d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
2000d0 | main | cmd_name | | | | | status (status)
2001d0 | main | region_enter | r1 | 0.001791 | | index | label:do_read_index .git/index
2002d0 | main | data | r1 | 0.002494 | 0.000703 | index | ..read/version:2
2003d0 | main | data | r1 | 0.002520 | 0.000729 | index | ..read/cache_nr:3552
2004d0 | main | region_leave | r1 | 0.002539 | 0.000748 | index | label:do_read_index .git/index
2005...</code></pre>
2006</div></div>
2007</dd>
2008<dt class="hdlist1">
2009Thread Events
2010</dt>
2011<dd>
2012<p>
2013 Thread messages added to a thread-proc.
2014</p>
2015<div class="paragraph"><p>For example, the multithreaded preload-index code can be
2016instrumented with a region around the thread pool and then
2017per-thread start and exit events within the threadproc.</p></div>
2018<div class="listingblock">
2019<div class="content">
2020<pre><code>static void *preload_thread(void *_data)
2021{
2022 // start the per-thread clock and emit a message.
2023 trace2_thread_start("preload_thread");
2024
2025 // report which chunk of the array this thread was assigned.
2026 trace2_data_intmax("index", the_repository, "offset", p-&gt;offset);
2027 trace2_data_intmax("index", the_repository, "count", nr);
2028
2029 do {
2030 ...
2031 } while (--nr &gt; 0);
2032 ...
2033
2034 // report elapsed time taken by this thread.
2035 trace2_thread_exit();
2036 return NULL;
2037}
2038
2039void preload_index(struct index_state *index,
2040 const struct pathspec *pathspec,
2041 unsigned int refresh_flags)
2042{
2043 trace2_region_enter("index", "preload", the_repository);
2044
2045 for (i = 0; i &lt; threads; i++) {
2046 ... /* create thread */
2047 }
2048
2049 for (i = 0; i &lt; threads; i++) {
2050 ... /* join thread */
2051 }
2052
2053 trace2_region_leave("index", "preload", the_repository);
2054}</code></pre>
2055</div></div>
2056<div class="paragraph"><p>In this example preload_index() was executed by the <code>main</code> thread
2057and started the <code>preload</code> region. Seven threads, named
2058<code>th01:preload_thread</code> through <code>th07:preload_thread</code>, were started.
2059Events from each thread are atomically appended to the shared target
2060stream as they occur so they may appear in random order with respect
2061other threads. Finally, the main thread waits for the threads to
2062finish and leaves the region.</p></div>
2063<div class="paragraph"><p>Data events are tagged with the active thread name. They are used
2064to report the per-thread parameters.</p></div>
2065<div class="listingblock">
2066<div class="content">
Junio C Hamanoc01eecf2019-05-30 18:17:47[diff] [blame]2067<pre><code>$ export GIT_TRACE2_PERF_BRIEF=1
2068$ export GIT_TRACE2_PERF=~/log.perf
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]2069$ git status
2070...
2071$ cat ~/log.perf
2072...
2073d0 | main | region_enter | r1 | 0.002595 | | index | label:preload
2074d0 | th01:preload_thread | thread_start | | 0.002699 | | |
2075d0 | th02:preload_thread | thread_start | | 0.002721 | | |
2076d0 | th01:preload_thread | data | r1 | 0.002736 | 0.000037 | index | offset:0
2077d0 | th02:preload_thread | data | r1 | 0.002751 | 0.000030 | index | offset:2032
2078d0 | th03:preload_thread | thread_start | | 0.002711 | | |
2079d0 | th06:preload_thread | thread_start | | 0.002739 | | |
2080d0 | th01:preload_thread | data | r1 | 0.002766 | 0.000067 | index | count:508
2081d0 | th06:preload_thread | data | r1 | 0.002856 | 0.000117 | index | offset:2540
2082d0 | th03:preload_thread | data | r1 | 0.002824 | 0.000113 | index | offset:1016
2083d0 | th04:preload_thread | thread_start | | 0.002710 | | |
2084d0 | th02:preload_thread | data | r1 | 0.002779 | 0.000058 | index | count:508
2085d0 | th06:preload_thread | data | r1 | 0.002966 | 0.000227 | index | count:508
2086d0 | th07:preload_thread | thread_start | | 0.002741 | | |
2087d0 | th07:preload_thread | data | r1 | 0.003017 | 0.000276 | index | offset:3048
2088d0 | th05:preload_thread | thread_start | | 0.002712 | | |
2089d0 | th05:preload_thread | data | r1 | 0.003067 | 0.000355 | index | offset:1524
2090d0 | th05:preload_thread | data | r1 | 0.003090 | 0.000378 | index | count:508
2091d0 | th07:preload_thread | data | r1 | 0.003037 | 0.000296 | index | count:504
2092d0 | th03:preload_thread | data | r1 | 0.002971 | 0.000260 | index | count:508
2093d0 | th04:preload_thread | data | r1 | 0.002983 | 0.000273 | index | offset:508
2094d0 | th04:preload_thread | data | r1 | 0.007311 | 0.004601 | index | count:508
2095d0 | th05:preload_thread | thread_exit | | 0.008781 | 0.006069 | |
2096d0 | th01:preload_thread | thread_exit | | 0.009561 | 0.006862 | |
2097d0 | th03:preload_thread | thread_exit | | 0.009742 | 0.007031 | |
2098d0 | th06:preload_thread | thread_exit | | 0.009820 | 0.007081 | |
2099d0 | th02:preload_thread | thread_exit | | 0.010274 | 0.007553 | |
2100d0 | th07:preload_thread | thread_exit | | 0.010477 | 0.007736 | |
2101d0 | th04:preload_thread | thread_exit | | 0.011657 | 0.008947 | |
2102d0 | main | region_leave | r1 | 0.011717 | 0.009122 | index | label:preload
2103...
2104d0 | main | exit | | 0.029996 | | | code:0
2105d0 | main | atexit | | 0.030027 | | | code:0</code></pre>
2106</div></div>
2107<div class="paragraph"><p>In this example, the preload region took 0.009122 seconds. The 7 threads
2108took between 0.006069 and 0.008947 seconds to work on their portion of
2109the index. Thread "th01" worked on 508 items at offset 0. Thread "th02"
Junio C Hamano8ef91f32019-12-01 22:58:27[diff] [blame]2110worked on 508 items at offset 2032. Thread "th04" worked on 508 items
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]2111at offset 508.</p></div>
2112<div class="paragraph"><p>This example also shows that thread names are assigned in a racy manner
2113as each thread starts and allocates TLS storage.</p></div>
2114</dd>
2115</dl></div>
2116</div>
2117</div>
2118<div class="sect1">
2119<h2 id="_future_work">Future Work</h2>
2120<div class="sectionbody">
2121<div class="sect2">
2122<h3 id="_relationship_to_the_existing_trace_api_api_trace_txt">Relationship to the Existing Trace Api (api-trace.txt)</h3>
2123<div class="paragraph"><p>There are a few issues to resolve before we can completely
2124switch to Trace2.</p></div>
2125<div class="ulist"><ul>
2126<li>
2127<p>
2128Updating existing tests that assume GIT_TRACE format messages.
2129</p>
2130</li>
2131<li>
2132<p>
2133How to best handle custom GIT_TRACE_&lt;key&gt; messages?
2134</p>
2135<div class="ulist"><ul>
2136<li>
2137<p>
2138The GIT_TRACE_&lt;key&gt; mechanism allows each &lt;key&gt; to write to a
2139different file (in addition to just stderr).
2140</p>
2141</li>
2142<li>
2143<p>
2144Do we want to maintain that ability or simply write to the existing
2145Trace2 targets (and convert &lt;key&gt; to a "category").
2146</p>
2147</li>
2148</ul></div>
2149</li>
2150</ul></div>
2151</div>
2152</div>
2153</div>
2154</div>
2155<div id="footnotes"><hr /></div>
2156<div id="footer">
2157<div id="footer-text">
2158Last updated
Junio C Hamano4078a552021-04-30 06:08:10[diff] [blame]2159 2021-04-30 15:03:30 JST
Junio C Hamano11f15372019-03-07 03:17:00[diff] [blame]2160</div>
2161</div>
2162</body>
2163</html>