Trace2 tracing facility #108
Closed
Conversation
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Member
|
For the record, |
Author
|
@dscho Thanks for the info. I'll give it another chance later after I do a little cleanup and re-push. |
Member
|
You're welcome. I submitted #109 to fix it. |
jeffhostetler
force-pushed
the
core-trace2-2019-v0
branch
3 times, most recently
from
f1855e5 to
0d53e0e
Compare
Member
|
From the build log:
... whoops ;-) This is a problem I introduced in my endeavor to minimize the subset of the Git for Windows SDK used for the continuous testing. I added that header to the sparse checkout file and am rebuilding the minimal SDK here: https://git-for-windows.visualstudio.com/git/_build/results?buildId=29013. Once that is done, I'll trigger another CI for GitGitGadget's Git fork run here. |
Member
|
@jeffhostetler I started a rebuild with the updated minimal SDK. |
Member
There you go. All green. |
git-for-windows-ci
pushed a commit
to git-for-windows/git-sdk-64
that referenced
this pull request
Jan 19, 2019
This header is used in gitgitgadget/git#108. Signed-off-by: Johannes Schindelin <[email protected]>
git-for-windows-ci
pushed a commit
to git-for-windows/git-sdk-64
that referenced
this pull request
Jan 19, 2019
They are needed in gitgitgadget/git#108. Signed-off-by: Johannes Schindelin <[email protected]>
git-for-windows-ci
pushed a commit
to git-for-windows/git-sdk-64
that referenced
this pull request
Jan 19, 2019
All of these are needed in gitgitgadget/git#108. Signed-off-by: Johannes Schindelin <[email protected]>
jeffhostetler
force-pushed
the
core-trace2-2019-v0
branch
from
de1ced8 to
33a1ca7
Compare
jeffhostetler
changed the title
Author
|
/queue |
Author
|
/submit |
|
Submitted as [email protected] |
|
This branch is now known as |
|
This patch series was integrated into pu via git@cb3b9e7. |
|
On the Git mailing list, Josh Steadmon wrote (reply to this): |
![gitgitgadget[bot]](https://avatars.githubusercontent.com/in/12836?s=60&v=4){kind=small}
| @@ -0,0 +1,1158 @@ | |||
| Trace2 API | |||
There was a problem hiding this comment.
On the Git mailing list, Jeff Hostetler wrote (reply to this):
On 1/23/2019 3:51 PM, Junio C Hamano wrote:
> "Jeff Hostetler via GitGitGadget" <[email protected]> writes:
>
>> +These high-level events are written to one or more Trace2 Targets
>> +in a target-specific format. Each Trace2 Target defines a different
>> +purpose-specific view onto the event data stream. In this mannor,
>
> "In this manner"
>
>> +a single set of Trace2 API event calls in the Git source can drive
>> +different types of analysis.
>> +
>> ...
>> +$ cat ~/log.perf
>> +12:28:42.620675 common-main.c:38 | d0 | main | version | | | | | 2.20.1.155.g426c96fcdb
>> +12:28:42.621001 common-main.c:39 | d0 | main | start | | | | | git version
>> +12:28:42.621111 git.c:432 | d0 | main | cmd_verb | | | | | version (version)
>> +12:28:42.621225 git.c:662 | d0 | main | exit | | 0.001227 | | | code:0
>> +12:28:42.621259 trace2/tr2_tgt_perf.c:211 | d0 | main | atexit | | 0.001265 | | | code:0
>> +------------
>> ...
>> +
>> +trace2_def_param(...)
>
> Not limited to this single one, but please either
>
> - omit "..." in parens, unless all of these functions take varargs
> of unspecified type (which I do not think is the case), or
>
> - write a proper prototype for these functions, explain what the
> function itself and what the parameters are for.
>
> I'll complain about lack of info around here later X-<.
I documented the prototypes in trace2.h and was hoping to avoid
duplicating all that text here in this document. The list of
functions here in this document was more of an overview of the
groups of concepts covered. I'll revisit this.
>
>> +trace2_def_repo(...)
>
>> +----------------
>> +
>> +Git Child Process Events::
>> +
>> + These are concerned with the various spawned child processes,
>> + including sub-git processes and hooks,
>> ++
>> +----------------
>> +trace2_child_start(...)
>> +trace2_child_exit(...)
>> +
>> +trace2_exec(...)
>> +trace2_exec_result(...)
>> +----------------
>> +
>> +Git Thread Events::
>> +
>> + These are concerned with Git thread usage.
>> ++
>> +----------------
>> +trace2_thread_start(...)
>> +trace2_thread_exit(...)
>> +----------------
>
> Lack of _wait()/_join() feels a bit curious, but _exit() from what
> is being waited would suffice as a substitute.
The 2 trace2_thread_ functions have to be run by the thread-proc itself
rather than by the code calling the pthread functions. So to me it made
more sense inside the thread-proc for them to be named _start and _exit.
This gives us an event with the elapsed time of the thread in isolation
using TLS data within each thread.
If I understand your question about _wait/_join, adding trace2 calls
near the pthread_create and pthread_join, would be a bit of a mess
because of the usual create loop and then later the join loop. And
the exit times would be less accurate, since we typically _join them
in array order rather in the order they finish.
And having the trace2_thread_ calls in the pthread caller doesn't let
me access the thread's private TLS data.
Wrapping a region (like I show later in the preload_index() example)
around both of the pthread loops gives us the overall time for the
threading and insight into the thread overhead. (One could even
have a region around the pthread_create loop and another around the
pthread_join loop, but that might not be worth the trouble.
>
>> +Initialization::
>> +
>> + Initialization happens in `main()`. The initialization code
>> + determines which, if any, Trace2 Targets should be enabled and
>> + emits the `version`, `start`, and `exit` events. It causes an
>> + `atexit` function and `signal` handler to be registered that
>> + will emit `atexit` and `signal` events.
>> ++
>> +----------------
>> +int main(int argc, const char **argv)
>> +{
>> + int exit_code;
>> +
>> + trace2_initialize();
>> + trace2_cmd_start(argv);
>
> Nobody other than trace2 integration would make a call to this
> helper, so it may not matter, but sending av alone without ac, even
> though ac is almost always redundant, feels somewhat unexpected.
Agreed. There were other places that took an argv that didn't have
an argc on hand in the calling code. So rather than fake up one for
them, I just omitted it from all the calls in my API.
>
>> +Command Details::
>> +
>> + After the basics are established, additional process
>> + information can be sent to Trace2 as it is discovered, such as
>> + the command verb, alias expansion, interesting config
>> + settings, the repository worktree, error messages, and etc.
>> ++
>> +----------------
>> +int cmd_checkout(int argc, const char **argv)
>> +{
>> + // emit a single "def_param" event
>> + trace2_def_param("core.editor", "emacs");
>
> Without knowing what "def_param event" is, this example is hard to
> fathom. At this point in the doc, the reader does not even know
> what "def" stands for. Is this call to define a param called
> core.editor? Is it reporting that the default value for core.editor
> is emacs?
>
>> + // emit def_params for any config setting matching a pattern
>> + // in GIT_TR2_CONFIG_PARAMS.
>> + trace2_cmd_list_config();
>
> As the reader does not know what def_param is, this is also hard to
> follow.
I'll rewrite that section. The idea is to define a parameter that
a perf-tester might consider important. For example, "core.abbrev"
used to cause massive perf problems on our mega repo where it might
take minutes to compute 7 or 8 digit abbreviations for a log or
branch command (completely dominating the time to actually compute
the log or branch list).
>
>> + trace2_cmd_verb("checkout");
>> + trace2_cmd_subverb("branch");
>
> These are guessable. It probably reports what the codepath is
> doing.
These are to help post-processing. The git command line is parsed
in 2 or 3 different phases and it takes quite a bit of work to get
to cmd_*() function (such as skipping over the -c, -C, --exec-path,
and other such args, and handling the commands where there isn't
a cmd_*() function (such as "git --exec-path")). Then within the
cmd_*() function, a lot of work to see which variant of the command
is (such as is this checkout checking out a branch or a single
file). And there are short and long forms of many arguments. And then
there is the alias expansion which wants to rewrite the command line
(possibly recursively). And then there is the code to try to run the
non-builtin dashed form.
For post-processing, you want to be able to do something like this:
select elapsed_time where verb='checkout' and subverb='branch'
select elapsed_time where verb='checkout' and subverb='path'
and report averages over those 2 sets independently without having
to recreate all that argv parsing inside the database query (or perl
script on the trace log).
>
>> + trace2_def_repo(the_repository);
>
> Again, this is not easy to guess. Is it reporting what the default
> repository is?
I'll reword this.
>
>> + if (do_something(...))
>> + trace2_cmd_error("Path '%s': cannot do something", path);
>
> This is guessable, which is good.
>
>> +void run_child(...)
>> +{
>> + int child_exit_code;
>> + struct child_process cmd = CHILD_PROCESS_INIT;
>> + ...
>> +
>> + trace2_child_start(&cmd);
>> + child_exit_code = ...();
>> + trace2_child_exit(&cmd, child_exit_code);
>
> Even though child_exit() has not been explained just like
> def_param(), this is far more guessable. I wonder why it is. The
> name of the variable passed to it in the example certainly helps, as
> it is totally unclear where the string constant "emacs" in the
> earlier example came from (e.g. is it hardcoded in the program? is
> it merely illustrating "here is how you report the value you have
> decided to use for 'core.editor' variable"?).
yes, some of these are synthetic uses of the API to illustrate
the trace2 concepts. I just picked 'core.editor' at random. I'll
revisit the examples.
>
>> ...
>> +$ cat ~/log.perf
>> +d0 | main | version | | | | | 2.20.1.160.g5676107ecd.dirty
>> +d0 | main | start | | | | | git status
>> +d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
>> +d0 | main | cmd_verb | | | | | status (status)
>> +...
>> +d0 | main | region_enter | r1 | 0.010988 | | status | label:worktrees
>
> It is hard to guess what "d0" and "r1" stand for here.
>
> In an earlier example we also saw an unexplained "d0" there, which I
> think was OK because the illustration was merely to give the "feel"
> of the format up there. But now we are giving a bit more detailed
> explanation, we probably would want to at least briefly mention what
> each column means.
yes, the example at the top was just to preview the formats.
I'll add more info here.
> I'd stop here for now, as I am more interested in reading the code
> ;-)
>
Thanks
Jeff
|
This patch series was integrated into pu via git@d28b107. |
|
On the Git mailing list, Jeff Hostetler wrote (reply to this): |
|
On the Git mailing list, Junio C Hamano wrote (reply to this): |
|
This patch series was integrated into pu via git@6240162. |
jeffhostetler
force-pushed
the
core-trace2-2019-v0
branch
from
33a1ca7 to
851aa8f
Compare
Author
|
/submit |
|
Submitted as [email protected] |
Signed-off-by: Jeff Hostetler <[email protected]>
Create unit tests for Trace2. Signed-off-by: Jeff Hostetler <[email protected]>
Signed-off-by: Jeff Hostetler <[email protected]>
jeffhostetler
force-pushed
the
core-trace2-2019-v0
branch
from
28209de to
662201f
Compare
Author
|
/submit |
|
Submitted as [email protected] |
|
This patch series was integrated into pu via git@d524676. |
|
This patch series was integrated into next via git@4c84c62. |
|
This patch series was integrated into pu via git@27373ae. |
|
This patch series was integrated into pu via git@b00e53d. |
|
This patch series was integrated into pu via git@faf76e1. |
|
This patch series was integrated into pu via git@b0949e5. |
|
This patch series was integrated into pu via git@cece601. |
|
This patch series was integrated into pu via git@32038fe. |
|
This patch series was integrated into next via git@32038fe. |
|
This patch series was integrated into master via git@32038fe. |
|
Closed via 32038fe. |
|
On the Git mailing list, =?utf-8?B?w4Z2YXIgQXJuZmrDtnLDsA==?= Bjarmason wrote (reply to this): |
|
On the Git mailing list, Johannes Schindelin wrote (reply to this): |
|
On the Git mailing list, =?utf-8?B?w4Z2YXIgQXJuZmrDtnLDsA==?= Bjarmason wrote (reply to this): |
|
On the Git mailing list, Johannes Schindelin wrote (reply to this): |
|
On the Git mailing list, Jeff Hostetler wrote (reply to this): |
|
On the Git mailing list, =?utf-8?B?w4Z2YXIgQXJuZmrDtnLDsA==?= Bjarmason wrote (reply to this): |
|
On the Git mailing list, Jeff Hostetler wrote (reply to this): |
| die(_("unable to join load_index_extensions thread: %s"), strerror(ret)); | ||
| } else { | ||
| p.src_offset = src_offset; | ||
| load_index_extensions(&p); |
There was a problem hiding this comment.
On the Git mailing list, Ævar Arnfjörð Bjarmason wrote (reply to this):
Fix a trivial bug that's been here since the shared/do_write_index
tracing was added in 42fee7a388 ("trace2:data: add trace2
instrumentation to index read/write", 2019-02-22). We should have
enter/leave points, not two enter/enter points. This resulted in an
"enter" event without a corresponding "leave" event.
Signed-off-by: Ævar Arnfjörð Bjarmason <[email protected]>
---
read-cache.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/read-cache.c b/read-cache.c
index 61b043bac3..4fad4e3f9a 100644
--- a/read-cache.c
+++ b/read-cache.c
@@ -3131,7 +3131,7 @@ static int write_shared_index(struct index_state *istate,
trace2_region_enter_printf("index", "shared/do_write_index",
the_repository, "%s", (*temp)->filename.buf);
ret = do_write_index(si->base, *temp, 1);
- trace2_region_enter_printf("index", "shared/do_write_index",
+ trace2_region_leave_printf("index", "shared/do_write_index",
the_repository, "%s", (*temp)->filename.buf);
if (ret)
--
2.21.0.1020.gf2820cf01a
There was a problem hiding this comment.
On the Git mailing list, Derrick Stolee wrote (reply to this):
On 5/10/2019 9:37 AM, Ævar Arnfjörð Bjarmason wrote:
> Fix a trivial bug that's been here since the shared/do_write_index
> tracing was added in 42fee7a388 ("trace2:data: add trace2
> instrumentation to index read/write", 2019-02-22). We should have
> enter/leave points, not two enter/enter points. This resulted in an
> "enter" event without a corresponding "leave" event.
>
> Signed-off-by: Ævar Arnfjörð Bjarmason <[email protected]>
> ---
> read-cache.c | 2 +-
> 1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/read-cache.c b/read-cache.c
> index 61b043bac3..4fad4e3f9a 100644
> --- a/read-cache.c
> +++ b/read-cache.c
> @@ -3131,7 +3131,7 @@ static int write_shared_index(struct index_state *istate,
> trace2_region_enter_printf("index", "shared/do_write_index",
> the_repository, "%s", (*temp)->filename.buf);
> ret = do_write_index(si->base, *temp, 1);
> - trace2_region_enter_printf("index", "shared/do_write_index",
> + trace2_region_leave_printf("index", "shared/do_write_index",
> the_repository, "%s", (*temp)->filename.buf);
>
> if (ret)
>
Thanks! Obviously correct.
-Stolee
There was a problem hiding this comment.
On the Git mailing list, Jeff Hostetler wrote (reply to this):
On 5/10/2019 9:37 AM, Ævar Arnfjörð Bjarmason wrote:
> Fix a trivial bug that's been here since the shared/do_write_index
> tracing was added in 42fee7a388 ("trace2:data: add trace2
> instrumentation to index read/write", 2019-02-22). We should have
> enter/leave points, not two enter/enter points. This resulted in an
> "enter" event without a corresponding "leave" event.
>
> Signed-off-by: Ævar Arnfjörð Bjarmason <[email protected]>
> ---
> read-cache.c | 2 +-
> 1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/read-cache.c b/read-cache.c
> index 61b043bac3..4fad4e3f9a 100644
> --- a/read-cache.c
> +++ b/read-cache.c
> @@ -3131,7 +3131,7 @@ static int write_shared_index(struct index_state *istate,
> trace2_region_enter_printf("index", "shared/do_write_index",
> the_repository, "%s", (*temp)->filename.buf);
> ret = do_write_index(si->base, *temp, 1);
> - trace2_region_enter_printf("index", "shared/do_write_index",
> + trace2_region_leave_printf("index", "shared/do_write_index",
> the_repository, "%s", (*temp)->filename.buf);
>
> if (ret)
>
Good catch!
Thanks,
Jeff
| LIB_OBJS += symlinks.o | ||
| LIB_OBJS += tag.o | ||
| LIB_OBJS += tempfile.o | ||
| LIB_OBJS += thread-utils.o |
There was a problem hiding this comment.
On the Git mailing list, SZEDER Gábor wrote (reply to this):
On Fri, Feb 22, 2019 at 02:25:01PM -0800, Jeff Hostetler via GitGitGadget wrote:
> From: Jeff Hostetler <[email protected]>
>
> Create a new unified tracing facility for git. The eventual intent is to
> replace the current trace_printf* and trace_performance* routines with a
> unified set of git_trace2* routines.
>
> In addition to the usual printf-style API, trace2 provides higer-level
> event verbs with fixed-fields allowing structured data to be written.
> This makes post-processing and analysis easier for external tools.
>
> Trace2 defines 3 output targets. These are set using the environment
> variables "GIT_TR2", "GIT_TR2_PERF", and "GIT_TR2_EVENT". These may be
> set to "1" or to an absolute pathname (just like the current GIT_TRACE).
>
> * GIT_TR2 is intended to be a replacement for GIT_TRACE and logs command
> summary data.
>
> * GIT_TR2_PERF is intended as a replacement for GIT_TRACE_PERFORMANCE.
> It extends the output with columns for the command process, thread,
> repo, absolute and relative elapsed times. It reports events for
> child process start/stop, thread start/stop, and per-thread function
> nesting.
>
> * GIT_TR2_EVENT is a new structured format. It writes event data as a
> series of JSON records.
Please document these new environment variables in
'Documentation/git.txt', where the other environment variables,
including GIT_TRACE_*, are already documented.
While doing so, please note that the description about the possible
values of these variables and of GIT_TRACE above is incomplete,
because it's not just "1" or an absolute pathname. Quoting the
description of GIT_TRACE:
If this variable is set to "1", "2" or "true" (comparison is case
insensitive), trace messages will be printed to stderr.
If the variable is set to an integer value greater than 2 and lower
than 10 (strictly) then Git will interpret this value as an open
file descriptor and will try to write the trace messages into this
file descriptor.
The way I see it in tr2_dst_get_trace_fd() below, this applies to
GIT_TRACE2* as well, and it even offers the possibility to specify a
Unix Domain Socket, too.
And sorry for barging in with a big bucket of paint this late, but,
really... why GIT_TR2 instead of GIT_TRACE2?
> +int tr2_dst_get_trace_fd(struct tr2_dst *dst)
> +{
> + const char *tgt_value;
> +
> + /* don't open twice */
> + if (dst->initialized)
> + return dst->fd;
> +
> + dst->initialized = 1;
> +
> + tgt_value = getenv(dst->env_var_name);
> +
> + if (!tgt_value || !strcmp(tgt_value, "") || !strcmp(tgt_value, "0") ||
> + !strcasecmp(tgt_value, "false")) {
> + dst->fd = 0;
> + return dst->fd;
> + }
> +
> + if (!strcmp(tgt_value, "1") || !strcasecmp(tgt_value, "true")) {
> + dst->fd = STDERR_FILENO;
> + return dst->fd;
> + }
> +
> + if (strlen(tgt_value) == 1 && isdigit(*tgt_value)) {
> + dst->fd = atoi(tgt_value);
> + return dst->fd;
> + }
> +
> + if (is_absolute_path(tgt_value))
> + return tr2_dst_try_path(dst, tgt_value);
> +
> +#ifndef NO_UNIX_SOCKETS
> + if (starts_with(tgt_value, PREFIX_AF_UNIX))
> + return tr2_dst_try_unix_domain_socket(dst, tgt_value);
> +#endif
> +
> + /* Always warn about malformed values. */
> + tr2_dst_malformed_warning(dst, tgt_value);
> + tr2_dst_trace_disable(dst);
> + return 0;
> +}
There was a problem hiding this comment.
On the Git mailing list, Derrick Stolee wrote (reply to this):
On 5/10/2019 1:28 PM, SZEDER Gábor wrote:
> On Fri, Feb 22, 2019 at 02:25:01PM -0800, Jeff Hostetler via GitGitGadget wrote:
>> From: Jeff Hostetler <[email protected]>
>>
>> * GIT_TR2_EVENT is a new structured format. It writes event data as a
>> series of JSON records.
>
> Please document these new environment variables in
> 'Documentation/git.txt', where the other environment variables,
> including GIT_TRACE_*, are already documented.
Thanks for the report!
> While doing so, please note that the description about the possible
> values of these variables and of GIT_TRACE above is incomplete,
> because it's not just "1" or an absolute pathname. Quoting the
> description of GIT_TRACE:
>
> If this variable is set to "1", "2" or "true" (comparison is case
> insensitive), trace messages will be printed to stderr.
>
> If the variable is set to an integer value greater than 2 and lower
> than 10 (strictly) then Git will interpret this value as an open
> file descriptor and will try to write the trace messages into this
> file descriptor.
>
> The way I see it in tr2_dst_get_trace_fd() below, this applies to
> GIT_TRACE2* as well, and it even offers the possibility to specify a
> Unix Domain Socket, too.
Please see [1] for a possible direction here.
[1] https://public-inbox.org/git/[email protected]/
> And sorry for barging in with a big bucket of paint this late, but,
> really... why GIT_TR2 instead of GIT_TRACE2?
I did not do anything in response to this. I'll leave that discussion
to others.
Thanks,
-Stolee
gitgitgadget bot
pushed a commit
that referenced
this pull request
Oct 21, 2024
Update clar from:
- 1516124 (Merge pull request #97 from pks-t/pks-whitespace-fixes, 2024-08-15).
To:
- 206accb (Merge pull request #108 from pks-t/pks-uclibc-without-wchar, 2024-10-21)
This update includes a bunch of fixes and improvements that we have
discussed in Git when initial support for clar was merged:
- There is a ".editorconfig" file now.
- Compatibility with Windows has been improved so that the clar
compiles on this platform without an issue. This has been tested
with Cygwin, MinGW and Microsoft Visual Studio.
- clar now uses CMake. This does not impact us at all as we wire up
the clar into our own build infrastructure anyway. This conversion
was done such that we can easily run CI jobs against Windows.
- Allocation failures are now checked for consistently.
- We now define feature test macros in "clar.c", which fixes
compilation on some platforms that didn't previously pull in
non-standard functions like lstat(3p) or strdup(3p). This was
reported by a user of OpenSUSE Leap.
- We stop using `struct timezone`, which is undefined behaviour
nowadays and results in a compilation error on some platforms.
- We now use the combination of mktemp(3) and mkdir(3) on SunOS, same
as we do on NonStop.
- We now support uClibc without support for <wchar.h>.
The most important bits here are the improved platform compatibility
with Windows, OpenSUSE, SunOS and uClibc.
Signed-off-by: Patrick Steinhardt <[email protected]>
Signed-off-by: Taylor Blau <[email protected]>
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
3 participants
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
V7 addresses:
[] squashes in the fixup for windows process ancestry calculation.
[] adds optional socket_type parameter to the unix domain socket syntax.
[] allow unix domain socket syntax to try both stream and dgram if socket_type not specified.
[] add Perl prereq checks for JSON:PP in trace2 tests.
[] minor clang-format cleanup.
Thanks
Jeff
Cc: [email protected]
Cc: [email protected]
Cc: [email protected]
Cc: [email protected]