api-trace2

API Trace2 можно использовать для вывода отладочной информации, данных о производительности и телеметрии в stderr или файл. Функция Trace2 неактивна, если явно не включена одна или несколько целей Trace2.

API Trace2 предназначен для замены существующей трассировки в стиле printf() (Trace1), предоставляемой средствами GIT_TRACE и GIT_TRACE_PERFORMANCE. На начальном этапе реализации Trace2 и Trace1 могут работать параллельно.

API Trace2 определяет набор высокоуровневых сообщений с известными полями, например (start: argv) и (exit: {exit-code, elapsed-time}).

Инструментирование Trace2 во всей кодовой базе Git отправляет сообщения Trace2 включённым целям Trace2. Цели преобразуют содержимое этих сообщений в форматы, предназначенные для конкретных задач, и записывают события в свои потоки данных. Таким образом, API Trace2 позволяет выполнять анализ самых разных типов.

Цели определяются с помощью 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> — записывает данные в файл в режиме добавления. Если цель уже существует и является каталогом, трассировки будут записываться в файлы (по одному на процесс) внутри указанного каталога.
af_unix:[<socket-type>:]<absolute-pathname> — записывает данные в Unix DomainSocket (на платформах, которые их поддерживают). Тип сокета может быть stream или dgram; если он не указан, Git попробует оба варианта.

Если файлы трассировки записываются в каталог-цель, их имена будут соответствовать последнему компоненту SID (при необходимости за ним будет добавлен счётчик, чтобы избежать совпадения имён файлов).

API Trace2

Открытый API Trace2 определён и описан в 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". Для дочернего процесса второго уровня — "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

Каждое событие представляет собой 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>: это идентификатор сеанса. Эта уникальная строка позволяет идентифицировать экземпляр процесса и связывать с ним все созданные им события. Вместо PID используется идентификатор сеанса, так как операционная система повторно использует PID. Для дочерних процессов git к идентификатору сеанса добавляется идентификатор сеанса родительского процесса git, чтобы при последующей обработке можно было установить отношения между родителем и дочерними процессами.
"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"

Это событие записывается в файл-маркер git-trace2-discard, если в целевом каталоге трассировки слишком много файлов (см. параметр конфигурации trace2.maxFiles).

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

"start"

Это событие содержит полный argv, полученный функцией main().

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

Обратите внимание: идентификатор сеанса дочернего процесса недоступен текущему процессу (который его запустил), поэтому здесь в качестве подсказки для последующей обработки указывается PID дочернего процесса. (Это лишь подсказка, поскольку дочерний процесс может быть сценарием оболочки, у которого нет идентификатора сеанса.)

Обратите внимание: поле 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
}

Это событие создаётся после запуска дочернего процесса в фоновом режиме, когда ему даётся немного времени на загрузку и начало работы. Если дочерний процесс запускается нормально, пока родительский процесс ожидает, поле "ready" будет иметь значение "ready". Если дочерний процесс запускается слишком медленно и время ожидания родительского процесса истекает, поле будет иметь значение "timeout". Если дочерний процесс запускается, но родительский процесс не может проверить его состояние, поле будет иметь значение "error".

После создания этого события родительский процесс освободит все свои дескрипторы, связанные с дочерним процессом, и будет считать его фоновым демоном. Поэтому даже если дочерний процесс завершит загрузку позднее, родительский процесс не создаст обновлённое событие.

Обратите внимание: поле t_rel содержит измеренное время работы в секундах на момент, когда родительский процесс отправил дочерний процесс в фоновый режим. Предполагается, что дочерний процесс является долго работающим демоном и может пережить родительский процесс. Поэтому время событий дочернего процесса, указанное родительским процессом, не следует сравнивать со временем atexit дочернего процесса.

"exec"

Это событие создаётся перед тем, как git попытается выполнить exec() другой команды вместо запуска дочернего процесса.

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

Поле "exec_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_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
}

Пример использования API trace2

Ниже приведён гипотетический пример использования API Trace2, демонстрирующий предполагаемый сценарий применения (без учёта конкретных деталей Git).

Инициализация

Инициализация выполняется в main(). Внутри регистрируются обработчики atexit и signal.

int main(int argc, const char **argv)
{
        int exit_code;

        trace2_initialize();
        trace2_cmd_start(argv);

        exit_code = cmd_main(argc, argv);

        trace2_cmd_exit(exit_code);

        return exit_code;
}

Сведения о команде

