e544221d97 · matheusbsbs/matheus-bagliano

@@ -0,0 +1,1349 @@

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 +

25 +== Trace2 Targets

26 +

27 +Trace2 defines the following set of Trace2 Targets.

28 +Format details are given in a later section.

29 +

30 +`GIT_TR2` (NORMAL)::

31 +

32 + a simple printf format like GIT_TRACE.

33 ++

34 +------------

35 +$ export GIT_TR2=~/log.normal

36 +$ git version

37 +git version 2.20.1.155.g426c96fcdb

38 +------------

39 ++

40 +------------

41 +$ cat ~/log.normal

42 +12:28:42.620009 common-main.c:38 version 2.20.1.155.g426c96fcdb

43 +12:28:42.620989 common-main.c:39 start git version

44 +12:28:42.621101 git.c:432 cmd_name version (version)

45 +12:28:42.621215 git.c:662 exit elapsed:0.001227 code:0

46 +12:28:42.621250 trace2/tr2_tgt_normal.c:124 atexit elapsed:0.001265 code:0

47 +------------

48 +

49 +`GIT_TR2_PERF` (PERF)::

50 +

51 + a column-based format to replace GIT_TRACE_PERFORMANCE suitable for

52 + development and testing, possibly to complement tools like gprof.

53 ++

54 +------------

55 +$ export GIT_TR2_PERF=~/log.perf

56 +$ git version

57 +git version 2.20.1.155.g426c96fcdb

58 +------------

59 ++

60 +------------

61 +$ cat ~/log.perf

67 +------------

68 +

69 +`GIT_TR2_EVENT` (EVENT)::

70 +

71 + a JSON-based format of event data suitable for telemetry analysis.

72 ++

73 +------------

74 +$ export GIT_TR2_EVENT=~/log.event

75 +$ git version

76 +git version 2.20.1.155.g426c96fcdb

77 +------------

78 ++

79 +------------

80 +$ cat ~/log.event

81 +{"event":"version","sid":"1547659722619736-11614","thread":"main","time":"2019-01-16 17:28:42.620713","file":"common-main.c","line":38,"evt":"1","exe":"2.20.1.155.g426c96fcdb"}

82 +{"event":"start","sid":"1547659722619736-11614","thread":"main","time":"2019-01-16 17:28:42.621027","file":"common-main.c","line":39,"argv":["git","version"]}

83 +{"event":"cmd_name","sid":"1547659722619736-11614","thread":"main","time":"2019-01-16 17:28:42.621122","file":"git.c","line":432,"name":"version","hierarchy":"version"}

84 +{"event":"exit","sid":"1547659722619736-11614","thread":"main","time":"2019-01-16 17:28:42.621236","file":"git.c","line":662,"t_abs":0.001227,"code":0}

85 +{"event":"atexit","sid":"1547659722619736-11614","thread":"main","time":"2019-01-16 17:28:42.621268","file":"trace2/tr2_tgt_event.c","line":163,"t_abs":0.001265,"code":0}

86 +------------

87 +

88 +== Enabling a Target

89 +

90 +A Trace2 Target is enabled when the corresponding environment variable

91 +(`GIT_TR2`, `GIT_TR2_PERF`, or `GIT_TR2_EVENT`) is set. The following

92 +values are recognized.

93 +

94 +`0`::

95 +`false`::

96 +

97 + Disables the target.

98 +

99 +`1`::

100 +`true`::

101 +

102 + Enables the target and writes stream to `STDERR`.

103 +

104 +`[2-9]`::

105 +

106 + Enables the target and writes to the already opened file descriptor.

107 +

108 +`<absolute-pathname>`::

109 +

110 + Enables the target, opens and writes to the file in append mode.

111 +

112 +`af_unix:[<socket_type>:]<absolute-pathname>`::

113 +

114 + Enables the target, opens and writes to a Unix Domain Socket

115 + (on platforms that support them).

116 ++

117 +Socket type can be either `stream` or `dgram`. If the socket type is

118 +omitted, Git will try both.

119 +

120 +== Trace2 API

121 +

122 +All public Trace2 functions and macros are defined in `trace2.h` and

123 +`trace2.c`. All public symbols are prefixed with `trace2_`.

124 +

125 +There are no public Trace2 data structures.

126 +

127 +The Trace2 code also defines a set of private functions and data types

128 +in the `trace2/` directory. These symbols are prefixed with `tr2_`

129 +and should only be used by functions in `trace2.c`.

130 +

131 +== Conventions for Public Functions and Macros

132 +

133 +The functions defined by the Trace2 API are declared and documented

134 +in `trace2.h`. It defines the API functions and wrapper macros for

135 +Trace2.

136 +

137 +Some functions have a `_fl()` suffix to indicate that they take `file`

138 +and `line-number` arguments.

139 +

140 +Some functions have a `_va_fl()` suffix to indicate that they also

141 +take a `va_list` argument.

142 +

143 +Some functions have a `_printf_fl()` suffix to indicate that they also

144 +take a varargs argument.

145 +

146 +There are CPP wrapper macros and ifdefs to hide most of these details.

147 +See `trace2.h` for more details. The following discussion will only

148 +describe the simplified forms.

149 +

150 +== Public API

151 +

152 +All Trace2 API functions send a messsage to all of the active

153 +Trace2 Targets. This section describes the set of available

154 +messages.

155 +

156 +It helps to divide these functions into groups for discussion

157 +purposes.

158 +

159 +=== Basic Command Messages

160 +

161 +These are concerned with the lifetime of the overall git process.

162 +

163 +`void trace2_initialize()`::

164 +

165 + Determines if any Trace2 Targets should be enabled and

166 + initializes the Trace2 facility. This includes starting the

167 + elapsed time clocks and thread local storage (TLS).

168 ++

169 +This function emits a "version" message containing the version of git

170 +and the Trace2 protocol.

171 ++

172 +This function should be called from `main()` as early as possible in

173 +the life of the process.

174 +

175 +`int trace2_is_enabled()`::

176 +

177 + Returns 1 if Trace2 is enabled (at least one target is

178 + active).

179 +

