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