После настройки основных параметров дополнительные сведения о команде можно передавать в Trace2 по мере их обнаружения.

int cmd_checkout(int argc, const char **argv)
{
        trace2_cmd_name("checkout");
        trace2_cmd_mode("branch");
        trace2_def_repo(the_repository);

        // emit "def_param" messages for "interesting" config settings.
        trace2_cmd_list_config();

        if (do_something())
            trace2_cmd_error("Path '%s': cannot do something", path);

        return 0;
}

Дочерние процессы

Оборачивайте код, запускающий дочерние процессы.

void run_child(...)
{
        int child_exit_code;
        struct child_process cmd = CHILD_PROCESS_INIT;
        ...
        cmd.trace2_child_class = "editor";

        trace2_child_start(&cmd);
        child_exit_code = spawn_child_and_wait_for_it();
        trace2_child_exit(&cmd, child_exit_code);
}

Например, следующая команда fetch запустила ssh, index-pack, rev-list и gc. Этот пример также показывает, что fetch выполнялась 5.199 секунды, из которых 4.932 секунды пришлись на ssh.

$ export GIT_TRACE2_BRIEF=1
$ export GIT_TRACE2=~/log.normal
$ git fetch origin
...

$ cat ~/log.normal
version 2.20.1.vfs.1.1.47.g534dbe1ad1
start git fetch origin
worktree /Users/jeffhost/work/gfw
cmd_name fetch (fetch)
child_start[0] ssh git@github.com ...
child_start[1] git index-pack ...
... (Trace2 events from child processes omitted)
child_exit[1] pid:14707 code:0 elapsed:0.076353
child_exit[0] pid:14706 code:0 elapsed:4.931869
child_start[2] git rev-list ...
... (Trace2 events from child process omitted)
child_exit[2] pid:14708 code:0 elapsed:0.110605
child_start[3] git gc --auto
... (Trace2 events from child process omitted)
child_exit[3] pid:14709 code:0 elapsed:0.006240
exit elapsed:5.198503 code:0
atexit elapsed:5.198541 code:0

Если процесс git является (прямым или косвенным) дочерним процессом другого процесса git, он наследует контекстную информацию Trace2. Это позволяет дочернему процессу выводить иерархию команд. В этом примере gc является дочерним процессом[3] для fetch. Когда процесс gc указывает своё имя как "gc", он также сообщает иерархию "fetch/gc". (В этом примере сообщения Trace2 дочернего процесса для наглядности имеют отступ.)

$ export GIT_TRACE2_BRIEF=1
$ export GIT_TRACE2=~/log.normal
$ git fetch origin
...

$ cat ~/log.normal
version 2.20.1.160.g5676107ecd.dirty
start git fetch official
worktree /Users/jeffhost/work/gfw
cmd_name fetch (fetch)
...
child_start[3] git gc --auto
    version 2.20.1.160.g5676107ecd.dirty
    start /Users/jeffhost/work/gfw/git gc --auto
    worktree /Users/jeffhost/work/gfw
    cmd_name gc (fetch/gc)
    exit elapsed:0.001959 code:0
    atexit elapsed:0.001997 code:0
child_exit[3] pid:20303 code:0 elapsed:0.007564
exit elapsed:3.868938 code:0
atexit elapsed:3.868970 code:0

Области

Области можно использовать для измерения времени выполнения интересующего фрагмента кода.

void wt_status_collect(struct wt_status *s)
{
        trace2_region_enter("status", "worktrees", s->repo);
        wt_status_collect_changes_worktree(s);
        trace2_region_leave("status", "worktrees", s->repo);

        trace2_region_enter("status", "index", s->repo);
        wt_status_collect_changes_index(s);
        trace2_region_leave("status", "index", s->repo);

        trace2_region_enter("status", "untracked", s->repo);
        wt_status_collect_untracked(s);
        trace2_region_leave("status", "untracked", s->repo);
}

void wt_status_print(struct wt_status *s)
{
        trace2_region_enter("status", "print", s->repo);
        switch (s->status_format) {
            ...
        }
        trace2_region_leave("status", "print", s->repo);
}

В этом примере поиск неотслеживаемых файлов выполнялся с +0.012568 до +0.027149 (с момента запуска процесса) и занял 0.014581 секунды.

$ export GIT_TRACE2_PERF_BRIEF=1
$ export GIT_TRACE2_PERF=~/log.perf
$ git status
...

