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] - 既に開かれているファイルディスクリプタに書き込みます。
<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/ 内の他のプライベートソースファイル) の関数のみが使用する必要があります。

公開関数とマクロの規約

一部の関数には _fl() サフィックスがあり、file および line-number 引数を取ることを示します。

一部の関数には _va_fl() サフィックスがあり、va_list 引数も取ることを示します。

一部の関数には _printf_fl() サフィックスがあり、可変個引数を持つ printf() スタイルの形式も取ることを示します。

これらの詳細のほとんどを隠すために、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-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 ターゲットは、開発中の対話的なパフォーマンス分析を目的としており、かなりノイズが多いです。

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":<event>: はイベント名です。
"sid":<sid>: はセッション ID です。これは、プロセスによって発行されたすべてのイベントを識別できるようにする、プロセスインスタンスを識別するための一意の文字列です。PID は OS によって再利用されるため、PID の代わりにセッション ID が使用されます。子 git プロセスの場合、セッション ID は親 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 形式を提供します。トレースセッションでは常に最初のイベントである必要があります。新しいイベントタイプが追加された場合、既存のフィールドが削除された場合、または既存のイベントやフィールドの解釈に重大な変更があった場合、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 ルーチンによって発行されます。これはプロセスによって発行される最後のイベントである必要があります。

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

{
	"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 フィールドには、子プロセスの観測された実行時間（秒単位）が含まれています（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"

このイベントは、スレッドが開始されたときに生成されます。新しいスレッドの thread-proc の**内部から**生成されます (スレッドの thread-local ストレージのデータにアクセスする必要があるため)。

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

"thread_exit"

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

{
	"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 使用例

以下に、意図された使用法を示す 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);
}

たとえば、次のフェッチコマンドは 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 がフェッチの子[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
...

スレッドイベント

thread-proc に追加されたスレッドメッセージ。

たとえば、マルチスレッドの preload-index コードは、スレッドプールを囲む領域と、thread-proc 内の各スレッドの開始および終了イベントで計測できます。

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 アイテムを処理しました。

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

Config (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

次に、設定 color.ui を 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

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

プロセス全体のライフサイクルにおいて、コード内の多くの場所から呼び出される可能性のある関数呼び出しまたはコード範囲に費やされた時間を測定します。

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> を「カテゴリ」に変換する)。

セットアップと設定

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

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

ブランチとマージ

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

検査と比較

パッチ適用

デバッグ

メール

外部システム

サーバー管理

ガイド

管理

配管コマンド