Git - api-trace2 ドキュメント

api-trace2 は 2.47.0 で最終更新されました

Trace2 APIは、デバッグ、パフォーマンス、テレメトリの情報を標準エラー出力またはファイルに出力するために使用できます。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] - 既に開かれているファイルディスクリプタに書き込みます。
<absolute-pathname> - ファイルに追記モードで書き込みます。ターゲットが既に存在しディレクトリである場合、トレースは指定されたディレクトリの下にファイル（プロセスごとに1つ）として書き込まれます。
af_unix:[<socket-type>:]<absolute-pathname> - 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

<イベント名>: はイベント名です。
<イベントメッセージ>: は、人間が読めるように意図された自由形式の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

<深さ>: はgitプロセスの深さです。これは親gitプロセスの数です。トップレベルのgitコマンドは深さの値"d0"を持ちます。その子は深さの値"d1"を持ちます。2番目のレベルの子は深さの値"d2"を持ち、以下同様です。
<スレッド名>: はスレッドの一意の名前です。プライマリスレッドは「main」と呼ばれます。その他のスレッド名は「th%d:%s」の形式で、一意の番号とスレッドプロセスの名前を含みます。
<イベント名>: はイベント名です。
<リポジトリID>: 存在する場合、使用中のリポジトリを示す数値です。リポジトリが開かれると、def_repoイベントが発行されます。これにより、リポジトリIDと関連するワークツリーが定義されます。その後のリポジトリ固有のイベントはこのリポジトリIDを参照します。

現在、これはメインリポジトリでは常に「r1」です。このフィールドは、将来のプロセス内サブモジュールを見越したものです。
<t_abs>: 存在する場合、プログラム開始からの絶対時間（秒単位）です。
<t_rel>: 存在する場合、現在のリージョンの開始からの相対時間（秒単位）です。スレッド終了イベントの場合、それはスレッドの経過時間です。
<カテゴリ>: はリージョンおよびデータイベントに存在し、「index」や「status」などの広範なカテゴリを示すために使用されます。
<パフォーマンスイベントメッセージ>: は、人間が読めるように意図された自由形式の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ターゲットは開発中の対話型パフォーマンス分析を目的としており、かなりノイズが多いです。

EVENT フォーマット

各イベントは、単一行で記述され、LFが続く複数のキー/値ペアを含むJSONオブジェクトです。

'{' <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":<イベント>: はイベント名です。
"sid":<SID>: はセッションIDです。これは、プロセスによって発行されたすべてのイベントを識別できるように、プロセスインスタンスを一意に識別するための文字列です。PIDはOSによって再利用されるため、PIDの代わりにセッションIDが使用されます。子gitプロセスの場合、セッションIDは親gitプロセスのセッションIDで先頭に付加され、後処理中に親子関係を識別できるようにします。
"thread":<スレッド>: はスレッド名です。
"time":<時間>: はイベントのUTC時間です。
"file":<ファイル名>: はイベントを生成したソースファイルです。
"line":<行番号>: はイベントを生成した整数ソース行番号です。
"repo":<リポジトリID>: 存在する場合、前述の整数リポジトリIDです。

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

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

"version"

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

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

"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フィールドには、子プロセスの観測された実行時間（秒単位）が含まれていることに注意してください（fork/exec/spawnの前から始まり、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"

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

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

このイベントはリポジトリIDを定義し、それをワークツリーのルートと関連付けます。

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

前述の通り、現在リポジトリ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 使用例

以下に、意図されたTrace2 APIの使用例を仮想的に示します（実際のGitの詳細については考慮していません）。

初期化

初期化は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);
}

例えば、以下のfetchコマンドはssh、index-pack、rev-list、gcを生成しました。この例はまた、fetchが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);
}

この例では、preload_index()はmainスレッドによって実行され、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

この例では、プリロードリージョンが0.009122秒かかりました。7つのスレッドは、インデックスのそれぞれの部分を処理するのに0.006069秒から0.008947秒かかりました。スレッド「th01」はオフセット0で508項目を処理しました。スレッド「th02」はオフセット2032で508項目を処理しました。スレッド「th04」はオフセット508で508項目を処理しました。

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

設定（デフォルトパラメータ）イベント

「興味深い」設定値を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_<key>メッセージを最適に処理する方法は？
- GIT_TRACE_<key>メカニズムでは、各<key>が異なるファイル（stderrに加えて）に書き込むことができます。
- その機能を維持したいですか、それとも既存のTrace2ターゲットに単純に書き込みたいですか（そして<key>を「カテゴリ」に変換しますか）。

セットアップと設定

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

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

ブランチとマージ

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

検査と比較

パッチ適用

デバッグ

メール

外部システム

サーバー管理

ガイド

管理

配管コマンド

Trace2 ターゲット

通常フォーマットターゲット

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

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

ターゲットの有効化

Trace2 API

公開関数とマクロの慣例

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

NORMAL フォーマット

PERF フォーマット

EVENT フォーマット

共通のキー/値ペア

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

Trace2 API 使用例

今後の作業

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