$ cat ~/log.perf
d0 | main                     | version      |     |           |           |            | 2.20.1.160.g5676107ecd.dirty
d0 | main                     | start        |     |  0.001173 |           |            | git status
d0 | main                     | def_repo     | r1  |           |           |            | worktree:/Users/jeffhost/work/gfw
d0 | main                     | cmd_name     |     |           |           |            | status (status)
...
d0 | main                     | region_enter | r1  |  0.010988 |           | status     | label:worktrees
d0 | main                     | region_leave | r1  |  0.011236 |  0.000248 | status     | label:worktrees
d0 | main                     | region_enter | r1  |  0.011260 |           | status     | label:index
d0 | main                     | region_leave | r1  |  0.012542 |  0.001282 | status     | label:index
d0 | main                     | region_enter | r1  |  0.012568 |           | status     | label:untracked
d0 | main                     | region_leave | r1  |  0.027149 |  0.014581 | status     | label:untracked
d0 | main                     | region_enter | r1  |  0.027411 |           | status     | label:print
d0 | main                     | region_leave | r1  |  0.028741 |  0.001330 | status     | label:print
d0 | main                     | exit         |     |  0.028778 |           |            | code:0
d0 | main                     | atexit       |     |  0.028809 |           |            | code:0

Области можно вкладывать друг в друга. Например, в целевом формате PERF это приводит к отступам в сообщениях. Прошедшее время, как и ожидалось, отсчитывается относительно начала соответствующего уровня вложенности. Например, если добавить сообщение области к:

static enum path_treatment read_directory_recursive(struct dir_struct *dir,
        struct index_state *istate, const char *base, int baselen,
        struct untracked_cache_dir *untracked, int check_only,
        int stop_at_first_file, const struct pathspec *pathspec)
{
        enum path_treatment state, subdir_state, dir_state = path_none;

        trace2_region_enter_printf("dir", "read_recursive", NULL, "%.*s", baselen, base);
        ...
        trace2_region_leave_printf("dir", "read_recursive", NULL, "%.*s", baselen, base);
        return dir_state;
}

Можно подробнее изучить время, затраченное на поиск неотслеживаемых файлов.

$ export GIT_TRACE2_PERF_BRIEF=1
$ export GIT_TRACE2_PERF=~/log.perf
$ git status
...
$ cat ~/log.perf
d0 | main                     | version      |     |           |           |            | 2.20.1.162.gb4ccea44db.dirty
d0 | main                     | start        |     |  0.001173 |           |            | git status
d0 | main                     | def_repo     | r1  |           |           |            | worktree:/Users/jeffhost/work/gfw
d0 | main                     | cmd_name     |     |           |           |            | status (status)
...
d0 | main                     | region_enter | r1  |  0.015047 |           | status     | label:untracked
d0 | main                     | region_enter |     |  0.015132 |           | dir        | ..label:read_recursive
d0 | main                     | region_enter |     |  0.016341 |           | dir        | ....label:read_recursive vcs-svn/
d0 | main                     | region_leave |     |  0.016422 |  0.000081 | dir        | ....label:read_recursive vcs-svn/
d0 | main                     | region_enter |     |  0.016446 |           | dir        | ....label:read_recursive xdiff/
d0 | main                     | region_leave |     |  0.016522 |  0.000076 | dir        | ....label:read_recursive xdiff/
d0 | main                     | region_enter |     |  0.016612 |           | dir        | ....label:read_recursive git-gui/
d0 | main                     | region_enter |     |  0.016698 |           | dir        | ......label:read_recursive git-gui/po/
d0 | main                     | region_enter |     |  0.016810 |           | dir        | ........label:read_recursive git-gui/po/glossary/
d0 | main                     | region_leave |     |  0.016863 |  0.000053 | dir        | ........label:read_recursive git-gui/po/glossary/
...
d0 | main                     | region_enter |     |  0.031876 |           | dir        | ....label:read_recursive builtin/
d0 | main                     | region_leave |     |  0.032270 |  0.000394 | dir        | ....label:read_recursive builtin/
d0 | main                     | region_leave |     |  0.032414 |  0.017282 | dir        | ..label:read_recursive
d0 | main                     | region_leave | r1  |  0.032454 |  0.017407 | status     | label:untracked
...
d0 | main                     | exit         |     |  0.034279 |           |            | code:0
d0 | main                     | atexit       |     |  0.034322 |           |            | code:0

Области Trace2 похожи на существующие процедуры trace_performance_enter() и trace_performance_leave(), но являются потокобезопасными и поддерживают отдельные стеки таймеров для каждого потока.

