English ▾ Themen ▾ Neueste Version ▾ api-trace2 zuletzt aktualisiert in 2.47.0

Die Trace2 API kann verwendet werden, um Debug-, Performance- und Telemetrieinformationen nach stderr oder in eine Datei zu schreiben. Die Trace2-Funktion ist inaktiv, es sei denn, sie wird explizit durch Aktivierung eines oder mehrerer Trace2-Ziele aktiviert.

Die Trace2 API soll das bestehende (Trace1) printf()-basierte Tracing ersetzen, das von den bestehenden GIT_TRACE und GIT_TRACE_PERFORMANCE Einrichtungen bereitgestellt wird. Während der anfänglichen Implementierung können Trace2 und Trace1 parallel laufen.

Die Trace2 API definiert eine Reihe von High-Level-Nachrichten mit bekannten Feldern, wie z. B. (start: argv) und (exit: {exit-code, elapsed-time}).

Die Trace2-Instrumentierung im gesamten Git-Code sendet Trace2-Nachrichten an die aktivierten Trace2-Ziele. Ziele wandeln den Inhalt dieser Nachrichten in zweckspezifische Formate um und schreiben Ereignisse in ihre Datenströme. Auf diese Weise kann die Trace2 API viele verschiedene Arten von Analysen steuern.

Ziele werden mittels eines VTables definiert, was zukünftig eine einfache Erweiterung auf andere Formate ermöglicht. Dies könnte zum Beispiel zur Definition eines Binärformats verwendet werden.

Trace2 wird über trace2.* Konfigurationswerte in den System- und globalen Konfigurationsdateien und GIT_TRACE2* Umgebungsvariablen gesteuert. Trace2 liest nicht aus Repository-lokalen oder Worktree-Konfigurationsdateien und beachtet auch keine -c Kommandozeilen-Konfigurationseinstellungen.

Trace2 Ziele

Trace2 definiert die folgenden Trace2-Ziele. Die Formatdetails sind in einem späteren Abschnitt angegeben.

Das Normalformat-Ziel

Das Normalformat-Ziel ist ein traditionelles printf()-Format und ähnelt dem GIT_TRACE-Format. Dieses Format wird mit der Umgebungsvariable GIT_TRACE2 oder der System- oder globalen Konfigurationseinstellung trace2.normalTarget aktiviert.

Zum Beispiel

$ export GIT_TRACE2=~/log.normal
$ git version
git version 2.20.1.155.g426c96fcdb

oder

$ git config --global trace2.normalTarget ~/log.normal
$ git version
git version 2.20.1.155.g426c96fcdb

ergibt

$ cat ~/log.normal
12:28:42.620009 common-main.c:38                  version 2.20.1.155.g426c96fcdb
12:28:42.620989 common-main.c:39                  start git version
12:28:42.621101 git.c:432                         cmd_name version (version)
12:28:42.621215 git.c:662                         exit elapsed:0.001227 code:0
12:28:42.621250 trace2/tr2_tgt_normal.c:124       atexit elapsed:0.001265 code:0

Das Performanceformat-Ziel

Das Performanceformat-Ziel (PERF) ist ein spaltenbasiertes Format, das GIT_TRACE_PERFORMANCE ersetzen soll und sich für Entwicklung und Tests eignet, möglicherweise zur Ergänzung von Tools wie gprof. Dieses Format wird mit der Umgebungsvariable GIT_TRACE2_PERF oder der System- oder globalen Konfigurationseinstellung trace2.perfTarget aktiviert.

Zum Beispiel

$ export GIT_TRACE2_PERF=~/log.perf
$ git version
git version 2.20.1.155.g426c96fcdb

oder

$ git config --global trace2.perfTarget ~/log.perf
$ git version
git version 2.20.1.155.g426c96fcdb

ergibt

$ cat ~/log.perf
12:28:42.620675 common-main.c:38                  | d0 | main                     | version      |     |           |           |            | 2.20.1.155.g426c96fcdb
12:28:42.621001 common-main.c:39                  | d0 | main                     | start        |     |  0.001173 |           |            | git version
12:28:42.621111 git.c:432                         | d0 | main                     | cmd_name     |     |           |           |            | version (version)
12:28:42.621225 git.c:662                         | d0 | main                     | exit         |     |  0.001227 |           |            | code:0
12:28:42.621259 trace2/tr2_tgt_perf.c:211         | d0 | main                     | atexit       |     |  0.001265 |           |            | code:0

Das Eventformat-Ziel

Das Eventformat-Ziel ist ein JSON-basiertes Format von Ereignisdaten, das für Telemetrieanalysen geeignet ist. Dieses Format wird mit der Umgebungsvariable GIT_TRACE2_EVENT oder der System- oder globalen Konfigurationseinstellung trace2.eventTarget aktiviert.

Zum Beispiel

$ export GIT_TRACE2_EVENT=~/log.event
$ git version
git version 2.20.1.155.g426c96fcdb

oder

$ git config --global trace2.eventTarget ~/log.event
$ git version
git version 2.20.1.155.g426c96fcdb

ergibt

