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