Сообщения о данных

Добавление сообщений о данных в область.

int read_index_from(struct index_state *istate, const char *path,
        const char *gitdir)
{
        trace2_region_enter_printf("index", "do_read_index", the_repository, "%s", path);

        ...

        trace2_data_intmax("index", the_repository, "read/version", istate->version);
        trace2_data_intmax("index", the_repository, "read/cache_nr", istate->cache_nr);

        trace2_region_leave_printf("index", "do_read_index", the_repository, "%s", path);
}

Этот пример показывает, что индекс содержит 3552 записи.

$ export GIT_TRACE2_PERF_BRIEF=1
$ export GIT_TRACE2_PERF=~/log.perf
$ git status
...
$ cat ~/log.perf
d0 | main                     | version      |     |           |           |            | 2.20.1.156.gf9916ae094.dirty
d0 | main                     | start        |     |  0.001173 |           |            | git status
d0 | main                     | def_repo     | r1  |           |           |            | worktree:/Users/jeffhost/work/gfw
d0 | main                     | cmd_name     |     |           |           |            | status (status)
d0 | main                     | region_enter | r1  |  0.001791 |           | index      | label:do_read_index .git/index
d0 | main                     | data         | r1  |  0.002494 |  0.000703 | index      | ..read/version:2
d0 | main                     | data         | r1  |  0.002520 |  0.000729 | index      | ..read/cache_nr:3552
d0 | main                     | region_leave | r1  |  0.002539 |  0.000748 | index      | label:do_read_index .git/index
...

События потоков

Добавление сообщений о потоках в функцию потока.

Например, код preload-index с несколькими потоками можно инструментировать, задав область для пула потоков, а затем добавив события запуска и завершения для каждого потока внутри функции потока.

static void *preload_thread(void *_data)
{
        // start the per-thread clock and emit a message.
        trace2_thread_start("preload_thread");

        // report which chunk of the array this thread was assigned.
        trace2_data_intmax("index", the_repository, "offset", p->offset);
        trace2_data_intmax("index", the_repository, "count", nr);

        do {
            ...
        } while (--nr > 0);
        ...

        // report elapsed time taken by this thread.
        trace2_thread_exit();
        return NULL;
}

void preload_index(struct index_state *index,
        const struct pathspec *pathspec,
        unsigned int refresh_flags)
{
        trace2_region_enter("index", "preload", the_repository);

        for (i = 0; i < threads; i++) {
            ... /* create thread */
        }

        for (i = 0; i < threads; i++) {
            ... /* join thread */
        }

        trace2_region_leave("index", "preload", the_repository);
}

В этом примере preload_index() выполнялся потоком main и запускал область preload. Было запущено семь потоков с именами от th01:preload_thread до th07:preload_thread. События каждого потока атомарно добавляются в общий целевой поток по мере их возникновения, поэтому относительно событий других потоков они могут появляться в случайном порядке. В конце основной поток ожидает завершения потоков и покидает область.

События данных помечаются именем активного потока. Они используются для передачи параметров каждого потока.

$ 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 секунды. Семь потоков затратили от 0.006069 до 0.008947 секунды на обработку своих частей индекса. Поток "th01" обработал 508 элементов со смещением 0. Поток "th02" обработал 508 элементов со смещением 2032. Поток "th04" обработал 508 элементов со смещением 508.

Этот пример также показывает, что имена потокам присваиваются в условиях гонки по мере их запуска.

События конфигурации (def param)

Запись «интересных» значений конфигурации в журнал trace2.

При необходимости можно создавать события конфигурации. О том, как включить эту возможность, см. trace2.configparams в git-config[1].

$ 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

Дальнейшая работа

Связь с существующим Trace API (api-trace.txt)

Прежде чем полностью перейти на Trace2, необходимо решить несколько вопросов.

Обновить существующие тесты, в которых предполагаются сообщения в формате GIT_TRACE.
Как лучше всего обрабатывать пользовательские сообщения GIT_TRACE_<key>?
- Механизм GIT_TRACE_<key> позволяет каждому <key> записывать данные в отдельный файл (помимо stderr).
- Нужно ли сохранить эту возможность или просто записывать данные в существующие целевые объекты Trace2 (преобразуя <key> в «категорию»).

© 2005–2026 Linus Torvalds and others
Licensed under the GNU General Public License version 2.
https://git-scm.com/docs/api-trace2