Merge branch 'jh/trace2-sid-fix'

Polishing of the new trace2 facility continues.  The system-level
configuration can specify site-wide trace2 settings, which can be
overridden with per-user configuration and environment variables.

* jh/trace2-sid-fix:
  trace2: fixup access problem on /etc/gitconfig in read_very_early_config
  trace2: update docs to describe system/global config settings
  trace2: make SIDs more unique
  trace2: clarify UTC datetime formatting
  trace2: report peak memory usage of the process
  trace2: use system/global config for default trace2 settings
  config: add read_very_early_config()
  trace2: find exec-dir before trace2 initialization
  trace2: add absolute elapsed time to start event
  trace2: refactor setting process starting time
  config: initialize opts structure in repo_read_config()
This commit is contained in:
Junio C Hamano 2019-05-13 23:50:31 +09:00
commit 5b2d1c0c6e
29 changed files with 759 additions and 217 deletions

View File

@ -422,6 +422,8 @@ include::config/submodule.txt[]
include::config/tag.txt[]
include::config/trace2.txt[]
include::config/transfer.txt[]
include::config/uploadarchive.txt[]

View File

@ -0,0 +1,56 @@
Trace2 config settings are only read from the system and global
config files; repository local and worktree config files and `-c`
command line arguments are not respected.
trace2.normalTarget::
This variable controls the normal target destination.
It may be overridden by the `GIT_TR2` environment variable.
The following table shows possible values.
trace2.perfTarget::
This variable controls the performance target destination.
It may be overridden by the `GIT_TR2_PERF` environment variable.
The following table shows possible values.
trace2.eventTarget::
This variable controls the event target destination.
It may be overridden by the `GIT_TR2_EVENT` environment variable.
The following table shows possible values.
+
include::../trace2-target-values.txt[]
trace2.normalBrief::
Boolean. When true `time`, `filename`, and `line` fields are
omitted from normal output. May be overridden by the
`GIT_TR2_BRIEF` environment variable. Defaults to false.
trace2.perfBrief::
Boolean. When true `time`, `filename`, and `line` fields are
omitted from PERF output. May be overridden by the
`GIT_TR2_PERF_BRIEF` environment variable. Defaults to false.
trace2.eventBrief::
Boolean. When true `time`, `filename`, and `line` fields are
omitted from event output. May be overridden by the
`GIT_TR2_EVENT_BRIEF` environment variable. Defaults to false.
trace2.eventNesting::
Integer. Specifies desired depth of nested regions in the
event output. Regions deeper than this value will be
omitted. May be overridden by the `GIT_TR2_EVENT_NESTING`
environment variable. Defaults to 2.
trace2.configParams::
A comma-separated list of patterns of "important" config
settings that should be recorded in the trace2 output.
For example, `core.*,remote.*.url` would cause the trace2
output to contain events listing each configured remote.
May be overridden by the `GIT_TR2_CONFIG_PARAMS` environment
variable. Unset by default.
trace2.destinationDebug::
Boolean. When true Git will print error messages when a
trace target destination cannot be opened for writing.
By default, these errors are suppressed and tracing is
silently disabled. May be overridden by the
`GIT_TR2_DST_DEBUG` environment variable.

View File