180 +`void trace2_cmd_start(int argc, const char **argv)`::

181 +

182 + Emits a "start" message containing the process command line

183 + arguments.

184 +

185 +`int trace2_cmd_exit(int exit_code)`::

186 +

187 + Emits an "exit" message containing the process exit-code and

188 + elapsed time.

189 ++

190 +Returns the exit-code.

191 +

192 +`void trace2_cmd_error(const char *fmt, va_list ap)`::

193 +

194 + Emits an "error" message containing a formatted error message.

195 +

196 +`void trace2_cmd_path(const char *pathname)`::

197 +

198 + Emits a "cmd_path" message with the full pathname of the

199 + current process.

200 +

201 +=== Command Detail Messages

202 +

203 +These are concerned with describing the specific Git command

204 +after the command line, config, and environment are inspected.

205 +

206 +`void trace2_cmd_name(const char *name)`::

207 +

208 + Emits a "cmd_name" message with the canonical name of the

209 + command, for example "status" or "checkout".

210 +

211 +`void trace2_cmd_mode(const char *mode)`::

212 +

213 + Emits a "cmd_mode" message with a qualifier name to further

214 + describe the current git command.

215 ++

216 +This message is intended to be used with git commands having multiple

217 +major modes. For example, a "checkout" command can checkout a new

218 +branch or it can checkout a single file, so the checkout code could

219 +emit a cmd_mode message of "branch" or "file".

220 +

221 +`void trace2_cmd_alias(const char *alias, const char **argv_expansion)`::

222 +

223 + Emits an "alias" message containing the alias used and the

224 + argument expansion.

225 +

226 +`void trace2_def_param(const char *parameter, const char *value)`::

227 +

228 + Emits a "def_param" message containing a key/value pair.

229 ++

230 +This message is intended to report some global aspect of the current

231 +command, such as a configuration setting or command line switch that

232 +significantly affects program performance or behavior, such as

233 +`core.abbrev`, `status.showUntrackedFiles`, or `--no-ahead-behind`.

234 +

235 +`void trace2_cmd_list_config()`::

236 +

237 + Emits a "def_param" messages for "important" configuration

238 + settings.

239 ++

240 +The environment variable `GIT_TR2_CONFIG_PARAMS` can be set to a

241 +list of patterns of important configuration settings, for example:

242 +`core.*,remote.*.url`. This function will iterate over all config

243 +settings and emit a "def_param" message for each match.

244 +

245 +`void trace2_cmd_set_config(const char *key, const char *value)`::

246 +

247 + Emits a "def_param" message for a specific configuration

248 + setting IFF it matches the `GIT_TR2_CONFIG_PARAMS` pattern.

249 ++

250 +This is used to hook into `git_config_set()` and catch any

251 +configuration changes and update a value previously reported by

252 +`trace2_cmd_list_config()`.

253 +

254 +`void trace2_def_repo(struct repository *repo)`::

255 +

256 + Registers a repository with the Trace2 layer. Assigns a

257 + unique "repo-id" to `repo->trace2_repo_id`.

258 ++

259 +Emits a "worktree" messages containing the repo-id and the worktree

260 +pathname.

261 ++

262 +Region and data messages (described later) may refer to this repo-id.

263 ++

264 +The main/top-level repository will have repo-id value 1 (aka "r1").

265 ++

266 +The repo-id field is in anticipation of future in-proc submodule

267 +repositories.

268 +

269 +=== Child Process Messages

270 +

271 +These are concerned with the various spawned child processes,

272 +including shell scripts, git commands, editors, pagers, and hooks.

273 +

274 +`void trace2_child_start(struct child_process *cmd)`::

275 +

276 + Emits a "child_start" message containing the "child-id",

277 + "child-argv", and "child-classification".

278 ++

279 +Before calling this, set `cmd->trace2_child_class` to a name

280 +describing the type of child process, for example "editor".

281 ++

282 +This function assigns a unique "child-id" to `cmd->trace2_child_id`.

283 +This field is used later during the "child_exit" message to associate

284 +it with the "child_start" message.

285 ++

286 +This function should be called before spawning the child process.

287 +

288 +`void trace2_child_exit(struct child_proess *cmd, int child_exit_code)`::

289 +

290 + Emits a "child_exit" message containing the "child-id",

291 + the child's elapsed time and exit-code.

292 ++

293 +The reported elapsed time includes the process creation overhead and

294 +time spend waiting for it to exit, so it may be slightly longer than

295 +the time reported by the child itself.

296 ++

297 +This function should be called after reaping the child process.

298 +

299 +`int trace2_exec(const char *exe, const char **argv)`::

300 +

301 + Emits a "exec" message containing the "exec-id" and the

302 + argv of the new process.

303 ++

304 +This function should be called before calling one of the `exec()`

305 +variants, such as `execvp()`.

306 ++

307 +This function returns a unique "exec-id". This value is used later

308 +if the exec() fails and a "exec-result" message is necessary.

309 +

310 +`void trace2_exec_result(int exec_id, int error_code)`::

311 +

312 + Emits a "exec_result" message containing the "exec-id"

313 + and the error code.

314 ++

315 +On Unix-based systems, `exec()` does not return if successful.

316 +This message is used to indicate that the `exec()` failed and

317 +that the current program is continuing.

318 +

319 +=== Git Thread Messages

320 +

321 +These messages are concerned with Git thread usage.

322 +

323 +`void trace2_thread_start(const char *thread_name)`::

324 +

325 + Emits a "thread_start" message.

326 ++

327 +The `thread_name` field should be a descriptive name, such as the

328 +unique name of the thread-proc. A unique "thread-id" will be added

329 +to the name to uniquely identify thread instances.

330 ++

331 +Region and data messages (described later) may refer to this thread

332 +name.

333 ++

334 +This function must be called by the thread-proc of the new thread

335 +(so that TLS data is properly initialized) and not by the caller

336 +of `pthread_create()`.

337 +

338 +`void trace2_thread_exit()`::

339 +

340 + Emits a "thread_exit" message containing the thread name

341 + and the thread elapsed time.

342 ++

