Git
英语 ▾ 主题 ▾ 最新版本 ▾ 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 不会从 repo 本地或工作区配置文件中读取,也不尊重 -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] - 写入已打开的文件描述符。

  • <absolute-pathname> - 以追加模式写入文件。 如果目标已存在并且是目录,则跟踪将写入给定目录下的文件(每个进程一个)。

  • af_unix:[<socket-type>:]<absolute-pathname> - 写入 Unix 域套接字(在支持它们的平台上)。 套接字类型可以是 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 目标格式

正常格式

事件以以下形式的行写入

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

是事件名称。

<event-message>

是供人类阅读的自由格式 printf() 消息。

请注意,这可能包含未转义的嵌入式 LF 或 CRLF 字符,因此事件可能会跨多行溢出。

如果 GIT_TRACE2_BRIEFtrace2.normalBrief 为真,则 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
<depth>

是 git 进程深度。 这是父 git 进程的数量。 顶级 git 命令的深度值为“d0”。 其子项的深度值为“d1”。 第二级子项的深度值为“d2”,依此类推。

<thread-name>

是线程的唯一名称。 主线程称为“main”。 其他线程名称的格式为“th%d:%s”,包括唯一编号和线程进程的名称。

<event-name>

是事件名称。

<repo-id>

如果存在,则表示正在使用的存储库编号。 当打开存储库时,会发出 def_repo 事件。 这将定义 repo-id 和相关的 worktree。 随后的特定于 repo 的事件将引用此 repo-id。

目前,这对于主存储库始终是“r1”。 此字段是为了将来在进程内子模块的预期而设置的。

<t_abs>

如果存在,则是程序启动后以秒为单位的绝对时间。

<t_rel>

如果存在,则是相对于当前区域开始时间的以秒为单位的时间。 对于线程退出事件,它是线程的经过时间。

<category>

出现在区域和数据事件中,用于指示一个广泛的类别,例如“index”或“status”。

<perf-event-message>

是供人类阅读的自由格式 printf() 消息。

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

如果 GIT_TRACE2_PERF_BRIEFtrace2.perfBrief 为真,则会省略 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>

如果存在,则是前面描述的整数仓库 ID。

如果 GIT_TRACE2_EVENT_BRIEFtrace2.eventBrief 为真,则所有事件都会省略 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 脚本。)

请注意,t_rel 字段包含子进程的观察到的运行时间(以秒为单位)(从 fork/exec/spawn 开始,在 waitpid() 之后结束,包括操作系统进程创建开销)。因此,此时间将略大于子进程本身报告的 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 脚本。)

在后台启动子进程并留出一些时间让它启动并开始工作后,会生成此事件。如果子进程在父进程仍在等待时正常启动,则 "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"

此事件定义仓库 ID 并将其与工作树的根目录相关联。

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

如前所述,仓库 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);
}

例如,以下获取命令生成了 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 [email protected] ...
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);
}

在此示例中,preload_index() 由 main 线程执行,并启动了 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 个项目。

此示例还显示,每个线程启动时,线程名称都是以竞争的方式分配的。

配置(def param)事件

将“有趣”的配置值转储到 trace2 日志。

我们可以选择性地发出配置事件,请参阅 git-config[1] 中的 trace2.configparams,了解如何启用它。

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

然后,使用 GIT_TRACE2_CONFIG_PARAMS 将配置 color.ui 标记为“有趣”的配置。

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

测量在函数调用或代码段中花费的时间,这些函数调用或代码段可能在进程的生命周期内从代码中的许多地方调用。

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

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

	expensive_function();

	// Do something else 1...

	expensive_function();

	// Do something else 2...

	expensive_function();

	return 0;
}

在此示例中,我们测量了在 expensive_function() 中花费的总时间,无论它是在程序的整体流程中何时被调用。

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

未来的工作

与现有跟踪 API 的关系 (api-trace.txt)

在我们可以完全切换到 Trace2 之前,需要解决一些问题。

  • 更新假设 GIT_TRACE 格式消息的现有测试。

  • 如何最好地处理自定义 GIT_TRACE_<key> 消息?

    • GIT_TRACE_<key> 机制允许每个 <key> 写入不同的文件(除了 stderr)。

    • 我们是否希望保留这种能力,或者只是写入现有的 Trace2 目标(并将 <key> 转换为“类别”?

scroll-to-top