Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 1 | = Trace2 API |
| 2 | |
| 3 | The Trace2 API can be used to print debug, performance, and telemetry |
| 4 | information to stderr or a file. The Trace2 feature is inactive unless |
| 5 | explicitly enabled by enabling one or more Trace2 Targets. |
| 6 | |
| 7 | The Trace2 API is intended to replace the existing (Trace1) |
| 8 | printf-style tracing provided by the existing `GIT_TRACE` and |
| 9 | `GIT_TRACE_PERFORMANCE` facilities. During initial implementation, |
| 10 | Trace2 and Trace1 may operate in parallel. |
| 11 | |
| 12 | The Trace2 API defines a set of high-level messages with known fields, |
| 13 | such as (`start`: `argv`) and (`exit`: {`exit-code`, `elapsed-time`}). |
| 14 | |
| 15 | Trace2 instrumentation throughout the Git code base sends Trace2 |
| 16 | messages to the enabled Trace2 Targets. Targets transform these |
| 17 | messages content into purpose-specific formats and write events to |
| 18 | their data streams. In this manner, the Trace2 API can drive |
| 19 | many different types of analysis. |
| 20 | |
| 21 | Targets are defined using a VTable allowing easy extension to other |
| 22 | formats in the future. This might be used to define a binary format, |
| 23 | for example. |
| 24 | |
Jeff Hostetler | 81567ca | 2019-04-15 13:39:50 -0700 | [diff] [blame] | 25 | Trace2 is controlled using `trace2.*` config values in the system and |
SZEDER Gábor | e4b75d6 | 2019-05-19 16:43:08 +0200 | [diff] [blame^] | 26 | global config files and `GIT_TRACE2*` environment variables. Trace2 does |
Jeff Hostetler | 81567ca | 2019-04-15 13:39:50 -0700 | [diff] [blame] | 27 | not read from repo local or worktree config files or respect `-c` |
| 28 | command line config settings. |
| 29 | |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 30 | == Trace2 Targets |
| 31 | |
| 32 | Trace2 defines the following set of Trace2 Targets. |
| 33 | Format details are given in a later section. |
| 34 | |
Jeff Hostetler | 81567ca | 2019-04-15 13:39:50 -0700 | [diff] [blame] | 35 | === The Normal Format Target |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 36 | |
Jeff Hostetler | 81567ca | 2019-04-15 13:39:50 -0700 | [diff] [blame] | 37 | The normal format target is a tradition printf format and similar |
| 38 | to GIT_TRACE format. This format is enabled with the `GIT_TR` |
| 39 | environment variable or the `trace2.normalTarget` system or global |
| 40 | config setting. |
| 41 | |
| 42 | For example |
| 43 | |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 44 | ------------ |
SZEDER Gábor | e4b75d6 | 2019-05-19 16:43:08 +0200 | [diff] [blame^] | 45 | $ export GIT_TRACE2=~/log.normal |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 46 | $ git version |
| 47 | git version 2.20.1.155.g426c96fcdb |
| 48 | ------------ |
Jeff Hostetler | 81567ca | 2019-04-15 13:39:50 -0700 | [diff] [blame] | 49 | |
| 50 | or |
| 51 | |
| 52 | ------------ |
| 53 | $ git config --global trace2.normalTarget ~/log.normal |
| 54 | $ git version |
| 55 | git version 2.20.1.155.g426c96fcdb |
| 56 | ------------ |
| 57 | |
| 58 | yields |
| 59 | |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 60 | ------------ |
| 61 | $ cat ~/log.normal |
| 62 | 12:28:42.620009 common-main.c:38 version 2.20.1.155.g426c96fcdb |
| 63 | 12:28:42.620989 common-main.c:39 start git version |
| 64 | 12:28:42.621101 git.c:432 cmd_name version (version) |
| 65 | 12:28:42.621215 git.c:662 exit elapsed:0.001227 code:0 |
| 66 | 12:28:42.621250 trace2/tr2_tgt_normal.c:124 atexit elapsed:0.001265 code:0 |
| 67 | ------------ |
| 68 | |
Jeff Hostetler | 81567ca | 2019-04-15 13:39:50 -0700 | [diff] [blame] | 69 | === The Performance Format Target |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 70 | |
Jeff Hostetler | 81567ca | 2019-04-15 13:39:50 -0700 | [diff] [blame] | 71 | The performance format target (PERF) is a column-based format to |
| 72 | replace GIT_TRACE_PERFORMANCE and is suitable for development and |
| 73 | testing, possibly to complement tools like gprof. This format is |
SZEDER Gábor | e4b75d6 | 2019-05-19 16:43:08 +0200 | [diff] [blame^] | 74 | enabled with the `GIT_TRACE2_PERF` environment variable or the |
Jeff Hostetler | 81567ca | 2019-04-15 13:39:50 -0700 | [diff] [blame] | 75 | `trace2.perfTarget` system or global config setting. |
| 76 | |
| 77 | For example |
| 78 | |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 79 | ------------ |
SZEDER Gábor | e4b75d6 | 2019-05-19 16:43:08 +0200 | [diff] [blame^] | 80 | $ export GIT_TRACE2_PERF=~/log.perf |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 81 | $ git version |
| 82 | git version 2.20.1.155.g426c96fcdb |
| 83 | ------------ |
Jeff Hostetler | 81567ca | 2019-04-15 13:39:50 -0700 | [diff] [blame] | 84 | |
| 85 | or |
| 86 | |
| 87 | ------------ |
| 88 | $ git config --global trace2.perfTarget ~/log.perf |
| 89 | $ git version |
| 90 | git version 2.20.1.155.g426c96fcdb |
| 91 | ------------ |
| 92 | |
| 93 | yields |
| 94 | |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 95 | ------------ |
| 96 | $ cat ~/log.perf |
| 97 | 12:28:42.620675 common-main.c:38 | d0 | main | version | | | | | 2.20.1.155.g426c96fcdb |
Jeff Hostetler | 39f4317 | 2019-04-15 13:39:44 -0700 | [diff] [blame] | 98 | 12:28:42.621001 common-main.c:39 | d0 | main | start | | 0.001173 | | | git version |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 99 | 12:28:42.621111 git.c:432 | d0 | main | cmd_name | | | | | version (version) |
| 100 | 12:28:42.621225 git.c:662 | d0 | main | exit | | 0.001227 | | | code:0 |
| 101 | 12:28:42.621259 trace2/tr2_tgt_perf.c:211 | d0 | main | atexit | | 0.001265 | | | code:0 |
| 102 | ------------ |
| 103 | |
Jeff Hostetler | 81567ca | 2019-04-15 13:39:50 -0700 | [diff] [blame] | 104 | === The Event Format Target |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 105 | |
Jeff Hostetler | 81567ca | 2019-04-15 13:39:50 -0700 | [diff] [blame] | 106 | The event format target is a JSON-based format of event data suitable |
SZEDER Gábor | e4b75d6 | 2019-05-19 16:43:08 +0200 | [diff] [blame^] | 107 | for telemetry analysis. This format is enabled with the `GIT_TRACE2_EVENT` |
Jeff Hostetler | 81567ca | 2019-04-15 13:39:50 -0700 | [diff] [blame] | 108 | environment variable or the `trace2.eventTarget` system or global config |
| 109 | setting. |
| 110 | |
| 111 | For example |
| 112 | |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 113 | ------------ |
SZEDER Gábor | e4b75d6 | 2019-05-19 16:43:08 +0200 | [diff] [blame^] | 114 | $ export GIT_TRACE2_EVENT=~/log.event |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 115 | $ git version |
| 116 | git version 2.20.1.155.g426c96fcdb |
| 117 | ------------ |
Jeff Hostetler | 81567ca | 2019-04-15 13:39:50 -0700 | [diff] [blame] | 118 | |
| 119 | or |
| 120 | |
| 121 | ------------ |
| 122 | $ git config --global trace2.eventTarget ~/log.event |
| 123 | $ git version |
| 124 | git version 2.20.1.155.g426c96fcdb |
| 125 | ------------ |
| 126 | |
| 127 | yields |
| 128 | |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 129 | ------------ |
| 130 | $ cat ~/log.event |
Jeff Hostetler | 81567ca | 2019-04-15 13:39:50 -0700 | [diff] [blame] | 131 | {"event":"version","sid":"sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.620713Z","file":"common-main.c","line":38,"evt":"1","exe":"2.20.1.155.g426c96fcdb"} |
| 132 | {"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"]} |
| 133 | {"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"} |
| 134 | {"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} |
| 135 | {"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} |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 136 | ------------ |
| 137 | |
Jeff Hostetler | 81567ca | 2019-04-15 13:39:50 -0700 | [diff] [blame] | 138 | === Enabling a Target |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 139 | |
Jeff Hostetler | 81567ca | 2019-04-15 13:39:50 -0700 | [diff] [blame] | 140 | To enable a target, set the corresponding environment variable or |
| 141 | system or global config value to one of the following: |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 142 | |
Jeff Hostetler | 81567ca | 2019-04-15 13:39:50 -0700 | [diff] [blame] | 143 | include::../trace2-target-values.txt[] |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 144 | |
Junio C Hamano | 5b2d1c0 | 2019-05-13 23:50:31 +0900 | [diff] [blame] | 145 | If the target already exists and is a directory, the traces will be |
| 146 | written to files (one per process) underneath the given directory. They |
| 147 | will be named according to the last component of the SID (optionally |
| 148 | followed by a counter to avoid filename collisions). |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 149 | |
| 150 | == Trace2 API |
| 151 | |
| 152 | All public Trace2 functions and macros are defined in `trace2.h` and |
| 153 | `trace2.c`. All public symbols are prefixed with `trace2_`. |
| 154 | |
| 155 | There are no public Trace2 data structures. |
| 156 | |
| 157 | The Trace2 code also defines a set of private functions and data types |
| 158 | in the `trace2/` directory. These symbols are prefixed with `tr2_` |
| 159 | and should only be used by functions in `trace2.c`. |
| 160 | |
| 161 | == Conventions for Public Functions and Macros |
| 162 | |
| 163 | The functions defined by the Trace2 API are declared and documented |
| 164 | in `trace2.h`. It defines the API functions and wrapper macros for |
| 165 | Trace2. |
| 166 | |
| 167 | Some functions have a `_fl()` suffix to indicate that they take `file` |
| 168 | and `line-number` arguments. |
| 169 | |
| 170 | Some functions have a `_va_fl()` suffix to indicate that they also |
| 171 | take a `va_list` argument. |
| 172 | |
| 173 | Some functions have a `_printf_fl()` suffix to indicate that they also |
| 174 | take a varargs argument. |
| 175 | |
| 176 | There are CPP wrapper macros and ifdefs to hide most of these details. |
| 177 | See `trace2.h` for more details. The following discussion will only |
| 178 | describe the simplified forms. |
| 179 | |
| 180 | == Public API |
| 181 | |
| 182 | All Trace2 API functions send a messsage to all of the active |
| 183 | Trace2 Targets. This section describes the set of available |
| 184 | messages. |
| 185 | |
| 186 | It helps to divide these functions into groups for discussion |
| 187 | purposes. |
| 188 | |
| 189 | === Basic Command Messages |
| 190 | |
| 191 | These are concerned with the lifetime of the overall git process. |
| 192 | |
Jeff Hostetler | a089724 | 2019-04-15 13:39:43 -0700 | [diff] [blame] | 193 | `void trace2_initialize_clock()`:: |
| 194 | |
| 195 | Initialize the Trace2 start clock and nothing else. This should |
| 196 | be called at the very top of main() to capture the process start |
| 197 | time and reduce startup order dependencies. |
| 198 | |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 199 | `void trace2_initialize()`:: |
| 200 | |
| 201 | Determines if any Trace2 Targets should be enabled and |
Jeff Hostetler | a089724 | 2019-04-15 13:39:43 -0700 | [diff] [blame] | 202 | initializes the Trace2 facility. This includes setting up the |
| 203 | Trace2 thread local storage (TLS). |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 204 | + |
| 205 | This function emits a "version" message containing the version of git |
| 206 | and the Trace2 protocol. |
| 207 | + |
| 208 | This function should be called from `main()` as early as possible in |
Jeff Hostetler | a089724 | 2019-04-15 13:39:43 -0700 | [diff] [blame] | 209 | the life of the process after essential process initialization. |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 210 | |
| 211 | `int trace2_is_enabled()`:: |
| 212 | |
| 213 | Returns 1 if Trace2 is enabled (at least one target is |
| 214 | active). |
| 215 | |
| 216 | `void trace2_cmd_start(int argc, const char **argv)`:: |
| 217 | |
| 218 | Emits a "start" message containing the process command line |
| 219 | arguments. |
| 220 | |
| 221 | `int trace2_cmd_exit(int exit_code)`:: |
| 222 | |
| 223 | Emits an "exit" message containing the process exit-code and |
| 224 | elapsed time. |
| 225 | + |
| 226 | Returns the exit-code. |
| 227 | |
| 228 | `void trace2_cmd_error(const char *fmt, va_list ap)`:: |
| 229 | |
| 230 | Emits an "error" message containing a formatted error message. |
| 231 | |
| 232 | `void trace2_cmd_path(const char *pathname)`:: |
| 233 | |
| 234 | Emits a "cmd_path" message with the full pathname of the |
| 235 | current process. |
| 236 | |
| 237 | === Command Detail Messages |
| 238 | |
| 239 | These are concerned with describing the specific Git command |
| 240 | after the command line, config, and environment are inspected. |
| 241 | |
| 242 | `void trace2_cmd_name(const char *name)`:: |
| 243 | |
| 244 | Emits a "cmd_name" message with the canonical name of the |
| 245 | command, for example "status" or "checkout". |
| 246 | |
| 247 | `void trace2_cmd_mode(const char *mode)`:: |
| 248 | |
| 249 | Emits a "cmd_mode" message with a qualifier name to further |
| 250 | describe the current git command. |
| 251 | + |
| 252 | This message is intended to be used with git commands having multiple |
| 253 | major modes. For example, a "checkout" command can checkout a new |
| 254 | branch or it can checkout a single file, so the checkout code could |
| 255 | emit a cmd_mode message of "branch" or "file". |
| 256 | |
| 257 | `void trace2_cmd_alias(const char *alias, const char **argv_expansion)`:: |
| 258 | |
| 259 | Emits an "alias" message containing the alias used and the |
| 260 | argument expansion. |
| 261 | |
| 262 | `void trace2_def_param(const char *parameter, const char *value)`:: |
| 263 | |
| 264 | Emits a "def_param" message containing a key/value pair. |
| 265 | + |
| 266 | This message is intended to report some global aspect of the current |
| 267 | command, such as a configuration setting or command line switch that |
| 268 | significantly affects program performance or behavior, such as |
| 269 | `core.abbrev`, `status.showUntrackedFiles`, or `--no-ahead-behind`. |
| 270 | |
| 271 | `void trace2_cmd_list_config()`:: |
| 272 | |
| 273 | Emits a "def_param" messages for "important" configuration |
| 274 | settings. |
| 275 | + |
SZEDER Gábor | e4b75d6 | 2019-05-19 16:43:08 +0200 | [diff] [blame^] | 276 | The environment variable `GIT_TRACE2_CONFIG_PARAMS` or the `trace2.configParams` |
Jeff Hostetler | 81567ca | 2019-04-15 13:39:50 -0700 | [diff] [blame] | 277 | config value can be set to a |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 278 | list of patterns of important configuration settings, for example: |
| 279 | `core.*,remote.*.url`. This function will iterate over all config |
| 280 | settings and emit a "def_param" message for each match. |
| 281 | |
| 282 | `void trace2_cmd_set_config(const char *key, const char *value)`:: |
| 283 | |
Jeff Hostetler | 81567ca | 2019-04-15 13:39:50 -0700 | [diff] [blame] | 284 | Emits a "def_param" message for a new or updated key/value |
| 285 | pair IF `key` is considered important. |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 286 | + |
| 287 | This is used to hook into `git_config_set()` and catch any |
| 288 | configuration changes and update a value previously reported by |
| 289 | `trace2_cmd_list_config()`. |
| 290 | |
| 291 | `void trace2_def_repo(struct repository *repo)`:: |
| 292 | |
| 293 | Registers a repository with the Trace2 layer. Assigns a |
| 294 | unique "repo-id" to `repo->trace2_repo_id`. |
| 295 | + |
| 296 | Emits a "worktree" messages containing the repo-id and the worktree |
| 297 | pathname. |
| 298 | + |
| 299 | Region and data messages (described later) may refer to this repo-id. |
| 300 | + |
| 301 | The main/top-level repository will have repo-id value 1 (aka "r1"). |
| 302 | + |
| 303 | The repo-id field is in anticipation of future in-proc submodule |
| 304 | repositories. |
| 305 | |
| 306 | === Child Process Messages |
| 307 | |
| 308 | These are concerned with the various spawned child processes, |
| 309 | including shell scripts, git commands, editors, pagers, and hooks. |
| 310 | |
| 311 | `void trace2_child_start(struct child_process *cmd)`:: |
| 312 | |
| 313 | Emits a "child_start" message containing the "child-id", |
| 314 | "child-argv", and "child-classification". |
| 315 | + |
| 316 | Before calling this, set `cmd->trace2_child_class` to a name |
| 317 | describing the type of child process, for example "editor". |
| 318 | + |
| 319 | This function assigns a unique "child-id" to `cmd->trace2_child_id`. |
| 320 | This field is used later during the "child_exit" message to associate |
| 321 | it with the "child_start" message. |
| 322 | + |
| 323 | This function should be called before spawning the child process. |
| 324 | |
| 325 | `void trace2_child_exit(struct child_proess *cmd, int child_exit_code)`:: |
| 326 | |
| 327 | Emits a "child_exit" message containing the "child-id", |
| 328 | the child's elapsed time and exit-code. |
| 329 | + |
| 330 | The reported elapsed time includes the process creation overhead and |
| 331 | time spend waiting for it to exit, so it may be slightly longer than |
| 332 | the time reported by the child itself. |
| 333 | + |
| 334 | This function should be called after reaping the child process. |
| 335 | |
| 336 | `int trace2_exec(const char *exe, const char **argv)`:: |
| 337 | |
| 338 | Emits a "exec" message containing the "exec-id" and the |
| 339 | argv of the new process. |
| 340 | + |
| 341 | This function should be called before calling one of the `exec()` |
| 342 | variants, such as `execvp()`. |
| 343 | + |
| 344 | This function returns a unique "exec-id". This value is used later |
| 345 | if the exec() fails and a "exec-result" message is necessary. |
| 346 | |
| 347 | `void trace2_exec_result(int exec_id, int error_code)`:: |
| 348 | |
| 349 | Emits a "exec_result" message containing the "exec-id" |
| 350 | and the error code. |
| 351 | + |
| 352 | On Unix-based systems, `exec()` does not return if successful. |
| 353 | This message is used to indicate that the `exec()` failed and |
| 354 | that the current program is continuing. |
| 355 | |
| 356 | === Git Thread Messages |
| 357 | |
| 358 | These messages are concerned with Git thread usage. |
| 359 | |
| 360 | `void trace2_thread_start(const char *thread_name)`:: |
| 361 | |
| 362 | Emits a "thread_start" message. |
| 363 | + |
| 364 | The `thread_name` field should be a descriptive name, such as the |
| 365 | unique name of the thread-proc. A unique "thread-id" will be added |
| 366 | to the name to uniquely identify thread instances. |
| 367 | + |
| 368 | Region and data messages (described later) may refer to this thread |
| 369 | name. |
| 370 | + |
| 371 | This function must be called by the thread-proc of the new thread |
| 372 | (so that TLS data is properly initialized) and not by the caller |
| 373 | of `pthread_create()`. |
| 374 | |
| 375 | `void trace2_thread_exit()`:: |
| 376 | |
| 377 | Emits a "thread_exit" message containing the thread name |
| 378 | and the thread elapsed time. |
| 379 | + |
| 380 | This function must be called by the thread-proc before it returns |
| 381 | (so that the coorect TLS data is used and cleaned up. It should |
| 382 | not be called by the caller of `pthread_join()`. |
| 383 | |
| 384 | === Region and Data Messages |
| 385 | |
| 386 | These are concerned with recording performance data |
| 387 | over regions or spans of code. |
| 388 | |
| 389 | `void trace2_region_enter(const char *category, const char *label, const struct repository *repo)`:: |
| 390 | |
| 391 | `void trace2_region_enter_printf(const char *category, const char *label, const struct repository *repo, const char *fmt, ...)`:: |
| 392 | |
| 393 | `void trace2_region_enter_printf_va(const char *category, const char *label, const struct repository *repo, const char *fmt, va_list ap)`:: |
| 394 | |
| 395 | Emits a thread-relative "region_enter" message with optional |
| 396 | printf string. |
| 397 | + |
| 398 | This function pushes a new region nesting stack level on the current |
| 399 | thread and starts a clock for the new stack frame. |
| 400 | + |
| 401 | The `category` field is an arbitrary category name used to classify |
| 402 | regions by feature area, such as "status" or "index". At this time |
| 403 | it is only just printed along with the rest of the message. It may |
| 404 | be used in the future to filter messages. |
| 405 | + |
| 406 | The `label` field is an arbitrary label used to describe the activity |
| 407 | being started, such as "read_recursive" or "do_read_index". |
| 408 | + |
| 409 | The `repo` field, if set, will be used to get the "repo-id", so that |
| 410 | recursive oerations can be attributed to the correct repository. |
| 411 | |
| 412 | `void trace2_region_leave(const char *category, const char *label, const struct repository *repo)`:: |
| 413 | |
| 414 | `void trace2_region_leave_printf(const char *category, const char *label, const struct repository *repo, const char *fmt, ...)`:: |
| 415 | |
| 416 | `void trace2_region_leave_printf_va(const char *category, const char *label, const struct repository *repo, const char *fmt, va_list ap)`:: |
| 417 | |
| 418 | Emits a thread-relative "region_leave" message with optional |
| 419 | printf string. |
| 420 | + |
| 421 | This function pops the region nesting stack on the current thread |
| 422 | and reports the elapsed time of the stack frame. |
| 423 | + |
| 424 | The `category`, `label`, and `repo` fields are the same as above. |
| 425 | The `category` and `label` do not need to match the correpsonding |
| 426 | "region_enter" message, but it makes the data stream easier to |
| 427 | understand. |
| 428 | |
| 429 | `void trace2_data_string(const char *category, const struct repository *repo, const char *key, const char * value)`:: |
| 430 | |
| 431 | `void trace2_data_intmax(const char *category, const struct repository *repo, const char *key, intmax value)`:: |
| 432 | |
| 433 | `void trace2_data_json(const char *category, const struct repository *repo, const char *key, const struct json_writer *jw)`:: |
| 434 | |
| 435 | Emits a region- and thread-relative "data" or "data_json" message. |
| 436 | + |
| 437 | This is a key/value pair message containing information about the |
| 438 | current thread, region stack, and repository. This could be used |
| 439 | to print the number of files in a directory during a multi-threaded |
| 440 | recursive tree walk. |
| 441 | |
| 442 | `void trace2_printf(const char *fmt, ...)`:: |
| 443 | |
| 444 | `void trace2_printf_va(const char *fmt, va_list ap)`:: |
| 445 | |
| 446 | Emits a region- and thread-relative "printf" message. |
| 447 | |
| 448 | == Trace2 Target Formats |
| 449 | |
| 450 | === NORMAL Format |
| 451 | |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 452 | Events are written as lines of the form: |
| 453 | |
| 454 | ------------ |
| 455 | [<time> SP <filename>:<line> SP+] <event-name> [[SP] <event-message>] LF |
| 456 | ------------ |
| 457 | |
| 458 | `<event-name>`:: |
| 459 | |
| 460 | is the event name. |
| 461 | |
| 462 | `<event-message>`:: |
| 463 | is a free-form printf message intended for human consumption. |
| 464 | + |
| 465 | Note that this may contain embedded LF or CRLF characters that are |
| 466 | not escaped, so the event may spill across multiple lines. |
| 467 | |
SZEDER Gábor | e4b75d6 | 2019-05-19 16:43:08 +0200 | [diff] [blame^] | 468 | If `GIT_TRACE2_BRIEF` or `trace2.normalBrief` is true, the `time`, `filename`, |
Jeff Hostetler | 81567ca | 2019-04-15 13:39:50 -0700 | [diff] [blame] | 469 | and `line` fields are omitted. |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 470 | |
| 471 | This target is intended to be more of a summary (like GIT_TRACE) and |
| 472 | less detailed than the other targets. It ignores thread, region, and |
| 473 | data messages, for example. |
| 474 | |
| 475 | === PERF Format |
| 476 | |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 477 | Events are written as lines of the form: |
| 478 | |
| 479 | ------------ |
| 480 | [<time> SP <filename>:<line> SP+ |
| 481 | BAR SP] d<depth> SP |
| 482 | BAR SP <thread-name> SP+ |
| 483 | BAR SP <event-name> SP+ |
| 484 | BAR SP [r<repo-id>] SP+ |
| 485 | BAR SP [<t_abs>] SP+ |
| 486 | BAR SP [<t_rel>] SP+ |
| 487 | BAR SP [<category>] SP+ |
| 488 | BAR SP DOTS* <perf-event-message> |
| 489 | LF |
| 490 | ------------ |
| 491 | |
| 492 | `<depth>`:: |
| 493 | is the git process depth. This is the number of parent |
| 494 | git processes. A top-level git command has depth value "d0". |
| 495 | A child of it has depth value "d1". A second level child |
| 496 | has depth value "d2" and so on. |
| 497 | |
| 498 | `<thread-name>`:: |
| 499 | is a unique name for the thread. The primary thread |
| 500 | is called "main". Other thread names are of the form "th%d:%s" |
| 501 | and include a unique number and the name of the thread-proc. |
| 502 | |
| 503 | `<event-name>`:: |
| 504 | is the event name. |
| 505 | |
| 506 | `<repo-id>`:: |
| 507 | when present, is a number indicating the repository |
| 508 | in use. A `def_repo` event is emitted when a repository is |
| 509 | opened. This defines the repo-id and associated worktree. |
| 510 | Subsequent repo-specific events will reference this repo-id. |
| 511 | + |
| 512 | Currently, this is always "r1" for the main repository. |
| 513 | This field is in anticipation of in-proc submodules in the future. |
| 514 | |
| 515 | `<t_abs>`:: |
| 516 | when present, is the absolute time in seconds since the |
| 517 | program started. |
| 518 | |
| 519 | `<t_rel>`:: |
| 520 | when present, is time in seconds relative to the start of |
| 521 | the current region. For a thread-exit event, it is the elapsed |
| 522 | time of the thread. |
| 523 | |
| 524 | `<category>`:: |
| 525 | is present on region and data events and is used to |
| 526 | indicate a broad category, such as "index" or "status". |
| 527 | |
| 528 | `<perf-event-message>`:: |
| 529 | is a free-form printf message intended for human consumption. |
| 530 | |
| 531 | ------------ |
| 532 | 15:33:33.532712 wt-status.c:2310 | d0 | main | region_enter | r1 | 0.126064 | | status | label:print |
| 533 | 15:33:33.532712 wt-status.c:2331 | d0 | main | region_leave | r1 | 0.127568 | 0.001504 | status | label:print |
| 534 | ------------ |
| 535 | |
SZEDER Gábor | e4b75d6 | 2019-05-19 16:43:08 +0200 | [diff] [blame^] | 536 | If `GIT_TRACE2_PERF_BRIEF` or `trace2.perfBrief` is true, the `time`, `file`, |
Jeff Hostetler | 81567ca | 2019-04-15 13:39:50 -0700 | [diff] [blame] | 537 | and `line` fields are omitted. |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 538 | |
| 539 | ------------ |
| 540 | d0 | main | region_leave | r1 | 0.011717 | 0.009122 | index | label:preload |
| 541 | ------------ |
| 542 | |
| 543 | The PERF target is intended for interactive performance analysis |
| 544 | during development and is quite noisy. |
| 545 | |
| 546 | === EVENT Format |
| 547 | |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 548 | Each event is a JSON-object containing multiple key/value pairs |
| 549 | written as a single line and followed by a LF. |
| 550 | |
| 551 | ------------ |
| 552 | '{' <key> ':' <value> [',' <key> ':' <value>]* '}' LF |
| 553 | ------------ |
| 554 | |
| 555 | Some key/value pairs are common to all events and some are |
| 556 | event-specific. |
| 557 | |
| 558 | ==== Common Key/Value Pairs |
| 559 | |
| 560 | The following key/value pairs are common to all events: |
| 561 | |
| 562 | ------------ |
| 563 | { |
| 564 | "event":"version", |
Jeff Hostetler | 81567ca | 2019-04-15 13:39:50 -0700 | [diff] [blame] | 565 | "sid":"20190408T191827.272759Z-H9b68c35f-P00003510", |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 566 | "thread":"main", |
Jeff Hostetler | 08881b9 | 2019-04-15 13:39:49 -0700 | [diff] [blame] | 567 | "time":"2019-04-08T19:18:27.282761Z", |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 568 | "file":"common-main.c", |
Jeff Hostetler | 08881b9 | 2019-04-15 13:39:49 -0700 | [diff] [blame] | 569 | "line":42, |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 570 | ... |
| 571 | } |
| 572 | ------------ |
| 573 | |
| 574 | `"event":<event>`:: |
| 575 | is the event name. |
| 576 | |
| 577 | `"sid":<sid>`:: |
| 578 | is the session-id. This is a unique string to identify the |
| 579 | process instance to allow all events emitted by a process to |
| 580 | be identified. A session-id is used instead of a PID because |
| 581 | PIDs are recycled by the OS. For child git processes, the |
| 582 | session-id is prepended with the session-id of the parent git |
| 583 | process to allow parent-child relationships to be identified |
| 584 | during post-processing. |
| 585 | |
| 586 | `"thread":<thread>`:: |
| 587 | is the thread name. |
| 588 | |
| 589 | `"time":<time>`:: |
| 590 | is the UTC time of the event. |
| 591 | |
| 592 | `"file":<filename>`:: |
| 593 | is source file generating the event. |
| 594 | |
| 595 | `"line":<line-number>`:: |
| 596 | is the integer source line number generating the event. |
| 597 | |
| 598 | `"repo":<repo-id>`:: |
| 599 | when present, is the integer repo-id as described previously. |
| 600 | |
SZEDER Gábor | e4b75d6 | 2019-05-19 16:43:08 +0200 | [diff] [blame^] | 601 | If `GIT_TRACE2_EVENT_BRIEF` or `trace2.eventBrief` is true, the `file` |
Jeff Hostetler | 81567ca | 2019-04-15 13:39:50 -0700 | [diff] [blame] | 602 | and `line` fields are omitted from all events and the `time` field is |
| 603 | only present on the "start" and "atexit" events. |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 604 | |
| 605 | ==== Event-Specific Key/Value Pairs |
| 606 | |
| 607 | `"version"`:: |
| 608 | This event gives the version of the executable and the EVENT format. |
| 609 | + |
| 610 | ------------ |
| 611 | { |
| 612 | "event":"version", |
| 613 | ... |
| 614 | "evt":"1", # EVENT format version |
| 615 | "exe":"2.20.1.155.g426c96fcdb" # git version |
| 616 | } |
| 617 | ------------ |
| 618 | |
| 619 | `"start"`:: |
| 620 | This event contains the complete argv received by main(). |
| 621 | + |
| 622 | ------------ |
| 623 | { |
| 624 | "event":"start", |
| 625 | ... |
Jeff Hostetler | 39f4317 | 2019-04-15 13:39:44 -0700 | [diff] [blame] | 626 | "t_abs":0.001227, # elapsed time in seconds |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 627 | "argv":["git","version"] |
| 628 | } |
| 629 | ------------ |
| 630 | |
| 631 | `"exit"`:: |
| 632 | This event is emitted when git calls `exit()`. |
| 633 | + |
| 634 | ------------ |
| 635 | { |
| 636 | "event":"exit", |
| 637 | ... |
| 638 | "t_abs":0.001227, # elapsed time in seconds |
| 639 | "code":0 # exit code |
| 640 | } |
| 641 | ------------ |
| 642 | |
| 643 | `"atexit"`:: |
| 644 | This event is emitted by the Trace2 `atexit` routine during |
| 645 | final shutdown. It should be the last event emitted by the |
| 646 | process. |
| 647 | + |
| 648 | (The elapsed time reported here is greater than the time reported in |
| 649 | the "exit" event because it runs after all other atexit tasks have |
| 650 | completed.) |
| 651 | + |
| 652 | ------------ |
| 653 | { |
| 654 | "event":"atexit", |
| 655 | ... |
| 656 | "t_abs":0.001227, # elapsed time in seconds |
| 657 | "code":0 # exit code |
| 658 | } |
| 659 | ------------ |
| 660 | |
| 661 | `"signal"`:: |
| 662 | This event is emitted when the program is terminated by a user |
| 663 | signal. Depending on the platform, the signal event may |
| 664 | prevent the "atexit" event from being generated. |
| 665 | + |
| 666 | ------------ |
| 667 | { |
| 668 | "event":"signal", |
| 669 | ... |
| 670 | "t_abs":0.001227, # elapsed time in seconds |
| 671 | "signal":13 # SIGTERM, SIGINT, etc. |
| 672 | } |
| 673 | ------------ |
| 674 | |
| 675 | `"error"`:: |
| 676 | This event is emitted when one of the `error()`, `die()`, |
| 677 | or `usage()` functions are called. |
| 678 | + |
| 679 | ------------ |
| 680 | { |
| 681 | "event":"error", |
| 682 | ... |
| 683 | "msg":"invalid option: --cahced", # formatted error message |
| 684 | "fmt":"invalid option: %s" # error format string |
| 685 | } |
| 686 | ------------ |
| 687 | + |
| 688 | The error event may be emitted more than once. The format string |
| 689 | allows post-processors to group errors by type without worrying |
| 690 | about specific error arguments. |
| 691 | |
| 692 | `"cmd_path"`:: |
| 693 | This event contains the discovered full path of the git |
| 694 | executable (on platforms that are configured to resolve it). |
| 695 | + |
| 696 | ------------ |
| 697 | { |
| 698 | "event":"cmd_path", |
| 699 | ... |
| 700 | "path":"C:/work/gfw/git.exe" |
| 701 | } |
| 702 | ------------ |
| 703 | |
| 704 | `"cmd_name"`:: |
| 705 | This event contains the command name for this git process |
| 706 | and the hierarchy of commands from parent git processes. |
| 707 | + |
| 708 | ------------ |
| 709 | { |
| 710 | "event":"cmd_name", |
| 711 | ... |
| 712 | "name":"pack-objects", |
| 713 | "hierarchy":"push/pack-objects" |
| 714 | } |
| 715 | ------------ |
| 716 | + |
| 717 | Normally, the "name" field contains the canonical name of the |
| 718 | command. When a canonical name is not available, one of |
| 719 | these special values are used: |
| 720 | + |
| 721 | ------------ |
| 722 | "_query_" # "git --html-path" |
| 723 | "_run_dashed_" # when "git foo" tries to run "git-foo" |
| 724 | "_run_shell_alias_" # alias expansion to a shell command |
| 725 | "_run_git_alias_" # alias expansion to a git command |
| 726 | "_usage_" # usage error |
| 727 | ------------ |
| 728 | |
| 729 | `"cmd_mode"`:: |
| 730 | This event, when present, describes the command variant This |
| 731 | event may be emitted more than once. |
| 732 | + |
| 733 | ------------ |
| 734 | { |
| 735 | "event":"cmd_mode", |
| 736 | ... |
| 737 | "name":"branch" |
| 738 | } |
| 739 | ------------ |
| 740 | + |
| 741 | The "name" field is an arbitrary string to describe the command mode. |
| 742 | For example, checkout can checkout a branch or an individual file. |
| 743 | And these variations typically have different performance |
| 744 | characteristics that are not comparable. |
| 745 | |
| 746 | `"alias"`:: |
| 747 | This event is present when an alias is expanded. |
| 748 | + |
| 749 | ------------ |
| 750 | { |
| 751 | "event":"alias", |
| 752 | ... |
| 753 | "alias":"l", # registered alias |
| 754 | "argv":["log","--graph"] # alias expansion |
| 755 | } |
| 756 | ------------ |
| 757 | |
| 758 | `"child_start"`:: |
| 759 | This event describes a child process that is about to be |
| 760 | spawned. |
| 761 | + |
| 762 | ------------ |
| 763 | { |
| 764 | "event":"child_start", |
| 765 | ... |
| 766 | "child_id":2, |
| 767 | "child_class":"?", |
| 768 | "use_shell":false, |
| 769 | "argv":["git","rev-list","--objects","--stdin","--not","--all","--quiet"] |
| 770 | |
| 771 | "hook_name":"<hook_name>" # present when child_class is "hook" |
| 772 | "cd":"<path>" # present when cd is required |
| 773 | } |
| 774 | ------------ |
| 775 | + |
| 776 | The "child_id" field can be used to match this child_start with the |
| 777 | corresponding child_exit event. |
| 778 | + |
| 779 | The "child_class" field is a rough classification, such as "editor", |
| 780 | "pager", "transport/*", and "hook". Unclassified children are classified |
| 781 | with "?". |
| 782 | |
| 783 | `"child_exit"`:: |
| 784 | This event is generated after the current process has returned |
| 785 | from the waitpid() and collected the exit information from the |
| 786 | child. |
| 787 | + |
| 788 | ------------ |
| 789 | { |
| 790 | "event":"child_exit", |
| 791 | ... |
| 792 | "child_id":2, |
| 793 | "pid":14708, # child PID |
| 794 | "code":0, # child exit-code |
| 795 | "t_rel":0.110605 # observed run-time of child process |
| 796 | } |
| 797 | ------------ |
| 798 | + |
| 799 | Note that the session-id of the child process is not available to |
| 800 | the current/spawning process, so the child's PID is reported here as |
| 801 | a hint for post-processing. (But it is only a hint because the child |
| 802 | proces may be a shell script which doesn't have a session-id.) |
| 803 | + |
| 804 | Note that the `t_rel` field contains the observed run time in seconds |
| 805 | for the child process (starting before the fork/exec/spawn and |
| 806 | stopping after the waitpid() and includes OS process creation overhead). |
| 807 | So this time will be slightly larger than the atexit time reported by |
| 808 | the child process itself. |
| 809 | |
| 810 | `"exec"`:: |
| 811 | This event is generated before git attempts to `exec()` |
| 812 | another command rather than starting a child process. |
| 813 | + |
| 814 | ------------ |
| 815 | { |
| 816 | "event":"exec", |
| 817 | ... |
| 818 | "exec_id":0, |
| 819 | "exe":"git", |
| 820 | "argv":["foo", "bar"] |
| 821 | } |
| 822 | ------------ |
| 823 | + |
| 824 | The "exec_id" field is a command-unique id and is only useful if the |
| 825 | `exec()` fails and a corresponding exec_result event is generated. |
| 826 | |
| 827 | `"exec_result"`:: |
| 828 | This event is generated if the `exec()` fails and control |
| 829 | returns to the current git command. |
| 830 | + |
| 831 | ------------ |
| 832 | { |
| 833 | "event":"exec_result", |
| 834 | ... |
| 835 | "exec_id":0, |
| 836 | "code":1 # error code (errno) from exec() |
| 837 | } |
| 838 | ------------ |
| 839 | |
| 840 | `"thread_start"`:: |
| 841 | This event is generated when a thread is started. It is |
| 842 | generated from *within* the new thread's thread-proc (for TLS |
| 843 | reasons). |
| 844 | + |
| 845 | ------------ |
| 846 | { |
| 847 | "event":"thread_start", |
| 848 | ... |
| 849 | "thread":"th02:preload_thread" # thread name |
| 850 | } |
| 851 | ------------ |
| 852 | |
| 853 | `"thread_exit"`:: |
| 854 | This event is generated when a thread exits. It is generated |
| 855 | from *within* the thread's thread-proc (for TLS reasons). |
| 856 | + |
| 857 | ------------ |
| 858 | { |
| 859 | "event":"thread_exit", |
| 860 | ... |
| 861 | "thread":"th02:preload_thread", # thread name |
| 862 | "t_rel":0.007328 # thread elapsed time |
| 863 | } |
| 864 | ------------ |
| 865 | |
| 866 | `"def_param"`:: |
| 867 | This event is generated to log a global parameter. |
| 868 | + |
| 869 | ------------ |
| 870 | { |
| 871 | "event":"def_param", |
| 872 | ... |
| 873 | "param":"core.abbrev", |
| 874 | "value":"7" |
| 875 | } |
| 876 | ------------ |
| 877 | |
| 878 | `"def_repo"`:: |
| 879 | This event defines a repo-id and associates it with the root |
| 880 | of the worktree. |
| 881 | + |
| 882 | ------------ |
| 883 | { |
| 884 | "event":"def_repo", |
| 885 | ... |
| 886 | "repo":1, |
| 887 | "worktree":"/Users/jeffhost/work/gfw" |
| 888 | } |
| 889 | ------------ |
| 890 | + |
| 891 | As stated earlier, the repo-id is currently always 1, so there will |
| 892 | only be one def_repo event. Later, if in-proc submodules are |
| 893 | supported, a def_repo event should be emitted for each submodule |
| 894 | visited. |
| 895 | |
| 896 | `"region_enter"`:: |
| 897 | This event is generated when entering a region. |
| 898 | + |
| 899 | ------------ |
| 900 | { |
| 901 | "event":"region_enter", |
| 902 | ... |
| 903 | "repo":1, # optional |
| 904 | "nesting":1, # current region stack depth |
| 905 | "category":"index", # optional |
| 906 | "label":"do_read_index", # optional |
| 907 | "msg":".git/index" # optional |
| 908 | } |
| 909 | ------------ |
| 910 | + |
| 911 | The `category` field may be used in a future enhancement to |
| 912 | do category-based filtering. |
| 913 | + |
SZEDER Gábor | e4b75d6 | 2019-05-19 16:43:08 +0200 | [diff] [blame^] | 914 | `GIT_TRACE2_EVENT_NESTING` or `trace2.eventNesting` can be used to |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 915 | filter deeply nested regions and data events. It defaults to "2". |
| 916 | |
| 917 | `"region_leave"`:: |
| 918 | This event is generated when leaving a region. |
| 919 | + |
| 920 | ------------ |
| 921 | { |
| 922 | "event":"region_leave", |
| 923 | ... |
| 924 | "repo":1, # optional |
| 925 | "t_rel":0.002876, # time spent in region in seconds |
| 926 | "nesting":1, # region stack depth |
| 927 | "category":"index", # optional |
| 928 | "label":"do_read_index", # optional |
| 929 | "msg":".git/index" # optional |
| 930 | } |
| 931 | ------------ |
| 932 | |
| 933 | `"data"`:: |
| 934 | This event is generated to log a thread- and region-local |
| 935 | key/value pair. |
| 936 | + |
| 937 | ------------ |
| 938 | { |
| 939 | "event":"data", |
| 940 | ... |
| 941 | "repo":1, # optional |
| 942 | "t_abs":0.024107, # absolute elapsed time |
| 943 | "t_rel":0.001031, # elapsed time in region/thread |
| 944 | "nesting":2, # region stack depth |
| 945 | "category":"index", |
| 946 | "key":"read/cache_nr", |
| 947 | "value":"3552" |
| 948 | } |
| 949 | ------------ |
| 950 | + |
| 951 | The "value" field may be an integer or a string. |
| 952 | |
| 953 | `"data-json"`:: |
| 954 | This event is generated to log a pre-formatted JSON string |
| 955 | containing structured data. |
| 956 | + |
| 957 | ------------ |
| 958 | { |
| 959 | "event":"data_json", |
| 960 | ... |
| 961 | "repo":1, # optional |
| 962 | "t_abs":0.015905, |
| 963 | "t_rel":0.015905, |
| 964 | "nesting":1, |
| 965 | "category":"process", |
| 966 | "key":"windows/ancestry", |
| 967 | "value":["bash.exe","bash.exe"] |
| 968 | } |
| 969 | ------------ |
| 970 | |
| 971 | == Example Trace2 API Usage |
| 972 | |
| 973 | Here is a hypothetical usage of the Trace2 API showing the intended |
| 974 | usage (without worrying about the actual Git details). |
| 975 | |
| 976 | Initialization:: |
| 977 | |
| 978 | Initialization happens in `main()`. Behind the scenes, an |
| 979 | `atexit` and `signal` handler are registered. |
| 980 | + |
| 981 | ---------------- |
| 982 | int main(int argc, const char **argv) |
| 983 | { |
| 984 | int exit_code; |
| 985 | |
| 986 | trace2_initialize(); |
| 987 | trace2_cmd_start(argv); |
| 988 | |
| 989 | exit_code = cmd_main(argc, argv); |
| 990 | |
| 991 | trace2_cmd_exit(exit_code); |
| 992 | |
| 993 | return exit_code; |
| 994 | } |
| 995 | ---------------- |
| 996 | |
| 997 | Command Details:: |
| 998 | |
| 999 | After the basics are established, additional command |
| 1000 | information can be sent to Trace2 as it is discovered. |
| 1001 | + |
| 1002 | ---------------- |
| 1003 | int cmd_checkout(int argc, const char **argv) |
| 1004 | { |
| 1005 | trace2_cmd_name("checkout"); |
| 1006 | trace2_cmd_mode("branch"); |
| 1007 | trace2_def_repo(the_repository); |
| 1008 | |
| 1009 | // emit "def_param" messages for "interesting" config settings. |
| 1010 | trace2_cmd_list_config(); |
| 1011 | |
| 1012 | if (do_something()) |
| 1013 | trace2_cmd_error("Path '%s': cannot do something", path); |
| 1014 | |
| 1015 | return 0; |
| 1016 | } |
| 1017 | ---------------- |
| 1018 | |
| 1019 | Child Processes:: |
| 1020 | |
| 1021 | Wrap code spawning child processes. |
| 1022 | + |
| 1023 | ---------------- |
| 1024 | void run_child(...) |
| 1025 | { |
| 1026 | int child_exit_code; |
| 1027 | struct child_process cmd = CHILD_PROCESS_INIT; |
| 1028 | ... |
| 1029 | cmd.trace2_child_class = "editor"; |
| 1030 | |
| 1031 | trace2_child_start(&cmd); |
| 1032 | child_exit_code = spawn_child_and_wait_for_it(); |
| 1033 | trace2_child_exit(&cmd, child_exit_code); |
| 1034 | } |
| 1035 | ---------------- |
| 1036 | + |
| 1037 | For example, the following fetch command spawned ssh, index-pack, |
| 1038 | rev-list, and gc. This example also shows that fetch took |
| 1039 | 5.199 seconds and of that 4.932 was in ssh. |
| 1040 | + |
| 1041 | ---------------- |
SZEDER Gábor | e4b75d6 | 2019-05-19 16:43:08 +0200 | [diff] [blame^] | 1042 | $ export GIT_TRACE2_BRIEF=1 |
| 1043 | $ export GIT_TRACE2=~/log.normal |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 1044 | $ git fetch origin |
| 1045 | ... |
| 1046 | ---------------- |
| 1047 | + |
| 1048 | ---------------- |
| 1049 | $ cat ~/log.normal |
| 1050 | version 2.20.1.vfs.1.1.47.g534dbe1ad1 |
| 1051 | start git fetch origin |
| 1052 | worktree /Users/jeffhost/work/gfw |
| 1053 | cmd_name fetch (fetch) |
| 1054 | child_start[0] ssh git@github.com ... |
| 1055 | child_start[1] git index-pack ... |
| 1056 | ... (Trace2 events from child processes omitted) |
| 1057 | child_exit[1] pid:14707 code:0 elapsed:0.076353 |
| 1058 | child_exit[0] pid:14706 code:0 elapsed:4.931869 |
| 1059 | child_start[2] git rev-list ... |
| 1060 | ... (Trace2 events from child process omitted) |
| 1061 | child_exit[2] pid:14708 code:0 elapsed:0.110605 |
| 1062 | child_start[3] git gc --auto |
| 1063 | ... (Trace2 events from child process omitted) |
| 1064 | child_exit[3] pid:14709 code:0 elapsed:0.006240 |
| 1065 | exit elapsed:5.198503 code:0 |
| 1066 | atexit elapsed:5.198541 code:0 |
| 1067 | ---------------- |
| 1068 | + |
| 1069 | When a git process is a (direct or indirect) child of another |
| 1070 | git process, it inherits Trace2 context information. This |
| 1071 | allows the child to print the command hierarchy. This example |
| 1072 | shows gc as child[3] of fetch. When the gc process reports |
| 1073 | its name as "gc", it also reports the hierarchy as "fetch/gc". |
| 1074 | (In this example, trace2 messages from the child process is |
| 1075 | indented for clarity.) |
| 1076 | + |
| 1077 | ---------------- |
SZEDER Gábor | e4b75d6 | 2019-05-19 16:43:08 +0200 | [diff] [blame^] | 1078 | $ export GIT_TRACE2_BRIEF=1 |
| 1079 | $ export GIT_TRACE2=~/log.normal |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 1080 | $ git fetch origin |
| 1081 | ... |
| 1082 | ---------------- |
| 1083 | + |
| 1084 | ---------------- |
| 1085 | $ cat ~/log.normal |
| 1086 | version 2.20.1.160.g5676107ecd.dirty |
| 1087 | start git fetch official |
| 1088 | worktree /Users/jeffhost/work/gfw |
| 1089 | cmd_name fetch (fetch) |
| 1090 | ... |
| 1091 | child_start[3] git gc --auto |
| 1092 | version 2.20.1.160.g5676107ecd.dirty |
| 1093 | start /Users/jeffhost/work/gfw/git gc --auto |
| 1094 | worktree /Users/jeffhost/work/gfw |
| 1095 | cmd_name gc (fetch/gc) |
| 1096 | exit elapsed:0.001959 code:0 |
| 1097 | atexit elapsed:0.001997 code:0 |
| 1098 | child_exit[3] pid:20303 code:0 elapsed:0.007564 |
| 1099 | exit elapsed:3.868938 code:0 |
| 1100 | atexit elapsed:3.868970 code:0 |
| 1101 | ---------------- |
| 1102 | |
| 1103 | Regions:: |
| 1104 | |
| 1105 | Regions can be use to time an interesting section of code. |
| 1106 | + |
| 1107 | ---------------- |
| 1108 | void wt_status_collect(struct wt_status *s) |
| 1109 | { |
| 1110 | trace2_region_enter("status", "worktrees", s->repo); |
| 1111 | wt_status_collect_changes_worktree(s); |
| 1112 | trace2_region_leave("status", "worktrees", s->repo); |
| 1113 | |
| 1114 | trace2_region_enter("status", "index", s->repo); |
| 1115 | wt_status_collect_changes_index(s); |
| 1116 | trace2_region_leave("status", "index", s->repo); |
| 1117 | |
| 1118 | trace2_region_enter("status", "untracked", s->repo); |
| 1119 | wt_status_collect_untracked(s); |
| 1120 | trace2_region_leave("status", "untracked", s->repo); |
| 1121 | } |
| 1122 | |
| 1123 | void wt_status_print(struct wt_status *s) |
| 1124 | { |
| 1125 | trace2_region_enter("status", "print", s->repo); |
| 1126 | switch (s->status_format) { |
| 1127 | ... |
| 1128 | } |
| 1129 | trace2_region_leave("status", "print", s->repo); |
| 1130 | } |
| 1131 | ---------------- |
| 1132 | + |
| 1133 | In this example, scanning for untracked files ran from +0.012568 to |
| 1134 | +0.027149 (since the process started) and took 0.014581 seconds. |
| 1135 | + |
| 1136 | ---------------- |
SZEDER Gábor | e4b75d6 | 2019-05-19 16:43:08 +0200 | [diff] [blame^] | 1137 | $ export GIT_TRACE2_PERF_BRIEF=1 |
| 1138 | $ export GIT_TRACE2_PERF=~/log.perf |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 1139 | $ git status |
| 1140 | ... |
| 1141 | |
| 1142 | $ cat ~/log.perf |
| 1143 | d0 | main | version | | | | | 2.20.1.160.g5676107ecd.dirty |
Jeff Hostetler | 39f4317 | 2019-04-15 13:39:44 -0700 | [diff] [blame] | 1144 | d0 | main | start | | 0.001173 | | | git status |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 1145 | d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw |
| 1146 | d0 | main | cmd_name | | | | | status (status) |
| 1147 | ... |
| 1148 | d0 | main | region_enter | r1 | 0.010988 | | status | label:worktrees |
| 1149 | d0 | main | region_leave | r1 | 0.011236 | 0.000248 | status | label:worktrees |
| 1150 | d0 | main | region_enter | r1 | 0.011260 | | status | label:index |
| 1151 | d0 | main | region_leave | r1 | 0.012542 | 0.001282 | status | label:index |
| 1152 | d0 | main | region_enter | r1 | 0.012568 | | status | label:untracked |
| 1153 | d0 | main | region_leave | r1 | 0.027149 | 0.014581 | status | label:untracked |
| 1154 | d0 | main | region_enter | r1 | 0.027411 | | status | label:print |
| 1155 | d0 | main | region_leave | r1 | 0.028741 | 0.001330 | status | label:print |
| 1156 | d0 | main | exit | | 0.028778 | | | code:0 |
| 1157 | d0 | main | atexit | | 0.028809 | | | code:0 |
| 1158 | ---------------- |
| 1159 | + |
| 1160 | Regions may be nested. This causes messages to be indented in the |
| 1161 | PERF target, for example. |
| 1162 | Elapsed times are relative to the start of the correpsonding nesting |
| 1163 | level as expected. For example, if we add region message to: |
| 1164 | + |
| 1165 | ---------------- |
| 1166 | static enum path_treatment read_directory_recursive(struct dir_struct *dir, |
| 1167 | struct index_state *istate, const char *base, int baselen, |
| 1168 | struct untracked_cache_dir *untracked, int check_only, |
| 1169 | int stop_at_first_file, const struct pathspec *pathspec) |
| 1170 | { |
| 1171 | enum path_treatment state, subdir_state, dir_state = path_none; |
| 1172 | |
| 1173 | trace2_region_enter_printf("dir", "read_recursive", NULL, "%.*s", baselen, base); |
| 1174 | ... |
| 1175 | trace2_region_leave_printf("dir", "read_recursive", NULL, "%.*s", baselen, base); |
| 1176 | return dir_state; |
| 1177 | } |
| 1178 | ---------------- |
| 1179 | + |
| 1180 | We can further investigate the time spent scanning for untracked files. |
| 1181 | + |
| 1182 | ---------------- |
SZEDER Gábor | e4b75d6 | 2019-05-19 16:43:08 +0200 | [diff] [blame^] | 1183 | $ export GIT_TRACE2_PERF_BRIEF=1 |
| 1184 | $ export GIT_TRACE2_PERF=~/log.perf |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 1185 | $ git status |
| 1186 | ... |
| 1187 | $ cat ~/log.perf |
| 1188 | d0 | main | version | | | | | 2.20.1.162.gb4ccea44db.dirty |
Jeff Hostetler | 39f4317 | 2019-04-15 13:39:44 -0700 | [diff] [blame] | 1189 | d0 | main | start | | 0.001173 | | | git status |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 1190 | d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw |
| 1191 | d0 | main | cmd_name | | | | | status (status) |
| 1192 | ... |
| 1193 | d0 | main | region_enter | r1 | 0.015047 | | status | label:untracked |
| 1194 | d0 | main | region_enter | | 0.015132 | | dir | ..label:read_recursive |
| 1195 | d0 | main | region_enter | | 0.016341 | | dir | ....label:read_recursive vcs-svn/ |
| 1196 | d0 | main | region_leave | | 0.016422 | 0.000081 | dir | ....label:read_recursive vcs-svn/ |
| 1197 | d0 | main | region_enter | | 0.016446 | | dir | ....label:read_recursive xdiff/ |
| 1198 | d0 | main | region_leave | | 0.016522 | 0.000076 | dir | ....label:read_recursive xdiff/ |
| 1199 | d0 | main | region_enter | | 0.016612 | | dir | ....label:read_recursive git-gui/ |
| 1200 | d0 | main | region_enter | | 0.016698 | | dir | ......label:read_recursive git-gui/po/ |
| 1201 | d0 | main | region_enter | | 0.016810 | | dir | ........label:read_recursive git-gui/po/glossary/ |
| 1202 | d0 | main | region_leave | | 0.016863 | 0.000053 | dir | ........label:read_recursive git-gui/po/glossary/ |
| 1203 | ... |
| 1204 | d0 | main | region_enter | | 0.031876 | | dir | ....label:read_recursive builtin/ |
| 1205 | d0 | main | region_leave | | 0.032270 | 0.000394 | dir | ....label:read_recursive builtin/ |
| 1206 | d0 | main | region_leave | | 0.032414 | 0.017282 | dir | ..label:read_recursive |
| 1207 | d0 | main | region_leave | r1 | 0.032454 | 0.017407 | status | label:untracked |
| 1208 | ... |
| 1209 | d0 | main | exit | | 0.034279 | | | code:0 |
| 1210 | d0 | main | atexit | | 0.034322 | | | code:0 |
| 1211 | ---------------- |
| 1212 | + |
| 1213 | Trace2 regions are similar to the existing trace_performance_enter() |
| 1214 | and trace_performance_leave() routines, but are thread safe and |
| 1215 | maintain per-thread stacks of timers. |
| 1216 | |
| 1217 | Data Messages:: |
| 1218 | |
| 1219 | Data messages added to a region. |
| 1220 | + |
| 1221 | ---------------- |
| 1222 | int read_index_from(struct index_state *istate, const char *path, |
| 1223 | const char *gitdir) |
| 1224 | { |
| 1225 | trace2_region_enter_printf("index", "do_read_index", the_repository, "%s", path); |
| 1226 | |
| 1227 | ... |
| 1228 | |
| 1229 | trace2_data_intmax("index", the_repository, "read/version", istate->version); |
| 1230 | trace2_data_intmax("index", the_repository, "read/cache_nr", istate->cache_nr); |
| 1231 | |
| 1232 | trace2_region_leave_printf("index", "do_read_index", the_repository, "%s", path); |
| 1233 | } |
| 1234 | ---------------- |
| 1235 | + |
| 1236 | This example shows that the index contained 3552 entries. |
| 1237 | + |
| 1238 | ---------------- |
SZEDER Gábor | e4b75d6 | 2019-05-19 16:43:08 +0200 | [diff] [blame^] | 1239 | $ export GIT_TRACE2_PERF_BRIEF=1 |
| 1240 | $ export GIT_TRACE2_PERF=~/log.perf |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 1241 | $ git status |
| 1242 | ... |
| 1243 | $ cat ~/log.perf |
| 1244 | d0 | main | version | | | | | 2.20.1.156.gf9916ae094.dirty |
Jeff Hostetler | 39f4317 | 2019-04-15 13:39:44 -0700 | [diff] [blame] | 1245 | d0 | main | start | | 0.001173 | | | git status |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 1246 | d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw |
| 1247 | d0 | main | cmd_name | | | | | status (status) |
| 1248 | d0 | main | region_enter | r1 | 0.001791 | | index | label:do_read_index .git/index |
| 1249 | d0 | main | data | r1 | 0.002494 | 0.000703 | index | ..read/version:2 |
| 1250 | d0 | main | data | r1 | 0.002520 | 0.000729 | index | ..read/cache_nr:3552 |
| 1251 | d0 | main | region_leave | r1 | 0.002539 | 0.000748 | index | label:do_read_index .git/index |
| 1252 | ... |
| 1253 | ---------------- |
| 1254 | |
| 1255 | Thread Events:: |
| 1256 | |
| 1257 | Thread messages added to a thread-proc. |
| 1258 | + |
| 1259 | For example, the multithreaded preload-index code can be |
| 1260 | instrumented with a region around the thread pool and then |
| 1261 | per-thread start and exit events within the threadproc. |
| 1262 | + |
| 1263 | ---------------- |
| 1264 | static void *preload_thread(void *_data) |
| 1265 | { |
| 1266 | // start the per-thread clock and emit a message. |
| 1267 | trace2_thread_start("preload_thread"); |
| 1268 | |
| 1269 | // report which chunk of the array this thread was assigned. |
| 1270 | trace2_data_intmax("index", the_repository, "offset", p->offset); |
| 1271 | trace2_data_intmax("index", the_repository, "count", nr); |
| 1272 | |
| 1273 | do { |
| 1274 | ... |
| 1275 | } while (--nr > 0); |
| 1276 | ... |
| 1277 | |
| 1278 | // report elapsed time taken by this thread. |
| 1279 | trace2_thread_exit(); |
| 1280 | return NULL; |
| 1281 | } |
| 1282 | |
| 1283 | void preload_index(struct index_state *index, |
| 1284 | const struct pathspec *pathspec, |
| 1285 | unsigned int refresh_flags) |
| 1286 | { |
| 1287 | trace2_region_enter("index", "preload", the_repository); |
| 1288 | |
| 1289 | for (i = 0; i < threads; i++) { |
| 1290 | ... /* create thread */ |
| 1291 | } |
| 1292 | |
| 1293 | for (i = 0; i < threads; i++) { |
| 1294 | ... /* join thread */ |
| 1295 | } |
| 1296 | |
| 1297 | trace2_region_leave("index", "preload", the_repository); |
| 1298 | } |
| 1299 | ---------------- |
| 1300 | + |
| 1301 | In this example preload_index() was executed by the `main` thread |
| 1302 | and started the `preload` region. Seven threads, named |
| 1303 | `th01:preload_thread` through `th07:preload_thread`, were started. |
| 1304 | Events from each thread are atomically appended to the shared target |
| 1305 | stream as they occur so they may appear in random order with respect |
| 1306 | other threads. Finally, the main thread waits for the threads to |
| 1307 | finish and leaves the region. |
| 1308 | + |
| 1309 | Data events are tagged with the active thread name. They are used |
| 1310 | to report the per-thread parameters. |
| 1311 | + |
| 1312 | ---------------- |
SZEDER Gábor | e4b75d6 | 2019-05-19 16:43:08 +0200 | [diff] [blame^] | 1313 | $ export GIT_TRACE2_PERF_BRIEF=1 |
| 1314 | $ export GIT_TRACE2_PERF=~/log.perf |
Jeff Hostetler | e544221 | 2019-02-22 14:25:00 -0800 | [diff] [blame] | 1315 | $ git status |
| 1316 | ... |
| 1317 | $ cat ~/log.perf |
| 1318 | ... |
| 1319 | d0 | main | region_enter | r1 | 0.002595 | | index | label:preload |
| 1320 | d0 | th01:preload_thread | thread_start | | 0.002699 | | | |
| 1321 | d0 | th02:preload_thread | thread_start | | 0.002721 | | | |
| 1322 | d0 | th01:preload_thread | data | r1 | 0.002736 | 0.000037 | index | offset:0 |
| 1323 | d0 | th02:preload_thread | data | r1 | 0.002751 | 0.000030 | index | offset:2032 |
| 1324 | d0 | th03:preload_thread | thread_start | | 0.002711 | | | |
| 1325 | d0 | th06:preload_thread | thread_start | | 0.002739 | | | |
| 1326 | d0 | th01:preload_thread | data | r1 | 0.002766 | 0.000067 | index | count:508 |
| 1327 | d0 | th06:preload_thread | data | r1 | 0.002856 | 0.000117 | index | offset:2540 |
| 1328 | d0 | th03:preload_thread | data | r1 | 0.002824 | 0.000113 | index | offset:1016 |
| 1329 | d0 | th04:preload_thread | thread_start | | 0.002710 | | | |
| 1330 | d0 | th02:preload_thread | data | r1 | 0.002779 | 0.000058 | index | count:508 |
| 1331 | d0 | th06:preload_thread | data | r1 | 0.002966 | 0.000227 | index | count:508 |
| 1332 | d0 | th07:preload_thread | thread_start | | 0.002741 | | | |
| 1333 | d0 | th07:preload_thread | data | r1 | 0.003017 | 0.000276 | index | offset:3048 |
| 1334 | d0 | th05:preload_thread | thread_start | | 0.002712 | | | |
| 1335 | d0 | th05:preload_thread | data | r1 | 0.003067 | 0.000355 | index | offset:1524 |
| 1336 | d0 | th05:preload_thread | data | r1 | 0.003090 | 0.000378 | index | count:508 |
| 1337 | d0 | th07:preload_thread | data | r1 | 0.003037 | 0.000296 | index | count:504 |
| 1338 | d0 | th03:preload_thread | data | r1 | 0.002971 | 0.000260 | index | count:508 |
| 1339 | d0 | th04:preload_thread | data | r1 | 0.002983 | 0.000273 | index | offset:508 |
| 1340 | d0 | th04:preload_thread | data | r1 | 0.007311 | 0.004601 | index | count:508 |
| 1341 | d0 | th05:preload_thread | thread_exit | | 0.008781 | 0.006069 | | |
| 1342 | d0 | th01:preload_thread | thread_exit | | 0.009561 | 0.006862 | | |
| 1343 | d0 | th03:preload_thread | thread_exit | | 0.009742 | 0.007031 | | |
| 1344 | d0 | th06:preload_thread | thread_exit | | 0.009820 | 0.007081 | | |
| 1345 | d0 | th02:preload_thread | thread_exit | | 0.010274 | 0.007553 | | |
| 1346 | d0 | th07:preload_thread | thread_exit | | 0.010477 | 0.007736 | | |
| 1347 | d0 | th04:preload_thread | thread_exit | | 0.011657 | 0.008947 | | |
| 1348 | d0 | main | region_leave | r1 | 0.011717 | 0.009122 | index | label:preload |
| 1349 | ... |
| 1350 | d0 | main | exit | | 0.029996 | | | code:0 |
| 1351 | d0 | main | atexit | | 0.030027 | | | code:0 |
| 1352 | ---------------- |
| 1353 | + |
| 1354 | In this example, the preload region took 0.009122 seconds. The 7 threads |
| 1355 | took between 0.006069 and 0.008947 seconds to work on their portion of |
| 1356 | the index. Thread "th01" worked on 508 items at offset 0. Thread "th02" |
| 1357 | worked on 508 items at offset 2032. Thread "th04" worked on 508 itemts |
| 1358 | at offset 508. |
| 1359 | + |
| 1360 | This example also shows that thread names are assigned in a racy manner |
| 1361 | as each thread starts and allocates TLS storage. |
| 1362 | |
| 1363 | == Future Work |
| 1364 | |
| 1365 | === Relationship to the Existing Trace Api (api-trace.txt) |
| 1366 | |
| 1367 | There are a few issues to resolve before we can completely |
| 1368 | switch to Trace2. |
| 1369 | |
| 1370 | * Updating existing tests that assume GIT_TRACE format messages. |
| 1371 | |
| 1372 | * How to best handle custom GIT_TRACE_<key> messages? |
| 1373 | |
| 1374 | ** The GIT_TRACE_<key> mechanism allows each <key> to write to a |
| 1375 | different file (in addition to just stderr). |
| 1376 | |
| 1377 | ** Do we want to maintain that ability or simply write to the existing |
| 1378 | Trace2 targets (and convert <key> to a "category"). |