343 +This function must be called by the thread-proc before it returns

344 +(so that the coorect TLS data is used and cleaned up. It should

345 +not be called by the caller of `pthread_join()`.

346 +

347 +=== Region and Data Messages

348 +

349 +These are concerned with recording performance data

350 +over regions or spans of code.

351 +

352 +`void trace2_region_enter(const char *category, const char *label, const struct repository *repo)`::

353 +

354 +`void trace2_region_enter_printf(const char *category, const char *label, const struct repository *repo, const char *fmt, ...)`::

355 +

356 +`void trace2_region_enter_printf_va(const char *category, const char *label, const struct repository *repo, const char *fmt, va_list ap)`::

357 +

358 + Emits a thread-relative "region_enter" message with optional

359 + printf string.

360 ++

361 +This function pushes a new region nesting stack level on the current

362 +thread and starts a clock for the new stack frame.

363 ++

364 +The `category` field is an arbitrary category name used to classify

365 +regions by feature area, such as "status" or "index". At this time

366 +it is only just printed along with the rest of the message. It may

367 +be used in the future to filter messages.

368 ++

369 +The `label` field is an arbitrary label used to describe the activity

370 +being started, such as "read_recursive" or "do_read_index".

371 ++

372 +The `repo` field, if set, will be used to get the "repo-id", so that

373 +recursive oerations can be attributed to the correct repository.

374 +

375 +`void trace2_region_leave(const char *category, const char *label, const struct repository *repo)`::

376 +

377 +`void trace2_region_leave_printf(const char *category, const char *label, const struct repository *repo, const char *fmt, ...)`::

378 +

379 +`void trace2_region_leave_printf_va(const char *category, const char *label, const struct repository *repo, const char *fmt, va_list ap)`::

380 +

381 + Emits a thread-relative "region_leave" message with optional

382 + printf string.

383 ++

384 +This function pops the region nesting stack on the current thread

385 +and reports the elapsed time of the stack frame.

386 ++

387 +The `category`, `label`, and `repo` fields are the same as above.

388 +The `category` and `label` do not need to match the correpsonding

389 +"region_enter" message, but it makes the data stream easier to

390 +understand.

391 +

392 +`void trace2_data_string(const char *category, const struct repository *repo, const char *key, const char * value)`::

393 +

394 +`void trace2_data_intmax(const char *category, const struct repository *repo, const char *key, intmax value)`::

395 +

396 +`void trace2_data_json(const char *category, const struct repository *repo, const char *key, const struct json_writer *jw)`::

397 +

398 + Emits a region- and thread-relative "data" or "data_json" message.

399 ++

400 +This is a key/value pair message containing information about the

401 +current thread, region stack, and repository. This could be used

402 +to print the number of files in a directory during a multi-threaded

403 +recursive tree walk.

404 +

405 +`void trace2_printf(const char *fmt, ...)`::

406 +

407 +`void trace2_printf_va(const char *fmt, va_list ap)`::

408 +

409 + Emits a region- and thread-relative "printf" message.

410 +

411 +== Trace2 Target Formats

412 +

413 +=== NORMAL Format

414 +

415 +NORMAL format is enabled when the `GIT_TR2` environment variable is

416 +set.

417 +

418 +Events are written as lines of the form:

419 +

420 +------------

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

422 +------------

423 +

424 +`<event-name>`::

425 +

426 + is the event name.

427 +

428 +`<event-message>`::

429 + is a free-form printf message intended for human consumption.

430 ++

431 +Note that this may contain embedded LF or CRLF characters that are

432 +not escaped, so the event may spill across multiple lines.

433 +

434 +If `GIT_TR2_BRIEF` is true, the `time`, `filename`, and `line` fields

435 +are omitted.

436 +

437 +This target is intended to be more of a summary (like GIT_TRACE) and

438 +less detailed than the other targets. It ignores thread, region, and

439 +data messages, for example.

440 +

441 +=== PERF Format

442 +

443 +PERF format is enabled when the `GIT_TR2_PERF` environment variable

444 +is set.

445 +

446 +Events are written as lines of the form:

447 +

448 +------------

449 +[<time> SP <filename>:<line> SP+

450 + BAR SP] d<depth> SP

451 + BAR SP <thread-name> SP+

452 + BAR SP <event-name> SP+

453 + BAR SP [r<repo-id>] SP+

454 + BAR SP [<t_abs>] SP+

455 + BAR SP [<t_rel>] SP+

456 + BAR SP [<category>] SP+

457 + BAR SP DOTS* <perf-event-message>

458 + LF

459 +------------

460 +

461 +`<depth>`::

462 + is the git process depth. This is the number of parent

463 + git processes. A top-level git command has depth value "d0".

464 + A child of it has depth value "d1". A second level child

465 + has depth value "d2" and so on.

466 +

467 +`<thread-name>`::

468 + is a unique name for the thread. The primary thread

469 + is called "main". Other thread names are of the form "th%d:%s"

470 + and include a unique number and the name of the thread-proc.

471 +

472 +`<event-name>`::

473 + is the event name.

474 +

475 +`<repo-id>`::

476 + when present, is a number indicating the repository

477 + in use. A `def_repo` event is emitted when a repository is

478 + opened. This defines the repo-id and associated worktree.

479 + Subsequent repo-specific events will reference this repo-id.

480 ++

481 +Currently, this is always "r1" for the main repository.

482 +This field is in anticipation of in-proc submodules in the future.

483 +

484 +`<t_abs>`::

485 + when present, is the absolute time in seconds since the

486 + program started.

487 +

488 +`<t_rel>`::

489 + when present, is time in seconds relative to the start of

490 + the current region. For a thread-exit event, it is the elapsed

491 + time of the thread.

492 +

493 +`<category>`::

494 + is present on region and data events and is used to

495 + indicate a broad category, such as "index" or "status".

496 +

497 +`<perf-event-message>`::

498 + is a free-form printf message intended for human consumption.

499 +

500 +------------

502 +15:33:33.532712 wt-status.c:2331 | d0 | main | region_leave | r1 | 0.127568 | 0.001504 | status | label:print

503 +------------

504 +

505 +If `GIT_TR2_PERF_BRIEF` is true, the `time`, `file`, and `line`

506 +fields are omitted.

507 +

508 +------------

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

510 +------------

511 +

512 +The PERF target is intended for interactive performance analysis

513 +during development and is quite noisy.

514 +

515 +=== EVENT Format

516 +

517 +EVENT format is enabled when the `GIT_TR2_EVENT` environment

518 +variable is set.

519 +

520 +Each event is a JSON-object containing multiple key/value pairs

521 +written as a single line and followed by a LF.

522 +

523 +------------

524 +'{' <key> ':' <value> [',' <key> ':' <value>]* '}' LF

525 +------------

526 +

527 +Some key/value pairs are common to all events and some are

528 +event-specific.

529 +

530 +==== Common Key/Value Pairs

531 +

532 +The following key/value pairs are common to all events:

533 +

534 +------------

535 +{

536 + "event":"version",

537 + "sid":"1547659722619736-11614",

538 + "thread":"main",

539 + "time":"2019-01-16 17:28:42.620713",

540 + "file":"common-main.c",

541 + "line":38,

542 + ...

543 +}

544 +------------

545 +

546 +`"event":<event>`::

547 + is the event name.

548 +

549 +`"sid":<sid>`::

550 + is the session-id. This is a unique string to identify the

551 + process instance to allow all events emitted by a process to

552 + be identified. A session-id is used instead of a PID because

553 + PIDs are recycled by the OS. For child git processes, the

554 + session-id is prepended with the session-id of the parent git

555 + process to allow parent-child relationships to be identified

556 + during post-processing.

557 +

558 +`"thread":<thread>`::

559 + is the thread name.

560 +

561 +`"time":<time>`::

562 + is the UTC time of the event.

563 +

564 +`"file":<filename>`::

565 + is source file generating the event.

566 +

567 +`"line":<line-number>`::

568 + is the integer source line number generating the event.

569 +

570 +`"repo":<repo-id>`::

571 + when present, is the integer repo-id as described previously.

572 +

573 +If `GIT_TR2_EVENT_BRIEF` is true, the `file` and `line` fields are omitted

574 +from all events and the `time` field is only present on the "start" and

575 +"atexit" events.

576 +

577 +==== Event-Specific Key/Value Pairs

578 +

579 +`"version"`::

580 + This event gives the version of the executable and the EVENT format.

581 ++

582 +------------

583 +{

584 + "event":"version",

585 + ...

586 + "evt":"1", # EVENT format version

587 + "exe":"2.20.1.155.g426c96fcdb" # git version

588 +}

589 +------------

590 +

591 +`"start"`::

592 + This event contains the complete argv received by main().

593 ++

594 +------------

595 +{

596 + "event":"start",

597 + ...

598 + "argv":["git","version"]

599 +}

600 +------------

601 +

602 +`"exit"`::

603 + This event is emitted when git calls `exit()`.

604 ++

605 +------------

606 +{

607 + "event":"exit",

608 + ...

609 + "t_abs":0.001227, # elapsed time in seconds

610 + "code":0 # exit code

611 +}

612 +------------

613 +

614 +`"atexit"`::

615 + This event is emitted by the Trace2 `atexit` routine during

616 + final shutdown. It should be the last event emitted by the

617 + process.

618 ++

619 +(The elapsed time reported here is greater than the time reported in

620 +the "exit" event because it runs after all other atexit tasks have

621 +completed.)

622 ++

623 +------------

624 +{

625 + "event":"atexit",

626 + ...

627 + "t_abs":0.001227, # elapsed time in seconds

628 + "code":0 # exit code

629 +}

630 +------------

631 +

632 +`"signal"`::

633 + This event is emitted when the program is terminated by a user

634 + signal. Depending on the platform, the signal event may

635 + prevent the "atexit" event from being generated.

636 ++

637 +------------

638 +{

639 + "event":"signal",

640 + ...

641 + "t_abs":0.001227, # elapsed time in seconds

642 + "signal":13 # SIGTERM, SIGINT, etc.

643 +}

644 +------------

645 +

646 +`"error"`::

647 + This event is emitted when one of the `error()`, `die()`,

648 + or `usage()` functions are called.

649 ++

650 +------------

651 +{

652 + "event":"error",

653 + ...

654 + "msg":"invalid option: --cahced", # formatted error message

655 + "fmt":"invalid option: %s" # error format string

656 +}

657 +------------

658 ++

659 +The error event may be emitted more than once. The format string

660 +allows post-processors to group errors by type without worrying

661 +about specific error arguments.

662 +

663 +`"cmd_path"`::

664 + This event contains the discovered full path of the git

665 + executable (on platforms that are configured to resolve it).

666 ++

667 +------------

668 +{

669 + "event":"cmd_path",

670 + ...

671 + "path":"C:/work/gfw/git.exe"

672 +}

673 +------------

674 +

675 +`"cmd_name"`::

676 + This event contains the command name for this git process

677 + and the hierarchy of commands from parent git processes.

678 ++

679 +------------

680 +{

681 + "event":"cmd_name",

682 + ...

683 + "name":"pack-objects",

684 + "hierarchy":"push/pack-objects"

685 +}

686 +------------

687 ++

688 +Normally, the "name" field contains the canonical name of the

689 +command. When a canonical name is not available, one of

690 +these special values are used:

691 ++

692 +------------

693 +"_query_" # "git --html-path"

694 +"_run_dashed_" # when "git foo" tries to run "git-foo"

695 +"_run_shell_alias_" # alias expansion to a shell command

696 +"_run_git_alias_" # alias expansion to a git command

697 +"_usage_" # usage error

698 +------------

699 +

700 +`"cmd_mode"`::

701 + This event, when present, describes the command variant This

702 + event may be emitted more than once.

703 ++

704 +------------

705 +{

706 + "event":"cmd_mode",

707 + ...

708 + "name":"branch"

709 +}

710 +------------

711 ++

712 +The "name" field is an arbitrary string to describe the command mode.

713 +For example, checkout can checkout a branch or an individual file.

714 +And these variations typically have different performance

715 +characteristics that are not comparable.

716 +

717 +`"alias"`::

718 + This event is present when an alias is expanded.

719 ++

720 +------------

721 +{

722 + "event":"alias",

723 + ...

724 + "alias":"l", # registered alias

725 + "argv":["log","--graph"] # alias expansion

726 +}

727 +------------

728 +

729 +`"child_start"`::

730 + This event describes a child process that is about to be

731 + spawned.

732 ++

733 +------------

734 +{

735 + "event":"child_start",

736 + ...

737 + "child_id":2,

738 + "child_class":"?",

739 + "use_shell":false,

740 + "argv":["git","rev-list","--objects","--stdin","--not","--all","--quiet"]

741 +

742 + "hook_name":"<hook_name>" # present when child_class is "hook"

743 + "cd":"<path>" # present when cd is required

744 +}

745 +------------

746 ++

747 +The "child_id" field can be used to match this child_start with the

748 +corresponding child_exit event.

749 ++

750 +The "child_class" field is a rough classification, such as "editor",

751 +"pager", "transport/*", and "hook". Unclassified children are classified

752 +with "?".

753 +

754 +`"child_exit"`::

755 + This event is generated after the current process has returned

756 + from the waitpid() and collected the exit information from the

757 + child.

758 ++

759 +------------

760 +{

761 + "event":"child_exit",

762 + ...

763 + "child_id":2,

764 + "pid":14708, # child PID

765 + "code":0, # child exit-code

766 + "t_rel":0.110605 # observed run-time of child process

767 +}

768 +------------

769 ++

770 +Note that the session-id of the child process is not available to

771 +the current/spawning process, so the child's PID is reported here as

772 +a hint for post-processing. (But it is only a hint because the child

773 +proces may be a shell script which doesn't have a session-id.)

774 ++

775 +Note that the `t_rel` field contains the observed run time in seconds

776 +for the child process (starting before the fork/exec/spawn and

777 +stopping after the waitpid() and includes OS process creation overhead).

778 +So this time will be slightly larger than the atexit time reported by

779 +the child process itself.

780 +

781 +`"exec"`::

782 + This event is generated before git attempts to `exec()`

783 + another command rather than starting a child process.

784 ++

785 +------------

786 +{

787 + "event":"exec",

788 + ...

789 + "exec_id":0,

790 + "exe":"git",

791 + "argv":["foo", "bar"]

792 +}

793 +------------

794 ++

795 +The "exec_id" field is a command-unique id and is only useful if the

796 +`exec()` fails and a corresponding exec_result event is generated.

797 +

798 +`"exec_result"`::

799 + This event is generated if the `exec()` fails and control

800 + returns to the current git command.

801 ++

802 +------------

803 +{

804 + "event":"exec_result",

805 + ...

806 + "exec_id":0,

807 + "code":1 # error code (errno) from exec()

808 +}

809 +------------

810 +

811 +`"thread_start"`::

812 + This event is generated when a thread is started. It is

813 + generated from *within* the new thread's thread-proc (for TLS

814 + reasons).

815 ++

816 +------------

817 +{

818 + "event":"thread_start",

819 + ...

820 + "thread":"th02:preload_thread" # thread name

821 +}

822 +------------

823 +

824 +`"thread_exit"`::

825 + This event is generated when a thread exits. It is generated

826 + from *within* the thread's thread-proc (for TLS reasons).

827 ++

828 +------------

829 +{

830 + "event":"thread_exit",

831 + ...

832 + "thread":"th02:preload_thread", # thread name

833 + "t_rel":0.007328 # thread elapsed time

834 +}

835 +------------

836 +

837 +`"def_param"`::

838 + This event is generated to log a global parameter.

839 ++

840 +------------

841 +{

842 + "event":"def_param",

843 + ...

844 + "param":"core.abbrev",

845 + "value":"7"

846 +}

847 +------------

848 +

849 +`"def_repo"`::

850 + This event defines a repo-id and associates it with the root

851 + of the worktree.

852 ++

853 +------------

854 +{

855 + "event":"def_repo",

856 + ...

857 + "repo":1,

858 + "worktree":"/Users/jeffhost/work/gfw"

859 +}

860 +------------

861 ++

862 +As stated earlier, the repo-id is currently always 1, so there will

863 +only be one def_repo event. Later, if in-proc submodules are

864 +supported, a def_repo event should be emitted for each submodule

865 +visited.

866 +

867 +`"region_enter"`::

868 + This event is generated when entering a region.

869 ++

870 +------------

871 +{

872 + "event":"region_enter",

873 + ...

874 + "repo":1, # optional

875 + "nesting":1, # current region stack depth

876 + "category":"index", # optional

877 + "label":"do_read_index", # optional

878 + "msg":".git/index" # optional

879 +}

880 +------------

881 ++

882 +The `category` field may be used in a future enhancement to

883 +do category-based filtering.

884 ++

885 +The `GIT_TR2_EVENT_NESTING` environment variable can be used to

886 +filter deeply nested regions and data events. It defaults to "2".

887 +

888 +`"region_leave"`::

889 + This event is generated when leaving a region.

890 ++

891 +------------

892 +{

893 + "event":"region_leave",

894 + ...

895 + "repo":1, # optional

896 + "t_rel":0.002876, # time spent in region in seconds

897 + "nesting":1, # region stack depth

898 + "category":"index", # optional

899 + "label":"do_read_index", # optional

900 + "msg":".git/index" # optional

901 +}

902 +------------

903 +

904 +`"data"`::

905 + This event is generated to log a thread- and region-local

906 + key/value pair.

907 ++

908 +------------

909 +{

910 + "event":"data",

911 + ...

912 + "repo":1, # optional

913 + "t_abs":0.024107, # absolute elapsed time

914 + "t_rel":0.001031, # elapsed time in region/thread

915 + "nesting":2, # region stack depth

916 + "category":"index",

917 + "key":"read/cache_nr",

918 + "value":"3552"

919 +}

920 +------------

921 ++

922 +The "value" field may be an integer or a string.

923 +

924 +`"data-json"`::

925 + This event is generated to log a pre-formatted JSON string

926 + containing structured data.

927 ++

928 +------------

929 +{

930 + "event":"data_json",

931 + ...

932 + "repo":1, # optional

933 + "t_abs":0.015905,

934 + "t_rel":0.015905,

935 + "nesting":1,

936 + "category":"process",

937 + "key":"windows/ancestry",

938 + "value":["bash.exe","bash.exe"]

939 +}

940 +------------

941 +

942 +== Example Trace2 API Usage

943 +

944 +Here is a hypothetical usage of the Trace2 API showing the intended

945 +usage (without worrying about the actual Git details).

946 +

947 +Initialization::

948 +

949 + Initialization happens in `main()`. Behind the scenes, an

950 + `atexit` and `signal` handler are registered.

951 ++

952 +----------------

953 +int main(int argc, const char **argv)

954 +{

955 + int exit_code;

956 +

957 + trace2_initialize();

958 + trace2_cmd_start(argv);

959 +

960 + exit_code = cmd_main(argc, argv);

961 +

962 + trace2_cmd_exit(exit_code);

963 +

964 + return exit_code;

965 +}

966 +----------------

967 +

968 +Command Details::

969 +

970 + After the basics are established, additional command

971 + information can be sent to Trace2 as it is discovered.

972 ++

973 +----------------

974 +int cmd_checkout(int argc, const char **argv)

975 +{

976 + trace2_cmd_name("checkout");

977 + trace2_cmd_mode("branch");

978 + trace2_def_repo(the_repository);

979 +

980 + // emit "def_param" messages for "interesting" config settings.

981 + trace2_cmd_list_config();

982 +

983 + if (do_something())

984 + trace2_cmd_error("Path '%s': cannot do something", path);

985 +

986 + return 0;

987 +}

988 +----------------

989 +

990 +Child Processes::

991 +

992 + Wrap code spawning child processes.

993 ++

994 +----------------

995 +void run_child(...)

996 +{

997 + int child_exit_code;

998 + struct child_process cmd = CHILD_PROCESS_INIT;

999 + ...

1000 + cmd.trace2_child_class = "editor";

1001 +

1002 + trace2_child_start(&cmd);

1003 + child_exit_code = spawn_child_and_wait_for_it();

1004 + trace2_child_exit(&cmd, child_exit_code);

1005 +}

1006 +----------------

1007 ++

1008 +For example, the following fetch command spawned ssh, index-pack,

1009 +rev-list, and gc. This example also shows that fetch took

1010 +5.199 seconds and of that 4.932 was in ssh.

1011 ++

1012 +----------------

1013 +$ export GIT_TR2_BRIEF=1

1014 +$ export GIT_TR2=~/log.normal

1015 +$ git fetch origin

1016 +...

1017 +----------------

1018 ++

1019 +----------------

1020 +$ cat ~/log.normal

1021 +version 2.20.1.vfs.1.1.47.g534dbe1ad1

1022 +start git fetch origin

1023 +worktree /Users/jeffhost/work/gfw

1024 +cmd_name fetch (fetch)

1025 +child_start[0] ssh git@github.com ...

1026 +child_start[1] git index-pack ...

1027 +... (Trace2 events from child processes omitted)

1028 +child_exit[1] pid:14707 code:0 elapsed:0.076353

1029 +child_exit[0] pid:14706 code:0 elapsed:4.931869

1030 +child_start[2] git rev-list ...

1031 +... (Trace2 events from child process omitted)

1032 +child_exit[2] pid:14708 code:0 elapsed:0.110605

1033 +child_start[3] git gc --auto

1034 +... (Trace2 events from child process omitted)

1035 +child_exit[3] pid:14709 code:0 elapsed:0.006240

1036 +exit elapsed:5.198503 code:0

1037 +atexit elapsed:5.198541 code:0

1038 +----------------

1039 ++

1040 +When a git process is a (direct or indirect) child of another

1041 +git process, it inherits Trace2 context information. This

1042 +allows the child to print the command hierarchy. This example

1043 +shows gc as child[3] of fetch. When the gc process reports

1044 +its name as "gc", it also reports the hierarchy as "fetch/gc".

1045 +(In this example, trace2 messages from the child process is

1046 +indented for clarity.)

1047 ++

1048 +----------------

1049 +$ export GIT_TR2_BRIEF=1

1050 +$ export GIT_TR2=~/log.normal

1051 +$ git fetch origin

1052 +...

1053 +----------------

1054 ++

1055 +----------------

1056 +$ cat ~/log.normal

1057 +version 2.20.1.160.g5676107ecd.dirty

1058 +start git fetch official

1059 +worktree /Users/jeffhost/work/gfw

1060 +cmd_name fetch (fetch)

1061 +...

1062 +child_start[3] git gc --auto

1063 + version 2.20.1.160.g5676107ecd.dirty

1064 + start /Users/jeffhost/work/gfw/git gc --auto

1065 + worktree /Users/jeffhost/work/gfw

1066 + cmd_name gc (fetch/gc)

1067 + exit elapsed:0.001959 code:0

1068 + atexit elapsed:0.001997 code:0

1069 +child_exit[3] pid:20303 code:0 elapsed:0.007564

1070 +exit elapsed:3.868938 code:0

1071 +atexit elapsed:3.868970 code:0

1072 +----------------

1073 +

1074 +Regions::

1075 +

1076 + Regions can be use to time an interesting section of code.

1077 ++

1078 +----------------

1079 +void wt_status_collect(struct wt_status *s)

1080 +{

1081 + trace2_region_enter("status", "worktrees", s->repo);

1082 + wt_status_collect_changes_worktree(s);

1083 + trace2_region_leave("status", "worktrees", s->repo);

1084 +

1085 + trace2_region_enter("status", "index", s->repo);

1086 + wt_status_collect_changes_index(s);

1087 + trace2_region_leave("status", "index", s->repo);

1088 +

1089 + trace2_region_enter("status", "untracked", s->repo);

1090 + wt_status_collect_untracked(s);

1091 + trace2_region_leave("status", "untracked", s->repo);

1092 +}

1093 +

1094 +void wt_status_print(struct wt_status *s)

1095 +{

1096 + trace2_region_enter("status", "print", s->repo);

1097 + switch (s->status_format) {

1098 + ...

1099 + }

1100 + trace2_region_leave("status", "print", s->repo);

1101 +}

1102 +----------------

1103 ++

1104 +In this example, scanning for untracked files ran from +0.012568 to

1105 ++0.027149 (since the process started) and took 0.014581 seconds.

1106 ++

1107 +----------------

1108 +$ export GIT_TR2_PERF_BRIEF=1

1109 +$ export GIT_TR2_PERF=~/log.perf

1110 +$ git status

1111 +...

1112 +

1113 +$ cat ~/log.perf

1118 +...

1119 +d0 | main | region_enter | r1 | 0.010988 | | status | label:worktrees

1120 +d0 | main | region_leave | r1 | 0.011236 | 0.000248 | status | label:worktrees

1121 +d0 | main | region_enter | r1 | 0.011260 | | status | label:index

1122 +d0 | main | region_leave | r1 | 0.012542 | 0.001282 | status | label:index

1123 +d0 | main | region_enter | r1 | 0.012568 | | status | label:untracked

1124 +d0 | main | region_leave | r1 | 0.027149 | 0.014581 | status | label:untracked

1125 +d0 | main | region_enter | r1 | 0.027411 | | status | label:print

1126 +d0 | main | region_leave | r1 | 0.028741 | 0.001330 | status | label:print

1129 +----------------

1130 ++

1131 +Regions may be nested. This causes messages to be indented in the

1132 +PERF target, for example.

1133 +Elapsed times are relative to the start of the correpsonding nesting

1134 +level as expected. For example, if we add region message to:

1135 ++

1136 +----------------

1137 +static enum path_treatment read_directory_recursive(struct dir_struct *dir,

1138 + struct index_state *istate, const char *base, int baselen,

1139 + struct untracked_cache_dir *untracked, int check_only,

1140 + int stop_at_first_file, const struct pathspec *pathspec)

1141 +{

1142 + enum path_treatment state, subdir_state, dir_state = path_none;

1143 +

1144 + trace2_region_enter_printf("dir", "read_recursive", NULL, "%.*s", baselen, base);

1145 + ...

1146 + trace2_region_leave_printf("dir", "read_recursive", NULL, "%.*s", baselen, base);

1147 + return dir_state;

1148 +}

1149 +----------------

1150 ++

1151 +We can further investigate the time spent scanning for untracked files.

1152 ++

1153 +----------------

1154 +$ export GIT_TR2_PERF_BRIEF=1

1155 +$ export GIT_TR2_PERF=~/log.perf

1156 +$ git status

1157 +...

1158 +$ cat ~/log.perf

1163 +...

1164 +d0 | main | region_enter | r1 | 0.015047 | | status | label:untracked

1165 +d0 | main | region_enter | | 0.015132 | | dir | ..label:read_recursive

1166 +d0 | main | region_enter | | 0.016341 | | dir | ....label:read_recursive vcs-svn/

1167 +d0 | main | region_leave | | 0.016422 | 0.000081 | dir | ....label:read_recursive vcs-svn/

1168 +d0 | main | region_enter | | 0.016446 | | dir | ....label:read_recursive xdiff/

1169 +d0 | main | region_leave | | 0.016522 | 0.000076 | dir | ....label:read_recursive xdiff/

1170 +d0 | main | region_enter | | 0.016612 | | dir | ....label:read_recursive git-gui/

1171 +d0 | main | region_enter | | 0.016698 | | dir | ......label:read_recursive git-gui/po/

1172 +d0 | main | region_enter | | 0.016810 | | dir | ........label:read_recursive git-gui/po/glossary/

1173 +d0 | main | region_leave | | 0.016863 | 0.000053 | dir | ........label:read_recursive git-gui/po/glossary/

1174 +...

1175 +d0 | main | region_enter | | 0.031876 | | dir | ....label:read_recursive builtin/

1176 +d0 | main | region_leave | | 0.032270 | 0.000394 | dir | ....label:read_recursive builtin/

1177 +d0 | main | region_leave | | 0.032414 | 0.017282 | dir | ..label:read_recursive

1178 +d0 | main | region_leave | r1 | 0.032454 | 0.017407 | status | label:untracked

1179 +...

1182 +----------------

1183 ++

1184 +Trace2 regions are similar to the existing trace_performance_enter()

1185 +and trace_performance_leave() routines, but are thread safe and

1186 +maintain per-thread stacks of timers.

1187 +

1188 +Data Messages::

1189 +

1190 + Data messages added to a region.

1191 ++

1192 +----------------

1193 +int read_index_from(struct index_state *istate, const char *path,

1194 + const char *gitdir)

1195 +{

1196 + trace2_region_enter_printf("index", "do_read_index", the_repository, "%s", path);

1197 +

1198 + ...

1199 +

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

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

1202 +

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

1204 +}

1205 +----------------

1206 ++

1207 +This example shows that the index contained 3552 entries.

1208 ++

1209 +----------------

1210 +$ export GIT_TR2_PERF_BRIEF=1

1211 +$ export GIT_TR2_PERF=~/log.perf

1212 +$ git status

1213 +...

1214 +$ cat ~/log.perf

1219 +d0 | main | region_enter | r1 | 0.001791 | | index | label:do_read_index .git/index

1220 +d0 | main | data | r1 | 0.002494 | 0.000703 | index | ..read/version:2

1221 +d0 | main | data | r1 | 0.002520 | 0.000729 | index | ..read/cache_nr:3552

1222 +d0 | main | region_leave | r1 | 0.002539 | 0.000748 | index | label:do_read_index .git/index

1223 +...

1224 +----------------

1225 +

1226 +Thread Events::

1227 +

1228 + Thread messages added to a thread-proc.

1229 ++

1230 +For example, the multithreaded preload-index code can be

1231 +instrumented with a region around the thread pool and then

1232 +per-thread start and exit events within the threadproc.

1233 ++

1234 +----------------

1235 +static void *preload_thread(void *_data)

1236 +{

1237 + // start the per-thread clock and emit a message.

1238 + trace2_thread_start("preload_thread");

1239 +

1240 + // report which chunk of the array this thread was assigned.

1241 + trace2_data_intmax("index", the_repository, "offset", p->offset);

1242 + trace2_data_intmax("index", the_repository, "count", nr);

1243 +

1244 + do {

1245 + ...

1246 + } while (--nr > 0);

1247 + ...

1248 +

1249 + // report elapsed time taken by this thread.

1250 + trace2_thread_exit();

1251 + return NULL;

1252 +}

1253 +

1254 +void preload_index(struct index_state *index,

1255 + const struct pathspec *pathspec,

1256 + unsigned int refresh_flags)

1257 +{

1258 + trace2_region_enter("index", "preload", the_repository);

1259 +

1260 + for (i = 0; i < threads; i++) {

1261 + ... /* create thread */

1262 + }

1263 +

1264 + for (i = 0; i < threads; i++) {

1265 + ... /* join thread */

1266 + }

1267 +

1268 + trace2_region_leave("index", "preload", the_repository);

1269 +}

1270 +----------------

1271 ++

1272 +In this example preload_index() was executed by the `main` thread

1273 +and started the `preload` region. Seven threads, named

1274 +`th01:preload_thread` through `th07:preload_thread`, were started.

1275 +Events from each thread are atomically appended to the shared target

1276 +stream as they occur so they may appear in random order with respect

1277 +other threads. Finally, the main thread waits for the threads to

1278 +finish and leaves the region.

1279 ++

1280 +Data events are tagged with the active thread name. They are used

1281 +to report the per-thread parameters.

1282 ++

1283 +----------------

1284 +$ export GIT_TR2_PERF_BRIEF=1

1285 +$ export GIT_TR2_PERF=~/log.perf

1286 +$ git status

1287 +...

1288 +$ cat ~/log.perf

1289 +...

1290 +d0 | main | region_enter | r1 | 0.002595 | | index | label:preload

1291 +d0 | th01:preload_thread | thread_start | | 0.002699 | | |

1292 +d0 | th02:preload_thread | thread_start | | 0.002721 | | |

1293 +d0 | th01:preload_thread | data | r1 | 0.002736 | 0.000037 | index | offset:0

1294 +d0 | th02:preload_thread | data | r1 | 0.002751 | 0.000030 | index | offset:2032

1295 +d0 | th03:preload_thread | thread_start | | 0.002711 | | |

1296 +d0 | th06:preload_thread | thread_start | | 0.002739 | | |

1297 +d0 | th01:preload_thread | data | r1 | 0.002766 | 0.000067 | index | count:508

1298 +d0 | th06:preload_thread | data | r1 | 0.002856 | 0.000117 | index | offset:2540

1299 +d0 | th03:preload_thread | data | r1 | 0.002824 | 0.000113 | index | offset:1016

1300 +d0 | th04:preload_thread | thread_start | | 0.002710 | | |

1301 +d0 | th02:preload_thread | data | r1 | 0.002779 | 0.000058 | index | count:508

1302 +d0 | th06:preload_thread | data | r1 | 0.002966 | 0.000227 | index | count:508

1303 +d0 | th07:preload_thread | thread_start | | 0.002741 | | |

1304 +d0 | th07:preload_thread | data | r1 | 0.003017 | 0.000276 | index | offset:3048

1305 +d0 | th05:preload_thread | thread_start | | 0.002712 | | |

1306 +d0 | th05:preload_thread | data | r1 | 0.003067 | 0.000355 | index | offset:1524

1307 +d0 | th05:preload_thread | data | r1 | 0.003090 | 0.000378 | index | count:508

1308 +d0 | th07:preload_thread | data | r1 | 0.003037 | 0.000296 | index | count:504

1309 +d0 | th03:preload_thread | data | r1 | 0.002971 | 0.000260 | index | count:508

1310 +d0 | th04:preload_thread | data | r1 | 0.002983 | 0.000273 | index | offset:508

1311 +d0 | th04:preload_thread | data | r1 | 0.007311 | 0.004601 | index | count:508

1312 +d0 | th05:preload_thread | thread_exit | | 0.008781 | 0.006069 | |

1313 +d0 | th01:preload_thread | thread_exit | | 0.009561 | 0.006862 | |

1314 +d0 | th03:preload_thread | thread_exit | | 0.009742 | 0.007031 | |

1315 +d0 | th06:preload_thread | thread_exit | | 0.009820 | 0.007081 | |

1316 +d0 | th02:preload_thread | thread_exit | | 0.010274 | 0.007553 | |

1317 +d0 | th07:preload_thread | thread_exit | | 0.010477 | 0.007736 | |

1318 +d0 | th04:preload_thread | thread_exit | | 0.011657 | 0.008947 | |

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

1320 +...

1323 +----------------

1324 ++

1325 +In this example, the preload region took 0.009122 seconds. The 7 threads

1326 +took between 0.006069 and 0.008947 seconds to work on their portion of

1327 +the index. Thread "th01" worked on 508 items at offset 0. Thread "th02"

1328 +worked on 508 items at offset 2032. Thread "th04" worked on 508 itemts

1329 +at offset 508.

1330 ++

1331 +This example also shows that thread names are assigned in a racy manner

1332 +as each thread starts and allocates TLS storage.

1333 +

1334 +== Future Work

1335 +

1336 +=== Relationship to the Existing Trace Api (api-trace.txt)

1337 +

1338 +There are a few issues to resolve before we can completely

1339 +switch to Trace2.

1340 +

1341 +* Updating existing tests that assume GIT_TRACE format messages.

1342 +

1343 +* How to best handle custom GIT_TRACE_<key> messages?

1344 +

1345 +** The GIT_TRACE_<key> mechanism allows each <key> to write to a

1346 +different file (in addition to just stderr).

1347 +

1348 +** Do we want to maintain that ability or simply write to the existing

1349 +Trace2 targets (and convert <key> to a "category").

trace2: Documentation/technical/api-trace2.txt