technical/api-trace2.html

   1 <?xml version="1.0" encoding="UTF-8"?>
   2 <!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.1//EN"
   3     "http://www.w3.org/TR/xhtml11/DTD/xhtml11.dtd">
   4 <html xmlns="http://www.w3.org/1999/xhtml" xml:lang="en">
   5 <head>
   6 <meta http-equiv="Content-Type" content="application/xhtml+xml; charset=UTF-8" />
   7 <meta name="generator" content="AsciiDoc 10.2.0" />
   8 <title>Trace2 API</title>
   9 <style type="text/css">
  10 /* Shared CSS for AsciiDoc xhtml11 and html5 backends */
  11
  12 /* Default font. */
  13 body {
  14   font-family: Georgia,serif;
  15 }
  16
  17 /* Title font. */
  18 h1, h2, h3, h4, h5, h6,
  19 div.title, caption.title,
  20 thead, p.table.header,
  21 #toctitle,
  22 #author, #revnumber, #revdate, #revremark,
  23 #footer {
  24   font-family: Arial,Helvetica,sans-serif;
  25 }
  26
  27 body {
  28   margin: 1em 5% 1em 5%;
  29 }
  30
  31 a {
  32   color: blue;
  33   text-decoration: underline;
  34 }
  35 a:visited {
  36   color: fuchsia;
  37 }
  38
  39 em {
  40   font-style: italic;
  41   color: navy;
  42 }
  43
  44 strong {
  45   font-weight: bold;
  46   color: #083194;
  47 }
  48
  49 h1, 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
  56 h1, h2, h3 {
  57   border-bottom: 2px solid silver;
  58 }
  59 h2 {
  60   padding-top: 0.5em;
  61 }
  62 h3 {
  63   float: left;
  64 }
  65 h3 + * {
  66   clear: left;
  67 }
  68 h5 {
  69   font-size: 1.0em;
  70 }
  71
  72 div.sectionbody {
  73   margin-left: 0;
  74 }
  75
  76 hr {
  77   border: 1px solid silver;
  78 }
  79
  80 p {
  81   margin-top: 0.5em;
  82   margin-bottom: 0.5em;
  83 }
  84
  85 ul, ol, li > p {
  86   margin-top: 0;
  87 }
  88 ul > li     { color: #aaa; }
  89 ul > 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 }
  98 pre {
  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 }
 131 div.imageblock, div.exampleblock, div.verseblock,
 132 div.quoteblock, div.literalblock, div.listingblock, div.sidebarblock,
 133 div.admonitionblock {
 134   margin-top: 1.0em;
 135   margin-bottom: 1.5em;
 136 }
 137 div.admonitionblock {
 138   margin-top: 2.0em;
 139   margin-bottom: 2.0em;
 140   margin-right: 10%;
 141   color: #606060;
 142 }
 143
 144 div.content { /* Block element content. */
 145   padding: 0;
 146 }
 147
 148 /* Block element titles. */
 149 div.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 }
 156 div.title + * {
 157   margin-top: 0;
 158 }
 159
 160 td div.title:first-child {
 161   margin-top: 0.0em;
 162 }
 163 div.content div.title:first-child {
 164   margin-top: 0.0em;
 165 }
 166 div.content + div.title {
 167   margin-top: 0.0em;
 168 }
 169
 170 div.sidebarblock > div.content {
 171   background: #ffffee;
 172   border: 1px solid #dddddd;
 173   border-left: 4px solid #f0f0f0;
 174   padding: 0.5em;
 175 }
 176
 177 div.listingblock > div.content {
 178   border: 1px solid #dddddd;
 179   border-left: 5px solid #f0f0f0;
 180   background: #f8f8f8;
 181   padding: 0.5em;
 182 }
 183
 184 div.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
 192 div.quoteblock > div.attribution {
 193   padding-top: 0.5em;
 194   text-align: right;
 195 }
 196
 197 div.verseblock > pre.content {
 198   font-family: inherit;
 199   font-size: inherit;
 200 }
 201 div.verseblock > div.attribution {
 202   padding-top: 0.75em;
 203   text-align: left;
 204 }
 205 /* DEPRECATED: Pre version 8.2.7 verse style literal block. */
 206 div.verseblock + div.attribution {
 207   text-align: left;
 208 }
 209
 210 div.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 }
 218 div.admonitionblock td.content {
 219   padding-left: 0.5em;
 220   border-left: 3px solid #dddddd;
 221 }
 222
 223 div.exampleblock > div.content {
 224   border-left: 3px solid #dddddd;
 225   padding-left: 0.5em;
 226 }
 227
 228 div.imageblock div.content { padding-left: 0; }
 229 span.image img { border-style: none; vertical-align: text-bottom; }
 230 a.image:visited { color: white; }
 231
 232 dl {
 233   margin-top: 0.8em;
 234   margin-bottom: 0.8em;
 235 }
 236 dt {
 237   margin-top: 0.5em;
 238   margin-bottom: 0;
 239   font-style: normal;
 240   color: navy;
 241 }
 242 dd > *:first-child {
 243   margin-top: 0.1em;
 244 }
 245
 246 ul, ol {
 247     list-style-position: outside;
 248 }
 249 ol.arabic {
 250   list-style-type: decimal;
 251 }
 252 ol.loweralpha {
 253   list-style-type: lower-alpha;
 254 }
 255 ol.upperalpha {
 256   list-style-type: upper-alpha;
 257 }
 258 ol.lowerroman {
 259   list-style-type: lower-roman;
 260 }
 261 ol.upperroman {
 262   list-style-type: upper-roman;
 263 }
 264
 265 div.compact ul, div.compact ol,
 266 div.compact p, div.compact p,
 267 div.compact div, div.compact div {
 268   margin-top: 0.1em;
 269   margin-bottom: 0.1em;
 270 }
 271
 272 tfoot {
 273   font-weight: bold;
 274 }
 275 td > div.verse {
 276   white-space: pre;
 277 }
 278
 279 div.hdlist {
 280   margin-top: 0.8em;
 281   margin-bottom: 0.8em;
 282 }
 283 div.hdlist tr {
 284   padding-bottom: 15px;
 285 }
 286 dt.hdlist1.strong, td.hdlist1.strong {
 287   font-weight: bold;
 288 }
 289 td.hdlist1 {
 290   vertical-align: top;
 291   font-style: normal;
 292   padding-right: 0.8em;
 293   color: navy;
 294 }
 295 td.hdlist2 {
 296   vertical-align: top;
 297 }
 298 div.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
 311 span.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
 334 div.colist td {
 335   padding-right: 0.5em;
 336   padding-bottom: 0.3em;
 337   vertical-align: top;
 338 }
 339 div.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
 359 div.toclevel0, div.toclevel1, div.toclevel2, div.toclevel3, div.toclevel4 {
 360   margin-top: 0;
 361   margin-bottom: 0;
 362 }
 363 div.toclevel2 {
 364   margin-left: 2em;
 365   font-size: 0.9em;
 366 }
 367 div.toclevel3 {
 368   margin-left: 4em;
 369   font-size: 0.9em;
 370 }
 371 div.toclevel4 {
 372   margin-left: 6em;
 373   font-size: 0.9em;
 374 }
 375
 376 span.aqua { color: aqua; }
 377 span.black { color: black; }
 378 span.blue { color: blue; }
 379 span.fuchsia { color: fuchsia; }
 380 span.gray { color: gray; }
 381 span.green { color: green; }
 382 span.lime { color: lime; }
 383 span.maroon { color: maroon; }
 384 span.navy { color: navy; }
 385 span.olive { color: olive; }
 386 span.purple { color: purple; }
 387 span.red { color: red; }
 388 span.silver { color: silver; }
 389 span.teal { color: teal; }
 390 span.white { color: white; }
 391 span.yellow { color: yellow; }
 392
 393 span.aqua-background { background: aqua; }
 394 span.black-background { background: black; }
 395 span.blue-background { background: blue; }
 396 span.fuchsia-background { background: fuchsia; }
 397 span.gray-background { background: gray; }
 398 span.green-background { background: green; }
 399 span.lime-background { background: lime; }
 400 span.maroon-background { background: maroon; }
 401 span.navy-background { background: navy; }
 402 span.olive-background { background: olive; }
 403 span.purple-background { background: purple; }
 404 span.red-background { background: red; }
 405 span.silver-background { background: silver; }
 406 span.teal-background { background: teal; }
 407 span.white-background { background: white; }
 408 span.yellow-background { background: yellow; }
 409
 410 span.big { font-size: 2em; }
 411 span.small { font-size: 0.6em; }
 412
 413 span.underline { text-decoration: underline; }
 414 span.overline { text-decoration: overline; }
 415 span.line-through { text-decoration: line-through; }
 416
 417 div.unbreakable { page-break-inside: avoid; }
 418
 419
 420 /*
 421  * xhtml11 specific
 422  *
 423  * */
 424
 425 div.tableblock {
 426   margin-top: 1.0em;
 427   margin-bottom: 1.5em;
 428 }
 429 div.tableblock > table {
 430   border: 3px solid #527bbd;
 431 }
 432 thead, p.table.header {
 433   font-weight: bold;
 434   color: #527bbd;
 435 }
 436 p.table {
 437   margin-top: 0;
 438 }
 439 /* Because the table frame attribute is overridden by CSS in most browsers. */
 440 div.tableblock > table[frame="void"] {
 441   border-style: none;
 442 }
 443 div.tableblock > table[frame="hsides"] {
 444   border-left-style: none;
 445   border-right-style: none;
 446 }
 447 div.tableblock > table[frame="vsides"] {
 448   border-top-style: none;
 449   border-bottom-style: none;
 450 }
 451
 452
 453 /*
 454  * html5 specific
 455  *
 456  * */
 457
 458 table.tableblock {
 459   margin-top: 1.0em;
 460   margin-bottom: 1.5em;
 461 }
 462 thead, p.tableblock.header {
 463   font-weight: bold;
 464   color: #527bbd;
 465 }
 466 p.tableblock {
 467   margin-top: 0;
 468 }
 469 table.tableblock {
 470   border-width: 3px;
 471   border-spacing: 0px;
 472   border-style: solid;
 473   border-color: #527bbd;
 474   border-collapse: collapse;
 475 }
 476 th.tableblock, td.tableblock {
 477   border-width: 1px;
 478   padding: 4px;
 479   border-style: solid;
 480   border-color: #527bbd;
 481 }
 482
 483 table.tableblock.frame-topbot {
 484   border-left-style: hidden;
 485   border-right-style: hidden;
 486 }
 487 table.tableblock.frame-sides {
 488   border-top-style: hidden;
 489   border-bottom-style: hidden;
 490 }
 491 table.tableblock.frame-none {
 492   border-style: hidden;
 493 }
 494
 495 th.tableblock.halign-left, td.tableblock.halign-left {
 496   text-align: left;
 497 }
 498 th.tableblock.halign-center, td.tableblock.halign-center {
 499   text-align: center;
 500 }
 501 th.tableblock.halign-right, td.tableblock.halign-right {
 502   text-align: right;
 503 }
 504
 505 th.tableblock.valign-top, td.tableblock.valign-top {
 506   vertical-align: top;
 507 }
 508 th.tableblock.valign-middle, td.tableblock.valign-middle {
 509   vertical-align: middle;
 510 }
 511 th.tableblock.valign-bottom, td.tableblock.valign-bottom {
 512   vertical-align: bottom;
 513 }
 514
 515
 516 /*
 517  * manpage specific
 518  *
 519  * */
 520
 521 body.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 }
 527 body.manpage h2 {
 528   border-style: none;
 529 }
 530 body.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[*/
 542 var 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.
 562 toc: 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
 648 footnotes: 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
 708 install: 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 }
 731 asciidoc.install();
 732 /*]]>*/
 733 </script>
 734 </head>
 735 <body class="article">
 736 <div id="header">
 737 <h1>Trace2 API</h1>
 738 <span id="revdate">2024-02-06</span>
 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
 744 information to stderr or a file.  The Trace2 feature is inactive unless
 745 explicitly 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)
 747 <code>printf()</code>-style tracing provided by the existing <code>GIT_TRACE</code> and
 748 <code>GIT_TRACE_PERFORMANCE</code> facilities.  During initial implementation,
 749 Trace2 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,
 751 such 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
 753 messages to the enabled Trace2 Targets.  Targets transform these
 754 messages content into purpose-specific formats and write events to
 755 their data streams.  In this manner, the Trace2 API can drive
 756 many different types of analysis.</p></div>
 757 <div class="paragraph"><p>Targets are defined using a VTable allowing easy extension to other
 758 formats in the future.  This might be used to define a binary format,
 759 for example.</p></div>
 760 <div class="paragraph"><p>Trace2 is controlled using <code>trace2.*</code> config values in the system and
 761 global config files and <code>GIT_TRACE2*</code> environment variables.  Trace2 does
 762 not read from repo local or worktree config files, nor does it respect
 763 <code>-c</code> command line config settings.</p></div>
 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.
 770 Format details are given in a later section.</p></div>
 771 <div class="sect2">
 772 <h3 id="_the_normal_format_target">The Normal Format Target</h3>
 773 <div class="paragraph"><p>The normal format target is a traditional <code>printf()</code> format and similar
 774 to the <code>GIT_TRACE</code> format.  This format is enabled with the <code>GIT_TRACE2</code>
 775 environment variable or the <code>trace2.normalTarget</code> system or global
 776 config setting.</p></div>
 777 <div class="paragraph"><p>For example</p></div>
 778 <div class="listingblock">
 779 <div class="content">
 780 <pre><code>$ export GIT_TRACE2=~/log.normal
 781 $ git version
 782 git version 2.20.1.155.g426c96fcdb</code></pre>
 783 </div></div>
 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
 789 git version 2.20.1.155.g426c96fcdb</code></pre>
 790 </div></div>
 791 <div class="paragraph"><p>yields</p></div>
 792 <div class="listingblock">
 793 <div class="content">
 794 <pre><code>$ cat ~/log.normal
 795 12:28:42.620009 common-main.c:38                  version 2.20.1.155.g426c96fcdb
 796 12:28:42.620989 common-main.c:39                  start git version
 797 12:28:42.621101 git.c:432                         cmd_name version (version)
 798 12:28:42.621215 git.c:662                         exit elapsed:0.001227 code:0
 799 12:28:42.621250 trace2/tr2_tgt_normal.c:124       atexit elapsed:0.001265 code:0</code></pre>
 800 </div></div>
 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
 805 replace <code>GIT_TRACE_PERFORMANCE</code> and is suitable for development and
 806 testing, possibly to complement tools like <code>gprof</code>.  This format is
 807 enabled with the <code>GIT_TRACE2_PERF</code> environment variable or the
 808 <code>trace2.perfTarget</code> system or global config setting.</p></div>
 809 <div class="paragraph"><p>For example</p></div>
 810 <div class="listingblock">
 811 <div class="content">
 812 <pre><code>$ export GIT_TRACE2_PERF=~/log.perf
 813 $ git version
 814 git version 2.20.1.155.g426c96fcdb</code></pre>
 815 </div></div>
 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
 821 git version 2.20.1.155.g426c96fcdb</code></pre>
 822 </div></div>
 823 <div class="paragraph"><p>yields</p></div>
 824 <div class="listingblock">
 825 <div class="content">
 826 <pre><code>$ cat ~/log.perf
 827 12:28:42.620675 common-main.c:38                  | d0 | main                     | version      |     |           |           |            | 2.20.1.155.g426c96fcdb
 828 12:28:42.621001 common-main.c:39                  | d0 | main                     | start        |     |  0.001173 |           |            | git version
 829 12:28:42.621111 git.c:432                         | d0 | main                     | cmd_name     |     |           |           |            | version (version)
 830 12:28:42.621225 git.c:662                         | d0 | main                     | exit         |     |  0.001227 |           |            | code:0
 831 12:28:42.621259 trace2/tr2_tgt_perf.c:211         | d0 | main                     | atexit       |     |  0.001265 |           |            | code:0</code></pre>
 832 </div></div>
 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
 837 for telemetry analysis.  This format is enabled with the <code>GIT_TRACE2_EVENT</code>
 838 environment variable or the <code>trace2.eventTarget</code> system or global config
 839 setting.</p></div>
 840 <div class="paragraph"><p>For example</p></div>
 841 <div class="listingblock">
 842 <div class="content">
 843 <pre><code>$ export GIT_TRACE2_EVENT=~/log.event
 844 $ git version
 845 git version 2.20.1.155.g426c96fcdb</code></pre>
 846 </div></div>
 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
 852 git version 2.20.1.155.g426c96fcdb</code></pre>
 853 </div></div>
 854 <div class="paragraph"><p>yields</p></div>
 855 <div class="listingblock">
 856 <div class="content">
 857 <pre><code>$ cat ~/log.event
 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"}
 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>
 863 </div></div>
 864 </div>
 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
 868 system or global config value to one of the following:</p></div>
 869 <div class="openblock">
 870 <div class="content">
 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>
 889 <code>&lt;absolute-pathname&gt;</code> - Writes to the file in append mode. If the target
 890 already exists and is a directory, the traces will be written to files (one
 891 per process) underneath the given directory.
 892 </p>
 893 </li>
 894 <li>
 895 <p>
 896 <code>af_unix:[&lt;socket_type&gt;:]&lt;absolute-pathname&gt;</code> - Write to a
 897 Unix DomainSocket (on platforms that support them).  Socket
 898 type can be either <code>stream</code> or <code>dgram</code>; if omitted Git will
 899 try both.
 900 </p>
 901 </li>
 902 </ul></div>
 903 </div></div>
 904 <div class="paragraph"><p>When trace files are written to a target directory, they will be named according
 905 to the last component of the SID (optionally followed by a counter to avoid
 906 filename collisions).</p></div>
 907 </div>
 908 </div>
 909 </div>
 910 <div class="sect1">
 911 <h2 id="_trace2_api">Trace2 API</h2>
 912 <div class="sectionbody">
 913 <div class="paragraph"><p>The Trace2 public API is defined and documented in <code>trace2.h</code>; refer to it for
 914 more information.  All public functions and macros are prefixed
 915 with <code>trace2_</code> and are implemented in <code>trace2.c</code>.</p></div>
 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
 918 in the <code>trace2/</code> directory.  These symbols are prefixed with <code>tr2_</code>
 919 and should only be used by functions in <code>trace2.c</code> (or other private
 920 source 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>
 923 <div class="paragraph"><p>Some functions have a <code>_fl()</code> suffix to indicate that they take <code>file</code>
 924 and <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
 926 take 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
 928 take a <code>printf()</code> style format with a variable number of arguments.</p></div>
 929 <div class="paragraph"><p>CPP wrapper macros are defined to hide most of these details.</p></div>
 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>
 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>
 957         is a free-form <code>printf()</code> message intended for human consumption.
 958 </p>
 959 <div class="paragraph"><p>Note that this may contain embedded LF or CRLF characters that are
 960 not escaped, so the event may spill across multiple lines.</p></div>
 961 </dd>
 962 </dl></div>
 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>,
 964 and <code>line</code> fields are omitted.</p></div>
 965 <div class="paragraph"><p>This target is intended to be more of a summary (like GIT_TRACE) and
 966 less detailed than the other targets.  It ignores thread, region, and
 967 data messages, for example.</p></div>
 968 </div>
 969 <div class="sect2">
 970 <h3 id="_perf_format">PERF Format</h3>
 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.
1026 This 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>
1061         is a free-form <code>printf()</code> message intended for human consumption.
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
1068 15:33:33.532712 wt-status.c:2331                  | d0 | main                     | region_leave | r1  |  0.127568 |  0.001504 | status     | label:print</code></pre>
1069 </div></div>
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>,
1071 and <code>line</code> fields are omitted.</p></div>
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
1077 during development and is quite noisy.</p></div>
1078 </div>
1079 <div class="sect2">
1080 <h3 id="_event_format">EVENT Format</h3>
1081 <div class="paragraph"><p>Each event is a JSON-object containing multiple key/value pairs
1082 written 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
1088 event-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",
1096         "sid":"20190408T191827.272759Z-H9b68c35f-P00003510",
1097         "thread":"main",
1098         "time":"2019-04-08T19:18:27.282761Z",
1099         "file":"common-main.c",
1100         "line":42,
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>
1168 <div class="paragraph"><p>If <code>GIT_TRACE2_EVENT_BRIEF</code> or <code>trace2.eventBrief</code> is true, the <code>file</code>
1169 and <code>line</code> fields are omitted from all events and the <code>time</code> field is
1170 only present on the "start" and "atexit" events.</p></div>
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>
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.
1187 </p>
1188 <div class="listingblock">
1189 <div class="content">
1190 <pre><code>{
1191         "event":"version",
1192         ...
1193         "evt":"3",                     # EVENT format version
1194         "exe":"2.20.1.155.g426c96fcdb" # git version
1195 }</code></pre>
1196 </div></div>
1197 </dd>
1198 <dt class="hdlist1">
1199 <code>"too_many_files"</code>
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>{
1210         "event":"too_many_files",
1211         ...
1212 }</code></pre>
1213 </div></div>
1214 </dd>
1215 <dt class="hdlist1">
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         ...
1227         "t_abs":0.001227, # elapsed time in seconds
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
1259 the "exit" event because it runs after all other atexit tasks have
1260 completed.)</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
1286         "signo":13         # SIGTERM, SIGINT, etc.
1287 }</code></pre>
1288 </div></div>
1289 </dd>
1290 <dt class="hdlist1">
1291 <code>"error"</code>
1292 </dt>
1293 <dd>
1294 <p>
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.
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
1308 allows post-processors to group errors by type without worrying
1309 about 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">
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">
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
1365 command.  When a canonical name is not available, one of
1366 these 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>
1381         This event, when present, describes the command variant. This
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.
1393 For example, checkout can checkout a branch or an individual file.
1394 And these variations typically have different performance
1395 characteristics 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
1437 corresponding 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
1440 with "?".</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
1448         from the <code>waitpid()</code> and collected the exit information from the
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
1463 the current/spawning process, so the child&#8217;s PID is reported here as
1464 a hint for post-processing.  (But it is only a hint because the child
1465 process may be a shell script which doesn&#8217;t have a session-id.)</p></div>
1466 <div class="paragraph"><p>Note that the <code>t_rel</code> field contains the observed run time in seconds
1467 for the child process (starting before the fork/exec/spawn and
1468 stopping after the <code>waitpid()</code> and includes OS process creation overhead).
1469 So this time will be slightly larger than the atexit time reported by
1470 the child process itself.</p></div>
1471 </dd>
1472 <dt class="hdlist1">
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
1492 the current/spawning process, so the child&#8217;s PID is reported here as
1493 a hint for post-processing.  (But it is only a hint because the child
1494 process 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
1496 and given a little time to boot up and start working.  If the child
1497 starts up normally while the parent is still waiting, the "ready"
1498 field will have the value "ready".
1499 If the child is too slow to start and the parent times out, the field
1500 will have the value "timeout".
1501 If the child starts but the parent is unable to probe it, the field
1502 will have the value "error".</p></div>
1503 <div class="paragraph"><p>After the parent process emits this event, it will release all of its
1504 handles to the child process and treat the child as a background
1505 daemon.  So even if the child does eventually finish booting up,
1506 the 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
1508 when the parent released the child process into the background.
1509 The child is assumed to be a long-running daemon process and may
1510 outlive the parent process.  So the parent&#8217;s child event times should
1511 not be compared to the child&#8217;s atexit times.</p></div>
1512 </dd>
1513 <dt class="hdlist1">
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
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).
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
1576         from <strong>within</strong> the thread&#8217;s thread-proc.
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>
1593         This event is generated to log a global parameter, such as a config
1594         setting, command-line flag, or environment variable.
1595 </p>
1596 <div class="listingblock">
1597 <div class="content">
1598 <pre><code>{
1599         "event":"def_param",
1600         ...
1601         "scope":"global",
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
1625 only be one def_repo event.  Later, if in-proc submodules are
1626 supported, a def_repo event should be emitted for each submodule
1627 visited.</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
1649 do category-based filtering.</p></div>
1650 <div class="paragraph"><p><code>GIT_TRACE2_EVENT_NESTING</code> or <code>trace2.eventNesting</code> can be used to
1651 filter 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>
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>
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
1816 usage (without worrying about the actual Git details).</p></div>
1817 <div class="dlist"><dl>
1818 <dt class="hdlist1">
1819 Initialization
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">
1844 Command 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">
1870 Child 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,
1891 rev-list, and gc.  This example also shows that fetch took
1892 5.199 seconds and of that 4.932 was in ssh.</p></div>
1893 <div class="listingblock">
1894 <div class="content">
1895 <pre><code>$ export GIT_TRACE2_BRIEF=1
1896 $ export GIT_TRACE2=~/log.normal
1897 $ git fetch origin
1898 ...</code></pre>
1899 </div></div>
1900 <div class="listingblock">
1901 <div class="content">
1902 <pre><code>$ cat ~/log.normal
1903 version 2.20.1.vfs.1.1.47.g534dbe1ad1
1904 start git fetch origin
1905 worktree /Users/jeffhost/work/gfw
1906 cmd_name fetch (fetch)
1907 child_start[0] ssh git@github.com ...
1908 child_start[1] git index-pack ...
1909 ... (Trace2 events from child processes omitted)
1910 child_exit[1] pid:14707 code:0 elapsed:0.076353
1911 child_exit[0] pid:14706 code:0 elapsed:4.931869
1912 child_start[2] git rev-list ...
1913 ... (Trace2 events from child process omitted)
1914 child_exit[2] pid:14708 code:0 elapsed:0.110605
1915 child_start[3] git gc --auto
1916 ... (Trace2 events from child process omitted)
1917 child_exit[3] pid:14709 code:0 elapsed:0.006240
1918 exit elapsed:5.198503 code:0
1919 atexit 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
1922 git process, it inherits Trace2 context information.  This
1923 allows the child to print the command hierarchy.  This example
1924 shows gc as child[3] of fetch.  When the gc process reports
1925 its name as "gc", it also reports the hierarchy as "fetch/gc".
1926 (In this example, trace2 messages from the child process is
1927 indented for clarity.)</p></div>
1928 <div class="listingblock">
1929 <div class="content">
1930 <pre><code>$ export GIT_TRACE2_BRIEF=1
1931 $ export GIT_TRACE2=~/log.normal
1932 $ git fetch origin
1933 ...</code></pre>
1934 </div></div>
1935 <div class="listingblock">
1936 <div class="content">
1937 <pre><code>$ cat ~/log.normal
1938 version 2.20.1.160.g5676107ecd.dirty
1939 start git fetch official
1940 worktree /Users/jeffhost/work/gfw
1941 cmd_name fetch (fetch)
1942 ...
1943 child_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
1950 child_exit[3] pid:20303 code:0 elapsed:0.007564
1951 exit elapsed:3.868938 code:0
1952 atexit elapsed:3.868970 code:0</code></pre>
1953 </div></div>
1954 </dd>
1955 <dt class="hdlist1">
1956 Regions
1957 </dt>
1958 <dd>
1959 <p>
1960         Regions can be used to time an interesting section of code.
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
1979 void 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">
1992 <pre><code>$ export GIT_TRACE2_PERF_BRIEF=1
1993 $ export GIT_TRACE2_PERF=~/log.perf
1994 $ git status
1995 ...
1996
1997 $ cat ~/log.perf
1998 d0 | main                     | version      |     |           |           |            | 2.20.1.160.g5676107ecd.dirty
1999 d0 | main                     | start        |     |  0.001173 |           |            | git status
2000 d0 | main                     | def_repo     | r1  |           |           |            | worktree:/Users/jeffhost/work/gfw
2001 d0 | main                     | cmd_name     |     |           |           |            | status (status)
2002 ...
2003 d0 | main                     | region_enter | r1  |  0.010988 |           | status     | label:worktrees
2004 d0 | main                     | region_leave | r1  |  0.011236 |  0.000248 | status     | label:worktrees
2005 d0 | main                     | region_enter | r1  |  0.011260 |           | status     | label:index
2006 d0 | main                     | region_leave | r1  |  0.012542 |  0.001282 | status     | label:index
2007 d0 | main                     | region_enter | r1  |  0.012568 |           | status     | label:untracked
2008 d0 | main                     | region_leave | r1  |  0.027149 |  0.014581 | status     | label:untracked
2009 d0 | main                     | region_enter | r1  |  0.027411 |           | status     | label:print
2010 d0 | main                     | region_leave | r1  |  0.028741 |  0.001330 | status     | label:print
2011 d0 | main                     | exit         |     |  0.028778 |           |            | code:0
2012 d0 | 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
2015 PERF target, for example.
2016 Elapsed times are relative to the start of the corresponding nesting
2017 level 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">
2036 <pre><code>$ export GIT_TRACE2_PERF_BRIEF=1
2037 $ export GIT_TRACE2_PERF=~/log.perf
2038 $ git status
2039 ...
2040 $ cat ~/log.perf
2041 d0 | main                     | version      |     |           |           |            | 2.20.1.162.gb4ccea44db.dirty
2042 d0 | main                     | start        |     |  0.001173 |           |            | git status
2043 d0 | main                     | def_repo     | r1  |           |           |            | worktree:/Users/jeffhost/work/gfw
2044 d0 | main                     | cmd_name     |     |           |           |            | status (status)
2045 ...
2046 d0 | main                     | region_enter | r1  |  0.015047 |           | status     | label:untracked
2047 d0 | main                     | region_enter |     |  0.015132 |           | dir        | ..label:read_recursive
2048 d0 | main                     | region_enter |     |  0.016341 |           | dir        | ....label:read_recursive vcs-svn/
2049 d0 | main                     | region_leave |     |  0.016422 |  0.000081 | dir        | ....label:read_recursive vcs-svn/
2050 d0 | main                     | region_enter |     |  0.016446 |           | dir        | ....label:read_recursive xdiff/
2051 d0 | main                     | region_leave |     |  0.016522 |  0.000076 | dir        | ....label:read_recursive xdiff/
2052 d0 | main                     | region_enter |     |  0.016612 |           | dir        | ....label:read_recursive git-gui/
2053 d0 | main                     | region_enter |     |  0.016698 |           | dir        | ......label:read_recursive git-gui/po/
2054 d0 | main                     | region_enter |     |  0.016810 |           | dir        | ........label:read_recursive git-gui/po/glossary/
2055 d0 | main                     | region_leave |     |  0.016863 |  0.000053 | dir        | ........label:read_recursive git-gui/po/glossary/
2056 ...
2057 d0 | main                     | region_enter |     |  0.031876 |           | dir        | ....label:read_recursive builtin/
2058 d0 | main                     | region_leave |     |  0.032270 |  0.000394 | dir        | ....label:read_recursive builtin/
2059 d0 | main                     | region_leave |     |  0.032414 |  0.017282 | dir        | ..label:read_recursive
2060 d0 | main                     | region_leave | r1  |  0.032454 |  0.017407 | status     | label:untracked
2061 ...
2062 d0 | main                     | exit         |     |  0.034279 |           |            | code:0
2063 d0 | 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()
2066 and trace_performance_leave() routines, but are thread safe and
2067 maintain per-thread stacks of timers.</p></div>
2068 </dd>
2069 <dt class="hdlist1">
2070 Data 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">
2094 <pre><code>$ export GIT_TRACE2_PERF_BRIEF=1
2095 $ export GIT_TRACE2_PERF=~/log.perf
2096 $ git status
2097 ...
2098 $ cat ~/log.perf
2099 d0 | main                     | version      |     |           |           |            | 2.20.1.156.gf9916ae094.dirty
2100 d0 | main                     | start        |     |  0.001173 |           |            | git status
2101 d0 | main                     | def_repo     | r1  |           |           |            | worktree:/Users/jeffhost/work/gfw
2102 d0 | main                     | cmd_name     |     |           |           |            | status (status)
2103 d0 | main                     | region_enter | r1  |  0.001791 |           | index      | label:do_read_index .git/index
2104 d0 | main                     | data         | r1  |  0.002494 |  0.000703 | index      | ..read/version:2
2105 d0 | main                     | data         | r1  |  0.002520 |  0.000729 | index      | ..read/cache_nr:3552
2106 d0 | 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">
2111 Thread Events
2112 </dt>
2113 <dd>
2114 <p>
2115         Thread messages added to a thread-proc.
2116 </p>
2117 <div class="paragraph"><p>For example, the multi-threaded preload-index code can be
2118 instrumented with a region around the thread pool and then
2119 per-thread start and exit events within the thread-proc.</p></div>
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
2141 void 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
2159 and started the <code>preload</code> region.  Seven threads, named
2160 <code>th01:preload_thread</code> through <code>th07:preload_thread</code>, were started.
2161 Events from each thread are atomically appended to the shared target
2162 stream as they occur so they may appear in random order with respect
2163 other threads. Finally, the main thread waits for the threads to
2164 finish and leaves the region.</p></div>
2165 <div class="paragraph"><p>Data events are tagged with the active thread name.  They are used
2166 to report the per-thread parameters.</p></div>
2167 <div class="listingblock">
2168 <div class="content">
2169 <pre><code>$ export GIT_TRACE2_PERF_BRIEF=1
2170 $ export GIT_TRACE2_PERF=~/log.perf
2171 $ git status
2172 ...
2173 $ cat ~/log.perf
2174 ...
2175 d0 | main                     | region_enter | r1  |  0.002595 |           | index      | label:preload
2176 d0 | th01:preload_thread      | thread_start |     |  0.002699 |           |            |
2177 d0 | th02:preload_thread      | thread_start |     |  0.002721 |           |            |
2178 d0 | th01:preload_thread      | data         | r1  |  0.002736 |  0.000037 | index      | offset:0
2179 d0 | th02:preload_thread      | data         | r1  |  0.002751 |  0.000030 | index      | offset:2032
2180 d0 | th03:preload_thread      | thread_start |     |  0.002711 |           |            |
2181 d0 | th06:preload_thread      | thread_start |     |  0.002739 |           |            |
2182 d0 | th01:preload_thread      | data         | r1  |  0.002766 |  0.000067 | index      | count:508
2183 d0 | th06:preload_thread      | data         | r1  |  0.002856 |  0.000117 | index      | offset:2540
2184 d0 | th03:preload_thread      | data         | r1  |  0.002824 |  0.000113 | index      | offset:1016
2185 d0 | th04:preload_thread      | thread_start |     |  0.002710 |           |            |
2186 d0 | th02:preload_thread      | data         | r1  |  0.002779 |  0.000058 | index      | count:508
2187 d0 | th06:preload_thread      | data         | r1  |  0.002966 |  0.000227 | index      | count:508
2188 d0 | th07:preload_thread      | thread_start |     |  0.002741 |           |            |
2189 d0 | th07:preload_thread      | data         | r1  |  0.003017 |  0.000276 | index      | offset:3048
2190 d0 | th05:preload_thread      | thread_start |     |  0.002712 |           |            |
2191 d0 | th05:preload_thread      | data         | r1  |  0.003067 |  0.000355 | index      | offset:1524
2192 d0 | th05:preload_thread      | data         | r1  |  0.003090 |  0.000378 | index      | count:508
2193 d0 | th07:preload_thread      | data         | r1  |  0.003037 |  0.000296 | index      | count:504
2194 d0 | th03:preload_thread      | data         | r1  |  0.002971 |  0.000260 | index      | count:508
2195 d0 | th04:preload_thread      | data         | r1  |  0.002983 |  0.000273 | index      | offset:508
2196 d0 | th04:preload_thread      | data         | r1  |  0.007311 |  0.004601 | index      | count:508
2197 d0 | th05:preload_thread      | thread_exit  |     |  0.008781 |  0.006069 |            |
2198 d0 | th01:preload_thread      | thread_exit  |     |  0.009561 |  0.006862 |            |
2199 d0 | th03:preload_thread      | thread_exit  |     |  0.009742 |  0.007031 |            |
2200 d0 | th06:preload_thread      | thread_exit  |     |  0.009820 |  0.007081 |            |
2201 d0 | th02:preload_thread      | thread_exit  |     |  0.010274 |  0.007553 |            |
2202 d0 | th07:preload_thread      | thread_exit  |     |  0.010477 |  0.007736 |            |
2203 d0 | th04:preload_thread      | thread_exit  |     |  0.011657 |  0.008947 |            |
2204 d0 | main                     | region_leave | r1  |  0.011717 |  0.009122 | index      | label:preload
2205 ...
2206 d0 | main                     | exit         |     |  0.029996 |           |            | code:0
2207 d0 | 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
2210 took between 0.006069 and 0.008947 seconds to work on their portion of
2211 the index.  Thread "th01" worked on 508 items at offset 0.  Thread "th02"
2212 worked on 508 items at offset 2032.  Thread "th04" worked on 508 items
2213 at offset 508.</p></div>
2214 <div class="paragraph"><p>This example also shows that thread names are assigned in a racy manner
2215 as each thread starts.</p></div>
2216 </dd>
2217 <dt class="hdlist1">
2218 Config (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
2226 it.</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'
2233 system  color.ui=never
2234 global  color.ui=always
2235 local   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
2247 d0 | main                     | version      |     |           |           |              | ...
2248 d0 | main                     | start        |     |  0.001642 |           |              | /usr/local/bin/git version
2249 d0 | main                     | cmd_name     |     |           |           |              | version (version)
2250 d0 | main                     | def_param    |     |           |           | scope:system | color.ui:never
2251 d0 | main                     | def_param    |     |           |           | scope:global | color.ui:always
2252 d0 | main                     | def_param    |     |           |           | scope:local  | color.ui:auto
2253 d0 | main                     | data         | r0  |  0.002100 |  0.002100 | fsync        | fsync/writeout-only:0
2254 d0 | main                     | data         | r0  |  0.002126 |  0.002126 | fsync        | fsync/hardware-flush:0
2255 d0 | main                     | exit         |     |  0.000470 |           |              | code:0
2256 d0 | main                     | atexit       |     |  0.000477 |           |              | code:0</code></pre>
2257 </div></div>
2258 </dd>
2259 <dt class="hdlist1">
2260 Stopwatch 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
2279 static 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
2298 in 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
2306 d0 | main                     | version      |     |           |           |              | ...
2307 d0 | main                     | start        |     |  0.001453 |           |              | t/helper/test-tool trace2 100timer 3 1000
2308 d0 | main                     | cmd_name     |     |           |           |              | trace2 (trace2)
2309 d0 | main                     | exit         |     |  3.003667 |           |              | code:0
2310 d0 | main                     | timer        |     |           |           | test         | name:test1 intervals:3 total:3.001686 min:1.000254 max:1.000929
2311 d0 | main                     | atexit       |     |  3.003796 |           |              | code:0</code></pre>
2312 </div></div>
2313 </dd>
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
2323 switch to Trace2.</p></div>
2324 <div class="ulist"><ul>
2325 <li>
2326 <p>
2327 Updating existing tests that assume <code>GIT_TRACE</code> format messages.
2328 </p>
2329 </li>
2330 <li>
2331 <p>
2332 How to best handle custom <code>GIT_TRACE_&lt;key&gt;</code> messages?
2333 </p>
2334 <div class="ulist"><ul>
2335 <li>
2336 <p>
2337 The <code>GIT_TRACE_&lt;key&gt;</code> mechanism allows each &lt;key&gt; to write to a
2338 different file (in addition to just stderr).
2339 </p>
2340 </li>
2341 <li>
2342 <p>
2343 Do we want to maintain that ability or simply write to the existing
2344 Trace2 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">
2357 Last updated
2358  2022-11-04 21:49:36 PDT
2359 </div>
2360 </div>
2361 </body>
2362 </html>