Git - api-trace2 ドキュメント

api-trace2 最終更新日: 2.47.0

Trace2 API は、デバッグ、パフォーマンス、テレメトリ情報を stderr またはファイルに出力するために使用できます。Trace2機能は、1つ以上のTrace2ターゲットを有効にしない限り、非アクティブです。

Trace2 API は、既存のGIT_TRACEおよびGIT_TRACE_PERFORMANCE機能によって提供される既存の(Trace1)printf()スタイルのトレースに置き換えることを目的としています。初期実装中は、Trace2とTrace1が並行して動作する場合があります。

Trace2 API は、(start: argv)や(exit: {exit-code, elapsed-time})など、既知のフィールドを持つ一連のハイレベルメッセージを定義します。

Gitコードベース全体にわたるTrace2インストルメンテーションは、有効なTrace2ターゲットにTrace2メッセージを送信します。ターゲットはこれらのメッセージの内容を目的固有の形式に変換し、イベントをデータストリームに書き込みます。このようにして、Trace2 API は多くの異なる種類の分析を推進できます。

ターゲットはVTableを使用して定義されており、将来他の形式に簡単に拡張できます。これは、たとえばバイナリ形式を定義するために使用できます。

Trace2は、システムとグローバル設定ファイルのtrace2.*設定値とGIT_TRACE2*環境変数を使用して制御されます。Trace2はリポジトリローカルまたはワークツリー設定ファイルからは読み取らず、-cコマンドライン設定も尊重しません。

Trace2 ターゲット

Trace2は、以下のTrace2ターゲットのセットを定義します。フォーマットの詳細については、後のセクションで説明します。

標準フォーマットターゲット

標準フォーマットターゲットは従来のprintf()フォーマットであり、GIT_TRACEフォーマットに似ています。このフォーマットは、GIT_TRACE2環境変数またはtrace2.normalTargetシステムまたはグローバル設定を使用して有効になります。

例えば

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

または

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

は以下を出力します

$ 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

パフォーマンスフォーマットターゲット

パフォーマンスフォーマットターゲット(PERF)は、GIT_TRACE_PERFORMANCEに代わる列ベースのフォーマットであり、開発とテストに適しており、gprofなどのツールを補完するために使用できます。このフォーマットは、GIT_TRACE2_PERF環境変数またはtrace2.perfTargetシステムまたはグローバル設定を使用して有効になります。

例えば

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

または

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

は以下を出力します

$ 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

イベントフォーマットターゲット

イベントフォーマットターゲットは、テレメトリ分析に適したイベントデータのJSONベースのフォーマットです。このフォーマットは、GIT_TRACE2_EVENT環境変数またはtrace2.eventTargetシステムまたはグローバル設定を使用して有効になります。

例えば

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

または

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

は以下を出力します

$ 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}

ターゲットの有効化

ターゲットを有効にするには、対応する環境変数またはシステムまたはグローバル設定値を以下のいずれかに設定します。

0 または false - ターゲットを無効にします。
1 または true - STDERRに書き込みます。
[2-9] - すでに開いているファイル記述子に書き込みます。
<絶対パス名> - ファイルに追記モードで書き込みます。ターゲットがすでに存在し、ディレクトリである場合、トレースは指定されたディレクトリの下にあるファイル(プロセスごとに1つ)に書き込まれます。
af_unix:[<ソケットタイプ>:]<絶対パス名> - Unixドメインソケットに書き込みます(サポートされているプラットフォームの場合)。ソケットタイプはstreamまたはdgramのいずれかです。省略された場合、Gitは両方を試みます。

トレースファイルがターゲットディレクトリに書き込まれる場合、SIDの最後のコンポーネントに従って名前が付けられます(ファイル名の競合を避けるためにカウンタが付く場合があります)。

Trace2 API

Trace2公開APIはtrace2.hで定義および文書化されています。詳細については、そちらを参照してください。すべての公開関数とマクロにはtrace2_プレフィックスが付けられており、trace2.cに実装されています。

公開Trace2データ構造はありません。

Trace2コードは、trace2/ディレクトリに一連のプライベート関数とデータ型も定義しています。これらのシンボルにはtr2_プレフィックスが付けられており、trace2.c(またはtrace2/内の他のプライベートソースファイル)の関数によってのみ使用される必要があります。

公開関数とマクロの規則

