Git
English ▾ 主題 ▾ 最新版本 ▾ api-trace2 最後更新於 2.47.0

Trace2 API 可用於將除錯、效能和遙測資訊列印到 stderr 或檔案。除非明確啟用一個或多個 Trace2 目標,否則 Trace2 功能會處於非活動狀態。

Trace2 API 旨在取代現有的 (Trace1) printf() 樣式追蹤,這些追蹤由現有的 GIT_TRACEGIT_TRACE_PERFORMANCE 功能提供。在初始實作期間,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}

啟用目標

若要啟用目標,請將對應的環境變數或系統或全域組態值設定為下列其中之一

  • 0false - 停用目標。

  • 1true - 寫入至 STDERR

  • [2-9] - 寫入至已開啟的檔案描述器。

  • <絕對路徑名稱> - 以附加模式寫入至檔案。如果目標已存在且為目錄,則追蹤將會寫入至給定目錄下的檔案 (每個處理程序一個檔案)。

  • af_unix:[<socket-type>:]<絕對路徑名稱> - 寫入至 Unix DomainSocket (在支援它們的平台上)。Socket 類型可以是 streamdgram;如果省略,Git 將會嘗試兩者。

當追蹤檔案寫入至目標目錄時,它們將根據 SID 的最後一個元件命名 (可選擇在後面加上計數器以避免檔案名稱衝突)。

Trace2 API

Trace2 公用 API 在 trace2.h 中定義並記錄;請參閱它以取得更多資訊。所有公用函式和巨集都以 trace2_ 作為前綴,並在 trace2.c 中實作。

沒有公用 Trace2 資料結構。

Trace2 程式碼也在 trace2/ 目錄中定義了一組私有函式和資料類型。這些符號以 tr2_ 作為前綴,且僅應由 trace2.c (或 trace2/ 中的其他私有來源檔案) 中的函式使用。

公用函式和巨集的慣例

某些函式具有 _fl() 後綴,表示它們採用 fileline-number 引數。

某些函式具有 _va_fl() 後綴,表示它們也採用 va_list 引數。

某些函式具有 _printf_fl() 後綴,表示它們也採用具有可變引數數量的 printf() 樣式格式。

定義了 CPP 包裝器巨集,以隱藏大多數這些詳細資訊。

Trace2 目標格式

NORMAL 格式

事件會以以下形式的行寫入

[<time> SP <filename>:<line> SP+] <event-name> [[SP] <event-message>] LF
<事件名稱>

是事件名稱。

<事件訊息>

是供人使用的自由格式 printf() 訊息。

請注意,這可能包含未轉義的內嵌 LF 或 CRLF 字元,因此事件可能會跨越多行。

如果 GIT_TRACE2_BRIEFtrace2.normalBrief 為 true,則會省略 timefilenameline 欄位。

此目標旨在更像是一個摘要 (如 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"。第二層子項的深度值為 "d2",依此類推。

<執行緒名稱>

是執行緒的唯一名稱。主要執行緒稱為「main」。其他執行緒名稱的形式為「th%d:%s」,並包含唯一編號和執行緒程序的名稱。

<事件名稱>

是事件名稱。

<儲存庫 ID>

存在時,是一個指示所使用儲存庫的數字。當儲存庫開啟時,會發出 def_repo 事件。這會定義儲存庫 ID 和關聯的工作樹。後續的儲存庫特定事件將會參考此儲存庫 ID。

目前,主要儲存庫的此值一律為「r1」。此欄位是為了預期未來在程序內的子模組。

<t_abs>

存在時,是程式啟動以來經過的絕對時間 (以秒為單位)。

<t_rel>

存在時,是相對於目前區域開始的時間 (以秒為單位)。對於執行緒結束事件,它是執行緒的經過時間。

<類別>

存在於區域和資料事件,並用於指示廣泛的類別,例如「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_BRIEFtrace2.perfBrief 為 true,則會省略 timefileline 欄位。

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

PERF 目標旨在用於開發期間的互動式效能分析,且雜訊較多。

事件格式

每個事件都是一個 JSON 物件,包含多個鍵/值對,以單行寫入並後接 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。這是一個獨特的字串,用於識別程序實例,以便識別由程序發出的所有事件。使用會話 ID 而不是 PID,是因為 PID 會被作業系統回收。對於子 git 程序,會話 ID 會加上父 git 程序的會話 ID 作為前綴,以便在後處理期間識別父子關係。

"thread":<thread>

是執行緒名稱。

"time":<time>

是事件的 UTC 時間。

"file":<filename>

是產生事件的原始程式檔。

"line":<line-number>

是產生事件的原始程式碼行號 (整數)。

"repo":<repo-id>

如果存在,則是以整數表示的 repo-id,如先前所述。

如果 GIT_TRACE2_EVENT_BRIEFtrace2.eventBrief 為 true,則會從所有事件中省略 fileline 欄位,而 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" 欄位是一個任意字串,用於描述命令模式。例如,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 的 shell script。)

請注意,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
}

請注意,目前的/產生的程序無法使用子程序的會話 ID,因此會在此處報告子程序的 PID,作為後處理的提示。(但這只是一個提示,因為子程序可能是沒有會話 ID 的 shell script。)

在子程序於背景啟動並給予一些時間啟動並開始工作後,會產生此事件。如果子程序在父程序仍在等待時正常啟動,則 "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"

當啟動執行緒時,會產生此事件。它會從新執行緒的執行緒程序「內部」產生 (因為它需要存取執行緒的執行緒本機儲存體中的資料)。

{
	"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 事件。稍後,如果支援程序內子模組,則應為每個造訪的子模組發出 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_NESTINGtrace2.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() 中。在幕後,會註冊一個 atexitsignal 處理程式。

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 的子項 [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_threadth07:preload_thread。每個執行緒的事件會以原子方式附加到共享目標串流,因此它們可能會相對於其他執行緒以隨機順序出現。最後,主執行緒會等待執行緒完成並離開區域。

資料事件會標記有活動執行緒名稱。它們用於報告每個執行緒的參數。

$ 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 個項目。

此範例還顯示,執行緒名稱在每個執行緒啟動時以競爭的方式指派。

配置(預設參數)事件

將「有趣」的配置值傾印到 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> 轉換為「類別」)。

scroll-to-top