[01/14] trace2: Documentation/technical/api-trace2.txt

Message ID	1a90de9dab0dd836e54fee9e08ab9e2284e1027a.1548192131.git.gitgitgadget@gmail.com (mailing list archive)
State	New, archived
Headers	show Return-Path: <git-owner@kernel.org> Date: Tue, 22 Jan 2019 13:22:12 -0800 (PST) Message-Id: <1a90de9dab0dd836e54fee9e08ab9e2284e1027a.1548192131.git.gitgitgadget@gmail.com> In-Reply-To: <pull.108.git.gitgitgadget@gmail.com> References: <pull.108.git.gitgitgadget@gmail.com> From: "Jeff Hostetler via GitGitGadget" <gitgitgadget@gmail.com> Subject: [PATCH 01/14] trace2: Documentation/technical/api-trace2.txt Fcc: Sent Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit MIME-Version: 1.0 To: git@vger.kernel.org Cc: jeffhost@microsoft.com, Junio C Hamano <gitster@pobox.com>, Jeff Hostetler <jeffhost@microsoft.com> Sender: git-owner@vger.kernel.org Precedence: bulk
Series	Trace2 tracing facility \| expand [00/14] Trace2 tracing facility [01/14] trace2: Documentation/technical/api-trace2.txt [02/14] trace2: create new combined trace facility [03/14] trace2: collect platform-specific process information [04/14] trace2:data: add trace2 regions to wt-status [05/14] trace2:data: add editor/pager child classification [06/14] trace2:data: add trace2 sub-process classification [07/14] trace2:data: add trace2 transport child classification [08/14] trace2:data: add trace2 hook classification [09/14] trace2:data: add trace2 instrumentation to index read/write [10/14] pack-objects: add trace2 regions [11/14] trace2:data: add subverb to checkout command [12/14] trace2:data: add subverb to reset command [13/14] trace2:data: add subverb for rebase [14/14] trace2: t/helper/test-trace2, t0210.sh, t0211.sh, t0212.sh