一部の関数は、fileとline-number引数を取ることを示すために_fl()サフィックスが付いています。

一部の関数は、va_list引数も取ることを示すために_va_fl()サフィックスが付いています。

一部の関数は、可変数の引数を持つprintf()スタイルのフォーマットも取ることを示すために_printf_fl()サフィックスが付いています。

これらの詳細のほとんどを隠すために、CPPラッパーマクロが定義されています。

Trace2ターゲットフォーマット

NORMALフォーマット

イベントは、次の形式の行として書き込まれます。

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

<event-name>: はイベント名です。
<event-message>: は、人間が読むための自由形式のprintf()メッセージです。

これには、エスケープされていない埋め込みLFまたはCRLF文字が含まれる場合があるため、イベントは複数の行にまたがる可能性があります。

GIT_TRACE2_BRIEFまたはtrace2.normalBriefがtrueの場合、time、filename、lineフィールドは省略されます。

このターゲットは、(GIT_TRACEのように)より概要的なものであり、他のターゲットほど詳細ではありません。たとえば、スレッド、リージョン、データメッセージは無視されます。

PERFフォーマット

イベントは、次の形式の行として書き込まれます。

[<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>: はgitプロセスの深さです。これは、親gitプロセスの数です。トップレベルのgitコマンドの深さは"d0"です。その子プロセスの深さは"d1"です。2番目のレベルの子プロセスの深さは"d2"となります。
<thread-name>: は、スレッドの一意の名前です。プライマリ・スレッドは"main"と呼ばれます。他のスレッド名は"th%d:%s"という形式で、一意の番号とスレッドプロセスの名前が含まれています。
<event-name>: はイベント名です。
<repo-id>: 存在する場合、使用中のリポジトリを示す番号です。リポジトリが開かれると、def_repoイベントが送信されます。これにより、repo-idと関連付けられたワークツリーが定義されます。その後のrepo固有のイベントはこのrepo-idを参照します。

現在、これはメインリポジトリでは常に"r1"です。このフィールドは、将来のプロセス内サブモジュールを見越したものです。
<t_abs>: 存在する場合、プログラムの開始からの経過秒数です。
<t_rel>: 存在する場合、現在のリージョンの開始からの経過秒数です。スレッド終了イベントの場合、スレッドの経過時間です。
<category>: は、領域イベントとデータイベントに存在し、「index」や「status」などの大まかなカテゴリを示すために使用されます。
<perf-event-message>: は、人間が読むための自由形式のprintf()メッセージです。

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

GIT_TRACE2_PERF_BRIEFまたはtrace2.perfBriefがtrueの場合、time、file、lineフィールドは省略されます。

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

PERFターゲットは、開発中の対話型パフォーマンス分析を目的としており、非常にノイズが多いです。

イベント形式

各イベントは、複数のキー/値のペアを含むJSONオブジェクトであり、1行で記述され、LFで終わります。

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

一部のキー/値のペアはすべてのイベントに共通しており、一部はイベント固有です。

共通キー/値ペア

以下のキー/値のペアは、すべてのイベントに共通しています。

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

"event":<event>: はイベント名です。
"sid":<sid>: はセッションIDです。これは、プロセスインスタンスを一意に識別するための文字列であり、プロセスによって発行されたすべてのイベントを識別するために使用されます。OSによってPIDが再利用されるため、PIDの代わりにセッションIDが使用されます。子gitプロセスの場合、親gitプロセスのセッションIDが接頭辞として追加され、後処理中に親子関係を識別できるようにします。
"thread":<thread>: はスレッド名です。
"time":<time>: はイベントのUTC時間です。
"file":<filename>: はイベントを生成するソースファイルです。
"line":<line-number>: はイベントを生成する整数型のソース行番号です。
"repo":<repo-id>: 存在する場合、前に説明した整数型のrepo-idです。

GIT_TRACE2_EVENT_BRIEFまたはtrace2.eventBriefがtrueの場合、fileとlineフィールドはすべてのイベントから省略され、timeフィールドは「start」と「atexit」イベントにのみ存在します。

イベント固有のキー/値ペア

"version"

このイベントは、実行可能ファイルとイベント形式のバージョンを示します。トレースセッションの最初のイベントである必要があります。新しいイベントタイプが追加された場合、既存のフィールドが削除された場合、または既存のイベントやフィールドの解釈に大きな変更があった場合、イベント形式のバージョンはインクリメントされます。新しいフィールドを既存のイベントに追加するなど、小さな変更では、イベント形式のバージョンのインクリメントは必要ありません。

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

"too_many_files"

このイベントは、ターゲットのトレースディレクトリにファイルが多すぎる場合（trace2.maxFiles構成オプションを参照）、git-trace2-discardセンティネルファイルに書き込まれます。

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

"start"

このイベントには、main()によって受信された完全なargvが含まれています。

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

"exit"

このイベントは、gitがexit()を呼び出したときに発行されます。

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

"atexit"

このイベントは、最終シャットダウン中にTrace2のatexitルーチンによって発行されます。プロセスによって発行される最後のイベントである必要があります。

（ここで報告される経過時間は、「exit」イベントで報告される時間よりも長くなります。これは、他のすべてのatexitタスクが完了した後に実行されるためです。）

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

"signal"

このイベントは、プログラムがユーザーシグナルによって終了されたときに発行されます。プラットフォームによっては、シグナルイベントによって「atexit」イベントの生成が妨げられる場合があります。

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

"error"

このイベントは、BUG()、bug()、error()、die()、warning()、またはusage()関数のいずれかが呼び出されたときに発行されます。

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

エラーイベントは複数回発行される場合があります。フォーマット文字列により、ポストプロセッサは特定のエラー引数を気にせずに、タイプ別にエラーをグループ化できます。

"cmd_path"

このイベントには、git実行可能ファイルの検出された完全パスが含まれています（解決するように構成されているプラットフォームの場合）。

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

"cmd_ancestry"

このイベントには、現在のプロセスの親（およびそれ以前の世代の親）のテキストコマンド名が、最も近い親から最も遠い曽祖父母まで順番に配列で含まれています。すべてのプラットフォームで実装されているとは限りません。

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

"cmd_name"

このイベントには、このgitプロセスのコマンド名と、親gitプロセスからのコマンドの階層が含まれています。

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

通常、「name」フィールドにはコマンドの標準名が含まれています。標準名が使用できない場合、これらの特殊値のいずれかが使用されます。

"_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"

このイベントは、存在する場合、コマンドのバリアントを記述します。このイベントは複数回発行される場合があります。

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

「name」フィールドは、コマンドモードを記述するための任意の文字列です。たとえば、チェックアウトはブランチまたは個々のファイルをチェックアウトできます。そして、これらのバリエーションは通常、比較できない異なるパフォーマンス特性を持っています。

"alias"

エイリアスが展開された場合、このイベントが存在します。

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

"child_start"

このイベントは、生成されようとしている子プロセスを記述します。

{
	"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
}

「child_id」フィールドを使用して、このchild_startと対応するchild_exitイベントを一致させることができます。

「child_class」フィールドは、「editor」、「pager」、「transport/*」、「hook」などのおおまかな分類です。分類されていない子は「?」で分類されます。

"child_exit"

このイベントは、現在のプロセスがwaitpid()から戻り、子プロセスから終了情報を収集した後に生成されます。

{
	"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
}

子プロセスのセッションIDは、現在/生成しているプロセスでは使用できないため、子のPIDが後処理の手がかりとしてここに報告されています。（ただし、子プロセスはセッションIDを持たないシェルスクリプトである可能性があるため、これはあくまで手がかりです。）

t_relフィールドには、子プロセスの観測された実行時間（フォーク/実行/生成の前に開始し、waitpid()の後に停止し、OSのプロセス作成オーバーヘッドを含む）が秒単位で含まれていることに注意してください。そのため、この時間は、子プロセス自体によって報告されるatexit時間よりもわずかに長くなります。

"child_ready"

このイベントは、現在のプロセスがバックグラウンドプロセスを開始し、そのすべてへのハンドルを解放した後に生成されます。

{
	"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
}

このイベントは、子がバックグラウンドで開始され、起動して作業を開始するのに少し時間が与えられた後に生成されます。親がまだ待機している間に子が正常に起動した場合、「ready」フィールドの値は「ready」になります。子が起動が遅すぎて親がタイムアウトした場合、フィールドの値は「timeout」になります。子が起動しますが、親がプローブできない場合、フィールドの値は「error」になります。

親プロセスがこのイベントを発行した後、子プロセスへのすべてのハンドルを解放し、子をバックグラウンドデーモンとして扱います。そのため、子が最終的に起動を完了した場合でも、親は更新されたイベントを発行しません。

t_relフィールドには、親が子プロセスをバックグラウンドに解放したときの観測された実行時間が秒単位で含まれていることに注意してください。子は長時間のデーモンプロセスと想定され、親プロセスよりも長生きする可能性があります。そのため、親の子イベント時間は、子のatexit時間と比較しないでください。

"exec"

このイベントは、gitが子プロセスを開始するのではなく、別のコマンドをexec()しようとする前に生成されます。

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

「exec_id」フィールドはコマンド一意のIDであり、exec()が失敗し、対応するexec_resultイベントが生成された場合にのみ役立ちます。

"exec_result"

このイベントは、exec()が失敗し、制御が現在のgitコマンドに戻った場合に生成されます。

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

"thread_start"

このイベントは、スレッドが開始されたときに生成されます。新しいスレッドのスレッドプロセスの**内部**から生成されます（スレッドのThread Local Storageにあるデータにアクセスする必要があるため）。

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

"thread_exit"

このイベントは、スレッドが終了したときに生成されます。スレッドのスレッドプロセスの**内部**から生成されます。

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

"def_param"

このイベントは、構成設定、コマンドラインフラグ、環境変数などのグローバルパラメーターをログに記録するために生成されます。

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

"def_repo"

このイベントはrepo-idを定義し、ワークツリーのルートに関連付けます。

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

前述のように、repo-idは現在常に1であるため、def_repoイベントは1つしかありません。後で、プロセス内サブモジュールがサポートされる場合、アクセスされた各サブモジュールに対してdef_repoイベントを発行する必要があります。

"region_enter"

このイベントは、領域に入ったときに生成されます。

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

categoryフィールドは、将来の機能強化でカテゴリベースのフィルタリングを行うために使用される可能性があります。

GIT_TRACE2_EVENT_NESTINGまたはtrace2.eventNestingを使用して、深くネストされた領域イベントとデータイベントをフィルタリングできます。デフォルトは「2」です。

"region_leave"

このイベントは、領域を出たときに生成されます。

{
	"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"

このイベントは、スレッドと領域のローカルなキー/値ペアをログに記録するために生成されます。

{
	"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"
}

「value」フィールドは、整数または文字列です。

"data-json"

このイベントは、構造化データを含む事前にフォーマットされたJSON文字列をログに記録するために生成されます。

{
	"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"

このイベントは、ストップウォッチタイマーがスレッドで実行されていた時間をログに記録します。このイベントは、スレッド単位のイベントを要求したタイマーについて、スレッドが終了したときに生成されます。

{
	"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"

このイベントは、すべてのスレッドにわたって集計されたストップウォッチタイマーの実行時間をログに記録します。このイベントは、プロセスが終了したときに生成されます。

{
	"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"

このイベントは、スレッド内のカウンター変数の値をログに記録します。このイベントは、スレッド単位のイベントを要求したカウンターについて、スレッドが終了したときに生成されます。

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

"counter"

このイベントは、すべてのスレッドにわたるカウンター変数の値をログに記録します。このイベントは、プロセスが終了したときに生成されます。ここで報告される合計値は、すべてのスレッドにわたる合計です。

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

"printf"

このイベントは、特定のフォーマットガイドラインのない、人間が読めるメッセージをログに記録します。

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

Trace2 APIの使用例

ここに、実際のGitの詳細を気にせずに、意図した使用方法を示すTrace2 APIの仮想的な使用方法を示します。

初期化

初期化はmain()で行われます。バックグラウンドでは、atexitハンドラーとsignalハンドラーが登録されます。

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;
}

コマンドの詳細

基本事項が確立された後、Trace2 には、発見された追加コマンド情報が送信できます。

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;
}

子プロセス

子プロセスを生成するコードをラップします。

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);
}

たとえば、次のフェッチコマンドは、ssh、index-pack、rev-list、およびgc を生成しました。この例では、フェッチに 5.199 秒かかり、そのうち 4.932 秒が ssh であったことも示しています。

$ 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

Git プロセスが別の Git プロセスの（直接的または間接的）子プロセスである場合、Trace2 コンテキスト情報を継承します。これにより、子プロセスはコマンド階層を出力できます。この例では、gc が fetch の child[3] として示されています。gc プロセスがその名前を "gc" として報告する場合、階層も "fetch/gc" として報告します。（この例では、子プロセスからの trace2 メッセージは明確にするためにインデントされています。）

$ 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

リージョン

リージョンを使用して、興味深いコードセクションの時間を測定できます。

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);
}

この例では、追跡されていないファイルのスキャンは +0.012568 から +0.027149（プロセス開始以降）まで実行され、0.014581 秒かかりました。

$ 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

リージョンはネストできます。これにより、たとえば PERF ターゲットでメッセージがインデントされます。経過時間は、予想どおり、対応するネストレベルの開始を基準としています。たとえば、リージョンメッセージを以下に追加した場合

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;
}

追跡されていないファイルのスキャンに費やされた時間をさらに調査できます。

$ 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 リージョンは既存の `trace_performance_enter()` および `trace_performance_leave()` ルーチンに似ていますが、スレッドセーフであり、タイマーのスレッドごとのスタックを維持します。

データメッセージ

リージョンに追加されたデータメッセージ。

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);
}

この例では、インデックスに 3552 エントリが含まれていることが示されています。

$ 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
...

スレッドイベント

スレッドプロセスの追加されたスレッドメッセージ。

たとえば、マルチスレッドの preload-index コードは、スレッドプールを中心としたリージョンで計測でき、スレッドプロセス内でスレッドごとの開始イベントと終了イベントを使用できます。

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);
}

この例では、`main` スレッドによって `preload_index()` が実行され、`preload` リージョンが開始されました。`th01:preload_thread` から `th07:preload_thread` という名前の7つのスレッドが開始されました。各スレッドからのイベントは、発生時に共有ターゲットストリームにアトミックに追加されるため、他のスレッドに対してランダムな順序で表示される場合があります。最後に、メインスレッドはスレッドが終了するのを待ち、リージョンを終了します。

データイベントには、アクティブなスレッド名がタグ付けされています。これらは、スレッドごとのパラメーターを報告するために使用されます。

$ 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

この例では、preload リージョンに 0.009122 秒かかりました。7つのスレッドは、インデックスの一部を処理するのに 0.006069 秒から 0.008947 秒かかりました。「th01」スレッドはオフセット 0 で 508 個のアイテムを処理しました。「th02」スレッドはオフセット 2032 で 508 個のアイテムを処理しました。「th04」スレッドはオフセット 508 で 508 個のアイテムを処理しました。

この例では、各スレッドの開始時にスレッド名が競合的な方法で割り当てられることも示しています。

設定（def param）イベント

Trace2 ログに「興味深い」設定値をダンプします。

オプションで設定イベントを出力できます。有効化する方法については、git-config[1] の `trace2.configparams` を参照してください。

$ 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

次に、`GIT_TRACE2_CONFIG_PARAMS` を使用して、設定 `color.ui` を「興味深い」設定としてマークします。

$ 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

ストップウォッチタイマーイベント

関数呼び出しまたはコードの範囲で費やされた時間を測定します。これは、プロセスの存続期間中にコード内の多くの場所から呼び出される可能性があります。

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;
}

この例では、プログラムの全体的な流れの中でいつ呼び出されても、`expensive_function()` で費やされた合計時間を測定します。

$ 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

今後の作業

既存のトレースAPI（api-trace.txt）との関係

Trace2 に完全に切り替える前に、解決する必要がある問題がいくつかあります。

`GIT_TRACE` 形式のメッセージを想定する既存のテストの更新。
カスタム `GIT_TRACE_` メッセージを最適に処理する方法。
- `GIT_TRACE_` メカニズムにより、各は（stderr だけではなく）異なるファイルに書き込むことができます。
- その機能を維持するか、既存の Trace2 ターゲットに書き込み（を「カテゴリ」に変換）するだけです。

セットアップと設定

プロジェクトの取得と作成

基本的なスナップショット

ブランチとマージ

プロジェクトの共有と更新

検査と比較

パッチ

デバッグ

メール

外部システム

サーバー管理

ガイド

管理

内部コマンド

Trace2 ターゲット

標準フォーマットターゲット

パフォーマンスフォーマットターゲット

イベントフォーマットターゲット

ターゲットの有効化

Trace2 API

公開関数とマクロの規則

Trace2ターゲットフォーマット

NORMALフォーマット

PERFフォーマット

イベント形式

共通キー/値ペア

イベント固有のキー/値ペア

Trace2 APIの使用例

今後の作業

既存のトレースAPI（api-trace.txt）との関係