From patchwork Thu Mar 28 13:30:57 2019 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Koji Nakamaru via GitGitGadget X-Patchwork-Id: 10874939 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 8ED5F1390 for ; Thu, 28 Mar 2019 13:31:04 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 7120D28DBB for ; Thu, 28 Mar 2019 13:31:04 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 6528128DCD; Thu, 28 Mar 2019 13:31:04 +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 AFFF428DE1 for ; Thu, 28 Mar 2019 13:31:03 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1726879AbfC1NbC (ORCPT ); Thu, 28 Mar 2019 09:31:02 -0400 Received: from mail-ed1-f65.google.com ([209.85.208.65]:41120 "EHLO mail-ed1-f65.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1726059AbfC1NbC (ORCPT ); Thu, 28 Mar 2019 09:31:02 -0400 Received: by mail-ed1-f65.google.com with SMTP id a25so17219624edc.8 for ; Thu, 28 Mar 2019 06:31:00 -0700 (PDT) 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=VsFPVQlrbd+oBjrpClEK4LCZ+NiKxOzUOqbfxGpd3qw=; b=L7oWL/uopKhskf5aF415iYf/RzZuTAax2BEDcK83LlsePnFVOcoGijKHdl9cJTni+/ m2IpFKobRog85pMz77eVvKaIGX4sMnIdXSJvfkLEJfLamgfIJ18mBaYrw0OrowvQuIlA WoTjFmHK5TEBm6Na/ij6Ij9N1yyIIg+Y/GrLiuB2t5KrJnCeO6RDlXyEMcpIPQACw+lD kWHhzhDjae2dtrgqyv5XQnWQthdq7hAIeTy5VuRHN6kScajIgtrIHtbP2lS0TzfhgbFt g75HV8G71vdbqpd1EQ/5w4HW3B8kSEflyD1YHLslRtj457qbNONfiwU1TFXT6/YLNmrj E7RQ== 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=VsFPVQlrbd+oBjrpClEK4LCZ+NiKxOzUOqbfxGpd3qw=; b=XyPdNdxzflS/PaslMeVoVeRjup/FBVmR8d3pKCn9fxaQ6QmzTX5DoiDHZ1t0/VgAhk BoAztHpoJAWVqIrdAt5kWtK/D2OFsFvoseUAPxX3Deu6qvD4OTVajxCQ8BI4GLDyIddE LNOFga3IBt9SqWOJ5kDe5+9r52VKzgs1iO5074RUFgndAskTcL87Sa0V0hOp4D4a5ZJr vGKIonJLlIVp16S3kfHymZ1qhW9Z81NL3TKzSCkpX8SX9horbDCidRj2wLxIb3QtQ1cH oR/18hO5UsrGCJ0CbnJx3J1f7OmLsCWIrZApxQ4hUnVQxa9uDiettYK9ykM1mZOUU+Pv ik7w== X-Gm-Message-State: APjAAAVNXsO+0Fn0Th42g5E6OUF0najO3q5en0YRkEjhCh3p52ScewdN 2ZcwZm8ztEO+5j6Y1ZBHSRypxlNn X-Google-Smtp-Source: APXvYqz2JhFK1wXisY+9uOAcTfxjYDVvjox/WDWhEaOm+/pGz0TeCySQl5B6KIG6ro0Ml7fak2AWuQ== X-Received: by 2002:a17:906:b756:: with SMTP id fx22mr24288474ejb.192.1553779859751; Thu, 28 Mar 2019 06:30:59 -0700 (PDT) Received: from [127.0.0.1] ([13.74.141.28]) by smtp.gmail.com with ESMTPSA id f13sm6111615eda.38.2019.03.28.06.30.57 (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Thu, 28 Mar 2019 06:30:57 -0700 (PDT) Date: Thu, 28 Mar 2019 06:30:57 -0700 (PDT) X-Google-Original-Date: Thu, 28 Mar 2019 13:30:48 GMT Message-Id: <7f1a34732271f9fbdbec0f4cd0a5990466ebd071.1553779851.git.gitgitgadget@gmail.com> In-Reply-To: References: From: "Jeff Hostetler via GitGitGadget" Subject: [PATCH 1/4] trace2: refactor setting process starting time Fcc: Sent MIME-Version: 1.0 To: git@vger.kernel.org Cc: gitster@pobox.com, peff@peff.net, jrnieder@gmail.com, steadmon@google.com, avarab@gmail.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 Create trace2_initialize_clock() and call from main() to capture process start time in isolation and before other sub-systems are ready. Signed-off-by: Jeff Hostetler --- Documentation/technical/api-trace2.txt | 12 ++++++-- common-main.c | 2 ++ compat/mingw.c | 2 ++ trace2.c | 7 ++++- trace2.h | 17 ++++++++++++ trace2/tr2_tls.c | 38 ++++++++++++++++---------- trace2/tr2_tls.h | 8 +++++- 7 files changed, 67 insertions(+), 19 deletions(-) diff --git a/Documentation/technical/api-trace2.txt b/Documentation/technical/api-trace2.txt index 2de565fa3d..f37fccf1da 100644 --- a/Documentation/technical/api-trace2.txt +++ b/Documentation/technical/api-trace2.txt @@ -160,17 +160,23 @@ purposes. These are concerned with the lifetime of the overall git process. +`void trace2_initialize_clock()`:: + + Initialize the Trace2 start clock and nothing else. This should + be called at the very top of main() to capture the process start + time and reduce startup order dependencies. + `void trace2_initialize()`:: Determines if any Trace2 Targets should be enabled and - initializes the Trace2 facility. This includes starting the - elapsed time clocks and thread local storage (TLS). + initializes the Trace2 facility. This includes setting up the + Trace2 thread local storage (TLS). + This function emits a "version" message containing the version of git and the Trace2 protocol. + This function should be called from `main()` as early as possible in -the life of the process. +the life of the process after essential process initialization. `int trace2_is_enabled()`:: diff --git a/common-main.c b/common-main.c index d484aec209..6137af0e63 100644 --- a/common-main.c +++ b/common-main.c @@ -27,6 +27,8 @@ int main(int argc, const char **argv) { int result; + trace2_initialize_clock(); + /* * Always open file descriptors 0/1/2 to avoid clobbering files * in die(). It also avoids messing up when the pipes are dup'ed diff --git a/compat/mingw.c b/compat/mingw.c index 6b04514cdc..a2f74aca6a 100644 --- a/compat/mingw.c +++ b/compat/mingw.c @@ -2569,6 +2569,8 @@ void mingw_startup(void) wchar_t **wenv, **wargv; _startupinfo si; + trace2_initialize_clock(); + maybe_redirect_std_handles(); /* get wide char arguments and environment */ diff --git a/trace2.c b/trace2.c index ccccd4ef09..6dd51e6aa5 100644 --- a/trace2.c +++ b/trace2.c @@ -142,6 +142,11 @@ static void tr2main_signal_handler(int signo) raise(signo); } +void trace2_initialize_clock(void) +{ + tr2tls_start_process_clock(); +} + void trace2_initialize_fl(const char *file, int line) { struct tr2_tgt *tgt_j; @@ -428,7 +433,7 @@ void trace2_thread_start_fl(const char *file, int line, const char *thread_name) us_now = getnanotime() / 1000; us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); - tr2tls_create_self(thread_name); + tr2tls_create_self(thread_name, us_now); for_each_wanted_builtin (j, tgt_j) if (tgt_j->pfn_thread_start_fl) diff --git a/trace2.h b/trace2.h index ae5020d0e6..8f89e70c44 100644 --- a/trace2.h +++ b/trace2.h @@ -19,6 +19,23 @@ struct json_writer; * [] trace2_printf* -- legacy trace[1] messages. */ +/* + * Initialize the TRACE2 clock and do nothing else, in particular + * no mallocs, no system inspection, and no environment inspection. + * + * This should be called at the very top of main() to capture the + * process start time. This is intended to reduce chicken-n-egg + * bootstrap pressure. + * + * It is safe to call this more than once. This allows capturing + * absolute startup costs on Windows which uses a little trickery + * to do setup work before common-main.c:main() is called. + * + * The main trace2_initialize_fl() may be called a little later + * after more infrastructure is established. + */ +void trace2_initialize_clock(void); + /* * Initialize TRACE2 tracing facility if any of the builtin TRACE2 * targets are enabled in the environment. Emits a 'version' event. diff --git a/trace2/tr2_tls.c b/trace2/tr2_tls.c index 8e65b0361d..31fb529f93 100644 --- a/trace2/tr2_tls.c +++ b/trace2/tr2_tls.c @@ -10,16 +10,30 @@ #define TR2_REGION_NESTING_INITIAL_SIZE (100) static struct tr2tls_thread_ctx *tr2tls_thread_main; -static uint64_t tr2tls_us_start_main; +static uint64_t tr2tls_us_start_process; static pthread_mutex_t tr2tls_mutex; static pthread_key_t tr2tls_key; static int tr2_next_thread_id; /* modify under lock */ -struct tr2tls_thread_ctx *tr2tls_create_self(const char *thread_name) +void tr2tls_start_process_clock(void) +{ + if (tr2tls_us_start_process) + return; + + /* + * Keep the absolute start time of the process (i.e. the main + * process) in a fixed variable since other threads need to + * access it. This allows them to do that without a lock on + * main thread's array data (because of reallocs). + */ + tr2tls_us_start_process = getnanotime() / 1000; +} + +struct tr2tls_thread_ctx *tr2tls_create_self(const char *thread_name, + uint64_t us_thread_start) { - uint64_t us_now = getnanotime() / 1000; struct tr2tls_thread_ctx *ctx = xcalloc(1, sizeof(*ctx)); /* @@ -29,7 +43,7 @@ struct tr2tls_thread_ctx *tr2tls_create_self(const char *thread_name) */ ctx->alloc = TR2_REGION_NESTING_INITIAL_SIZE; ctx->array_us_start = (uint64_t *)xcalloc(ctx->alloc, sizeof(uint64_t)); - ctx->array_us_start[ctx->nr_open_regions++] = us_now; + ctx->array_us_start[ctx->nr_open_regions++] = us_thread_start; ctx->thread_id = tr2tls_locked_increment(&tr2_next_thread_id); @@ -55,7 +69,7 @@ struct tr2tls_thread_ctx *tr2tls_get_self(void) * here and silently continue. */ if (!ctx) - ctx = tr2tls_create_self("unknown"); + ctx = tr2tls_create_self("unknown", getnanotime() / 1000); return ctx; } @@ -124,22 +138,18 @@ uint64_t tr2tls_absolute_elapsed(uint64_t us) if (!tr2tls_thread_main) return 0; - return us - tr2tls_us_start_main; + return us - tr2tls_us_start_process; } void tr2tls_init(void) { + tr2tls_start_process_clock(); + pthread_key_create(&tr2tls_key, NULL); init_recursive_mutex(&tr2tls_mutex); - tr2tls_thread_main = tr2tls_create_self("main"); - /* - * Keep a copy of the absolute start time of the main thread - * in a fixed variable since other threads need to access it. - * This also eliminates the need to lock accesses to the main - * thread's array (because of reallocs). - */ - tr2tls_us_start_main = tr2tls_thread_main->array_us_start[0]; + tr2tls_thread_main = tr2tls_create_self("main", + tr2tls_us_start_process); } void tr2tls_release(void) diff --git a/trace2/tr2_tls.h b/trace2/tr2_tls.h index bb80e3f8e7..b1e327a928 100644 --- a/trace2/tr2_tls.h +++ b/trace2/tr2_tls.h @@ -31,7 +31,8 @@ struct tr2tls_thread_ctx { * In this and all following functions the term "self" refers to the * current thread. */ -struct tr2tls_thread_ctx *tr2tls_create_self(const char *thread_name); +struct tr2tls_thread_ctx *tr2tls_create_self(const char *thread_name, + uint64_t us_thread_start); /* * Get our TLS data. @@ -94,4 +95,9 @@ void tr2tls_release(void); */ int tr2tls_locked_increment(int *p); +/* + * Capture the process start time and do nothing else. + */ +void tr2tls_start_process_clock(void); + #endif /* TR2_TLS_H */ From patchwork Thu Mar 28 13:31:00 2019 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Koji Nakamaru via GitGitGadget X-Patchwork-Id: 10874945 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 86D7E1390 for ; Thu, 28 Mar 2019 13:31:10 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 6B83828CD7 for ; Thu, 28 Mar 2019 13:31:10 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 5F5AA28DB8; Thu, 28 Mar 2019 13:31:10 +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 DE2DB28DBB for ; Thu, 28 Mar 2019 13:31:05 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1726971AbfC1NbE (ORCPT ); Thu, 28 Mar 2019 09:31:04 -0400 Received: from mail-ed1-f65.google.com ([209.85.208.65]:43676 "EHLO mail-ed1-f65.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1726281AbfC1NbE (ORCPT ); Thu, 28 Mar 2019 09:31:04 -0400 Received: by mail-ed1-f65.google.com with SMTP id d26so17191420ede.10 for ; Thu, 28 Mar 2019 06:31:02 -0700 (PDT) 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=yhflm1h/FZKF58Ok6RL8hgAJqkUeqZLAyJDxkCErf3w=; b=TmYcb2z5NqwpK1/gP/VncrlN+pc3r+Is3sSZ8vjwmP5lZa+zF2PPVN0ezBEfZJquki kyhY5x+Ko/C0PHjpYxWaJ0QIageuN6jfXI99JHNOR1/cevtjlanaBeyoamzXaVV5XmdJ iQAaf/UAGOpnDSNnKFcQYgM7p9iR4k+4Gk6nfoBTX87YTAjYI6yC6Obex6JPzEZ4LO16 nqIggJK0Y5kKjjISNCACcSql+aur28TF7kjZzhBZtu4+AvK80OOz0uDTdIkEtiDd1+Ok vwVnMRE98P9lEK6nqY46/eEBhao2E6N6BJrspJNAUPj8T79A4C8po1mxX/6yt2twxea/ jajg== 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=yhflm1h/FZKF58Ok6RL8hgAJqkUeqZLAyJDxkCErf3w=; b=PaUNEWRlCyuSV7BK0pWD12FLKbltEtSxzUD2TzWEli/+p8CEHX3ywZD+4HRuK5DxfN EuoRs3nFh2mZcBdlHa4hxCwGHHSsQmFuLL08/rcp2rmtzdnIZKbi8HSULkjE3+CQFmE0 3lFfVMtJn3y9UMCNF4P69UmBmAjf/HHclf2kUOjbBhycNyrGYE2PuoHU1Zqz/ErfzuH2 NYtifNwGdhQ1V5NQDyzUqEyngQgA2sogaPeS3NkMb1POkogb06UI6cY8VwQPxjWZWnZM RNC4YAD893B4Cv3LhHNn5cPeMcUJDlgg26g9HSn5LIoZRzz77/MlHLeWg7piHlZsTMWk bsdQ== X-Gm-Message-State: APjAAAWezY/Wfq+xLSb1Rv9bAf6jYc5TBNWUC4mPKxNa494zT4kkojqV 1DidfMA64CSvYgPQQdp4LBkp5XWd X-Google-Smtp-Source: APXvYqxXAX3ciKdJV0N9pyHBuBGjWdyRh6G5i6lBIQgXFtUYO2o7lrvkaoHXiC7Lqhf3c3aiiAezIQ== X-Received: by 2002:a17:906:4017:: with SMTP id v23mr24261291ejj.40.1553779861841; Thu, 28 Mar 2019 06:31:01 -0700 (PDT) Received: from [127.0.0.1] ([13.74.141.28]) by smtp.gmail.com with ESMTPSA id h15sm1196267edq.76.2019.03.28.06.30.59 (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Thu, 28 Mar 2019 06:31:00 -0700 (PDT) Date: Thu, 28 Mar 2019 06:31:00 -0700 (PDT) X-Google-Original-Date: Thu, 28 Mar 2019 13:30:49 GMT Message-Id: In-Reply-To: References: From: "Jeff Hostetler via GitGitGadget" Subject: [PATCH 2/4] trace2: add absolute elapsed time to start event Fcc: Sent MIME-Version: 1.0 To: git@vger.kernel.org Cc: gitster@pobox.com, peff@peff.net, jrnieder@gmail.com, steadmon@google.com, avarab@gmail.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 Add elapsed process time to "start" event to measure the performance of early process startup. Signed-off-by: Jeff Hostetler --- Documentation/technical/api-trace2.txt | 11 ++++++----- t/t0211-trace2-perf.sh | 12 ++++++------ trace2.c | 8 +++++++- trace2/tr2_tgt.h | 1 + trace2/tr2_tgt_event.c | 5 ++++- trace2/tr2_tgt_normal.c | 3 ++- trace2/tr2_tgt_perf.c | 7 ++++--- 7 files changed, 30 insertions(+), 17 deletions(-) diff --git a/Documentation/technical/api-trace2.txt b/Documentation/technical/api-trace2.txt index f37fccf1da..baaa1153bb 100644 --- a/Documentation/technical/api-trace2.txt +++ b/Documentation/technical/api-trace2.txt @@ -60,7 +60,7 @@ 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.621001 common-main.c:39 | d0 | main | start | | 0.001173 | | | git version 12:28:42.621111 git.c:432 | d0 | main | cmd_name | | | | | 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 @@ -79,7 +79,7 @@ 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":"start","sid":"1547659722619736-11614","thread":"main","time":"2019-01-16 17:28:42.621027","file":"common-main.c","line":39,"t_abs":0.001173,"argv":["git","version"]} {"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"} {"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} @@ -601,6 +601,7 @@ from all events and the `time` field is only present on the "start" and { "event":"start", ... + "t_abs":0.001227, # elapsed time in seconds "argv":["git","version"] } ------------ @@ -1118,7 +1119,7 @@ $ git status $ cat ~/log.perf d0 | main | version | | | | | 2.20.1.160.g5676107ecd.dirty -d0 | main | start | | | | | git status +d0 | main | start | | 0.001173 | | | git status d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw d0 | main | cmd_name | | | | | status (status) ... @@ -1163,7 +1164,7 @@ $ git status ... $ cat ~/log.perf d0 | main | version | | | | | 2.20.1.162.gb4ccea44db.dirty -d0 | main | start | | | | | git status +d0 | main | start | | 0.001173 | | | git status d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw d0 | main | cmd_name | | | | | status (status) ... @@ -1219,7 +1220,7 @@ $ git status ... $ cat ~/log.perf d0 | main | version | | | | | 2.20.1.156.gf9916ae094.dirty -d0 | main | start | | | | | git status +d0 | main | start | | 0.001173 | | | git status d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw d0 | main | cmd_name | | | | | status (status) d0 | main | region_enter | r1 | 0.001791 | | index | label:do_read_index .git/index diff --git a/t/t0211-trace2-perf.sh b/t/t0211-trace2-perf.sh index 953e2f7847..c9694b29f7 100755 --- a/t/t0211-trace2-perf.sh +++ b/t/t0211-trace2-perf.sh @@ -50,7 +50,7 @@ test_expect_success 'perf stream, return code 0' ' perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" actual && cat >expect <<-EOF && d0|main|version|||||$V - d0|main|start|||||_EXE_ trace2 001return 0 + d0|main|start||_T_ABS_|||_EXE_ trace2 001return 0 d0|main|cmd_name|||||trace2 (trace2) d0|main|exit||_T_ABS_|||code:0 d0|main|atexit||_T_ABS_|||code:0 @@ -64,7 +64,7 @@ test_expect_success 'perf stream, return code 1' ' perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" actual && cat >expect <<-EOF && d0|main|version|||||$V - d0|main|start|||||_EXE_ trace2 001return 1 + d0|main|start||_T_ABS_|||_EXE_ trace2 001return 1 d0|main|cmd_name|||||trace2 (trace2) d0|main|exit||_T_ABS_|||code:1 d0|main|atexit||_T_ABS_|||code:1 @@ -82,7 +82,7 @@ test_expect_success 'perf stream, error event' ' perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" actual && cat >expect <<-EOF && d0|main|version|||||$V - d0|main|start|||||_EXE_ trace2 003error '\''hello world'\'' '\''this is a test'\'' + d0|main|start||_T_ABS_|||_EXE_ trace2 003error '\''hello world'\'' '\''this is a test'\'' d0|main|cmd_name|||||trace2 (trace2) d0|main|error|||||hello world d0|main|error|||||this is a test @@ -128,15 +128,15 @@ test_expect_success 'perf stream, child processes' ' perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" actual && cat >expect <<-EOF && d0|main|version|||||$V - d0|main|start|||||_EXE_ trace2 004child test-tool trace2 004child test-tool trace2 001return 0 + d0|main|start||_T_ABS_|||_EXE_ trace2 004child test-tool trace2 004child test-tool trace2 001return 0 d0|main|cmd_name|||||trace2 (trace2) d0|main|child_start||_T_ABS_|||[ch0] class:? argv: test-tool trace2 004child test-tool trace2 001return 0 d1|main|version|||||$V - d1|main|start|||||_EXE_ trace2 004child test-tool trace2 001return 0 + d1|main|start||_T_ABS_|||_EXE_ trace2 004child test-tool trace2 001return 0 d1|main|cmd_name|||||trace2 (trace2/trace2) d1|main|child_start||_T_ABS_|||[ch0] class:? argv: test-tool trace2 001return 0 d2|main|version|||||$V - d2|main|start|||||_EXE_ trace2 001return 0 + d2|main|start||_T_ABS_|||_EXE_ trace2 001return 0 d2|main|cmd_name|||||trace2 (trace2/trace2/trace2) d2|main|exit||_T_ABS_|||code:0 d2|main|atexit||_T_ABS_|||code:0 diff --git a/trace2.c b/trace2.c index 6dd51e6aa5..1c180062dd 100644 --- a/trace2.c +++ b/trace2.c @@ -182,13 +182,19 @@ void trace2_cmd_start_fl(const char *file, int line, const char **argv) { struct tr2_tgt *tgt_j; int j; + uint64_t us_now; + uint64_t us_elapsed_absolute; if (!trace2_enabled) return; + us_now = getnanotime() / 1000; + us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); + for_each_wanted_builtin (j, tgt_j) if (tgt_j->pfn_start_fl) - tgt_j->pfn_start_fl(file, line, argv); + tgt_j->pfn_start_fl(file, line, us_elapsed_absolute, + argv); } int trace2_cmd_exit_fl(const char *file, int line, int code) diff --git a/trace2/tr2_tgt.h b/trace2/tr2_tgt.h index 297bb8ffbe..7b90469212 100644 --- a/trace2/tr2_tgt.h +++ b/trace2/tr2_tgt.h @@ -15,6 +15,7 @@ typedef void(tr2_tgt_term_t)(void); typedef void(tr2_tgt_evt_version_fl_t)(const char *file, int line); typedef void(tr2_tgt_evt_start_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, const char **argv); typedef void(tr2_tgt_evt_exit_fl_t)(const char *file, int line, uint64_t us_elapsed_absolute, int code); diff --git a/trace2/tr2_tgt_event.c b/trace2/tr2_tgt_event.c index 107cb5317d..89a4d3ae9a 100644 --- a/trace2/tr2_tgt_event.c +++ b/trace2/tr2_tgt_event.c @@ -122,13 +122,16 @@ static void fn_version_fl(const char *file, int line) jw_release(&jw); } -static void fn_start_fl(const char *file, int line, const char **argv) +static void fn_start_fl(const char *file, int line, + uint64_t us_elapsed_absolute, const char **argv) { const char *event_name = "start"; struct json_writer jw = JSON_WRITER_INIT; + double t_abs = (double)us_elapsed_absolute / 1000000.0; jw_object_begin(&jw, 0); event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_double(&jw, "t_abs", 6, t_abs); jw_object_inline_begin_array(&jw, "argv"); jw_array_argv(&jw, argv); jw_end(&jw); diff --git a/trace2/tr2_tgt_normal.c b/trace2/tr2_tgt_normal.c index 547183d5b6..57f3e18f5b 100644 --- a/trace2/tr2_tgt_normal.c +++ b/trace2/tr2_tgt_normal.c @@ -81,7 +81,8 @@ static void fn_version_fl(const char *file, int line) strbuf_release(&buf_payload); } -static void fn_start_fl(const char *file, int line, const char **argv) +static void fn_start_fl(const char *file, int line, + uint64_t us_elapsed_absolute, const char **argv) { struct strbuf buf_payload = STRBUF_INIT; diff --git a/trace2/tr2_tgt_perf.c b/trace2/tr2_tgt_perf.c index f0746fcf86..9c3b4d8a0f 100644 --- a/trace2/tr2_tgt_perf.c +++ b/trace2/tr2_tgt_perf.c @@ -159,15 +159,16 @@ static void fn_version_fl(const char *file, int line) strbuf_release(&buf_payload); } -static void fn_start_fl(const char *file, int line, const char **argv) +static void fn_start_fl(const char *file, int line, + uint64_t us_elapsed_absolute, const char **argv) { const char *event_name = "start"; struct strbuf buf_payload = STRBUF_INIT; sq_quote_argv_pretty(&buf_payload, argv); - perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL, - &buf_payload); + perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute, + NULL, NULL, &buf_payload); strbuf_release(&buf_payload); } From patchwork Thu Mar 28 13:31:02 2019 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Koji Nakamaru via GitGitGadget X-Patchwork-Id: 10874943 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 67C141669 for ; Thu, 28 Mar 2019 13:31:07 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 5311E28CD7 for ; Thu, 28 Mar 2019 13:31:07 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 4722428DD1; Thu, 28 Mar 2019 13:31:07 +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 EA5B528CD7 for ; Thu, 28 Mar 2019 13:31:06 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1727003AbfC1NbG (ORCPT ); Thu, 28 Mar 2019 09:31:06 -0400 Received: from mail-ed1-f68.google.com ([209.85.208.68]:39468 "EHLO mail-ed1-f68.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1726059AbfC1NbF (ORCPT ); Thu, 28 Mar 2019 09:31:05 -0400 Received: by mail-ed1-f68.google.com with SMTP id p20so16733162eds.6 for ; Thu, 28 Mar 2019 06:31:04 -0700 (PDT) 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=Vs307d+a1gx3jEA8oGCR7mKO5fqlVqvJOB3q3lxhDhc=; b=NkGBMhRVbyo5tOgIllQFTowsgNGxheFJ6nALgVG0LyoRt41x9LzBuBW2p/msqnBP4T HEVjIWmb8HlVjX/3/jlMOjI5IzcIM3tCcWDTQ2M31fKbVgjMYNHbcM4Vry3EoKt435n2 1JBzux1zUiVc251VqxJD41mCsj/Mw45E19FC8fhsJV1msKIozM0scN5qMdbxUawSKPOL sgLHp5oSwj8EgPZsNs5CtjBAZtKvUCaBL5JH0t7rg+tnIM7yCIB92ggIqNLXgwEt39xF wyzG0XbK/va+LPi96K4Lm78xszL0IKd/ORS7HtH7PM/Zt6gwPTXG13OJ84Po7ghRpeOG ZXww== 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=Vs307d+a1gx3jEA8oGCR7mKO5fqlVqvJOB3q3lxhDhc=; b=Jk50mPfdjMjCnVz1Mlq13FI24up/AP/OXqmi5E4lWzwl5laeAukZaHgr9vilTh22ge CtBJeTSxT9mYwYs9xyRKBF0tanuFUgEGf0ZqRwm9MQmh7XZQ+hDWS5YMjsxScXJKoQzq fSBQobgGJIOl3yu5C5Bqr6MVLRgsH/TlugjJ+U8jTyHYGb0bDaIcdY0Iwf42XQGJ5jco zbfQkzwzw2Ml0jHA1AJpYMeeoj9yhYXM0RI1cRHdHI7naJre/lId0wQkW43IX8w1IilD xBhUfPA7LVyGojZPRQNBeQgxPrGK7JztV1xiZprfbpUBIHZ5KrEpPY769yA0bR9xs10B t5Fw== X-Gm-Message-State: APjAAAU0VnTgXtagyooeGp2wFwI5qrX+0LW1KtKa3lIWjEgrW/VTdN53 Q4LASue/zzUlziNRJyBE49s/4Axs X-Google-Smtp-Source: APXvYqxciyOK651xcnk7bZR9Z8EmoN/SCymzp4XQFlBXw+DoGRQ/XM6iw6ATA5sYo4+WfZUmvxBtBw== X-Received: by 2002:a50:d591:: with SMTP id v17mr20339212edi.180.1553779863767; Thu, 28 Mar 2019 06:31:03 -0700 (PDT) Received: from [127.0.0.1] ([13.74.141.28]) by smtp.gmail.com with ESMTPSA id z35sm6805502edd.81.2019.03.28.06.31.01 (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Thu, 28 Mar 2019 06:31:02 -0700 (PDT) Date: Thu, 28 Mar 2019 06:31:02 -0700 (PDT) X-Google-Original-Date: Thu, 28 Mar 2019 13:30:50 GMT Message-Id: In-Reply-To: References: From: "Jeff Hostetler via GitGitGadget" Subject: [PATCH 3/4] trace2: find exec-dir before trace2 initialization Fcc: Sent MIME-Version: 1.0 To: git@vger.kernel.org Cc: gitster@pobox.com, peff@peff.net, jrnieder@gmail.com, steadmon@google.com, avarab@gmail.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 Teach Git to resolve the executable directory before initializing Trace2. This allows the system configuration directory to be discovered earlier (because it is sometimes relative to the prefix or runtime-prefix). This will be used by the next commit to allow trace2 settings to be loaded from the system config. Signed-off-by: Jeff Hostetler --- common-main.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/common-main.c b/common-main.c index 6137af0e63..299ca62a72 100644 --- a/common-main.c +++ b/common-main.c @@ -37,12 +37,12 @@ int main(int argc, const char **argv) sanitize_stdfds(); restore_sigpipe_to_default(); + git_resolve_executable_dir(argv[0]); + trace2_initialize(); trace2_cmd_start(argv); trace2_collect_process_info(); - git_resolve_executable_dir(argv[0]); - git_setup_gettext(); initialize_the_repository(); From patchwork Thu Mar 28 13:31:04 2019 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Koji Nakamaru via GitGitGadget X-Patchwork-Id: 10874947 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 248171669 for ; Thu, 28 Mar 2019 13:31:17 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 065CC28CC4 for ; Thu, 28 Mar 2019 13:31:17 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id EE73428CD7; Thu, 28 Mar 2019 13:31:16 +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 EAE9428DB8 for ; Thu, 28 Mar 2019 13:31:10 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1726407AbfC1NbK (ORCPT ); Thu, 28 Mar 2019 09:31:10 -0400 Received: from mail-ed1-f66.google.com ([209.85.208.66]:41136 "EHLO mail-ed1-f66.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1726059AbfC1NbJ (ORCPT ); Thu, 28 Mar 2019 09:31:09 -0400 Received: by mail-ed1-f66.google.com with SMTP id a25so17219942edc.8 for ; Thu, 28 Mar 2019 06:31:06 -0700 (PDT) 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=ZiXBtuFWKl1XVWq1iK1wO5AD52eXkLFZSWBZ1PYQEW4=; b=kpo38rGqjFKsRhVQuMEWBoL+nYMaQAhkFX9RqvlHdCCxeJ48u21aXwRBi2WKPKRlDT 1HcTAtRZJd8ZzwUcs/jRRGtH+qTMeuZemdZJD7d+JyVvkW1qL2QbHJDrp1axt7Wx0XVS slQBaC3p6acmecVcaKQCBpiuxFGyI7OsA7BdTR/1i3m8sk/3vGucECw/QAPkELKrMDyC o1z98eusdNojxrQsWovNIVsuvYRa5hihw7UuwPXfIcpMnqCA6Zq/ZTuPH+B7o/pZ4Kk2 K+kMjevhrjV97VcJUhtFNYK0R19iIaHPLayplqxrpU6xiLF/TdioL3A9bsqx71J2zAis sS8Q== 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=ZiXBtuFWKl1XVWq1iK1wO5AD52eXkLFZSWBZ1PYQEW4=; b=SVECxqvVHZN1jGWTLh9Xqi/UgAQGhjOhnSG7Ql14Fjj3vdwLoHaoy4P233kem+ctXV nw56jYWCn+tcaWHmV/4RReOvl7dd+oC/AG6lHTHCbvK3uyCyYJZ8YAQuvsxCBp+CSvKQ 5abDy/K93J1nTJfHOFHCldGx/Rk/aL0BtXE9kchpwd+yoUHsEguXpXdkbe4yI18MpYZl NZI0JHRpVeQTRi8P+K6gQGAXiZRf1tAT0IRaBkKt2aS6W3bMK0o/q3FJFj9/ucQvoGVi dOqezgSZyFq5M/dW6iuEBO/z4crKjcdHGFfmndq1hoSBIRmPwsq8Y4vlFzq90zCPP2Zv bqUg== X-Gm-Message-State: APjAAAXT5XifoHFyyLHEyZmUVVcw2UVl0t648LdmX4fY/dnZ2g8k2/kt 0Rv8XiWpYRdTG9/CUWbr/2zhFBPl X-Google-Smtp-Source: APXvYqwQ6UWpE1WME9imU6pXZ+ZKso/Yl9+6Wg8/SggSoOszrPvB/iOoEwUI6CLfNI85hUcdYnwNUA== X-Received: by 2002:a50:9956:: with SMTP id l22mr28310778edb.170.1553779864795; Thu, 28 Mar 2019 06:31:04 -0700 (PDT) Received: from [127.0.0.1] ([13.74.141.28]) by smtp.gmail.com with ESMTPSA id b2sm7002487eda.36.2019.03.28.06.31.03 (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Thu, 28 Mar 2019 06:31:04 -0700 (PDT) Date: Thu, 28 Mar 2019 06:31:04 -0700 (PDT) X-Google-Original-Date: Thu, 28 Mar 2019 13:30:51 GMT Message-Id: <7e0d4e20fbb3abbc787bc216d2c4bd8c18860aed.1553779851.git.gitgitgadget@gmail.com> In-Reply-To: References: From: "Jeff Hostetler via GitGitGadget" Subject: [PATCH 4/4] trace2: use system config for default trace2 settings Fcc: Sent MIME-Version: 1.0 To: git@vger.kernel.org Cc: gitster@pobox.com, peff@peff.net, jrnieder@gmail.com, steadmon@google.com, avarab@gmail.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 Teach git to read the system config (usually "/etc/gitconfig") for default Trace2 settings. This allows system-wide Trace2 settings to be installed and inherited to make it easier to manage a collection of systems. The original GIT_TR2* environment variables are loaded afterwards and can be used to override the system settings. Only the system config file is used. Trace2 config values are ignored in local, global, and other config files. Likewise, the "-c" command line arguments are ignored for Trace2 values. These limits are for performance reasons. (1) For users not using Trace2, there should be minimal overhead to detect that Trace2 is not enabled. In particular, Trace2 should not allocate lots of otherwise unused data strucutres. (2) For accurate performance measurements, Trace2 should be initialized as early in the git process as possible, and before most of the normal git process initialization (which involves discovering the .git directory and reading a hierarchy of config files). Added the GIT_TEST_TR2_SYSTEM_CONFIG environment variable for testing purposes to specify the pathname of a fake "system" config or disable use of the system config. Signed-off-by: Jeff Hostetler --- Documentation/technical/api-trace2.txt | 31 ++++++ Makefile | 1 + t/t0210-trace2-normal.sh | 41 +++++++- t/t0211-trace2-perf.sh | 41 +++++++- t/t0212-trace2-event.sh | 52 +++++++++- trace2.c | 4 + trace2.h | 7 +- trace2/tr2_cfg.c | 7 +- trace2/tr2_dst.c | 24 ++--- trace2/tr2_dst.h | 3 +- trace2/tr2_sysenv.c | 125 +++++++++++++++++++++++++ trace2/tr2_sysenv.h | 36 +++++++ trace2/tr2_tgt_event.c | 19 ++-- trace2/tr2_tgt_normal.c | 10 +- trace2/tr2_tgt_perf.c | 10 +- 15 files changed, 356 insertions(+), 55 deletions(-) create mode 100644 trace2/tr2_sysenv.c create mode 100644 trace2/tr2_sysenv.h diff --git a/Documentation/technical/api-trace2.txt b/Documentation/technical/api-trace2.txt index baaa1153bb..13ca595c69 100644 --- a/Documentation/technical/api-trace2.txt +++ b/Documentation/technical/api-trace2.txt @@ -117,6 +117,37 @@ values are recognized. Socket type can be either `stream` or `dgram`. If the socket type is omitted, Git will try both. +== Trace2 Settings in System Config + +Trace2 also reads configuration information from the system config. +This is intended to help adminstrators to gather system-wide Git +performance data. + +Trace2 only reads the system configuration, it does not read global, +local, worktree, or `-c` config settings. + +Trace2 will try to load the following system configuration settings +and then read the corresponding environment variables at startup. + +.... +--------------------------------------------------- +trace2.normalTarget GIT_TR2 +trace2.normalBrief GIT_TR2_BRIEF + +trace2.perfTarget GIT_TR2_PERF +trace2.perfBrief GIT_TR2_PERF_BRIEF + +trace2.eventTarget GIT_TR2_EVENT +trace2.eventBrief GIT_TR2_EVENT_BRIEF +trace2.eventNesting GIT_TR2_EVENT_NESTING + +trace2.configParams GIT_TR2_CONFIG_PARAMS + +trace2.destinationDebug GIT_TR2_DST_DEBUG +--------------------------------------------------- +.... + + == Trace2 API All public Trace2 functions and macros are defined in `trace2.h` and diff --git a/Makefile b/Makefile index 3e03290d8f..9ddfa3dfe7 100644 --- a/Makefile +++ b/Makefile @@ -1005,6 +1005,7 @@ LIB_OBJS += trace2/tr2_cfg.o LIB_OBJS += trace2/tr2_cmd_name.o LIB_OBJS += trace2/tr2_dst.o LIB_OBJS += trace2/tr2_sid.o +LIB_OBJS += trace2/tr2_sysenv.o LIB_OBJS += trace2/tr2_tbuf.o LIB_OBJS += trace2/tr2_tgt_event.o LIB_OBJS += trace2/tr2_tgt_normal.o diff --git a/t/t0210-trace2-normal.sh b/t/t0210-trace2-normal.sh index 03a0aedb1d..5d4c04ed30 100755 --- a/t/t0210-trace2-normal.sh +++ b/t/t0210-trace2-normal.sh @@ -1,5 +1,14 @@ #!/bin/sh +# Disable loading of Trace2 settings from the system config +# (usually "/etc/gitconfig") to eliminate system dependencies. +GIT_TEST_TR2_SYSTEM_CONFIG=0 && export GIT_TEST_TR2_SYSTEM_CONFIG + +# Turn off any inherited trace2 settings for this test. +unset GIT_TR2 GIT_TR2_PERF GIT_TR2_EVENT +unset GIT_TR2_BRIEF +unset GIT_TR2_CONFIG_PARAMS + test_description='test trace2 facility (normal target)' . ./test-lib.sh @@ -15,11 +24,6 @@ PATH="$TTDIR:$PATH" && export PATH # Warning: So you may see extra lines in artifact files when # Warning: interactively debugging. -# Turn off any inherited trace2 settings for this test. -unset GIT_TR2 GIT_TR2_PERF GIT_TR2_EVENT -unset GIT_TR2_BRIEF -unset GIT_TR2_CONFIG_PARAMS - V=$(git version | sed -e 's/^git version //') && export V # There are multiple trace2 targets: normal, perf, and event. @@ -132,4 +136,31 @@ test_expect_success 'normal stream, error event' ' test_cmp expect actual ' +# Now test using system config by using a mocked up config file +# rather than inheriting "/etc/gitconfig". Here we do not use +# GIT_TR2* environment variables. + +unset GIT_TR2_BRIEF + +MOCK=./mock_system_config + +test_expect_success 'setup mocked /etc/gitconfig' ' + git config --file $MOCK trace2.normalTarget "$(pwd)/trace.normal" && + git config --file $MOCK trace2.normalBrief 1 +' + +test_expect_success 'using mock, normal stream, return code 0' ' + test_when_finished "rm trace.normal actual expect" && + GIT_TEST_TR2_SYSTEM_CONFIG="$MOCK" test-tool trace2 001return 0 && + perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" actual && + cat >expect <<-EOF && + version $V + start _EXE_ trace2 001return 0 + cmd_name trace2 (trace2) + exit elapsed:_TIME_ code:0 + atexit elapsed:_TIME_ code:0 + EOF + test_cmp expect actual +' + test_done diff --git a/t/t0211-trace2-perf.sh b/t/t0211-trace2-perf.sh index c9694b29f7..abe35b2186 100755 --- a/t/t0211-trace2-perf.sh +++ b/t/t0211-trace2-perf.sh @@ -1,5 +1,14 @@ #!/bin/sh +# Disable loading of Trace2 settings from the system config +# (usually "/etc/gitconfig") to eliminate system dependencies. +GIT_TEST_TR2_SYSTEM_CONFIG=0 && export GIT_TEST_TR2_SYSTEM_CONFIG + +# Turn off any inherited trace2 settings for this test. +unset GIT_TR2 GIT_TR2_PERF GIT_TR2_EVENT +unset GIT_TR2_PERF_BRIEF +unset GIT_TR2_CONFIG_PARAMS + test_description='test trace2 facility (perf target)' . ./test-lib.sh @@ -15,11 +24,6 @@ PATH="$TTDIR:$PATH" && export PATH # Warning: So you may see extra lines in artifact files when # Warning: interactively debugging. -# Turn off any inherited trace2 settings for this test. -unset GIT_TR2 GIT_TR2_PERF GIT_TR2_EVENT -unset GIT_TR2_PERF_BRIEF -unset GIT_TR2_CONFIG_PARAMS - V=$(git version | sed -e 's/^git version //') && export V # There are multiple trace2 targets: normal, perf, and event. @@ -150,4 +154,31 @@ test_expect_success 'perf stream, child processes' ' test_cmp expect actual ' +# Now test using system config by using a mocked up config file +# rather than inheriting "/etc/gitconfig". Here we do not use +# GIT_TR2* environment variables. + +unset GIT_TR2_PERF_BRIEF + +MOCK=./mock_system_config + +test_expect_success 'setup mocked /etc/gitconfig' ' + git config --file $MOCK trace2.perfTarget "$(pwd)/trace.perf" && + git config --file $MOCK trace2.perfBrief 1 +' + +test_expect_success 'using mock, perf stream, return code 0' ' + test_when_finished "rm trace.perf actual expect" && + GIT_TEST_TR2_SYSTEM_CONFIG="$MOCK" test-tool trace2 001return 0 && + perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" actual && + cat >expect <<-EOF && + d0|main|version|||||$V + d0|main|start||_T_ABS_|||_EXE_ trace2 001return 0 + d0|main|cmd_name|||||trace2 (trace2) + d0|main|exit||_T_ABS_|||code:0 + d0|main|atexit||_T_ABS_|||code:0 + EOF + test_cmp expect actual +' + test_done diff --git a/t/t0212-trace2-event.sh b/t/t0212-trace2-event.sh index 028b6c5671..c535496261 100755 --- a/t/t0212-trace2-event.sh +++ b/t/t0212-trace2-event.sh @@ -1,5 +1,14 @@ #!/bin/sh +# Disable loading of Trace2 settings from the system config +# (usually "/etc/gitconfig") to eliminate system dependencies. +GIT_TEST_TR2_SYSTEM_CONFIG=0 && export GIT_TEST_TR2_SYSTEM_CONFIG + +# Turn off any inherited trace2 settings for this test. +unset GIT_TR2 GIT_TR2_PERF GIT_TR2_EVENT +unset GIT_TR2_BARE +unset GIT_TR2_CONFIG_PARAMS + test_description='test trace2 facility' . ./test-lib.sh @@ -17,11 +26,6 @@ PATH="$TTDIR:$PATH" && export PATH # Warning: So you may see extra lines in artifact files when # Warning: interactively debugging. -# Turn off any inherited trace2 settings for this test. -unset GIT_TR2 GIT_TR2_PERF GIT_TR2_EVENT -unset GIT_TR2_BARE -unset GIT_TR2_CONFIG_PARAMS - V=$(git version | sed -e 's/^git version //') && export V # There are multiple trace2 targets: normal, perf, and event. @@ -233,4 +237,42 @@ test_expect_success JSON_PP 'basic trace2_data' ' test_cmp expect actual ' +# Now test using system config by using a mocked up config file +# rather than inheriting "/etc/gitconfig". Here we do not use +# GIT_TR2* environment variables. + +MOCK=./mock_system_config + +test_expect_success 'setup mocked /etc/gitconfig' ' + git config --file $MOCK trace2.eventTarget "$(pwd)/trace.event" +' + +test_expect_success JSON_PP 'using mock, event stream, error event' ' + test_when_finished "rm trace.event actual expect" && + GIT_TEST_TR2_SYSTEM_CONFIG="$MOCK" test-tool trace2 003error "hello world" "this is a test" && + perl "$TEST_DIRECTORY/t0212/parse_events.perl" actual && + sed -e "s/^|//" >expect <<-EOF && + |VAR1 = { + | "_SID0_":{ + | "argv":[ + | "_EXE_", + | "trace2", + | "003error", + | "hello world", + | "this is a test" + | ], + | "errors":[ + | "%s", + | "%s" + | ], + | "exit_code":0, + | "hierarchy":"trace2", + | "name":"trace2", + | "version":"$V" + | } + |}; + EOF + test_cmp expect actual +' + test_done diff --git a/trace2.c b/trace2.c index 1c180062dd..490b3f071e 100644 --- a/trace2.c +++ b/trace2.c @@ -10,6 +10,7 @@ #include "trace2/tr2_cmd_name.h" #include "trace2/tr2_dst.h" #include "trace2/tr2_sid.h" +#include "trace2/tr2_sysenv.h" #include "trace2/tr2_tgt.h" #include "trace2/tr2_tls.h" @@ -120,6 +121,7 @@ static void tr2main_atexit_handler(void) tr2_sid_release(); tr2_cmd_name_release(); tr2_cfg_free_patterns(); + tr2_sysenv_release(); trace2_enabled = 0; } @@ -155,6 +157,8 @@ void trace2_initialize_fl(const char *file, int line) if (trace2_enabled) return; + tr2_sysenv_load(); + if (!tr2_tgt_want_builtins()) return; trace2_enabled = 1; diff --git a/trace2.h b/trace2.h index 8f89e70c44..cda8349058 100644 --- a/trace2.h +++ b/trace2.h @@ -38,7 +38,8 @@ void trace2_initialize_clock(void); /* * Initialize TRACE2 tracing facility if any of the builtin TRACE2 - * targets are enabled in the environment. Emits a 'version' event. + * targets are enabled in the system config or the environment. + * Emits a 'version' event. * * Cleanup/Termination is handled automatically by a registered * atexit() routine. @@ -125,8 +126,8 @@ void trace2_cmd_alias_fl(const char *file, int line, const char *alias, * Emit one or more 'def_param' events for "interesting" configuration * settings. * - * The environment variable "GIT_TR2_CONFIG_PARAMS" can be set to a - * list of patterns considered important. For example: + * Use the TR2_SYSENV_CFG_PARAM setting to register a list of patterns + * configured important. For example: * * GIT_TR2_CONFIG_PARAMS="core.*,remote.*.url" * diff --git a/trace2/tr2_cfg.c b/trace2/tr2_cfg.c index b329921ac5..caa7f06948 100644 --- a/trace2/tr2_cfg.c +++ b/trace2/tr2_cfg.c @@ -1,8 +1,7 @@ #include "cache.h" #include "config.h" -#include "tr2_cfg.h" - -#define TR2_ENVVAR_CFG_PARAM "GIT_TR2_CONFIG_PARAMS" +#include "trace2/tr2_cfg.h" +#include "trace2/tr2_sysenv.h" static struct strbuf **tr2_cfg_patterns; static int tr2_cfg_count_patterns; @@ -21,7 +20,7 @@ static int tr2_cfg_load_patterns(void) return tr2_cfg_count_patterns; tr2_cfg_loaded = 1; - envvar = getenv(TR2_ENVVAR_CFG_PARAM); + envvar = tr2_sysenv_get(TR2_SYSENV_CFG_PARAM); if (!envvar || !*envvar) return tr2_cfg_count_patterns; diff --git a/trace2/tr2_dst.c b/trace2/tr2_dst.c index fd490a43ad..575cd69aa9 100644 --- a/trace2/tr2_dst.c +++ b/trace2/tr2_dst.c @@ -1,5 +1,6 @@ #include "cache.h" #include "trace2/tr2_dst.h" +#include "trace2/tr2_sysenv.h" /* * If a Trace2 target cannot be opened for writing, we should issue a @@ -7,17 +8,13 @@ * or socket and beyond the user's control -- especially since every * git command (and sub-command) will print the message. So we silently * eat these warnings and just discard the trace data. - * - * Enable the following environment variable to see these warnings. */ -#define TR2_ENVVAR_DST_DEBUG "GIT_TR2_DST_DEBUG" - static int tr2_dst_want_warning(void) { static int tr2env_dst_debug = -1; if (tr2env_dst_debug == -1) { - const char *env_value = getenv(TR2_ENVVAR_DST_DEBUG); + const char *env_value = tr2_sysenv_get(TR2_SYSENV_DST_DEBUG); if (!env_value || !*env_value) tr2env_dst_debug = 0; else @@ -42,7 +39,9 @@ static int tr2_dst_try_path(struct tr2_dst *dst, const char *tgt_value) if (fd == -1) { if (tr2_dst_want_warning()) warning("trace2: could not open '%s' for '%s' tracing: %s", - tgt_value, dst->env_var_name, strerror(errno)); + tgt_value, + tr2_sysenv_display_name(dst->sysenv_var), + strerror(errno)); tr2_dst_trace_disable(dst); return 0; @@ -116,7 +115,7 @@ static int tr2_dst_try_unix_domain_socket(struct tr2_dst *dst, if (!path || !*path) { if (tr2_dst_want_warning()) warning("trace2: invalid AF_UNIX value '%s' for '%s' tracing", - tgt_value, dst->env_var_name); + tgt_value, tr2_sysenv_display_name(dst->sysenv_var)); tr2_dst_trace_disable(dst); return 0; @@ -126,7 +125,7 @@ static int tr2_dst_try_unix_domain_socket(struct tr2_dst *dst, strlen(path) >= sizeof(((struct sockaddr_un *)0)->sun_path)) { if (tr2_dst_want_warning()) warning("trace2: invalid AF_UNIX path '%s' for '%s' tracing", - path, dst->env_var_name); + path, tr2_sysenv_display_name(dst->sysenv_var)); tr2_dst_trace_disable(dst); return 0; @@ -148,7 +147,7 @@ static int tr2_dst_try_unix_domain_socket(struct tr2_dst *dst, error: if (tr2_dst_want_warning()) warning("trace2: could not connect to socket '%s' for '%s' tracing: %s", - path, dst->env_var_name, strerror(e)); + path, tr2_sysenv_display_name(dst->sysenv_var), strerror(e)); tr2_dst_trace_disable(dst); return 0; @@ -168,7 +167,7 @@ static void tr2_dst_malformed_warning(struct tr2_dst *dst, struct strbuf buf = STRBUF_INIT; strbuf_addf(&buf, "trace2: unknown value for '%s': '%s'", - dst->env_var_name, tgt_value); + tr2_sysenv_display_name(dst->sysenv_var), tgt_value); warning("%s", buf.buf); strbuf_release(&buf); @@ -184,7 +183,7 @@ int tr2_dst_get_trace_fd(struct tr2_dst *dst) dst->initialized = 1; - tgt_value = getenv(dst->env_var_name); + tgt_value = tr2_sysenv_get(dst->sysenv_var); if (!tgt_value || !strcmp(tgt_value, "") || !strcmp(tgt_value, "0") || !strcasecmp(tgt_value, "false")) { @@ -246,7 +245,8 @@ void tr2_dst_write_line(struct tr2_dst *dst, struct strbuf *buf_line) return; if (tr2_dst_want_warning()) - warning("unable to write trace to '%s': %s", dst->env_var_name, + warning("unable to write trace to '%s': %s", + tr2_sysenv_display_name(dst->sysenv_var), strerror(errno)); tr2_dst_trace_disable(dst); } diff --git a/trace2/tr2_dst.h b/trace2/tr2_dst.h index 9a64f05b02..3adf3bac13 100644 --- a/trace2/tr2_dst.h +++ b/trace2/tr2_dst.h @@ -2,9 +2,10 @@ #define TR2_DST_H struct strbuf; +#include "trace2/tr2_sysenv.h" struct tr2_dst { - const char *const env_var_name; + enum tr2_sysenv_variable sysenv_var; int fd; unsigned int initialized : 1; unsigned int need_close : 1; diff --git a/trace2/tr2_sysenv.c b/trace2/tr2_sysenv.c new file mode 100644 index 0000000000..656613e371 --- /dev/null +++ b/trace2/tr2_sysenv.c @@ -0,0 +1,125 @@ +#include "cache.h" +#include "config.h" +#include "dir.h" +#include "tr2_sysenv.h" + +/* + * Each entry represents a trace2 setting. + * See Documentation/technical/api-trace2.txt + */ +struct tr2_sysenv_entry { + const char *env_var_name; + const char *git_config_name; + + char *value; + unsigned int getenv_called : 1; +}; + +/* + * This table must match "enum tr2_sysenv_variable" in tr2_sysenv.h. + * These strings are constant and must match the published names as + * described in the documentation. + * + * We do not define entries for the GIT_TR2_PARENT_* environment + * variables because they are transient and used to pass information + * from parent to child git processes, rather than settings. + */ +/* clang-format off */ +static struct tr2_sysenv_entry tr2_sysenv_settings[] = { + { "GIT_TR2_CONFIG_PARAMS", "trace2.configparams" }, + + { "GIT_TR2_DST_DEBUG", "trace2.destinationdebug" }, + + { "GIT_TR2", "trace2.normaltarget" }, + { "GIT_TR2_BRIEF", "trace2.normalbrief" }, + + { "GIT_TR2_EVENT", "trace2.eventtarget" }, + { "GIT_TR2_EVENT_BRIEF", "trace2.eventbrief" }, + { "GIT_TR2_EVENT_NESTING", "trace2.eventnesting" }, + + { "GIT_TR2_PERF", "trace2.perftarget" }, + { "GIT_TR2_PERF_BRIEF", "trace2.perfbrief" }, +}; +/* clang-format on */ + +static int tr2_sysenv_cb(const char *key, const char *value, void *d) +{ + int k; + + for (k = 0; k < ARRAY_SIZE(tr2_sysenv_settings); k++) { + if (!strcmp(key, tr2_sysenv_settings[k].git_config_name)) { + free(tr2_sysenv_settings[k].value); + tr2_sysenv_settings[k].value = xstrdup(value); + return 0; + } + } + + return 0; +} + +/* + * Load Trace2 settings from the system config (usually "/etc/gitconfig" + * unless we were built with a runtime-prefix). These are intended to + * define the default values for Trace2 as requested by the administrator. + */ +void tr2_sysenv_load(void) +{ + const char *system_config_pathname; + const char *test_pathname; + + system_config_pathname = git_etc_gitconfig(); + + test_pathname = getenv("GIT_TEST_TR2_SYSTEM_CONFIG"); + if (test_pathname) { + if (!*test_pathname || !strcmp(test_pathname, "0")) + return; /* disable use of system config */ + + /* mock it with given test file */ + system_config_pathname = test_pathname; + } + + if (file_exists(system_config_pathname)) + git_config_from_file(tr2_sysenv_cb, system_config_pathname, + NULL); +} + +/* + * Return the value for the requested setting. Start with the /etc/gitconfig + * value and allow the corresponding environment variable to override it. + */ +const char *tr2_sysenv_get(enum tr2_sysenv_variable var) +{ + if (var >= TR2_SYSENV_MUST_BE_LAST) + BUG("tr2_sysenv_get invalid var '%d'", var); + + if (!tr2_sysenv_settings[var].getenv_called) { + const char *v = getenv(tr2_sysenv_settings[var].env_var_name); + if (v && *v) { + free(tr2_sysenv_settings[var].value); + tr2_sysenv_settings[var].value = xstrdup(v); + } + tr2_sysenv_settings[var].getenv_called = 1; + } + + return tr2_sysenv_settings[var].value; +} + +/* + * Return a friendly name for this setting that is suitable for printing + * in an error messages. + */ +const char *tr2_sysenv_display_name(enum tr2_sysenv_variable var) +{ + if (var >= TR2_SYSENV_MUST_BE_LAST) + BUG("tr2_sysenv_get invalid var '%d'", var); + + return tr2_sysenv_settings[var].env_var_name; +} + +void tr2_sysenv_release(void) +{ + int k; + + for (k = 0; k < ARRAY_SIZE(tr2_sysenv_settings); k++) + free(tr2_sysenv_settings[k].value); +} diff --git a/trace2/tr2_sysenv.h b/trace2/tr2_sysenv.h new file mode 100644 index 0000000000..369b20bd87 --- /dev/null +++ b/trace2/tr2_sysenv.h @@ -0,0 +1,36 @@ +#ifndef TR2_SYSENV_H +#define TR2_SYSENV_H + +/* + * The Trace2 settings that can be loaded from /etc/gitconfig + * and/or user environment variables. + * + * Note that this set does not contain any of the transient + * environment variables used to pass information from parent + * to child git processes, such "GIT_TR2_PARENT_SID". + */ +enum tr2_sysenv_variable { + TR2_SYSENV_CFG_PARAM = 0, + + TR2_SYSENV_DST_DEBUG, + + TR2_SYSENV_NORMAL, + TR2_SYSENV_NORMAL_BRIEF, + + TR2_SYSENV_EVENT, + TR2_SYSENV_EVENT_BRIEF, + TR2_SYSENV_EVENT_NESTING, + + TR2_SYSENV_PERF, + TR2_SYSENV_PERF_BRIEF, + + TR2_SYSENV_MUST_BE_LAST +}; + +void tr2_sysenv_load(void); + +const char *tr2_sysenv_get(enum tr2_sysenv_variable); +const char *tr2_sysenv_display_name(enum tr2_sysenv_variable var); +void tr2_sysenv_release(void); + +#endif /* TR2_SYSENV_H */ diff --git a/trace2/tr2_tgt_event.c b/trace2/tr2_tgt_event.c index 89a4d3ae9a..bb6e323953 100644 --- a/trace2/tr2_tgt_event.c +++ b/trace2/tr2_tgt_event.c @@ -6,10 +6,11 @@ #include "trace2/tr2_dst.h" #include "trace2/tr2_tbuf.h" #include "trace2/tr2_sid.h" +#include "trace2/tr2_sysenv.h" #include "trace2/tr2_tgt.h" #include "trace2/tr2_tls.h" -static struct tr2_dst tr2dst_event = { "GIT_TR2_EVENT", 0, 0, 0 }; +static struct tr2_dst tr2dst_event = { TR2_SYSENV_EVENT, 0, 0, 0 }; /* * The version number of the JSON data generated by the EVENT target @@ -28,17 +29,15 @@ static struct tr2_dst tr2dst_event = { "GIT_TR2_EVENT", 0, 0, 0 }; * are primarily intended for the performance target during debugging. * * Some of the outer-most messages, however, may be of interest to the - * event target. Set this environment variable to a larger integer for - * more detail in the event target. + * event target. Use the TR2_SYSENV_EVENT_NESTING setting to increase + * region details in the event target. */ -#define TR2_ENVVAR_EVENT_NESTING "GIT_TR2_EVENT_NESTING" static int tr2env_event_nesting_wanted = 2; /* - * Set this environment variable to true to omit the