From patchwork Tue Jan 22 21:22:12 2019 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Linus Arver via GitGitGadget X-Patchwork-Id: 10776311 Return-Path: Received: from mail.wl.linuxfoundation.org (pdx-wl-mail.web.codeaurora.org [172.30.200.125]) by pdx-korg-patchwork-2.web.codeaurora.org (Postfix) with ESMTP id 6780F1390 for ; Tue, 22 Jan 2019 21:22:41 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 518EF2BC87 for ; Tue, 22 Jan 2019 21:22:41 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 457882BC32; Tue, 22 Jan 2019 21:22:41 +0000 (UTC) X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on pdx-wl-mail.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-8.0 required=2.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,FREEMAIL_FROM,MAILING_LIST_MULTI,RCVD_IN_DNSWL_HI autolearn=ham version=3.3.1 Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id E4CB22BC76 for ; Tue, 22 Jan 2019 21:22:38 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1726352AbfAVVWS (ORCPT ); Tue, 22 Jan 2019 16:22:18 -0500 Received: from mail-ed1-f42.google.com ([209.85.208.42]:35071 "EHLO mail-ed1-f42.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1726166AbfAVVWS (ORCPT ); Tue, 22 Jan 2019 16:22:18 -0500 Received: by mail-ed1-f42.google.com with SMTP id x30so19826edx.2 for ; Tue, 22 Jan 2019 13:22:15 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=date:message-id:in-reply-to:references:from:subject:fcc :content-transfer-encoding:mime-version:to:cc; bh=j6V1XFQKpZOQw01j/9kYUfQznrNut0YJFynstafqWO8=; b=MHNe9GDHccqASSAAeoezswX9goBuFo5jGeI0Pfv47gEhX9fusdYGe3KhQrCR6Qn0sF VABbUs5fvouD4yIJZZqs9ffX6qBrRoXwvS5N4NEsuGHGnrkoXk/8XWXOIhURucR6FWpG RPeu+TJ2+O9VNs6KTQ0+rrysYuFXirsJO9yMB1L8O6KGSD7ncipLFlUma0yF6mmwTia3 UEuHAHcI0+oN5E3K+fMcmpV62Cl9gFrxJWdmtkfn/5HyAPFjLtGrPMKTCT2A25G+dfQZ OeC7HW+PckrxzG16vlZGdvKewelweQMzZ3RUgQUrjVZSFKPLqG0lREpqxkT8g0NPTOP3 4VKw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:date:message-id:in-reply-to:references:from :subject:fcc:content-transfer-encoding:mime-version:to:cc; bh=j6V1XFQKpZOQw01j/9kYUfQznrNut0YJFynstafqWO8=; b=Km2n+8Doi7UthfB3vNeaVsOa0gntnDFK6jgwEngK5i0YqQND8iepjMTxVCHFeWWtmd Kz6tg+7q973VF53elDAySrV68eUWEV6RNbn1TI+i+nNEj9ewl2HGlgIYEA9R5g8jvAKO QaLo99rTll+QWylpKQl/gE45WOcyYzbzjbsx82RcUXFf6ylymRnUq5Avq8g/Dz28QqMI 4jiE4SInvo+io4oxO9AU/oqnZ5HOmowZhp9dRnr6fZIJcLnOcwGz3uikC05nDbsGmQ34 TPMtFUdPJmv10inIfpCflssvDIVrgyH8CVOeFlfLE1A7KCCBb/biebdHixr+EiaD09y8 Tt8w== X-Gm-Message-State: AJcUukdcOC4bbOSUa4Rqno0hnArPsbN0Pist7+6xPa5CZIAjb4/qUzXA MrhfVpFJNOBQx4SUWi0Oc7hexJiU X-Google-Smtp-Source: ALg8bN7F1mLuwRBEzNblCOCtnzomWzVg15kRG28XVauhWRXtddXvCprG81Aj048hxnujQiJhfTbx3Q== X-Received: by 2002:a17:906:248c:: with SMTP id e12mr135884ejb.14.1548192133507; Tue, 22 Jan 2019 13:22:13 -0800 (PST) Received: from [127.0.0.1] ([13.74.141.28]) by smtp.gmail.com with ESMTPSA id n11-v6sm5404010ejh.74.2019.01.22.13.22.12 (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Tue, 22 Jan 2019 13:22:12 -0800 (PST) Date: Tue, 22 Jan 2019 13:22:12 -0800 (PST) X-Google-Original-Date: Tue, 22 Jan 2019 21:21:58 GMT Message-Id: <1a90de9dab0dd836e54fee9e08ab9e2284e1027a.1548192131.git.gitgitgadget@gmail.com> In-Reply-To: References: From: "Jeff Hostetler via GitGitGadget" Subject: [PATCH 01/14] trace2: Documentation/technical/api-trace2.txt Fcc: Sent MIME-Version: 1.0 To: git@vger.kernel.org Cc: jeffhost@microsoft.com, Junio C Hamano , Jeff Hostetler Sender: git-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: git@vger.kernel.org X-Virus-Scanned: ClamAV using ClamSMTP From: Jeff Hostetler Created design document for Trace2 feature. Signed-off-by: Jeff Hostetler --- Documentation/technical/api-trace2.txt | 1158 ++++++++++++++++++++++++ 1 file changed, 1158 insertions(+) create mode 100644 Documentation/technical/api-trace2.txt 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: + +------------ +[