$ cat ~/log.event
{"event":"version","sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.620713Z","file":"common-main.c","line":38,"evt":"4","exe":"2.20.1.155.g426c96fcdb"}
{"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"]}
{"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"}
{"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}
{"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}

Aktivieren eines Ziels

Um ein Ziel zu aktivieren, setzen Sie die entsprechende Umgebungsvariable oder den System- oder globalen Konfigurationswert auf einen der folgenden Werte:

  • 0 oder false - Deaktiviert das Ziel.

  • 1 oder true - Schreibt nach STDERR.

  • [2-9] - Schreibt in den bereits geöffneten Dateideskriptor.

  • <absoluter-Pfadname> - Schreibt im Anfügemodus in die Datei. Wenn das Ziel bereits existiert und ein Verzeichnis ist, werden die Traces in Dateien (eine pro Prozess) unter dem angegebenen Verzeichnis geschrieben.

  • af_unix:[<Socket-Typ>:]<absoluter-Pfadname> - Schreibt in einen Unix Domain Socket (auf Plattformen, die dies unterstützen). Der Socket-Typ kann entweder stream oder dgram sein; wenn weggelassen, versucht Git beide.

Wenn Trace-Dateien in ein Zielverzeichnis geschrieben werden, werden sie nach der letzten Komponente der SID benannt (optional gefolgt von einem Zähler, um Namenskollisionen zu vermeiden).

Trace2 API

Die öffentliche Trace2-API ist in trace2.h definiert und dokumentiert; dort finden Sie weitere Informationen. Alle öffentlichen Funktionen und Makros sind mit trace2_ präfigiert und in trace2.c implementiert.

Es gibt keine öffentlichen Trace2-Datenstrukturen.

Der Trace2-Code definiert auch eine Reihe von privaten Funktionen und Datentypen im Verzeichnis trace2/. Diese Symbole sind mit tr2_ präfigiert und sollten nur von Funktionen in trace2.c (oder anderen privaten Quelldateien in trace2/) verwendet werden.

Konventionen für öffentliche Funktionen und Makros

Einige Funktionen haben eine Suffix _fl(), um anzuzeigen, dass sie Argumente für file und line-number entgegennehmen.

Einige Funktionen haben eine Suffix _va_fl(), um anzuzeigen, dass sie auch ein va_list-Argument entgegennehmen.

Einige Funktionen haben eine Suffix _printf_fl(), um anzuzeigen, dass sie auch ein printf()-Format mit einer variablen Anzahl von Argumenten entgegennehmen.

CPP-Wrapper-Makros sind definiert, um die meisten dieser Details zu verbergen.

Trace2 Zielformate

NORMAL Format

Ereignisse werden als Zeilen des Formats geschrieben:

[<time> SP <filename>:<line> SP+] <event-name> [[SP] <event-message>] LF
<event-name>

ist der Ereignisname.

<event-message>

ist eine frei formatierte printf()-Nachricht, die für den menschlichen Verzehr bestimmt ist.

Beachten Sie, dass dies eingebettete LF- oder CRLF-Zeichen enthalten kann, die nicht escaped sind, sodass das Ereignis über mehrere Zeilen reichen kann.

Wenn GIT_TRACE2_BRIEF oder trace2.normalBrief wahr ist, werden die Felder time, filename und line weggelassen.

Dieses Ziel ist eher als Zusammenfassung (wie GIT_TRACE) und weniger detailliert als die anderen Ziele gedacht. Es ignoriert beispielsweise Thread-, Regions- und Datenmeldungen.

PERF Format

Ereignisse werden als Zeilen des Formats geschrieben:

[<time> SP <filename>:<line> SP+
    BAR SP] d<depth> SP
    BAR SP <thread-name> SP+
    BAR SP <event-name> SP+
    BAR SP [r<repo-id>] SP+
    BAR SP [<t_abs>] SP+
    BAR SP [<t_rel>] SP+
    BAR SP [<category>] SP+
    BAR SP DOTS* <perf-event-message>
    LF
<depth>

ist die Tiefe des Git-Prozesses. Dies ist die Anzahl der übergeordneten Git-Prozesse. Ein übergeordneter Git-Befehl hat den Tiefenwert "d0". Ein Kind davon hat den Tiefenwert "d1". Eine zweite Ebene Kind hat den Tiefenwert "d2" und so weiter.

<thread-name>

ist ein eindeutiger Name für den Thread. Der Hauptthread heißt "main". Andere Threadnamen haben das Format "th%d:%s" und enthalten eine eindeutige Nummer und den Namen des Thread-Prozesses.

<event-name>

ist der Ereignisname.

<repo-id>

wenn vorhanden, ist eine Zahl, die das verwendete Repository angibt. Ein def_repo-Ereignis wird ausgegeben, wenn ein Repository geöffnet wird. Dies definiert die Repo-ID und den zugehörigen Worktree. Nachfolgende Repository-spezifische Ereignisse verweisen auf diese Repo-ID.

Derzeit ist dies immer "r1" für das Hauptrepository. Dieses Feld ist für zukünftige In-Proc-Submodule gedacht.

<t_abs>

wenn vorhanden, ist die absolute Zeit in Sekunden seit Programmstart.

<t_rel>

wenn vorhanden, ist die Zeit in Sekunden relativ zum Beginn der aktuellen Region. Für ein Thread-Exit-Ereignis ist es die verstrichene Zeit des Threads.

<category>

ist vorhanden bei Regions- und Datenereignissen und wird verwendet, um eine breite Kategorie anzugeben, wie z. B. "index" oder "status".

<perf-event-message>

ist eine frei formatierte printf()-Nachricht, die für den menschlichen Verzehr bestimmt ist.

15:33:33.532712 wt-status.c:2310                  | d0 | main                     | region_enter | r1  |  0.126064 |           | status     | label:print
15:33:33.532712 wt-status.c:2331                  | d0 | main                     | region_leave | r1  |  0.127568 |  0.001504 | status     | label:print

Wenn GIT_TRACE2_PERF_BRIEF oder trace2.perfBrief wahr ist, werden die Felder time, file und line weggelassen.

d0 | main                     | region_leave | r1  |  0.011717 |  0.009122 | index      | label:preload

Das PERF-Ziel ist für die interaktive Performance-Analyse während der Entwicklung gedacht und ist recht "gesprächig".

EVENT Format

Jedes Ereignis ist ein JSON-Objekt mit mehreren Schlüssel/Wert-Paaren, das als einzelne Zeile geschrieben und von einem LF gefolgt wird.

'{' <key> ':' <value> [',' <key> ':' <value>]* '}' LF

Einige Schlüssel/Wert-Paare sind für alle Ereignisse gleich, einige sind ereignisspezifisch.

Gemeinsame Schlüssel/Wert-Paare

Die folgenden Schlüssel/Wert-Paare sind für alle Ereignisse gleich:

{
	"event":"version",
	"sid":"20190408T191827.272759Z-H9b68c35f-P00003510",
	"thread":"main",
	"time":"2019-04-08T19:18:27.282761Z",
	"file":"common-main.c",
	"line":42,
	...
}
"event":<event>

ist der Ereignisname.

"sid":<sid>

ist die Session-ID. Dies ist eine eindeutige Zeichenkette zur Identifizierung der Prozessinstanz, damit alle von einem Prozess ausgegebenen Ereignisse identifiziert werden können. Eine Session-ID wird anstelle einer PID verwendet, da PIDs vom Betriebssystem wiederverwendet werden. Bei Kindprozessen von Git wird die Session-ID mit der Session-ID des übergeordneten Git-Prozesses präfigiert, um Eltern-Kind-Beziehungen bei der Nachbearbeitung identifizieren zu können.

"thread":<thread>

ist der Thread-Name.

"time":<time>

ist die UTC-Zeit des Ereignisses.

"file":<filename>

ist die Quelldatei, die das Ereignis generiert.

"line":<line-number>

ist die ganzzahlige Quellzeilennummer, die das Ereignis generiert.

"repo":<repo-id>

wenn vorhanden, ist die ganzzahlige Repo-ID wie zuvor beschrieben.

Wenn GIT_TRACE2_EVENT_BRIEF oder trace2.eventBrief wahr ist, werden die Felder file und line aus allen Ereignissen weggelassen und das Feld time ist nur bei den Ereignissen "start" und "atexit" vorhanden.

Ereignisspezifische Schlüssel/Wert-Paare

"version"

Dieses Ereignis gibt die Version der ausführbaren Datei und das EVENT-Format an. Es sollte immer das erste Ereignis in einer Trace-Sitzung sein. Die EVENT-Format-Version wird erhöht, wenn neue Ereignistypen hinzugefügt werden, wenn bestehende Felder entfernt werden oder wenn es signifikante Änderungen bei der Interpretation bestehender Ereignisse oder Felder gibt. Kleinere Änderungen, wie das Hinzufügen eines neuen Feldes zu einem bestehenden Ereignis, erfordern keine Erhöhung der EVENT-Format-Version.

{
	"event":"version",
	...
	"evt":"4",		       # EVENT format version
	"exe":"2.20.1.155.g426c96fcdb" # git version
}
"too_many_files"

Dieses Ereignis wird in die Sentinel-Datei git-trace2-discard geschrieben, wenn zu viele Dateien im Ziel-Trace-Verzeichnis vorhanden sind (siehe Konfigurationsoption trace2.maxFiles).

{
	"event":"too_many_files",
	...
}
"start"

Dieses Ereignis enthält das vollständige argv, das von main() empfangen wurde.

{
	"event":"start",
	...
	"t_abs":0.001227, # elapsed time in seconds
	"argv":["git","version"]
}
"exit"

Dieses Ereignis wird ausgegeben, wenn Git exit() aufruft.

{
	"event":"exit",
	...
	"t_abs":0.001227, # elapsed time in seconds
	"code":0	  # exit code
}
"atexit"

Dieses Ereignis wird von der Trace2 atexit-Routine während der finalen Abschaltung ausgegeben. Es sollte das letzte vom Prozess ausgegebene Ereignis sein.

(Die hier angegebene verstrichene Zeit ist größer als die im "exit"-Ereignis angegebene Zeit, da sie nach Abschluss aller anderen atexit-Aufgaben ausgeführt wird.)

{
	"event":"atexit",
	...
	"t_abs":0.001227, # elapsed time in seconds
	"code":0          # exit code
}
"signal"

Dieses Ereignis wird ausgegeben, wenn das Programm durch ein Benutzersignal beendet wird. Je nach Plattform kann das Signalereignis verhindern, dass das "atexit"-Ereignis generiert wird.

{
	"event":"signal",
	...
	"t_abs":0.001227,  # elapsed time in seconds
	"signo":13         # SIGTERM, SIGINT, etc.
}
"error"

Dieses Ereignis wird ausgegeben, wenn eine der Funktionen BUG(), bug(), error(), die(), warning() oder usage() aufgerufen wird.

{
	"event":"error",
	...
	"msg":"invalid option: --cahced", # formatted error message
	"fmt":"invalid option: %s"	  # error format string
}

Das Fehlerereignis kann mehrfach ausgegeben werden. Die Formatzeichenkette ermöglicht es Nachbearbeitern, Fehler nach Typ zu gruppieren, ohne sich um spezifische Fehlerargumente kümmern zu müssen.

"cmd_path"

Dieses Ereignis enthält den ermittelten vollständigen Pfad der Git-ausführbaren Datei (auf Plattformen, die für deren Auflösung konfiguriert sind).

{
	"event":"cmd_path",
	...
	"path":"C:/work/gfw/git.exe"
}
"cmd_ancestry"

Dieses Ereignis enthält den Textbefehlsnamen für den Elternteil (und frühere Generationen von Elternteilen) des aktuellen Prozesses, in einem Array, geordnet vom nächsten Elternteil zum am weitesten entfernten Urgroßelternteil. Es ist möglicherweise nicht auf allen Plattformen implementiert.

{
	"event":"cmd_ancestry",
	...
	"ancestry":["bash","tmux: server","systemd"]
}
"cmd_name"

Dieses Ereignis enthält den Befehlsnamen für diesen Git-Prozess und die Hierarchie von Befehlen von übergeordneten Git-Prozessen.

{
	"event":"cmd_name",
	...
	"name":"pack-objects",
	"hierarchy":"push/pack-objects"
}

Normalerweise enthält das Feld "name" den kanonischen Namen des Befehls. Wenn kein kanonischer Name verfügbar ist, werden einer dieser Sonderwerte verwendet:

"_query_"            # "git --html-path"
"_run_dashed_"       # when "git foo" tries to run "git-foo"
"_run_shell_alias_"  # alias expansion to a shell command
"_run_git_alias_"    # alias expansion to a git command
"_usage_"            # usage error
"cmd_mode"

Dieses Ereignis beschreibt, wenn vorhanden, die Befehls-Variante. Dieses Ereignis kann mehrfach ausgegeben werden.

{
	"event":"cmd_mode",
	...
	"name":"branch"
}

Das Feld "name" ist eine beliebige Zeichenkette zur Beschreibung des Befehlsmodus. Zum Beispiel kann checkout einen Branch oder eine einzelne Datei auschecken. Und diese Variationen haben typischerweise unterschiedliche Leistungseigenschaften, die nicht vergleichbar sind.

"alias"

Dieses Ereignis ist vorhanden, wenn ein Alias erweitert wird.

{
	"event":"alias",
	...
	"alias":"l",		 # registered alias
	"argv":["log","--graph"] # alias expansion
}
"child_start"

Dieses Ereignis beschreibt einen Kindprozess, der gerade gestartet wird.

{
	"event":"child_start",
	...
	"child_id":2,
	"child_class":"?",
	"use_shell":false,
	"argv":["git","rev-list","--objects","--stdin","--not","--all","--quiet"]

	"hook_name":"<hook_name>"  # present when child_class is "hook"
	"cd":"<path>"		   # present when cd is required
}

Das Feld "child_id" kann verwendet werden, um diesen child_start mit dem entsprechenden child_exit-Ereignis abzugleichen.

Das Feld "child_class" ist eine grobe Klassifizierung, z. B. "editor", "pager", "transport/*" und "hook". Nicht klassifizierte Kinder werden mit "?" klassifiziert.

"child_exit"

Dieses Ereignis wird generiert, nachdem der aktuelle Prozess von waitpid() zurückgekehrt ist und die Exit-Informationen vom Kind gesammelt hat.

{
	"event":"child_exit",
	...
	"child_id":2,
	"pid":14708,	 # child PID
	"code":0,	 # child exit-code
	"t_rel":0.110605 # observed run-time of child process
}

Beachten Sie, dass die Session-ID des Kindprozesses für den aktuellen/spawnden Prozess nicht verfügbar ist, daher wird die PID des Kindes hier als Hinweis für die Nachbearbeitung angegeben. (Dies ist jedoch nur ein Hinweis, da der Kindprozess ein Shell-Skript sein kann, das keine Session-ID hat.)

Beachten Sie, dass das Feld t_rel die beobachtete Laufzeit in Sekunden für den Kindprozess enthält (beginnend vor dem fork/exec/spawn und endend nach dem waitpid(), einschließlich der Overhead-Kosten für die Betriebssystem-Prozesserstellung). Diese Zeit ist also etwas länger als die von Kindprozess selbst gemeldete atexit-Zeit.

"child_ready"

Dieses Ereignis wird generiert, nachdem der aktuelle Prozess einen Hintergrundprozess gestartet und alle Handles dazu freigegeben hat.

{
	"event":"child_ready",
	...
	"child_id":2,
	"pid":14708,	 # child PID
	"ready":"ready", # child ready state
	"t_rel":0.110605 # observed run-time of child process
}

Beachten Sie, dass die Session-ID des Kindprozesses für den aktuellen/spawnden Prozess nicht verfügbar ist, daher wird die PID des Kindes hier als Hinweis für die Nachbearbeitung angegeben. (Dies ist jedoch nur ein Hinweis, da der Kindprozess ein Shell-Skript sein kann, das keine Session-ID hat.)

Dieses Ereignis wird generiert, nachdem das Kind im Hintergrund gestartet wurde und etwas Zeit zum Hochfahren und Arbeiten erhalten hat. Wenn das Kind normal startet, während die Eltern noch warten, hat das Feld den Wert "ready". Wenn das Kind zu langsam startet und die Eltern ein Timeout haben, hat das Feld den Wert "timeout". Wenn das Kind startet, aber die Eltern es nicht abfragen können, hat das Feld den Wert "error".

Nachdem der Elternprozess dieses Ereignis ausgegeben hat, gibt er alle seine Handles an den Kindprozess frei und behandelt das Kind als Hintergrunddaemon. Selbst wenn das Kind schließlich hochfährt, gibt der Elternprozess kein aktualisiertes Ereignis aus.

Beachten Sie, dass das Feld t_rel die beobachtete Laufzeit in Sekunden enthält, als der Elternprozess das Kind in den Hintergrund entlassen hat. Es wird davon ausgegangen, dass das Kind ein langlebiger Daemonprozess ist und den Elternprozess überleben kann. Daher sollten die Zeitangaben der Elternprozess-Kindereignisse nicht mit den atexit-Zeiten des Kindes verglichen werden.

"exec"

Dieses Ereignis wird generiert, bevor Git versucht, einen anderen Befehl anstelle des Startens eines Kindprozesses auszuführen (exec()).

{
	"event":"exec",
	...
	"exec_id":0,
	"exe":"git",
	"argv":["foo", "bar"]
}

Das Feld "exec_id" ist eine Befehls-eindeutige ID und nur nützlich, wenn das exec() fehlschlägt und ein entsprechendes exec_result-Ereignis generiert wird.

"exec_result"

Dieses Ereignis wird generiert, wenn das exec() fehlschlägt und die Kontrolle an den aktuellen Git-Befehl zurückgibt.

{
	"event":"exec_result",
	...
	"exec_id":0,
	"code":1      # error code (errno) from exec()
}
"thread_start"

Dieses Ereignis wird generiert, wenn ein Thread gestartet wird. Es wird **innerhalb** der Thread-Proc des neuen Threads generiert (da es auf Daten im Thread-lokalen Speicher des Threads zugreifen muss).

{
	"event":"thread_start",
	...
	"thread":"th02:preload_thread" # thread name
}
"thread_exit"

Dieses Ereignis wird generiert, wenn ein Thread beendet wird. Es wird **innerhalb** der Thread-Proc des Threads generiert.

{
	"event":"thread_exit",
	...
	"thread":"th02:preload_thread", # thread name
	"t_rel":0.007328                # thread elapsed time
}
"def_param"

Dieses Ereignis wird generiert, um einen globalen Parameter zu protokollieren, wie z. B. eine Konfigurationseinstellung, ein Kommandozeilenflag oder eine Umgebungsvariable.

{
	"event":"def_param",
	...
	"scope":"global",
	"param":"core.abbrev",
	"value":"7"
}
"def_repo"

Dieses Ereignis definiert eine Repo-ID und ordnet sie dem Stammverzeichnis des Worktrees zu.

{
	"event":"def_repo",
	...
	"repo":1,
	"worktree":"/Users/jeffhost/work/gfw"
}

Wie bereits erwähnt, ist die Repo-ID derzeit immer 1, daher wird es nur ein def_repo-Ereignis geben. Später, wenn In-Proc-Submodule unterstützt werden, sollte für jedes besuchte Submodul ein def_repo-Ereignis ausgegeben werden.

"region_enter"

Dieses Ereignis wird beim Eintritt in eine Region generiert.

{
	"event":"region_enter",
	...
	"repo":1,                # optional
	"nesting":1,             # current region stack depth
	"category":"index",      # optional
	"label":"do_read_index", # optional
	"msg":".git/index"       # optional
}

Das Feld category kann in einer zukünftigen Erweiterung für die kategorienbasierte Filterung verwendet werden.

GIT_TRACE2_EVENT_NESTING oder trace2.eventNesting können verwendet werden, um tief verschachtelte Regionen und Datenereignisse zu filtern. Der Standardwert ist "2".

"region_leave"

Dieses Ereignis wird beim Verlassen einer Region generiert.

{
	"event":"region_leave",
	...
	"repo":1,                # optional
	"t_rel":0.002876,        # time spent in region in seconds
	"nesting":1,             # region stack depth
	"category":"index",      # optional
	"label":"do_read_index", # optional
	"msg":".git/index"       # optional
}
"data"

Dieses Ereignis wird generiert, um ein Thread- und regionslokales Schlüssel/Wert-Paar zu protokollieren.

{
	"event":"data",
	...
	"repo":1,              # optional
	"t_abs":0.024107,      # absolute elapsed time
	"t_rel":0.001031,      # elapsed time in region/thread
	"nesting":2,           # region stack depth
	"category":"index",
	"key":"read/cache_nr",
	"value":"3552"
}

Das Feld "value" kann eine Ganzzahl oder eine Zeichenkette sein.

"data-json"

Dieses Ereignis wird generiert, um eine vorformatierte JSON-Zeichenkette mit strukturierten Daten zu protokollieren.

{
	"event":"data_json",
	...
	"repo":1,              # optional
	"t_abs":0.015905,
	"t_rel":0.015905,
	"nesting":1,
	"category":"process",
	"key":"windows/ancestry",
	"value":["bash.exe","bash.exe"]
}
"th_timer"

Dieses Ereignis protokolliert die Zeitspanne, während der ein Stoppuhr-Timer im Thread lief. Dieses Ereignis wird generiert, wenn ein Thread beendet wird, für Timer, die pro-Thread-Ereignisse angefordert haben.

{
	"event":"th_timer",
	...
	"category":"my_category",
	"name":"my_timer",
	"intervals":5,         # number of time it was started/stopped
	"t_total":0.052741,    # total time in seconds it was running
	"t_min":0.010061,      # shortest interval
	"t_max":0.011648       # longest interval
}
"timer"

Dieses Ereignis protokolliert die Zeitspanne, während der ein Stoppuhr-Timer aggregiert über alle Threads lief. Dieses Ereignis wird generiert, wenn der Prozess beendet wird.

{
	"event":"timer",
	...
	"category":"my_category",
	"name":"my_timer",
	"intervals":5,         # number of time it was started/stopped
	"t_total":0.052741,    # total time in seconds it was running
	"t_min":0.010061,      # shortest interval
	"t_max":0.011648       # longest interval
}
"th_counter"

Dieses Ereignis protokolliert den Wert einer Zählervariablen in einem Thread. Dieses Ereignis wird generiert, wenn ein Thread beendet wird, für Zähler, die pro-Thread-Ereignisse angefordert haben.

{
	"event":"th_counter",
	...
	"category":"my_category",
	"name":"my_counter",
	"count":23
}
"counter"

Dieses Ereignis protokolliert den Wert einer Zählervariablen über alle Threads hinweg. Dieses Ereignis wird generiert, wenn der Prozess beendet wird. Der hier gemeldete Gesamtwert ist die Summe über alle Threads.

{
	"event":"counter",
	...
	"category":"my_category",
	"name":"my_counter",
	"count":23
}
"printf"

Dieses Ereignis protokolliert eine menschenlesbare Nachricht ohne besondere Formatierungsrichtlinien.

{
	"event":"printf",
	...
	"t_abs":0.015905,      # elapsed time in seconds
	"msg":"Hello world"    # optional
}

Beispielhafte Verwendung der Trace2 API

Hier ist eine hypothetische Verwendung der Trace2 API, die die beabsichtigte Verwendung zeigt (ohne sich um die tatsächlichen Git-Details zu kümmern).

Initialisierung

Die Initialisierung geschieht in main(). Im Hintergrund werden ein atexit- und ein signal-Handler registriert.

int main(int argc, const char **argv)
{
	int exit_code;

	trace2_initialize();
	trace2_cmd_start(argv);

	exit_code = cmd_main(argc, argv);

	trace2_cmd_exit(exit_code);

	return exit_code;
}
Befehlsdetails

Nachdem die Grundlagen eingerichtet sind, können zusätzliche Befehlsinformationen an Trace2 gesendet werden, sobald sie entdeckt werden.

int cmd_checkout(int argc, const char **argv)
{
	trace2_cmd_name("checkout");
	trace2_cmd_mode("branch");
	trace2_def_repo(the_repository);

	// emit "def_param" messages for "interesting" config settings.
	trace2_cmd_list_config();

	if (do_something())
	    trace2_cmd_error("Path '%s': cannot do something", path);

	return 0;
}
Kindprozesse

Code, der Kindprozesse startet, umschließen.

void run_child(...)
{
	int child_exit_code;
	struct child_process cmd = CHILD_PROCESS_INIT;
	...
	cmd.trace2_child_class = "editor";

	trace2_child_start(&cmd);
	child_exit_code = spawn_child_and_wait_for_it();
	trace2_child_exit(&cmd, child_exit_code);
}

Zum Beispiel startete der folgende fetch-Befehl ssh, index-pack, rev-list und gc. Dieses Beispiel zeigt auch, dass fetch 5,199 Sekunden dauerte und davon 4,932 in ssh verbraucht wurden.

$ export GIT_TRACE2_BRIEF=1
$ export GIT_TRACE2=~/log.normal
$ git fetch origin
...
$ cat ~/log.normal
version 2.20.1.vfs.1.1.47.g534dbe1ad1
start git fetch origin
worktree /Users/jeffhost/work/gfw
cmd_name fetch (fetch)
child_start[0] ssh git@github.com ...
child_start[1] git index-pack ...
... (Trace2 events from child processes omitted)
child_exit[1] pid:14707 code:0 elapsed:0.076353
child_exit[0] pid:14706 code:0 elapsed:4.931869
child_start[2] git rev-list ...
... (Trace2 events from child process omitted)
child_exit[2] pid:14708 code:0 elapsed:0.110605
child_start[3] git gc --auto
... (Trace2 events from child process omitted)
child_exit[3] pid:14709 code:0 elapsed:0.006240
exit elapsed:5.198503 code:0
atexit elapsed:5.198541 code:0

Wenn ein Git-Prozess ein (direktes oder indirektes) Kind eines anderen Git-Prozesses ist, erbt er Trace2-Kontextinformationen. Dies ermöglicht es dem Kind, die Befehlshierarchie auszugeben. Dieses Beispiel zeigt gc als child[3] von fetch. Wenn der gc-Prozess seinen Namen als "gc" meldet, meldet er auch die Hierarchie als "fetch/gc". (In diesem Beispiel sind Trace2-Nachrichten vom Kindprozess zur besseren Lesbarkeit eingerückt.)

$ export GIT_TRACE2_BRIEF=1
$ export GIT_TRACE2=~/log.normal
$ git fetch origin
...
$ cat ~/log.normal
version 2.20.1.160.g5676107ecd.dirty
start git fetch official
worktree /Users/jeffhost/work/gfw
cmd_name fetch (fetch)
...
child_start[3] git gc --auto
    version 2.20.1.160.g5676107ecd.dirty
    start /Users/jeffhost/work/gfw/git gc --auto
    worktree /Users/jeffhost/work/gfw
    cmd_name gc (fetch/gc)
    exit elapsed:0.001959 code:0
    atexit elapsed:0.001997 code:0
child_exit[3] pid:20303 code:0 elapsed:0.007564
exit elapsed:3.868938 code:0
atexit elapsed:3.868970 code:0
Regionen

Regionen können verwendet werden, um einen interessanten Codeabschnitt zu messen.

void wt_status_collect(struct wt_status *s)
{
	trace2_region_enter("status", "worktrees", s->repo);
	wt_status_collect_changes_worktree(s);
	trace2_region_leave("status", "worktrees", s->repo);

	trace2_region_enter("status", "index", s->repo);
	wt_status_collect_changes_index(s);
	trace2_region_leave("status", "index", s->repo);

	trace2_region_enter("status", "untracked", s->repo);
	wt_status_collect_untracked(s);
	trace2_region_leave("status", "untracked", s->repo);
}

void wt_status_print(struct wt_status *s)
{
	trace2_region_enter("status", "print", s->repo);
	switch (s->status_format) {
	    ...
	}
	trace2_region_leave("status", "print", s->repo);
}

In diesem Beispiel lief das Scannen nach nicht nachverfolgten Dateien von +0,012568 bis +0,027149 (seit Beginn des Prozesses) und dauerte 0,014581 Sekunden.

$ export GIT_TRACE2_PERF_BRIEF=1
$ export GIT_TRACE2_PERF=~/log.perf
$ git status
...

$ cat ~/log.perf
d0 | main                     | version      |     |           |           |            | 2.20.1.160.g5676107ecd.dirty
d0 | main                     | start        |     |  0.001173 |           |            | git status
d0 | main                     | def_repo     | r1  |           |           |            | worktree:/Users/jeffhost/work/gfw
d0 | main                     | cmd_name     |     |           |           |            | status (status)
...
d0 | main                     | region_enter | r1  |  0.010988 |           | status     | label:worktrees
d0 | main                     | region_leave | r1  |  0.011236 |  0.000248 | status     | label:worktrees
d0 | main                     | region_enter | r1  |  0.011260 |           | status     | label:index
d0 | main                     | region_leave | r1  |  0.012542 |  0.001282 | status     | label:index
d0 | main                     | region_enter | r1  |  0.012568 |           | status     | label:untracked
d0 | main                     | region_leave | r1  |  0.027149 |  0.014581 | status     | label:untracked
d0 | main                     | region_enter | r1  |  0.027411 |           | status     | label:print
d0 | main                     | region_leave | r1  |  0.028741 |  0.001330 | status     | label:print
d0 | main                     | exit         |     |  0.028778 |           |            | code:0
d0 | main                     | atexit       |     |  0.028809 |           |            | code:0

Regionen können verschachtelt sein. Dies führt beispielsweise dazu, dass Nachrichten im PERF-Ziel eingerückt werden. Die verstrichenen Zeiten sind, wie erwartet, relativ zum Beginn der entsprechenden Verschachtelungsebene. Wenn wir zum Beispiel eine Region-Nachricht hinzufügen zu

static enum path_treatment read_directory_recursive(struct dir_struct *dir,
	struct index_state *istate, const char *base, int baselen,
	struct untracked_cache_dir *untracked, int check_only,
	int stop_at_first_file, const struct pathspec *pathspec)
{
	enum path_treatment state, subdir_state, dir_state = path_none;

	trace2_region_enter_printf("dir", "read_recursive", NULL, "%.*s", baselen, base);
	...
	trace2_region_leave_printf("dir", "read_recursive", NULL, "%.*s", baselen, base);
	return dir_state;
}

können wir die Zeit, die für das Scannen nach nicht nachverfolgten Dateien aufgewendet wurde, weiter untersuchen.

$ export GIT_TRACE2_PERF_BRIEF=1
$ export GIT_TRACE2_PERF=~/log.perf
$ git status
...
$ cat ~/log.perf
d0 | main                     | version      |     |           |           |            | 2.20.1.162.gb4ccea44db.dirty
d0 | main                     | start        |     |  0.001173 |           |            | git status
d0 | main                     | def_repo     | r1  |           |           |            | worktree:/Users/jeffhost/work/gfw
d0 | main                     | cmd_name     |     |           |           |            | status (status)
...
d0 | main                     | region_enter | r1  |  0.015047 |           | status     | label:untracked
d0 | main                     | region_enter |     |  0.015132 |           | dir        | ..label:read_recursive
d0 | main                     | region_enter |     |  0.016341 |           | dir        | ....label:read_recursive vcs-svn/
d0 | main                     | region_leave |     |  0.016422 |  0.000081 | dir        | ....label:read_recursive vcs-svn/
d0 | main                     | region_enter |     |  0.016446 |           | dir        | ....label:read_recursive xdiff/
d0 | main                     | region_leave |     |  0.016522 |  0.000076 | dir        | ....label:read_recursive xdiff/
d0 | main                     | region_enter |     |  0.016612 |           | dir        | ....label:read_recursive git-gui/
d0 | main                     | region_enter |     |  0.016698 |           | dir        | ......label:read_recursive git-gui/po/
d0 | main                     | region_enter |     |  0.016810 |           | dir        | ........label:read_recursive git-gui/po/glossary/
d0 | main                     | region_leave |     |  0.016863 |  0.000053 | dir        | ........label:read_recursive git-gui/po/glossary/
...
d0 | main                     | region_enter |     |  0.031876 |           | dir        | ....label:read_recursive builtin/
d0 | main                     | region_leave |     |  0.032270 |  0.000394 | dir        | ....label:read_recursive builtin/
d0 | main                     | region_leave |     |  0.032414 |  0.017282 | dir        | ..label:read_recursive
d0 | main                     | region_leave | r1  |  0.032454 |  0.017407 | status     | label:untracked
...
d0 | main                     | exit         |     |  0.034279 |           |            | code:0
d0 | main                     | atexit       |     |  0.034322 |           |            | code:0

Trace2-Regionen sind ähnlich wie die bestehenden trace_performance_enter() und trace_performance_leave() Routinen, sind aber Thread-sicher und verwalten Thread-lokale Stacks von Timern.

Datenmeldungen

Datenmeldungen, die einer Region hinzugefügt werden.

int read_index_from(struct index_state *istate, const char *path,
	const char *gitdir)
{
	trace2_region_enter_printf("index", "do_read_index", the_repository, "%s", path);

	...

	trace2_data_intmax("index", the_repository, "read/version", istate->version);
	trace2_data_intmax("index", the_repository, "read/cache_nr", istate->cache_nr);

	trace2_region_leave_printf("index", "do_read_index", the_repository, "%s", path);
}

Dieses Beispiel zeigt, dass der Index 3552 Einträge enthielt.

$ export GIT_TRACE2_PERF_BRIEF=1
$ export GIT_TRACE2_PERF=~/log.perf
$ git status
...
$ cat ~/log.perf
d0 | main                     | version      |     |           |           |            | 2.20.1.156.gf9916ae094.dirty
d0 | main                     | start        |     |  0.001173 |           |            | git status
d0 | main                     | def_repo     | r1  |           |           |            | worktree:/Users/jeffhost/work/gfw
d0 | main                     | cmd_name     |     |           |           |            | status (status)
d0 | main                     | region_enter | r1  |  0.001791 |           | index      | label:do_read_index .git/index
d0 | main                     | data         | r1  |  0.002494 |  0.000703 | index      | ..read/version:2
d0 | main                     | data         | r1  |  0.002520 |  0.000729 | index      | ..read/cache_nr:3552
d0 | main                     | region_leave | r1  |  0.002539 |  0.000748 | index      | label:do_read_index .git/index
...
Thread-Ereignisse

Thread-Nachrichten, die zu einem Thread-Prozess hinzugefügt werden.

Zum Beispiel kann der Multi-Thread-Code preload-index mit einer Region um den Thread-Pool und dann pro-Thread-Start- und Exit-Ereignissen innerhalb des Thread-Prozesses instrumentiert werden.

static void *preload_thread(void *_data)
{
	// start the per-thread clock and emit a message.
	trace2_thread_start("preload_thread");

	// report which chunk of the array this thread was assigned.
	trace2_data_intmax("index", the_repository, "offset", p->offset);
	trace2_data_intmax("index", the_repository, "count", nr);

	do {
	    ...
	} while (--nr > 0);
	...

	// report elapsed time taken by this thread.
	trace2_thread_exit();
	return NULL;
}

void preload_index(struct index_state *index,
	const struct pathspec *pathspec,
	unsigned int refresh_flags)
{
	trace2_region_enter("index", "preload", the_repository);

	for (i = 0; i < threads; i++) {
	    ... /* create thread */
	}

	for (i = 0; i < threads; i++) {
	    ... /* join thread */
	}

	trace2_region_leave("index", "preload", the_repository);
}

In diesem Beispiel wurde preload_index() vom main-Thread ausgeführt und startete die Region preload. Sieben Threads, benannt von th01:preload_thread bis th07:preload_thread, wurden gestartet. Ereignisse von jedem Thread werden atomar an den gemeinsamen Zielstream angehängt, wenn sie auftreten, sodass sie in zufälliger Reihenfolge im Verhältnis zu anderen Threads erscheinen können. Schließlich wartet der Hauptthread darauf, dass die Threads beendet werden, und verlässt die Region.

Datenereignisse sind mit dem aktiven Threadnamen gekennzeichnet. Sie werden verwendet, um pro-Thread-Parameter zu melden.

$ export GIT_TRACE2_PERF_BRIEF=1
$ export GIT_TRACE2_PERF=~/log.perf
$ git status
...
$ cat ~/log.perf
...
d0 | main                     | region_enter | r1  |  0.002595 |           | index      | label:preload
d0 | th01:preload_thread      | thread_start |     |  0.002699 |           |            |
d0 | th02:preload_thread      | thread_start |     |  0.002721 |           |            |
d0 | th01:preload_thread      | data         | r1  |  0.002736 |  0.000037 | index      | offset:0
d0 | th02:preload_thread      | data         | r1  |  0.002751 |  0.000030 | index      | offset:2032
d0 | th03:preload_thread      | thread_start |     |  0.002711 |           |            |
d0 | th06:preload_thread      | thread_start |     |  0.002739 |           |            |
d0 | th01:preload_thread      | data         | r1  |  0.002766 |  0.000067 | index      | count:508
d0 | th06:preload_thread      | data         | r1  |  0.002856 |  0.000117 | index      | offset:2540
d0 | th03:preload_thread      | data         | r1  |  0.002824 |  0.000113 | index      | offset:1016
d0 | th04:preload_thread      | thread_start |     |  0.002710 |           |            |
d0 | th02:preload_thread      | data         | r1  |  0.002779 |  0.000058 | index      | count:508
d0 | th06:preload_thread      | data         | r1  |  0.002966 |  0.000227 | index      | count:508
d0 | th07:preload_thread      | thread_start |     |  0.002741 |           |            |
d0 | th07:preload_thread      | data         | r1  |  0.003017 |  0.000276 | index      | offset:3048
d0 | th05:preload_thread      | thread_start |     |  0.002712 |           |            |
d0 | th05:preload_thread      | data         | r1  |  0.003067 |  0.000355 | index      | offset:1524
d0 | th05:preload_thread      | data         | r1  |  0.003090 |  0.000378 | index      | count:508
d0 | th07:preload_thread      | data         | r1  |  0.003037 |  0.000296 | index      | count:504
d0 | th03:preload_thread      | data         | r1  |  0.002971 |  0.000260 | index      | count:508
d0 | th04:preload_thread      | data         | r1  |  0.002983 |  0.000273 | index      | offset:508
d0 | th04:preload_thread      | data         | r1  |  0.007311 |  0.004601 | index      | count:508
d0 | th05:preload_thread      | thread_exit  |     |  0.008781 |  0.006069 |            |
d0 | th01:preload_thread      | thread_exit  |     |  0.009561 |  0.006862 |            |
d0 | th03:preload_thread      | thread_exit  |     |  0.009742 |  0.007031 |            |
d0 | th06:preload_thread      | thread_exit  |     |  0.009820 |  0.007081 |            |
d0 | th02:preload_thread      | thread_exit  |     |  0.010274 |  0.007553 |            |
d0 | th07:preload_thread      | thread_exit  |     |  0.010477 |  0.007736 |            |
d0 | th04:preload_thread      | thread_exit  |     |  0.011657 |  0.008947 |            |
d0 | main                     | region_leave | r1  |  0.011717 |  0.009122 | index      | label:preload
...
d0 | main                     | exit         |     |  0.029996 |           |            | code:0
d0 | main                     | atexit       |     |  0.030027 |           |            | code:0

In diesem Beispiel dauerte die Region preload 0,009122 Sekunden. Die 7 Threads benötigten zwischen 0,006069 und 0,008947 Sekunden, um ihren Teil des Index zu bearbeiten. Thread "th01" bearbeitete 508 Elemente bei Offset 0. Thread "th02" bearbeitete 508 Elemente bei Offset 2032. Thread "th04" bearbeitete 508 Elemente bei Offset 508.

Dieses Beispiel zeigt auch, dass Thread-Namen auf eine "racey"-Weise zugewiesen werden, wenn jeder Thread startet.

Config (def param) Ereignisse

Interessante Konfigurationswerte werden in das Trace2-Log ausgegeben.

Wir können optional Konfigurationsereignisse ausgeben, siehe trace2.configparams in git-config[1], wie man sie aktiviert.

$ git config --system color.ui never
$ git config --global color.ui always
$ git config --local color.ui auto
$ git config --list --show-scope | grep 'color.ui'
system  color.ui=never
global  color.ui=always
local   color.ui=auto

Dann markieren wir die Konfiguration color.ui als "interessant" mit GIT_TRACE2_CONFIG_PARAMS

$ export GIT_TRACE2_PERF_BRIEF=1
$ export GIT_TRACE2_PERF=~/log.perf
$ export GIT_TRACE2_CONFIG_PARAMS=color.ui
$ git version
...
$ cat ~/log.perf
d0 | main                     | version      |     |           |           |              | ...
d0 | main                     | start        |     |  0.001642 |           |              | /usr/local/bin/git version
d0 | main                     | cmd_name     |     |           |           |              | version (version)
d0 | main                     | def_param    |     |           |           | scope:system | color.ui:never
d0 | main                     | def_param    |     |           |           | scope:global | color.ui:always
d0 | main                     | def_param    |     |           |           | scope:local  | color.ui:auto
d0 | main                     | data         | r0  |  0.002100 |  0.002100 | fsync        | fsync/writeout-only:0
d0 | main                     | data         | r0  |  0.002126 |  0.002126 | fsync        | fsync/hardware-flush:0
d0 | main                     | exit         |     |  0.000470 |           |              | code:0
d0 | main                     | atexit       |     |  0.000477 |           |              | code:0
Stoppuhr-Timer-Ereignisse

Messen Sie die Zeit, die in einem Funktionsaufruf oder einem Codebereich verbracht wurde, der von vielen Stellen im Code während der Lebensdauer des Prozesses aufgerufen werden könnte.

static void expensive_function(void)
{
	trace2_timer_start(TRACE2_TIMER_ID_TEST1);
	...
	sleep_millisec(1000); // Do something expensive
	...
	trace2_timer_stop(TRACE2_TIMER_ID_TEST1);
}

static int ut_100timer(int argc, const char **argv)
{
	...

	expensive_function();

	// Do something else 1...

	expensive_function();

	// Do something else 2...

	expensive_function();

	return 0;
}

In diesem Beispiel messen wir die Gesamtzeit, die in expensive_function() verbracht wurde, unabhängig davon, wann sie im gesamten Programmablauf aufgerufen wird.

$ export GIT_TRACE2_PERF_BRIEF=1
$ export GIT_TRACE2_PERF=~/log.perf
$ t/helper/test-tool trace2 100timer 3 1000
...
$ cat ~/log.perf
d0 | main                     | version      |     |           |           |              | ...
d0 | main                     | start        |     |  0.001453 |           |              | t/helper/test-tool trace2 100timer 3 1000
d0 | main                     | cmd_name     |     |           |           |              | trace2 (trace2)
d0 | main                     | exit         |     |  3.003667 |           |              | code:0
d0 | main                     | timer        |     |           |           | test         | name:test1 intervals:3 total:3.001686 min:1.000254 max:1.000929
d0 | main                     | atexit       |     |  3.003796 |           |              | code:0

Zukünftige Arbeiten

Beziehung zur bestehenden Trace API (api-trace.txt)

Es gibt einige Probleme zu lösen, bevor wir vollständig zu Trace2 wechseln können.

  • Aktualisierung bestehender Tests, die GIT_TRACE-Format-Nachrichten erwarten.

  • Wie können benutzerdefinierte GIT_TRACE_<key>-Nachrichten am besten behandelt werden?

    • Der GIT_TRACE_<key>-Mechanismus ermöglicht es jedem <key>, in eine andere Datei zu schreiben (zusätzlich zu nur stderr).

    • Möchten wir diese Fähigkeit beibehalten oder einfach in die bestehenden Trace2-Ziele schreiben (und <key> in eine "Kategorie" umwandeln).