On 1/23/2019 3:51 PM, Junio C Hamano wrote: > "Jeff Hostetler via GitGitGadget" <gitgitgadget@gmail.com> writes: > >> +These high-level events are written to one or more Trace2 Targets >> +in a target-specific format. Each Trace2 Target defines a different >> +purpose-specific view onto the event data stream. In this mannor, > > "In this manner" > >> +a single set of Trace2 API event calls in the Git source can drive >> +different types of analysis. >> + >> ... >> +$ cat ~/log.perf >> +12:28:42.620675 common-main.c:38 | d0 | main | version | | | | | 2.20.1.155.g426c96fcdb >> +12:28:42.621001 common-main.c:39 | d0 | main | start | | | | | git version >> +12:28:42.621111 git.c:432 | d0 | main | cmd_verb | | | | | version (version) >> +12:28:42.621225 git.c:662 | d0 | main | exit | | 0.001227 | | | code:0 >> +12:28:42.621259 trace2/tr2_tgt_perf.c:211 | d0 | main | atexit | | 0.001265 | | | code:0 >> +------------ >> ... >> + >> +trace2_def_param(...) > > Not limited to this single one, but please either > > - omit "..." in parens, unless all of these functions take varargs > of unspecified type (which I do not think is the case), or > > - write a proper prototype for these functions, explain what the > function itself and what the parameters are for. > > I'll complain about lack of info around here later X-<. I documented the prototypes in trace2.h and was hoping to avoid duplicating all that text here in this document. The list of functions here in this document was more of an overview of the groups of concepts covered. I'll revisit this. > >> +trace2_def_repo(...) > >> +---------------- >> + >> +Git Child Process Events:: >> + >> + These are concerned with the various spawned child processes, >> + including sub-git processes and hooks, >> ++ >> +---------------- >> +trace2_child_start(...) >> +trace2_child_exit(...) >> + >> +trace2_exec(...) >> +trace2_exec_result(...) >> +---------------- >> + >> +Git Thread Events:: >> + >> + These are concerned with Git thread usage. >> ++ >> +---------------- >> +trace2_thread_start(...) >> +trace2_thread_exit(...) >> +---------------- > > Lack of _wait()/_join() feels a bit curious, but _exit() from what > is being waited would suffice as a substitute. The 2 trace2_thread_ functions have to be run by the thread-proc itself rather than by the code calling the pthread functions. So to me it made more sense inside the thread-proc for them to be named _start and _exit. This gives us an event with the elapsed time of the thread in isolation using TLS data within each thread. If I understand your question about _wait/_join, adding trace2 calls near the pthread_create and pthread_join, would be a bit of a mess because of the usual create loop and then later the join loop. And the exit times would be less accurate, since we typically _join them in array order rather in the order they finish. And having the trace2_thread_ calls in the pthread caller doesn't let me access the thread's private TLS data. Wrapping a region (like I show later in the preload_index() example) around both of the pthread loops gives us the overall time for the threading and insight into the thread overhead. (One could even have a region around the pthread_create loop and another around the pthread_join loop, but that might not be worth the trouble. > >> +Initialization:: >> + >> + Initialization happens in `main()`. The initialization code >> + determines which, if any, Trace2 Targets should be enabled and >> + emits the `version`, `start`, and `exit` events. It causes an >> + `atexit` function and `signal` handler to be registered that >> + will emit `atexit` and `signal` events. >> ++ >> +---------------- >> +int main(int argc, const char **argv) >> +{ >> + int exit_code; >> + >> + trace2_initialize(); >> + trace2_cmd_start(argv); > > Nobody other than trace2 integration would make a call to this > helper, so it may not matter, but sending av alone without ac, even > though ac is almost always redundant, feels somewhat unexpected. Agreed. There were other places that took an argv that didn't have an argc on hand in the calling code. So rather than fake up one for them, I just omitted it from all the calls in my API. > >> +Command Details:: >> + >> + After the basics are established, additional process >> + information can be sent to Trace2 as it is discovered, such as >> + the command verb, alias expansion, interesting config >> + settings, the repository worktree, error messages, and etc. >> ++ >> +---------------- >> +int cmd_checkout(int argc, const char **argv) >> +{ >> + // emit a single "def_param" event >> + trace2_def_param("core.editor", "emacs"); > > Without knowing what "def_param event" is, this example is hard to > fathom. At this point in the doc, the reader does not even know > what "def" stands for. Is this call to define a param called > core.editor? Is it reporting that the default value for core.editor > is emacs? > >> + // emit def_params for any config setting matching a pattern >> + // in GIT_TR2_CONFIG_PARAMS. >> + trace2_cmd_list_config(); > > As the reader does not know what def_param is, this is also hard to > follow. I'll rewrite that section. The idea is to define a parameter that a perf-tester might consider important. For example, "core.abbrev" used to cause massive perf problems on our mega repo where it might take minutes to compute 7 or 8 digit abbreviations for a log or branch command (completely dominating the time to actually compute the log or branch list). > >> + trace2_cmd_verb("checkout"); >> + trace2_cmd_subverb("branch"); > > These are guessable. It probably reports what the codepath is > doing. These are to help post-processing. The git command line is parsed in 2 or 3 different phases and it takes quite a bit of work to get to cmd_*() function (such as skipping over the -c, -C, --exec-path, and other such args, and handling the commands where there isn't a cmd_*() function (such as "git --exec-path")). Then within the cmd_*() function, a lot of work to see which variant of the command is (such as is this checkout checking out a branch or a single file). And there are short and long forms of many arguments. And then there is the alias expansion which wants to rewrite the command line (possibly recursively). And then there is the code to try to run the non-builtin dashed form. For post-processing, you want to be able to do something like this: select elapsed_time where verb='checkout' and subverb='branch' select elapsed_time where verb='checkout' and subverb='path' and report averages over those 2 sets independently without having to recreate all that argv parsing inside the database query (or perl script on the trace log). > >> + trace2_def_repo(the_repository); > > Again, this is not easy to guess. Is it reporting what the default > repository is? I'll reword this. > >> + if (do_something(...)) >> + trace2_cmd_error("Path '%s': cannot do something", path); > > This is guessable, which is good. > >> +void run_child(...) >> +{ >> + int child_exit_code; >> + struct child_process cmd = CHILD_PROCESS_INIT; >> + ... >> + >> + trace2_child_start(&cmd); >> + child_exit_code = ...(); >> + trace2_child_exit(&cmd, child_exit_code); > > Even though child_exit() has not been explained just like > def_param(), this is far more guessable. I wonder why it is. The > name of the variable passed to it in the example certainly helps, as > it is totally unclear where the string constant "emacs" in the > earlier example came from (e.g. is it hardcoded in the program? is > it merely illustrating "here is how you report the value you have > decided to use for 'core.editor' variable"?). yes, some of these are synthetic uses of the API to illustrate the trace2 concepts. I just picked 'core.editor' at random. I'll revisit the examples. > >> ... >> +$ cat ~/log.perf >> +d0 | main | version | | | | | 2.20.1.160.g5676107ecd.dirty >> +d0 | main | start | | | | | git status >> +d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw >> +d0 | main | cmd_verb | | | | | status (status) >> +... >> +d0 | main | region_enter | r1 | 0.010988 | | status | label:worktrees > > It is hard to guess what "d0" and "r1" stand for here. > > In an earlier example we also saw an unexplained "d0" there, which I > think was OK because the illustration was merely to give the "feel" > of the format up there. But now we are giving a bit more detailed > explanation, we probably would want to at least briefly mention what > each column means. yes, the example at the top was just to preview the formats. I'll add more info here. > I'd stop here for now, as I am more interested in reading the code > ;-) > Thanks Jeff

diff --git a/Documentation/technical/api-trace2.txt b/Documentation/technical/api-trace2.txt new file mode 100644 index 0000000000..501fd770f2 --- /dev/null +++ b/Documentation/technical/api-trace2.txt @@ -0,0 +1,1158 @@ +Trace2 API +========== + +The Trace2 API can be used to print debug, performance, and telemetry +information to stderr or a file. The Trace2 feature is inactive unless +explicitly enabled by setting one or more of the `GIT_TR2`, `GIT_TR2_PERF`, +or `GIT_TR2_EVENT` environment variables. + +The Trace2 API is intended to replace the existing (Trace1) +printf-style tracing provided by the existing `GIT_TRACE` and +`GIT_TRACE_PERFORMANCE` facilities. During initial implementation, +Trace2 and Trace1 may operate in parallel. + +The Trace2 API defines a set of high-level events with known fields, +such as (`start`: `argv`) and (`exit`: {`exit-code`, `elapsed-time`}). + +These high-level events are written to one or more Trace2 Targets +in a target-specific format. Each Trace2 Target defines a different +purpose-specific view onto the event data stream. In this mannor, +a single set of Trace2 API event calls in the Git source can drive +different types of analysis. + +Trace2 Targets +-------------- + +Trace2 defines the following set of Trace2 Targets. These can be +independently enabled and disabled. Trace2 API events are sent to +each enabled target. Each enabled target writes an event message +in a target-specific format (described later). + +`GIT_TR2` (NORMAL):: + + a simple printf format like GIT_TRACE. ++ +------------ +$ export GIT_TR2=~/log.normal +$ git version +git version 2.20.1.155.g426c96fcdb +------------ ++ +------------ +$ cat ~/log.normal +12:28:42.620009 common-main.c:38 version 2.20.1.155.g426c96fcdb +12:28:42.620989 common-main.c:39 start git version +12:28:42.621101 git.c:432 cmd_verb version (version) +12:28:42.621215 git.c:662 exit elapsed:0.001227 code:0 +12:28:42.621250 trace2/tr2_tgt_normal.c:124 atexit elapsed:0.001265 code:0 +------------ + +`GIT_TR2_PERF` (PERF):: + + a column-based format to replace GIT_TRACE_PERFORMANCE suitable for + development and testing, possibly to complement tools like gprof. ++ +------------ +$ export GIT_TR2_PERF=~/log.perf +$ git version +git version 2.20.1.155.g426c96fcdb +------------ ++ +------------ +$ cat ~/log.perf +12:28:42.620675 common-main.c:38 | d0 | main | version | | | | | 2.20.1.155.g426c96fcdb +12:28:42.621001 common-main.c:39 | d0 | main | start | | | | | git version +12:28:42.621111 git.c:432 | d0 | main | cmd_verb | | | | | version (version) +12:28:42.621225 git.c:662 | d0 | main | exit | | 0.001227 | | | code:0 +12:28:42.621259 trace2/tr2_tgt_perf.c:211 | d0 | main | atexit | | 0.001265 | | | code:0 +------------ + +`GIT_TR2_EVENT` (EVENT):: + + a JSON-based format of event data suitable for telemetry analysis. ++ +------------ +$ export GIT_TR2_EVENT=~/log.event +$ git version +git version 2.20.1.155.g426c96fcdb +------------ ++ +------------ +$ cat ~/log.event +{"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"} +{"event":"start","sid":"1547659722619736-11614","thread":"main","time":"2019-01-16 17:28:42.621027","file":"common-main.c","line":39,"argv":["git","version"]} +{"event":"cmd_verb","sid":"1547659722619736-11614","thread":"main","time":"2019-01-16 17:28:42.621122","file":"git.c","line":432,"name":"version","hierarchy":"version"} +{"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} +{"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} +------------ + +Trace2 API Definitions +---------------------- + +All public Trace2 functions and macros are defined in `trace2.h` and +`trace2.c`. These are documented in detail in `trace2.h`. All +public symbols are prefixed with `trace2_`. + +There are no public Trace2 data structures. + +The Trace2 code also defines a set of private functions and data types +in the `trace2/` directory. These symbols are prefixed with `tr2_` +and should only be used by functions in `trace2.c`. + +The functions defined by the Trace2 API can be grouped into the +following groups. + +Basic Command Events:: + + These are concerned with the lifetime of the overall git process. ++ +---------------- +trace2_initialize(...) + +trace2_cmd_start(...) +trace2_cmd_exit(...) +trace2_cmd_error(...) +trace2_cmd_path(...) +---------------- + +Git Command Detail Events:: + + These are concerned with describing the specific Git command + after the command line, config, and environment are inspected. ++ +---------------- +trace2_cmd_verb(...) +trace2_cmd_subverb(...) +trace2_cmd_alias(...) + +trace2_cmd_list_config(...) +trace2_cmd_set_config(...) + +trace2_def_param(...) +trace2_def_repo(...) +---------------- + +Git Child Process Events:: + + These are concerned with the various spawned child processes, + including sub-git processes and hooks, ++ +---------------- +trace2_child_start(...) +trace2_child_exit(...) + +trace2_exec(...) +trace2_exec_result(...) +---------------- + +Git Thread Events:: + + These are concerned with Git thread usage. ++ +---------------- +trace2_thread_start(...) +trace2_thread_exit(...) +---------------- + +Region and Data Events:: + + These are concerned with recording performance data + over regions or spans of code. ++ +---------------- +trace2_region_enter(...) +trace2_region_enter_printf(...) +trace2_region_leave(...) +trace2_region_leave_printf(...) + +trace2_data_string(...) +trace2_data_intmax(...) +trace2_data_json(...) + +trace2_printf(...) +---------------- + +Trace2 API Usage +---------------- + +Here is a hypothetical usage of the Trace2 API showing the intended +usage (without worrying about the actual Git details). + +Initialization:: + + Initialization happens in `main()`. The initialization code + determines which, if any, Trace2 Targets should be enabled and + emits the `version`, `start`, and `exit` events. It causes an + `atexit` function and `signal` handler to be registered that + will emit `atexit` and `signal` events. ++ +---------------- +int main(int argc, const char **argv) +{ + int exit_code; + + trace2_initialize(); + trace2_cmd_start(argv); + + exit_code = cmd_main(argc, argv); + + trace2_cmd_exit(exit_code); + + return exit_code; +} +---------------- + +Command Details:: + + After the basics are established, additional process + information can be sent to Trace2 as it is discovered, such as + the command verb, alias expansion, interesting config + settings, the repository worktree, error messages, and etc. ++ +---------------- +int cmd_checkout(int argc, const char **argv) +{ + // emit a single "def_param" event + trace2_def_param("core.editor", "emacs"); + + // emit def_params for any config setting matching a pattern + // in GIT_TR2_CONFIG_PARAMS. + trace2_cmd_list_config(); + + trace2_cmd_verb("checkout"); + trace2_cmd_subverb("branch"); + trace2_def_repo(the_repository); + + if (do_something(...)) + trace2_cmd_error("Path '%s': cannot do something", path); + + return 0; +} +---------------- + +Child Processes:: + + Git typically spawns many sub-processes, such as sub-git + commands, shell scripts, editors, pagers, and hooks. + Trace2 child events record time spent waiting for child + processes and help track performance problems across + multiple layers of child processes. ++ +---------------- +void run_child(...) +{ + int child_exit_code; + struct child_process cmd = CHILD_PROCESS_INIT; + ... + + trace2_child_start(&cmd); + child_exit_code = ...(); + trace2_child_exit(&cmd, child_exit_code); +} +---------------- ++ +For example, the following fetch command spawned ssh, index-pack, +rev-list, and gc. This example also shows that fetch took +5.199 seconds and of that 4.932 was in ssh. ++ +---------------- +$ export GIT_TR2_BRIEF=1 +$ export GIT_TR2=~/log.normal +$ git fetch origin +... + +$ cat ~/log.normal +version 2.20.1.vfs.1.1.47.g534dbe1ad1 +start git fetch origin +worktree /Users/jeffhost/work/gfw +cmd_verb fetch (fetch) +child_start[0] ssh git@github.com ... +child_start[1] git index-pack ... +... (Trace2 events from child processes omitted) +child_exit[1] pid:14707 code:0 elapsed:0.076353 +child_exit[0] pid:14706 code:0 elapsed:4.931869 +child_start[2] git rev-list ... +... (Trace2 events from child process omitted) +child_exit[2] pid:14708 code:0 elapsed:0.110605 +child_start[3] git gc --auto +... (Trace2 events from child process omitted) +child_exit[3] pid:14709 code:0 elapsed:0.006240 +exit elapsed:5.198503 code:0 +atexit elapsed:5.198541 code:0 +---------------- ++ +When a git process is a (direct or indirect) child of another +git process, it inherits Trace2 context information. This +allows the child to print a verb hierarchy. This example +shows gc as child[3] of fetch. When the gc process reports +its verb as "gc", it also reports the hierarchy as "fetch/gc". +(In this example, trace2 messages from the child process is +indented for clarity.) ++ +---------------- +$ export GIT_TR2_BRIEF=1 +$ export GIT_TR2=~/log.normal +$ git fetch origin +... + +$ cat ~/log.normal +version 2.20.1.160.g5676107ecd.dirty +start git fetch official +worktree /Users/jeffhost/work/gfw +cmd_verb fetch (fetch) +... +child_start[3] git gc --auto + version 2.20.1.160.g5676107ecd.dirty + start /Users/jeffhost/work/gfw/git gc --auto + worktree /Users/jeffhost/work/gfw + cmd_verb gc (fetch/gc) + exit elapsed:0.001959 code:0 + atexit elapsed:0.001997 code:0 +child_exit[3] pid:20303 code:0 elapsed:0.007564 +exit elapsed:3.868938 code:0 +atexit elapsed:3.868970 code:0 +---------------- + +Region Events:: + + Trace2 defines a region as a timed span of code. ++ +---------------- +void wt_status_collect(struct wt_status *s) +{ + trace2_region_enter("status", "worktrees", s->repo); + wt_status_collect_changes_worktree(s); + trace2_region_leave("status", "worktrees", s->repo); + + trace2_region_enter("status", "index", s->repo); + wt_status_collect_changes_index(s); + trace2_region_leave("status", "index", s->repo); + + trace2_region_enter("status", "untracked", s->repo); + wt_status_collect_untracked(s); + trace2_region_leave("status", "untracked", s->repo); +} + +void wt_status_print(struct wt_status *s) +{ + trace2_region_enter("status", "print", s->repo); + switch (s->status_format) { + ... + } + trace2_region_leave("status", "print", s->repo); +} +---------------- ++ +In this example, scanning for untracked files ran from +0.012568 to ++0.027149 (since the process started) and took 0.014581 seconds. ++ +---------------- +$ export GIT_TR2_PERF_BRIEF=1 +$ export GIT_TR2_PERF=~/log.perf +$ git status +... + +$ cat ~/log.perf +d0 | main | version | | | | | 2.20.1.160.g5676107ecd.dirty +d0 | main | start | | | | | git status +d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw +d0 | main | cmd_verb | | | | | status (status) +... +d0 | main | region_enter | r1 | 0.010988 | | status | label:worktrees +d0 | main | region_leave | r1 | 0.011236 | 0.000248 | status | label:worktrees +d0 | main | region_enter | r1 | 0.011260 | | status | label:index +d0 | main | region_leave | r1 | 0.012542 | 0.001282 | status | label:index +d0 | main | region_enter | r1 | 0.012568 | | status | label:untracked +d0 | main | region_leave | r1 | 0.027149 | 0.014581 | status | label:untracked +d0 | main | region_enter | r1 | 0.027411 | | status | label:print +d0 | main | region_leave | r1 | 0.028741 | 0.001330 | status | label:print +d0 | main | exit | | 0.028778 | | | code:0 +d0 | main | atexit | | 0.028809 | | | code:0 +---------------- ++ +Regions may be nested. This causes event messages to be indented. +Elapsed times are relative to the start of the correpsonding nesting +level as expected. For example, if we add region events to: ++ +---------------- +static enum path_treatment read_directory_recursive(struct dir_struct *dir, + struct index_state *istate, const char *base, int baselen, + struct untracked_cache_dir *untracked, int check_only, + int stop_at_first_file, const struct pathspec *pathspec) +{ + enum path_treatment state, subdir_state, dir_state = path_none; + + trace2_region_enter_printf("dir", "read_recursive", NULL, "%.*s", baselen, base); + ... + trace2_region_leave_printf("dir", "read_recursive", NULL, "%.*s", baselen, base); + return dir_state; +} +---------------- ++ +We can further investigate the time spent scanning for untracked files. ++ +---------------- +$ export GIT_TR2_PERF_BRIEF=1 +$ export GIT_TR2_PERF=~/log.perf +$ git status +... +$ cat ~/log.perf +d0 | main | version | | | | | 2.20.1.162.gb4ccea44db.dirty +d0 | main | start | | | | | git status +d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw +d0 | main | cmd_verb | | | | | status (status) +... +d0 | main | region_enter | r1 | 0.015047 | | status | label:untracked +d0 | main | region_enter | | 0.015132 | | dir | ..label:read_recursive +d0 | main | region_enter | | 0.016341 | | dir | ....label:read_recursive vcs-svn/ +d0 | main | region_leave | | 0.016422 | 0.000081 | dir | ....label:read_recursive vcs-svn/ +d0 | main | region_enter | | 0.016446 | | dir | ....label:read_recursive xdiff/ +d0 | main | region_leave | | 0.016522 | 0.000076 | dir | ....label:read_recursive xdiff/ +d0 | main | region_enter | | 0.016612 | | dir | ....label:read_recursive git-gui/ +d0 | main | region_enter | | 0.016698 | | dir | ......label:read_recursive git-gui/po/ +d0 | main | region_enter | | 0.016810 | | dir | ........label:read_recursive git-gui/po/glossary/ +d0 | main | region_leave | | 0.016863 | 0.000053 | dir | ........label:read_recursive git-gui/po/glossary/ +... +d0 | main | region_enter | | 0.031876 | | dir | ....label:read_recursive builtin/ +d0 | main | region_leave | | 0.032270 | 0.000394 | dir | ....label:read_recursive builtin/ +d0 | main | region_leave | | 0.032414 | 0.017282 | dir | ..label:read_recursive +d0 | main | region_leave | r1 | 0.032454 | 0.017407 | status | label:untracked +... +d0 | main | exit | | 0.034279 | | | code:0 +d0 | main | atexit | | 0.034322 | | | code:0 +---------------- ++ +Trace2 regions are similar to the existing trace_performance_enter() +and trace_performance_leave() routines, but are thread safe and +maintain per-thread stacks of timers. + +Data Events:: + + Trace2 defines a data event to report important variables. + These events contain the active thread and are indented + relative to the current thread's open region stack. ++ +---------------- +int read_index_from(struct index_state *istate, const char *path, + const char *gitdir) +{ + trace2_region_enter_printf("index", "do_read_index", the_repository, "%s", path); + + ... + + trace2_data_intmax("index", the_repository, "read/version", istate->version); + trace2_data_intmax("index", the_repository, "read/cache_nr", istate->cache_nr); + + trace2_region_leave_printf("index", "do_read_index", the_repository, "%s", path); +} +---------------- ++ +---------------- +$ export GIT_TR2_PERF_BRIEF=1 +$ export GIT_TR2_PERF=~/log.perf +$ git status +... +$ cat ~/log.perf +d0 | main | version | | | | | 2.20.1.156.gf9916ae094.dirty +d0 | main | start | | | | | git status +d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw +d0 | main | cmd_verb | | | | | status (status) +d0 | main | region_enter | r1 | 0.001791 | | index | label:do_read_index .git/index +d0 | main | data | r1 | 0.002494 | 0.000703 | index | ..read/version:2 +d0 | main | data | r1 | 0.002520 | 0.000729 | index | ..read/cache_nr:3552 +d0 | main | region_leave | r1 | 0.002539 | 0.000748 | index | label:do_read_index .git/index +... +---------------- + +Thread Events:: + + Trace2 defines events to mark the start and end of a thread. + A thread name constructed during the start event. This name is + added to subsequent thread-specific events. The thread exit + event reports the elapsed time in the thread. ++ +For example, the multithreaded preload-index code can be +instrumented with a region around the thread pool and then +per-thread start and exit events within the threadproc. ++ +---------------- +static void *preload_thread(void *_data) +{ + trace2_thread_start("preload_thread"); + + trace2_data_intmax("index", the_repository, "offset", p->offset); + trace2_data_intmax("index", the_repository, "count", nr); + + do { + ... + } while (--nr > 0); + ... + + trace2_thread_exit(); + return NULL; +} + +void preload_index(struct index_state *index, + const struct pathspec *pathspec, + unsigned int refresh_flags) +{ + trace2_region_enter("index", "preload", the_repository); + + for (i = 0; i < threads; i++) { + ... /* create thread */ + } + + for (i = 0; i < threads; i++) { + ... /* join thread */ + } + + trace2_region_leave("index", "preload", the_repository); +} +---------------- ++ +In this example preload_index() was executed by the `main` thread +and started the `preload` region. Seven threads, named +`th01:preload_thread` through `th07:preload_thread`, were started. +Events from each thread are atomically appended to the shared target +stream as they occur so they may appear in random order with respect +other threads. Finally, the main thread waits for the threads to +finish and leaves the region. ++ +Data events are tagged with the active thread name. They are used +to report the per-thread parameters. ++ +---------------- +$ export GIT_TR2_PERF_BRIEF=1 +$ export GIT_TR2_PERF=~/log.perf +$ git status +... +$ cat ~/log.perf +d0 | main | version | | | | | 2.20.1.156.gf9916ae094.dirty +d0 | main | start | | | | | git status +d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw +d0 | main | cmd_verb | | | | | status (status) +... +d0 | main | region_enter | r1 | 0.002595 | | index | label:preload +d0 | th01:preload_thread | thread_start | | 0.002699 | | | +d0 | th02:preload_thread | thread_start | | 0.002721 | | | +d0 | th01:preload_thread | data | r1 | 0.002736 | 0.000037 | index | offset:0 +d0 | th02:preload_thread | data | r1 | 0.002751 | 0.000030 | index | offset:2032 +d0 | th03:preload_thread | thread_start | | 0.002711 | | | +d0 | th06:preload_thread | thread_start | | 0.002739 | | | +d0 | th01:preload_thread | data | r1 | 0.002766 | 0.000067 | index | count:508 +d0 | th06:preload_thread | data | r1 | 0.002856 | 0.000117 | index | offset:2540 +d0 | th03:preload_thread | data | r1 | 0.002824 | 0.000113 | index | offset:1016 +d0 | th04:preload_thread | thread_start | | 0.002710 | | | +d0 | th02:preload_thread | data | r1 | 0.002779 | 0.000058 | index | count:508 +d0 | th06:preload_thread | data | r1 | 0.002966 | 0.000227 | index | count:508 +d0 | th07:preload_thread | thread_start | | 0.002741 | | | +d0 | th07:preload_thread | data | r1 | 0.003017 | 0.000276 | index | offset:3048 +d0 | th05:preload_thread | thread_start | | 0.002712 | | | +d0 | th05:preload_thread | data | r1 | 0.003067 | 0.000355 | index | offset:1524 +d0 | th05:preload_thread | data | r1 | 0.003090 | 0.000378 | index | count:508 +d0 | th07:preload_thread | data | r1 | 0.003037 | 0.000296 | index | count:504 +d0 | th03:preload_thread | data | r1 | 0.002971 | 0.000260 | index | count:508 +d0 | th04:preload_thread | data | r1 | 0.002983 | 0.000273 | index | offset:508 +d0 | th04:preload_thread | data | r1 | 0.007311 | 0.004601 | index | count:508 +d0 | th05:preload_thread | thread_exit | | 0.008781 | 0.006069 | | +d0 | th01:preload_thread | thread_exit | | 0.009561 | 0.006862 | | +d0 | th03:preload_thread | thread_exit | | 0.009742 | 0.007031 | | +d0 | th06:preload_thread | thread_exit | | 0.009820 | 0.007081 | | +d0 | th02:preload_thread | thread_exit | | 0.010274 | 0.007553 | | +d0 | th07:preload_thread | thread_exit | | 0.010477 | 0.007736 | | +d0 | th04:preload_thread | thread_exit | | 0.011657 | 0.008947 | | +d0 | main | region_leave | r1 | 0.011717 | 0.009122 | index | label:preload +... +d0 | main | exit | | 0.029996 | | | code:0 +d0 | main | atexit | | 0.030027 | | | code:0 +---------------- ++ +In this example, the preload region took 0.009122 seconds. The 7 threads +took between 0.006069 and 0.008947 seconds to work on their portion of +the index. Thread "th01" worked on 508 items at offset 0. Thread "th02" +worked on 508 items at offset 2032. Thread "th04" worked on 508 itemts +at offset 508. ++ +This example also shows that thread names are assigned in a racy manner +as each thread starts and allocates TLS storage. + +Printf Events:: + + Trace2 defines a printf interface to write arbitrary messages + to the targets. These are convenient for development, but + may more difficult to post-process. + +Trace2 Target Formats +--------------------- + +NORMAL Target Format +~~~~~~~~~~~~~~~~~~~~ + +NORMAL format is enabled when the `GIT_TR2` environment variable +is set to "1" or an absolute pathname. + +Events are written as lines of the form: + +------------ +[<time> SP <filename>:<line> SP+] <event-name> [[SP] <event-message>] LF +------------ + +`<event-name>`:: + + is the event name. +`<event-message>`:: + is a free-form printf message intended for human consumption. ++ +Note that this may contain embedded LF or CRLF characters that are +not escaped, so the event may spill across multiple lines. + +If `GIT_TR2_BRIEF` is true, the time, filename, and line number fields +are omitted. + +This target is intended to be more of a summary (like GIT_TRACE) and +less detailed than the other targets, and therefore does not emit +messages for some of the Trace2 API verbs. For example, thread, +region, and data events are omitted. + +PERF Target Format +~~~~~~~~~~~~~~~~~~ + +PERF format is enabled when the `GIT_TR2_PERF` environment variable +is set to "1" or an absolute pathname. + +Events are written as lines of the form: + +------------ +[<time> SP <filename>:<line> SP+ + BAR SP] d<depth> SP + BAR SP <thread-name> SP+ + BAR SP <event-name> SP+ + BAR SP [r<repo-id>] SP+ + BAR SP [<t_abs>] SP+ + BAR SP [<t_rel>] SP+ + BAR SP [<category>] SP+ + BAR SP DOTS* <perf-event-message> + LF +------------ + +`<depth>`:: + is the git process depth. This is the number of parent + git processes. A top-level git command has depth value 0. + A child of it has depth value 1. + +`<thread-name>`:: + is a unique name for the thread. The primary thread + is called "main". Other thread names are of the form "th%d:%s" + and include a unique number and the name of the thread-proc. + +`<event-name>`:: + is the event name. + +`<repo-id>`:: + when present, is a number indicating the repository + in use. A `def_repo` event is emitted when a repository is + opened. This defines the repo-id and associated worktree. + Subsequent repo-specific events will reference this repo-id. ++ +Currently, this is always "r1" for the main repository. +This field is in anticipation of in-proc submodules in the future. + +`<t_abs>`:: + when present, is the absolute time in seconds since the + program started. + +`<t_rel>`:: + when present, is time in seconds relative to the start of + the current region. For a thread-exit event, it is the elapsed + time of the thread. + +`<category>`:: + is present on region and data events and is used to + indicate a broad category, such as "index" or "status". ++ +Currently, this is advisory. This field is in anticipation +of category-based filtering, similar to the `GIT_TRACE_<key>` +facility in Trace1. + +`<perf-event-message>`:: + is a free-form printf message intended for human consumption. + +If `GIT_TR2_PERF_BRIEF` is true, the time, filename, and line number +fields are omitted. + +This target is intended for interactive performance analysis +during development and is quite noisy. + +EVENT Target Format +~~~~~~~~~~~~~~~~~~~ + +EVENT format is enabled when the `GIT_TR2_EVENT` environment +variable is set to "1" or an absolute pathname. + +Each event is a JSON-object containing multiple key/value pairs +written as a single line and followed by a LF. + +------------ +'{' <key> ':' <value> [',' <key> ':' <value>]* '}' LF +------------ + +Some key/value pairs are common to all events and some are +event-specific. + +Common Key/Value Pairs +^^^^^^^^^^^^^^^^^^^^^^ + +The following key/value pairs are common to all events: + +------------ +{ + "event":"version", + "sid":"1547659722619736-11614", + "thread":"main", + "time":"2019-01-16 17:28:42.620713", + "file":"common-main.c", + "line":38, + ... +} +------------ + +`"event":<event>`:: + is the event name. + +`"sid":<sid>`:: + is the session-id. This is a unique string to identify the + process instance to allow all events emitted by a process to + be identified. A session-id is used instead of a PID because + PIDs are recycled by the OS. For child git processes, the + session-id is prepended with the session-id of the parent git + process to allow parent-child relationships to be identified + during post-processing. + +`"thread":<thread>`:: + is the thread name. + +`"time":<time>`:: + is the UTC time of the event. + +`"file":<filename>`:: + is source file generating the event. + +`"line":<line-number>`:: + is the integer source line number generating the event. + +`"repo":<repo-id>`:: + when present, is the integer repo-id as described previously. + +If `GIT_TR2_EVENT_BRIEF` is true, the file and line fields are omitted +from all events and the time field is only present on the `start` and +`atexit` events. + +Event-Specific Key/Value Pairs +^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ + +`version`:: + This event gives the version of the executable and the EVENT format. ++ +------------ +{ + "event":"version", + ... + "evt":"1", # EVENT format version + "exe":"2.20.1.155.g426c96fcdb" # git version +} +------------ + +`start`:: + This event contains the complete argv received by main(). ++ +------------ +{ + "event":"start", + ... + "argv":["git","version"] +} +------------ + +`exit`:: + This event is emitted when git calls `exit()`. ++ +------------ +{ + "event":"exit", + ... + "t_abs":0.001227, # elapsed time in seconds + "code":0 # exit code +} +------------ + +`atexit`:: + This event is emitted by the Trace2 `atexit` routine during + final shutdown. It should be the last event emitted by the + process. (The elapsed time reported here is greater than the + time reported in the `exit` event because it runs after all + other atexit tasks have completed.) ++ +------------ +{ + "event":"atexit", + ... + "t_abs":0.001227, + "code":0 +} +------------ + +`signal`:: + This event is emitted when the program is terminated by a user + signal. Depending on the platform, the signal event may + prevent the `atexit` event from being generated. ++ +------------ +{ + "event":"signal", + ... + "t_abs":0.001227, + "signal":13 +} +------------ + +`error`:: + This event is emitted when one of the `error()`, `die()`, + or `usage()` functions are called. ++ +------------ +{ + "event":"error", + ... + "msg":"invalid option: --cahced", # formatted error message + "fmt":"invalid option: %s" # error format string +} +------------ ++ +The error event may be emitted more than once. The format string +allows post-processors to group errors by type without worrying +about specific error arguments. + +`cmd_path`:: + This event contains the discovered full path of the git + executable (on platforms that are configured to resolve it). ++ +------------ +{ + "event":"cmd_path", + ... + "path":"C:/work/gfw/git.exe" +} +------------ + +`cmd_verb`:: + This event contains the primary verb for this command + and the hierarchy of command verbs. ++ +------------ +{ + "event":"cmd_verb", + ... + "name":"pack-objects", + "hierarchy":"push/pack-objects" +} +------------ ++ +Normally, the `name` field contains the canonical name of the +command. When a canonical command verb is not available, one of +these special values are used: ++ +------------ +"_query_" # "git --html-path" +"_run_dashed_" # when "git foo" tries to run "git-foo" +"_run_shell_alias_" # alias expansion to a shell command +"_run_git_alias_" # alias expansion to a git command +"_usage_" # usage error +------------ + +`cmd_subverb`:: + This event, when present, describes the variant of the main + command verb. This event may be emitted more than once. ++ +------------ +{ + "event":"cmd_subverb", + ... + "name":"branch" +} +------------ ++ +The `name` field is an arbitrary string that makes sense in the +context of the primary verb. For example, checkout can checkout a +branch or an individual file. And these variations typically have +different performance characteristics that are not comparable. + +`alias`:: + This event is present when an alias is expanded. ++ +------------ +{ + "event":"alias", + ... + "alias":"l", # registered alias + "argv":["log","--graph"] # alias expansion +} +------------ + +`child_start`:: + This event describes a child process that is about to be + spawned. ++ +------------ +{ + "event":"child_start", + ... + "child_id":2, + "child_class":"?", + "use_shell":false, + "argv":["git","rev-list","--objects","--stdin","--not","--all","--quiet"] + + "hook_name":"<hook_name>" # present when child_class is "hook" + "cd":"<path>" # present when cd is required +} +------------ ++ +The `child_id` field can be used to match this child_start with the +corresponding child_exit event. ++ +The `child_class` field is a rough classification, such as "editor", +"pager", "transport/*", and "hook". Unclassified children are classified +with "?". + +`child_exit`:: + This event is generated after the git process has returned + from the waitpid() and collected the exit information from the + child. ++ +------------ +{ + "event":"child_exit", + ... + "child_id":2, + "pid":14708, # child PID + "code":0, # child exit-code + "t_rel":0.110605 # observed run-time of child process +} +------------ ++ +Note that the session-id of the child process is not available to +the current/spawning process, so the child's PID is reported here as +a hint for post-processing. (But it is only a hint because the child +proces may be a shell script which doesn't have a session-id.) ++ +Note that the `t_rel` field contains the observed run time in seconds +for the child process (starting before the fork/exec/spawn and +stopping after the waitpid() and includes OS process creation overhead). +So this time will be slightly larger than the atexit time reported by +the child process itself. + +`exec`:: + This event is generated before git attempts to `exec()` + another command rather than starting a child process. ++ +------------ +{ + "event":"exec", + ... + "exec_id":0, + "exe":"git", + "argv":["foo", "bar"] +} +------------ ++ +Since `exec()` does not return if successful, this will be the last +event generated for the current git command before the new git commit +starts. ++ +The `exec_id` field is a command-unique id and is only useful if the +`exec()` fails and a corresponding exec_result event is generated. + +`exec_result`:: + This event is generated if the `exec()` fails and control + returns to the current git command. ++ +------------ +{ + "event":"exec_result", + ... + "exec_id":0, + "code":1 # error code (errno) from exec() +} +------------ + +`thread_start`:: + This event is generated when a thread is started. It is + generated from *within* the new thread's thread-proc (for TLS + reasons). ++ +------------ +{ + "event":"thread_start", + ... + "thread":"th02:preload_thread" +} +------------ + +`thread_exit`:: + This event is generated when a thread exits. It is generated + from *within* the thread's thread-proc (for TLS reasons). ++ +------------ +{ + "event":"thread_exit", + ... + "thread":"th02:preload_thread", + "t_rel":0.007328 # thread elapsed time +} +------------ + +`def_param`:: + This event is generated to log a global key/value pair for the + current command. ++ +------------ +{ + "event":"def_param", + ... + "param":"core.editor", + "value":"emacs" +} +------------ ++ +This is intended to log "values of interest" for post-processing. For +example, this might be configuration settings known to affect +performance or the remote URL so that different repos can be grouped +differently. For thread- or region-specific key/values pairs, see the +`data` and `data_json` events. + +`def_repo`:: + This event defines a repo-id and associates it with the root + of the worktree. Subsequent repo-relative events will refer + to this repo-id. Repo-id number 1 refers to the main + repository. ++ +------------ +{ + "event":"def_repo", + ... + "repo":1, + "worktree":"/Users/jeffhost/work/gfw" +} +------------ ++ +As stated earlier, the repo-id is currently always 1, so there will +only be one def_repo event. Later, if in-proc submodules are +supported, a def_repo event should be emitted for each submodule +visited. + +`region_enter`:: + This event is generated when entering a region. + It serves as a marker in the event stream. It starts an activity timer + for the region. And it pushes a frame on the region stack for the + current thread. ++ +------------ +{ + "event":"region_enter", + ... + "repo":1, + "nesting":1, # current region stack depth + "category":"index", # optional + "label":"do_read_index", # optional + "msg":".git/index" # optional +} +------------ ++ +The `category` field may be used in a future enhancement to +do category-based filtering. ++ +The `GIT_TR2_EVENT_NESTING` environment variable can be used to +filter deeply nested regions and data events. It defaults to "2". + +`region_leave`:: + This event is generated when leaving a region. It serves as a + marker in the event stream and reports the elapsed time spent + in the region. It pops a frame off of the region stack for + the current thread. ++ +------------ +{ + "event":"region_leave", + ... + "repo":1, + "t_rel":0.002876, # time spent in region in seconds + "nesting":1, # region stack depth + "category":"index", # optional + "label":"do_read_index", # optional + "msg":".git/index" # optional +} +------------ ++ +The examples in this document have generally shown the region_enter +and region_leave events with the same category and label fields. This +is not a requirement, but makes it easier to understand the logs. + +`data`:: + This event is generated to log a thread- and region-local + key/value pair. For example, during a recursive treewalk, + logging the relative path and the number of entries in the + tree. ++ +------------ +{ + "event":"data", + ... + "repo":1, # optional + "t_abs":0.024107, # absolute elapsed time + "t_rel":0.001031, # elapsed time in region/thread + "nesting":2, + "category":"index", + "key":"read/cache_nr", + "value":"3552"} +} +------------ ++ +The `value` field may be an integer or a string. + +`data-json`:: + This event is generated to log a pre-formatted JSON string + containing structured data. ++ +------------ +{ + "event":"data_json", + ... + "repo":1, # optional + "t_abs":0.015905, + "t_rel":0.015905, + "nesting":1, + "category":"process", + "key":"windows/ancestry", + "value":["bash.exe","bash.exe"] +} +------------ + +Appendix: Relationship to the Existing Trace Api (api-trace.txt) +---------------------------------------------------------------- + +Eventually, I would like Trace2 to replace the existing Trace1 API. + +Trace2 is a superset of Trace1 and the existing Trace1 API calls could +be converted to Trace2, but that work has not yet been attempted. + +There are a few issues here: + +* Updating existing tests that assume GIT_TRACE format messages. + +* How to best handle custom GIT_TRACE_<key> messages? + +** The GIT_TRACE_<key> mechanism allows each <key> to write to a +different file (in addition to just stderr). + +** Do we want to maintain that ability or simply write to the existing +Trace2 targets (and convert <key> to a "category"). +

[01/14] trace2: Documentation/technical/api-trace2.txt

Commit Message

Comments

Patch