@ -22,21 +22,41 @@ Targets are defined using a VTable allowing easy extension to other
formats in the future. This might be used to define a binary format,
for example.
Trace2 is controlled using `trace2.*` config values in the system and
global config files and `GIT_TR2*` environment variables. Trace2 does
not read from repo local or worktree config files or respect `-c`
command line config settings.
== Trace2 Targets
Trace2 defines the following set of Trace2 Targets.
Format details are given in a later section.
`GIT_TR2` (NORMAL)::
=== The Normal Format Target
The normal format target is a tradition printf format and similar
to GIT_TRACE format. This format is enabled with the `GIT_TR`
environment variable or the `trace2.normalTarget` system or global
config setting.
For example
a simple printf format like GIT_TRACE.
+
------------
$ export GIT_TR2=~/log.normal
$ git version
git version 2.20.1.155.g426c96fcdb
------------
+
or
------------
$ git config --global trace2.normalTarget ~/log.normal
$ git version
git version 2.20.1.155.g426c96fcdb
------------
yields
------------
$ cat ~/log.normal
12:28:42.620009 common-main.c:38 version 2.20.1.155.g426c96fcdb
@ -46,81 +66,86 @@ $ cat ~/log.normal
12:28:42.621250 trace2/tr2_tgt_normal.c:124 atexit elapsed:0.001265 code:0
------------
`GIT_TR2_PERF` (PERF)::
=== The Performance Format Target
The performance format target (PERF) is a column-based format to
replace GIT_TRACE_PERFORMANCE and is suitable for development and
testing, possibly to complement tools like gprof. This format is
enabled with the `GIT_TR2_PERF` environment variable or the
`trace2.perfTarget` system or global config setting.
For example
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
------------
+
or
------------
$ git config --global trace2.perfTarget ~/log.perf
$ git version
git version 2.20.1.155.g426c96fcdb
------------
yields
------------
$ 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
------------
`GIT_TR2_EVENT` (EVENT)::
=== The Event Format Target
The event format target is a JSON-based format of event data suitable
for telemetry analysis. This format is enabled with the `GIT_TR2_EVENT`
environment variable or the `trace2.eventTarget` system or global config
setting.
For example
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
------------
+
or
------------
$ git config --global trace2.eventTarget ~/log.event
$ git version
git version 2.20.1.155.g426c96fcdb
------------
yields
------------
$ 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_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}
{"event":"version","sid":"sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.620713Z","file":"common-main.c","line":38,"evt":"1","exe":"2.20.1.155.g426c96fcdb"}
{"event":"start","sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.621027Z","file":"common-main.c","line":39,"t_abs":0.001173,"argv":["git","version"]}
{"event":"cmd_name","sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.621122Z","file":"git.c","line":432,"name":"version","hierarchy":"version"}
{"event":"exit","sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.621236Z","file":"git.c","line":662,"t_abs":0.001227,"code":0}
{"event":"atexit","sid":"20190408T191610.507018Z-H9b68c35f-P000059a8","thread":"main","time":"2019-01-16T17:28:42.621268Z","file":"trace2/tr2_tgt_event.c","line":163,"t_abs":0.001265,"code":0}
------------
== Enabling a Target
=== Enabling a Target
A Trace2 Target is enabled when the corresponding environment variable
(`GIT_TR2`, `GIT_TR2_PERF`, or `GIT_TR2_EVENT`) is set. The following
values are recognized.
To enable a target, set the corresponding environment variable or
system or global config value to one of the following:
`0`::
`false`::
include::../trace2-target-values.txt[]
Disables the target.
`1`::
`true`::
Enables the target and writes stream to `STDERR`.
`[2-9]`::
Enables the target and writes to the already opened file descriptor.
`<absolute-pathname>`::
Enables the target, opens and writes to the file in append mode.
If the target already exists and is a directory, the traces will be
written to files (one per process) underneath the given directory. They
will be named according to the last component of the SID (optionally
followed by a counter to avoid filename collisions).
`af_unix:[<socket_type>:]<absolute-pathname>`::
Enables the target, opens and writes to a Unix Domain Socket
(on platforms that support them).
+
Socket type can be either `stream` or `dgram`. If the socket type is
omitted, Git will try both.
If the target already exists and is a directory, the traces will be
written to files (one per process) underneath the given directory. They
will be named according to the last component of the SID (optionally
followed by a counter to avoid filename collisions).
== Trace2 API
@ -165,17 +190,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()`::
@ -242,15 +273,16 @@ significantly affects program performance or behavior, such as
Emits a "def_param" messages for "important" configuration
settings.
+
The environment variable `GIT_TR2_CONFIG_PARAMS` can be set to a
The environment variable `GIT_TR2_CONFIG_PARAMS` or the `trace2.configParams`
config value can be set to a
list of patterns of important configuration settings, for example:
`core.*,remote.*.url`. This function will iterate over all config
settings and emit a "def_param" message for each match.
`void trace2_cmd_set_config(const char *key, const char *value)`::
Emits a "def_param" message for a specific configuration
setting IFF it matches the `GIT_TR2_CONFIG_PARAMS` pattern.
Emits a "def_param" message for a new or updated key/value
pair IF `key` is considered important.
+
This is used to hook into `git_config_set()` and catch any
configuration changes and update a value previously reported by
@ -417,9 +449,6 @@ recursive tree walk.
=== NORMAL Format
NORMAL format is enabled when the `GIT_TR2` environment variable is
set.
Events are written as lines of the form:
------------
@ -436,8 +465,8 @@ Events are written as lines of the form:
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` fields
are omitted.
If `GIT_TR2_BRIEF` or `trace2.normalBrief` is true, the `time`, `filename`,
and `line` fields are omitted.
This target is intended to be more of a summary (like GIT_TRACE) and
less detailed than the other targets. It ignores thread, region, and
@ -445,9 +474,6 @@ data messages, for example.
=== PERF Format
PERF format is enabled when the `GIT_TR2_PERF` environment variable
is set.
Events are written as lines of the form:
------------
@ -507,8 +533,8 @@ This field is in anticipation of in-proc submodules in the future.
15:33:33.532712 wt-status.c:2331 | d0 | main | region_leave | r1 | 0.127568 | 0.001504 | status | label:print
------------
If `GIT_TR2_PERF_BRIEF` is true, the `time`, `file`, and `line`
fields are omitted.
If `GIT_TR2_PERF_BRIEF` or `trace2.perfBrief` is true, the `time`, `file`,
and `line` fields are omitted.
------------
d0 | main | region_leave | r1 | 0.011717 | 0.009122 | index | label:preload
@ -519,9 +545,6 @@ during development and is quite noisy.
=== EVENT Format
EVENT format is enabled when the `GIT_TR2_EVENT` environment
variable is set.
Each event is a JSON-object containing multiple key/value pairs
written as a single line and followed by a LF.
@ -539,11 +562,11 @@ The following key/value pairs are common to all events:
------------
{
"event":"version",
"sid":"1547659722619736-11614",
"sid":"20190408T191827.272759Z-H9b68c35f-P00003510",
"thread":"main",
"time":"2019-01-16 17:28:42.620713",
"time":"2019-04-08T19:18:27.282761Z",
"file":"common-main.c",
"line":38,
"line":42,
...
}
------------
@ -575,9 +598,9 @@ The following key/value pairs are common to all events:
`"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.
If `GIT_TR2_EVENT_BRIEF` or `trace2.eventBrief` 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
@ -600,6 +623,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"]
}
------------
@ -887,7 +911,7 @@ visited.
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
`GIT_TR2_EVENT_NESTING` or `trace2.eventNesting` can be used to
filter deeply nested regions and data events. It defaults to "2".
`"region_leave"`::
@ -1117,7 +1141,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)
...
@ -1162,7 +1186,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)
...
@ -1218,7 +1242,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

View File

@ -0,0 +1,10 @@
--
* `0` or `false` - Disables the target.
* `1` or `true` - Writes to `STDERR`.
* `[2-9]` - Writes to the already opened file descriptor.
* `<absolute-pathname>` - Writes to the file in append mode.
* `af_unix:[<socket_type>:]<absolute-pathname>` - Write to a
Unix DomainSocket (on platforms that support them). Socket
type can be either `stream` or `dgram`; if omitted Git will
try both.
--

View File

@ -999,6 +999,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

View File

@ -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
@ -35,11 +37,11 @@ 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]);
trace2_collect_process_info(TRACE2_PROCESS_INFO_STARTUP);
git_setup_gettext();

View File

@ -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 */

View File

@ -1,5 +1,6 @@
#include "../../cache.h"
#include "../../json-writer.h"
#include "lazyload.h"
#include <Psapi.h>
#include <tlHelp32.h>
@ -137,11 +138,54 @@ static void get_is_being_debugged(void)
"windows/debugger_present", 1);
}
void trace2_collect_process_info(void)
/*
* Emit JSON data with the peak memory usage of the current process.
*/
static void get_peak_memory_info(void)
{
DECLARE_PROC_ADDR(psapi.dll, BOOL, GetProcessMemoryInfo, HANDLE,
PPROCESS_MEMORY_COUNTERS, DWORD);
if (INIT_PROC_ADDR(GetProcessMemoryInfo)) {
PROCESS_MEMORY_COUNTERS pmc;
if (GetProcessMemoryInfo(GetCurrentProcess(), &pmc,
sizeof(pmc))) {
struct json_writer jw = JSON_WRITER_INIT;
jw_object_begin(&jw, 0);
#define KV(kv) #kv, (intmax_t)pmc.kv
jw_object_intmax(&jw, KV(PageFaultCount));
jw_object_intmax(&jw, KV(PeakWorkingSetSize));
jw_object_intmax(&jw, KV(PeakPagefileUsage));
jw_end(&jw);
trace2_data_json("process", the_repository,
"windows/memory", &jw);
jw_release(&jw);
}
}
}
void trace2_collect_process_info(enum trace2_process_info_reason reason)
{
if (!trace2_is_enabled())
return;
get_is_being_debugged();
get_ancestry();
switch (reason) {
case TRACE2_PROCESS_INFO_STARTUP:
get_is_being_debugged();
get_ancestry();
return;
case TRACE2_PROCESS_INFO_EXIT:
get_peak_memory_info();
return;
default:
BUG("trace2_collect_process_info: unknown reason '%d'", reason);
}
}

View File

@ -1676,7 +1676,9 @@ static int do_git_config_sequence(const struct config_options *opts,
repo_config = NULL;
current_parsing_scope = CONFIG_SCOPE_SYSTEM;
if (git_config_system() && !access_or_die(git_etc_gitconfig(), R_OK, 0))
if (git_config_system() && !access_or_die(git_etc_gitconfig(), R_OK,
opts->system_gently ?
ACCESS_EACCES_OK : 0))
ret += git_config_from_file(fn, git_etc_gitconfig(),
data);
@ -1688,14 +1690,15 @@ static int do_git_config_sequence(const struct config_options *opts,
ret += git_config_from_file(fn, user_config, data);
current_parsing_scope = CONFIG_SCOPE_REPO;
if (repo_config && !access_or_die(repo_config, R_OK, 0))
if (!opts->ignore_repo && repo_config &&
!access_or_die(repo_config, R_OK, 0))
ret += git_config_from_file(fn, repo_config, data);
/*
* Note: this should have a new scope, CONFIG_SCOPE_WORKTREE.
* But let's not complicate things before it's actually needed.
*/
if (repository_format_worktree_config) {
if (!opts->ignore_worktree && repository_format_worktree_config) {
char *path = git_pathdup("config.worktree");
if (!access_or_die(path, R_OK, 0))
ret += git_config_from_file(fn, path, data);
@ -1703,7 +1706,7 @@ static int do_git_config_sequence(const struct config_options *opts,
}
current_parsing_scope = CONFIG_SCOPE_CMDLINE;
if (git_config_from_parameters(fn, data) < 0)
if (!opts->ignore_cmdline && git_config_from_parameters(fn, data) < 0)
die(_("unable to parse command-line config"));
current_parsing_scope = CONFIG_SCOPE_UNKNOWN;
@ -1794,6 +1797,23 @@ void read_early_config(config_fn_t cb, void *data)
strbuf_release(&gitdir);
}
/*
* Read config but only enumerate system and global settings.
* Omit any repo-local, worktree-local, or command-line settings.
*/
void read_very_early_config(config_fn_t cb, void *data)
{
struct config_options opts = { 0 };
opts.respect_includes = 1;
opts.ignore_repo = 1;
opts.ignore_worktree = 1;
opts.ignore_cmdline = 1;
opts.system_gently = 1;
config_with_options(cb, data, NULL, &opts);
}
static struct config_set_element *configset_find_element(struct config_set *cs, const char *key)
{
struct config_set_element k;
@ -2011,7 +2031,7 @@ int git_configset_get_pathname(struct config_set *cs, const char *key, const cha
/* Functions use to read configuration from a repository */
static void repo_read_config(struct repository *repo)
{
struct config_options opts;
struct config_options opts = { 0 };
opts.respect_includes = 1;
opts.commondir = repo->commondir;

View File

@ -55,6 +55,10 @@ typedef int (*config_parser_event_fn_t)(enum config_event_t type,
struct config_options {
unsigned int respect_includes : 1;
unsigned int ignore_repo : 1;
unsigned int ignore_worktree : 1;
unsigned int ignore_cmdline : 1;
unsigned int system_gently : 1;
const char *commondir;
const char *git_dir;
config_parser_event_fn_t event_fn;
@ -83,6 +87,7 @@ extern int git_config_from_blob_oid(config_fn_t fn, const char *name,
extern void git_config_push_parameter(const char *text);
extern int git_config_from_parameters(config_fn_t fn, void *data);
extern void read_early_config(config_fn_t cb, void *data);
extern void read_very_early_config(config_fn_t cb, void *data);
extern void git_config(config_fn_t fn, void *);
extern int config_with_options(config_fn_t fn, void *,
struct git_config_source *config_source,

View File

@ -3,6 +3,11 @@
test_description='test trace2 facility (normal target)'
. ./test-lib.sh
# Turn off any inherited trace2 settings for this test.
sane_unset GIT_TR2 GIT_TR2_PERF GIT_TR2_EVENT
sane_unset GIT_TR2_BRIEF
sane_unset GIT_TR2_CONFIG_PARAMS
# Add t/helper directory to PATH so that we can use a relative
# path to run nested instances of test-tool.exe (see 004child).
# This helps with HEREDOC comparisons later.
@ -15,11 +20,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.
@ -147,4 +147,43 @@ test_expect_success 'normal stream, error event' '
test_cmp expect actual
'
sane_unset GIT_TR2_BRIEF
# Now test without environment variables and get all Trace2 settings
# from the global config.
test_expect_success 'using global config, normal stream, return code 0' '
test_when_finished "rm trace.normal actual expect" &&
test_config_global trace2.normalBrief 1 &&
test_config_global trace2.normalTarget "$(pwd)/trace.normal" &&
test-tool trace2 001return 0 &&
perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <trace.normal >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_expect_success 'using global config with include' '
test_when_finished "rm trace.normal actual expect real.gitconfig" &&
test_config_global trace2.normalBrief 1 &&
test_config_global trace2.normalTarget "$(pwd)/trace.normal" &&
mv "$(pwd)/.gitconfig" "$(pwd)/real.gitconfig" &&
test_config_global include.path "$(pwd)/real.gitconfig" &&
test-tool trace2 001return 0 &&
perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <trace.normal >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

View File

@ -3,6 +3,11 @@
test_description='test trace2 facility (perf target)'
. ./test-lib.sh
# Turn off any inherited trace2 settings for this test.
sane_unset GIT_TR2 GIT_TR2_PERF GIT_TR2_EVENT
sane_unset GIT_TR2_PERF_BRIEF
sane_unset GIT_TR2_CONFIG_PARAMS
# Add t/helper directory to PATH so that we can use a relative
# path to run nested instances of test-tool.exe (see 004child).
# This helps with HEREDOC comparisons later.
@ -15,11 +20,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.
@ -50,7 +50,7 @@ test_expect_success 'perf stream, return code 0' '
perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >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" <trace.perf >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" <trace.perf >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" <trace.perf >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
@ -150,4 +150,25 @@ test_expect_success 'perf stream, child processes' '
test_cmp expect actual
'
sane_unset GIT_TR2_PERF_BRIEF
# Now test without environment variables and get all Trace2 settings
# from the global config.
test_expect_success 'using global config, perf stream, return code 0' '
test_when_finished "rm trace.perf actual expect" &&
test_config_global trace2.perfBrief 1 &&
test_config_global trace2.perfTarget "$(pwd)/trace.perf" &&
test-tool trace2 001return 0 &&
perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >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

View File

@ -3,6 +3,11 @@
test_description='test trace2 facility'
. ./test-lib.sh
# Turn off any inherited trace2 settings for this test.
sane_unset GIT_TR2 GIT_TR2_PERF GIT_TR2_EVENT
sane_unset GIT_TR2_BARE
sane_unset GIT_TR2_CONFIG_PARAMS
perl -MJSON::PP -e 0 >/dev/null 2>&1 && test_set_prereq JSON_PP
# Add t/helper directory to PATH so that we can use a relative
@ -17,11 +22,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 +233,36 @@ test_expect_success JSON_PP 'basic trace2_data' '
test_cmp expect actual
'
# Now test without environment variables and get all Trace2 settings
# from the global config.
test_expect_success JSON_PP 'using global config, event stream, error event' '
test_when_finished "rm trace.event actual expect" &&
test_config_global trace2.eventTarget "$(pwd)/trace.event" &&
test-tool trace2 003error "hello world" "this is a test" &&
perl "$TEST_DIRECTORY/t0212/parse_events.perl" <trace.event >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

View File

@ -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;
}
@ -142,6 +144,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;
@ -150,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;
@ -177,13 +186,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)
@ -198,6 +213,8 @@ int trace2_cmd_exit_fl(const char *file, int line, int code)
if (!trace2_enabled)
return code;
trace2_collect_process_info(TRACE2_PROCESS_INFO_EXIT);
tr2main_exit_code = code;
us_now = getnanotime() / 1000;
@ -428,7 +445,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)

View File

@ -19,9 +19,27 @@ 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.
* targets are enabled in the system config or the environment.
* Emits a 'version' event.
*
* Cleanup/Termination is handled automatically by a registered
* atexit() routine.
@ -108,10 +126,11 @@ 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:
*
* GIT_TR2_CONFIG_PARAMS="core.*,remote.*.url"
* Use the TR2_SYSENV_CFG_PARAM setting to register a comma-separated
* list of patterns configured important. For example:
* git config --system trace2.configParams 'core.*,remote.*.url'
* or:
* GIT_TR2_CONFIG_PARAMS=core.*,remote.*.url"
*
* Note: this routine does a read-only iteration on the config data
* (using read_early_config()), so it must not be called until enough
@ -372,13 +391,19 @@ void trace2_printf(const char *fmt, ...);
* Optional platform-specific code to dump information about the
* current and any parent process(es). This is intended to allow
* post-processors to know who spawned this git instance and anything
* else the platform may be able to tell us about the current process.
* else that the platform may be able to tell us about the current process.
*/
enum trace2_process_info_reason {
TRACE2_PROCESS_INFO_STARTUP,
TRACE2_PROCESS_INFO_EXIT,
};
#if defined(GIT_WINDOWS_NATIVE)
void trace2_collect_process_info(void);
void trace2_collect_process_info(enum trace2_process_info_reason reason);
#else
#define trace2_collect_process_info() \
do { \
#define trace2_collect_process_info(reason) \
do { \
} while (0)
#endif

View File

@ -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;

View File

@ -1,17 +1,7 @@
#include "cache.h"
#include "trace2/tr2_dst.h"
#include "trace2/tr2_sid.h"
/*
* If a Trace2 target cannot be opened for writing, we should issue a
* warning to stderr, but this is very annoying if the target is a pipe
* 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"
#include "trace2/tr2_sysenv.h"
/*
* How many attempts we will make at creating an automatically-named trace file.
@ -23,7 +13,7 @@ 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
@ -75,7 +65,8 @@ static int tr2_dst_try_auto_path(struct tr2_dst *dst, const char *tgt_prefix)
if (tr2_dst_want_warning())
warning("trace2: could not open '%.*s' for '%s' tracing: %s",
(int) base_path_len, path.buf,
dst->env_var_name, strerror(errno));
tr2_sysenv_display_name(dst->sysenv_var),
strerror(errno));
tr2_dst_trace_disable(dst);
strbuf_release(&path);
@ -97,7 +88,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;
@ -171,7 +164,8 @@ 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;
@ -181,7 +175,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;
@ -203,7 +197,8 @@ 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;
@ -223,7 +218,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);
@ -239,7 +234,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")) {
@ -305,7 +300,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);
}

View File

@ -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;

View File

@ -1,4 +1,5 @@
#include "cache.h"
#include "trace2/tr2_tbuf.h"
#include "trace2/tr2_sid.h"
#define TR2_ENVVAR_PARENT_SID "GIT_TR2_PARENT_SID"
@ -6,6 +7,53 @@
static struct strbuf tr2sid_buf = STRBUF_INIT;
static int tr2sid_nr_git_parents;
/*
* Compute the final component of the SID representing the current process.
* This should uniquely identify the process and be a valid filename (to
* allow writing trace2 data to per-process files). It should also be fixed
* length for possible use as a database key.
*
* "<yyyymmdd>T<hhmmss>.<fraction>Z-<host>-<process>"
*
* where <host> is a 9 character string:
* "H<first_8_chars_of_sha1_of_hostname>"
* "Localhost" when no hostname.
*
* where <process> is a 9 character string containing the least signifcant
* 32 bits in the process-id.
* "P<pid>"
* (This is an abribrary choice. On most systems pid_t is a 32 bit value,
* so limit doesn't matter. On larger systems, a truncated value is fine
* for our purposes here.)
*/
static void tr2_sid_append_my_sid_component(void)
{
const struct git_hash_algo *algo = &hash_algos[GIT_HASH_SHA1];
struct tr2_tbuf tb_now;
git_hash_ctx ctx;
pid_t pid = getpid();
unsigned char hash[GIT_MAX_RAWSZ + 1];
char hex[GIT_MAX_HEXSZ + 1];
char hostname[HOST_NAME_MAX + 1];
tr2_tbuf_utc_datetime(&tb_now);
strbuf_addstr(&tr2sid_buf, tb_now.buf);
strbuf_addch(&tr2sid_buf, '-');
if (xgethostname(hostname, sizeof(hostname)))
strbuf_add(&tr2sid_buf, "Localhost", 9);
else {
algo->init_fn(&ctx);
algo->update_fn(&ctx, hostname, strlen(hostname));
algo->final_fn(hash, &ctx);
hash_to_hex_algop_r(hex, hash, algo);
strbuf_addch(&tr2sid_buf, 'H');
strbuf_add(&tr2sid_buf, hex, 8);
}
strbuf_addf(&tr2sid_buf, "-P%08"PRIx32, (uint32_t)pid);
}
/*
* Compute a "unique" session id (SID) for the current process. This allows
* all events from this process to have a single label (much like a PID).
@ -20,7 +68,6 @@ static int tr2sid_nr_git_parents;
*/
static void tr2_sid_compute(void)
{
uint64_t us_now;
const char *parent_sid;
if (tr2sid_buf.len)
@ -38,9 +85,7 @@ static void tr2_sid_compute(void)
tr2sid_nr_git_parents++;
}
us_now = getnanotime() / 1000;
strbuf_addf(&tr2sid_buf, "%" PRIuMAX "-%" PRIdMAX, (uintmax_t)us_now,
(intmax_t)getpid());
tr2_sid_append_my_sid_component();
setenv(TR2_ENVVAR_PARENT_SID, tr2sid_buf.buf, 1);
}

127
trace2/tr2_sysenv.c Normal file
View File

@ -0,0 +1,127 @@
#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.
*
* The strings in this table are constant and must match the published
* config and environment variable 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[] = {
[TR2_SYSENV_CFG_PARAM] = { "GIT_TR2_CONFIG_PARAMS",
"trace2.configparams" },
[TR2_SYSENV_DST_DEBUG] = { "GIT_TR2_DST_DEBUG",
"trace2.destinationdebug" },
[TR2_SYSENV_NORMAL] = { "GIT_TR2",
"trace2.normaltarget" },
[TR2_SYSENV_NORMAL_BRIEF] = { "GIT_TR2_BRIEF",
"trace2.normalbrief" },
[TR2_SYSENV_EVENT] = { "GIT_TR2_EVENT",
"trace2.eventtarget" },
[TR2_SYSENV_EVENT_BRIEF] = { "GIT_TR2_EVENT_BRIEF",
"trace2.eventbrief" },
[TR2_SYSENV_EVENT_NESTING] = { "GIT_TR2_EVENT_NESTING",
"trace2.eventnesting" },
[TR2_SYSENV_PERF] = { "GIT_TR2_PERF",
"trace2.perftarget" },
[TR2_SYSENV_PERF_BRIEF] = { "GIT_TR2_PERF_BRIEF",
"trace2.perfbrief" },
};
/* clang-format on */
static int tr2_sysenv_cb(const char *key, const char *value, void *d)
{
int k;
if (!starts_with(key, "trace2."))
return 0;
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.
*
* Then override with the Trace2 settings from the global config.
*/
void tr2_sysenv_load(void)
{
if (ARRAY_SIZE(tr2_sysenv_settings) != TR2_SYSENV_MUST_BE_LAST)
BUG("tr2_sysenv_settings size is wrong");
read_very_early_config(tr2_sysenv_cb, NULL);
}
/*
* Return the value for the requested Trace2 setting from these sources:
* the system config, the global config, and the environment.
*/
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);
}

36
trace2/tr2_sysenv.h Normal file
View File

@ -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 */

View File

@ -15,7 +15,7 @@ void tr2_tbuf_local_time(struct tr2_tbuf *tb)
tm.tm_min, tm.tm_sec, (long)tv.tv_usec);
}
void tr2_tbuf_utc_time(struct tr2_tbuf *tb)
void tr2_tbuf_utc_datetime_extended(struct tr2_tbuf *tb)
{
struct timeval tv;
struct tm tm;
@ -26,7 +26,22 @@ void tr2_tbuf_utc_time(struct tr2_tbuf *tb)
gmtime_r(&secs, &tm);
xsnprintf(tb->buf, sizeof(tb->buf),
"%4d-%02d-%02d %02d:%02d:%02d.%06ld", tm.tm_year + 1900,
"%4d-%02d-%02dT%02d:%02d:%02d.%06ldZ", tm.tm_year + 1900,
tm.tm_mon + 1, tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec,
(long)tv.tv_usec);
}
void tr2_tbuf_utc_datetime(struct tr2_tbuf *tb)
{
struct timeval tv;
struct tm tm;
time_t secs;
gettimeofday(&tv, NULL);
secs = tv.tv_sec;
gmtime_r(&secs, &tm);
xsnprintf(tb->buf, sizeof(tb->buf), "%4d%02d%02dT%02d%02d%02d.%06ldZ",
tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday, tm.tm_hour,
tm.tm_min, tm.tm_sec, (long)tv.tv_usec);
}

View File

@ -16,8 +16,9 @@ struct tr2_tbuf {
void tr2_tbuf_local_time(struct tr2_tbuf *tb);
/*
* Fill buffer with formatted UTC time string.
* Fill buffer with formatted UTC datatime string.
*/
void tr2_tbuf_utc_time(struct tr2_tbuf *tb);
void tr2_tbuf_utc_datetime_extended(struct tr2_tbuf *tb);
void tr2_tbuf_utc_datetime(struct tr2_tbuf *tb);
#endif /* TR2_TBUF_H */

View File

@ -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);

View File

@ -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,37 +29,36 @@ 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;
static int tr2env_event_max_nesting_levels = 2;
/*
* Set this environment variable to true to omit the <time>, <file>, and
* Use the TR2_SYSENV_EVENT_BRIEF to omit the <time>, <file>, and
* <line> fields from most events.
*/
#define TR2_ENVVAR_EVENT_BRIEF "GIT_TR2_EVENT_BRIEF"
static int tr2env_event_brief;
static int tr2env_event_be_brief;
static int fn_init(void)
{
int want = tr2_dst_trace_want(&tr2dst_event);
int want_nesting;
int max_nesting;
int want_brief;
char *nesting;
char *brief;
const char *nesting;
const char *brief;
if (!want)
return want;
nesting = getenv(TR2_ENVVAR_EVENT_NESTING);
if (nesting && ((want_nesting = atoi(nesting)) > 0))
tr2env_event_nesting_wanted = want_nesting;
nesting = tr2_sysenv_get(TR2_SYSENV_EVENT_NESTING);
if (nesting && *nesting && ((max_nesting = atoi(nesting)) > 0))
tr2env_event_max_nesting_levels = max_nesting;
brief = getenv(TR2_ENVVAR_EVENT_BRIEF);
if (brief && ((want_brief = atoi(brief)) > 0))
tr2env_event_brief = want_brief;
brief = tr2_sysenv_get(TR2_SYSENV_EVENT_BRIEF);
if (brief && *brief &&
((want_brief = git_parse_maybe_bool(brief)) != -1))
tr2env_event_be_brief = want_brief;
return want;
}
@ -92,13 +92,13 @@ static void event_fmt_prepare(const char *event_name, const char *file,
/*
* In brief mode, only emit <time> on these 2 event types.
*/
if (!tr2env_event_brief || !strcmp(event_name, "version") ||
if (!tr2env_event_be_brief || !strcmp(event_name, "version") ||
!strcmp(event_name, "atexit")) {
tr2_tbuf_utc_time(&tb_now);
tr2_tbuf_utc_datetime_extended(&tb_now);
jw_object_string(jw, "time", tb_now.buf);
}
if (!tr2env_event_brief && file && *file) {
if (!tr2env_event_be_brief && file && *file) {
jw_object_string(jw, "file", file);
jw_object_intmax(jw, "line", line);
}
@ -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);
@ -456,7 +459,7 @@ static void fn_region_enter_printf_va_fl(const char *file, int line,
{
const char *event_name = "region_enter";
struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
if (ctx->nr_open_regions <= tr2env_event_nesting_wanted) {
if (ctx->nr_open_regions <= tr2env_event_max_nesting_levels) {
struct json_writer jw = JSON_WRITER_INIT;
jw_object_begin(&jw, 0);
@ -481,7 +484,7 @@ static void fn_region_leave_printf_va_fl(
{
const char *event_name = "region_leave";
struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
if (ctx->nr_open_regions <= tr2env_event_nesting_wanted) {
if (ctx->nr_open_regions <= tr2env_event_max_nesting_levels) {
struct json_writer jw = JSON_WRITER_INIT;
double t_rel = (double)us_elapsed_region / 1000000.0;
@ -508,7 +511,7 @@ static void fn_data_fl(const char *file, int line, uint64_t us_elapsed_absolute,
{
const char *event_name = "data";
struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
if (ctx->nr_open_regions <= tr2env_event_nesting_wanted) {
if (ctx->nr_open_regions <= tr2env_event_max_nesting_levels) {
struct json_writer jw = JSON_WRITER_INIT;
double t_abs = (double)us_elapsed_absolute / 1000000.0;
double t_rel = (double)us_elapsed_region / 1000000.0;
@ -536,7 +539,7 @@ static void fn_data_json_fl(const char *file, int line,
{
const char *event_name = "data_json";
struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
if (ctx->nr_open_regions <= tr2env_event_nesting_wanted) {
if (ctx->nr_open_regions <= tr2env_event_max_nesting_levels) {
struct json_writer jw = JSON_WRITER_INIT;
double t_abs = (double)us_elapsed_absolute / 1000000.0;
double t_rel = (double)us_elapsed_region / 1000000.0;

View File

@ -4,20 +4,20 @@
#include "quote.h"
#include "version.h"
#include "trace2/tr2_dst.h"
#include "trace2/tr2_sysenv.h"
#include "trace2/tr2_tbuf.h"
#include "trace2/tr2_tgt.h"
#include "trace2/tr2_tls.h"
static struct tr2_dst tr2dst_normal = { "GIT_TR2", 0, 0, 0 };
static struct tr2_dst tr2dst_normal = { TR2_SYSENV_NORMAL, 0, 0, 0 };
/*
* Set this environment variable to true to omit the "<time> <file>:<line>"
* Use the TR2_SYSENV_NORMAL_BRIEF setting to omit the "<time> <file>:<line>"
* fields from each line written to the builtin normal target.
*
* Unit tests may want to use this to help with testing.
*/
#define TR2_ENVVAR_NORMAL_BRIEF "GIT_TR2_BRIEF"
static int tr2env_normal_brief;
static int tr2env_normal_be_brief;
#define TR2FMT_NORMAL_FL_WIDTH (50)
@ -25,15 +25,15 @@ static int fn_init(void)
{
int want = tr2_dst_trace_want(&tr2dst_normal);
int want_brief;
char *brief;
const char *brief;
if (!want)
return want;
brief = getenv(TR2_ENVVAR_NORMAL_BRIEF);
brief = tr2_sysenv_get(TR2_SYSENV_NORMAL_BRIEF);
if (brief && *brief &&
((want_brief = git_parse_maybe_bool(brief)) != -1))
tr2env_normal_brief = want_brief;
tr2env_normal_be_brief = want_brief;
return want;
}
@ -47,7 +47,7 @@ static void normal_fmt_prepare(const char *file, int line, struct strbuf *buf)
{
strbuf_setlen(buf, 0);
if (!tr2env_normal_brief) {
if (!tr2env_normal_be_brief) {
struct tr2_tbuf tb_now;
tr2_tbuf_local_time(&tb_now);
@ -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;

View File

@ -6,20 +6,20 @@
#include "json-writer.h"
#include "trace2/tr2_dst.h"
#include "trace2/tr2_sid.h"
#include "trace2/tr2_sysenv.h"
#include "trace2/tr2_tbuf.h"
#include "trace2/tr2_tgt.h"
#include "trace2/tr2_tls.h"
static struct tr2_dst tr2dst_perf = { "GIT_TR2_PERF", 0, 0, 0 };
static struct tr2_dst tr2dst_perf = { TR2_SYSENV_PERF, 0, 0, 0 };
/*
* Set this environment variable to true to omit the "<time> <file>:<line>"
* Use TR2_SYSENV_PERF_BRIEF to omit the "<time> <file>:<line>"
* fields from each line written to the builtin performance target.
*
* Unit tests may want to use this to help with testing.
*/
#define TR2_ENVVAR_PERF_BRIEF "GIT_TR2_PERF_BRIEF"
static int tr2env_perf_brief;
static int tr2env_perf_be_brief;
#define TR2FMT_PERF_FL_WIDTH (50)
#define TR2FMT_PERF_MAX_EVENT_NAME (12)
@ -36,17 +36,17 @@ static int fn_init(void)
{
int want = tr2_dst_trace_want(&tr2dst_perf);
int want_brief;
char *brief;
const char *brief;
if (!want)
return want;
strbuf_addchars(&dots, '.', TR2_DOTS_BUFFER_SIZE);
brief = getenv(TR2_ENVVAR_PERF_BRIEF);
brief = tr2_sysenv_get(TR2_SYSENV_PERF_BRIEF);
if (brief && *brief &&
((want_brief = git_parse_maybe_bool(brief)) != -1))
tr2env_perf_brief = want_brief;
tr2env_perf_be_brief = want_brief;
return want;
}
@ -77,7 +77,7 @@ static void perf_fmt_prepare(const char *event_name,
strbuf_setlen(buf, 0);
if (!tr2env_perf_brief) {
if (!tr2env_perf_be_brief) {
struct tr2_tbuf tb_now;
tr2_tbuf_local_time(&tb_now);
@ -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);
}

View File

@ -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)

View File

@ -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 */