Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

(Experimental) Trace2 base plus GVFS extensions #28

Merged
merged 9 commits into from
Oct 10, 2018

Conversation

jeffhostetler
Copy link

@jeffhostetler jeffhostetler commented Sep 26, 2018

Experimental merge of basic Trace2 plus GVFS extensions into our GVFS branch for testing purposes.
The basic Trace2 commits (the ones starting with "trace2:") will eventually be submitted upstream and
should be considered experimental at this time.

The GVFS extension commits (the ones starting with "gvfs:trace2:") depend on GVFS-specific code
and might not be up-streamed until much later.

The "t0051" and "mingw" commits fix a bug introduced shortly before 2.19.0 was released. These
commits have already been submitted upstream.

Copy link

@benpeart benpeart left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

s/higer/higher

Copy link

@benpeart benpeart left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In general I like the direction this is taking but... it is a large change and was hard to review effectively. I feel like it needs a design document added in Documentation\trace2.txt so that I can get an overview of what it is trying to accomplish and how it goes about it. The closest thing I could find was the trace2 header file.

Some questions I have include:

what providers are available?
how do they differ?
when would I use one vs another?
how are they configured/used?

Some examples of sample output would also be very helpful. I see lots of tracing added to the source and I'm sure you have a specific goal you were trying to accomplish but I just have a hard time figuring out what it is.

config.c Outdated
@@ -1504,6 +1504,11 @@ int git_default_config(const char *var, const char *value, void *cb)
return 0;
}

if (starts_with(var, "gvfs.")) {

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do you have any thoughts on all the other git_config_get_* functions that are in this file? I think it's fine to say they can get tracing added "as needed."

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think I want to move this somewhere else. probably in a separate iteration so that we don't alter the main init sequence and so that we can cluster all of the fields we want to echo to trace2.


tr2_sid_get();

atexit(tr2main_atexit_handler);

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do you need to protect against multiple initialize calls here?

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yeah, i should.

trace2.c Outdated

code &= 0xff;

if (!trace2_initialized)

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I wonder if moving this initialization test (and the others in this file) out into the macro so that it is inlined would make any difference in the perf overhead when tracing isn't enabled?

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

i thought i would. i put it inside the functions for now to avoid cluttering up the .h with more macros. i'll revisit now that things have settled down.

trace2.h Show resolved Hide resolved
trace2.h Outdated Show resolved Hide resolved
*
* Emits a 'worktree' event for this repo instance.
*/
void trace2_def_repo_fl(const char *file, int line,

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm trying to understand when it makes sense to do a generic trace event vs create a new custom event (like the repo event). Do you have any guidelines on when each is appropriate? I ask because I was surprised when I saw this was a custom event.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm hoping that most new calls can be region-enter/leave or data.
def-repo is special because I wanted to add a new column to the perf and event views
saying what repo is being operated on. that is, when google gets the in-proc submodule stuff finished, we'll get "do_read_index" calls for each repo they visit. with this, we'll get a repo# column for each do_read_index call.

trace2.h Outdated
* repo-id and printf message.
*
* Enter a new nesting level on the current thread and remember the
* current time. This controls the indenting of subsequent thread

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

by "subsequent thread events" I assume you mean "all subsequent events on this thread" and not just thread specific events (ie thread_start/thread_exit)

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yes, thanks.

* This event implicitly contains information about thread, nesting region,
* and optional repo-id.
*
* On event-based TRACE2 targets, this generates a 'data' event suitable

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is there some documentation somewhere on what TRACE2 targets exist and how they behave? This information on how event-based targets and printf-based targets is interesting/good to know but is buried here where it is unlikely someone will discover it.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

not yet. i need to write the design doc/summary.

@jeffhostetler jeffhostetler force-pushed the gvfs-trace2-v1 branch 6 times, most recently from 4d83a13 to d983757 Compare October 4, 2018 15:44
@jeffhostetler jeffhostetler force-pushed the gvfs-trace2-v1 branch 5 times, most recently from 001c214 to 7bb7dbe Compare October 8, 2018 20:50

for_each_wanted_builtin(j, tgt_j) {
if (tgt_j->pfn_error_va_fl)
tgt_j->pfn_error_va_fl(file, line, fmt, ap);
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@jeffhostetler I got a segfault here when running GIT_TR2_PERF=1 git push origin topic when a force-push was required.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Here is my GDB data:

(gdb) run push gh-stolee push-trace
Starting program: /home/stolee/git/git push gh-stolee push-trace
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
14:04:16.895179 common-main.c:36                  | d0 | main                     | version      |     |           |           |            | 2.19.0.gvfs.1.23.g86fac7d809
14:04:16.900169 common-main.c:36                  | d0 | main                     | start        |     |           |           |            |  /home/stolee/git/git push gh-stolee push-trace
14:04:16.900257 repository.c:117                  | d0 | main                     | def_repo     | r1  |           |           |            | worktree:/home/stolee/git
14:04:16.910344 git.c:486                         | d0 | main                     | cmd_verb     |     |           |           |            | push
14:04:17.133183 run-command.c:710                 | d0 | main                     | child_start  |     |  0.238003 |           |            | [ch0] class:? argv: ssh git@github.com 'git-receive-pack '\''derrickstolee/git.git'\'''
14:04:19.032353 run-command.c:956                 | d0 | main                     | child_exit   |     |  2.137168 |  1.899165 |            | [ch0] code:0
To github.com:derrickstolee/git.git
 ! [rejected]              push-trace -> push-trace (non-fast-forward)
error: failed to push some refs to 'git@github.com:derrickstolee/git.git'

Program received signal SIGSEGV, Segmentation fault.
__strlen_avx2 () at ../sysdeps/x86_64/multiarch/strlen-avx2.S:62
62      ../sysdeps/x86_64/multiarch/strlen-avx2.S: No such file or directory.
(gdb) bt
#0  __strlen_avx2 () at ../sysdeps/x86_64/multiarch/strlen-avx2.S:62
#1  0x00007ffff73fd4d3 in _IO_vfprintf_internal (s=s@entry=0x7fffffffd6b0, format=format@entry=0x55555575dce0 "failed to push some refs to '%s'", ap=ap@entry=0x7fffffffd830) at vfprintf.c:1643
#2  0x00007ffff74d2169 in ___vsnprintf_chk (s=0x555555a4c080 "failed to push some refs to 'git", maxlen=<optimized out>, flags=flags@entry=1, slen=slen@entry=18446744073709551615,
    format=format@entry=0x55555575dce0 "failed to push some refs to '%s'", args=args@entry=0x7fffffffd830) at vsnprintf_chk.c:63
#3  0x00005555556f86d4 in vsnprintf (__ap=0x7fffffffd830, __fmt=0x55555575dce0 "failed to push some refs to '%s'", __n=<optimized out>, __s=<optimized out>) at /usr/include/x86_64-linux-gnu/bits/stdio2.h:77
#4  strbuf_vaddf (sb=sb@entry=0x7fffffffd870, fmt=0x55555575dce0 "failed to push some refs to '%s'", ap=0x7fffffffd900) at strbuf.c:343
#5  0x0000555555709b1c in fn_error_va_fl (file=0x55555578f9de "usage.c", line=59, fmt=<optimized out>, ap=<optimized out>) at trace2/tr2_tgt_perf.c:226
#6  0x0000555555705566 in trace2_cmd_error_va_fl (file=0x55555578f9de "usage.c", line=59, fmt=0x55555575dce0 "failed to push some refs to '%s'", ap=0x7fffffffd900) at trace2.c:213
#7  0x00005555557202ba in error (err=<optimized out>) at usage.c:213
#8  0x00005555555d25c4 in push_with_options (transport=0x555555a54460, rs=rs@entry=0x5555559f5320 <rs>, flags=flags@entry=0) at builtin/push.c:361
#9  0x00005555555d338c in do_push (push_options=0x5555559e3140 <push_options_config>, flags=0, repo=<optimized out>) at builtin/push.c:426
#10 cmd_push (argc=<optimized out>, argv=<optimized out>, prefix=<optimized out>) at builtin/push.c:636
#11 0x000055555556f2c6 in run_builtin (argv=<optimized out>, argc=<optimized out>, p=<optimized out>) at git.c:490
#12 handle_builtin (argc=<optimized out>, argv=<optimized out>) at git.c:724
#13 0x000055555557032f in run_argv (argv=0x7fffffffe2c0, argcp=0x7fffffffe2cc) at git.c:792
#14 cmd_main (argc=<optimized out>, argv=<optimized out>) at git.c:914
#15 0x000055555556edf2 in main (argc=4, argv=0x7fffffffe528) at common-main.c:46
(gdb) f 6
#6  0x0000555555705566 in trace2_cmd_error_va_fl (file=0x55555578f9de "usage.c", line=59, fmt=0x55555575dce0 "failed to push some refs to '%s'", ap=0x7fffffffd900) at trace2.c:213
213                             tgt_j->pfn_error_va_fl(file, line, fmt, ap);

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I ran valgrind which may help a little bit:

==33024== Invalid read of size 1
==33024==    at 0x4C32CF2: strlen (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==33024==    by 0x54DD4D2: vfprintf (vfprintf.c:1643)
==33024==    by 0x55B2168: __vsnprintf_chk (vsnprintf_chk.c:63)
==33024==    by 0x2AC6F3: vsnprintf (stdio2.h:77)
==33024==    by 0x2AC6F3: strbuf_vaddf (strbuf.c:343)
==33024==    by 0x2BDB3B: fn_error_va_fl (tr2_tgt_perf.c:226)
==33024==    by 0x2B9585: trace2_cmd_error_va_fl (trace2.c:213)
==33024==    by 0x2D42D9: error (usage.c:213)
==33024==    by 0x1865E1: push_with_options (push.c:362)
==33024==    by 0x1873AB: do_push (push.c:427)
==33024==    by 0x1873AB: cmd_push (push.c:637)
==33024==    by 0x1232C5: run_builtin (git.c:490)
==33024==    by 0x1232C5: handle_builtin (git.c:724)
==33024==    by 0x12432E: run_argv (git.c:792)
==33024==    by 0x12432E: cmd_main (git.c:914)
==33024==    by 0x122DF1: main (common-main.c:46)
==33024==  Address 0x1 is not stack'd, malloc'd or (recently) free'd
==33024==
==33024==
==33024== Process terminating with default action of signal 11 (SIGSEGV)
==33024==  Access not within mapped region at address 0x1
==33024==    at 0x4C32CF2: strlen (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==33024==    by 0x54DD4D2: vfprintf (vfprintf.c:1643)
==33024==    by 0x55B2168: __vsnprintf_chk (vsnprintf_chk.c:63)
==33024==    by 0x2AC6F3: vsnprintf (stdio2.h:77)
==33024==    by 0x2AC6F3: strbuf_vaddf (strbuf.c:343)
==33024==    by 0x2BDB3B: fn_error_va_fl (tr2_tgt_perf.c:226)
==33024==    by 0x2B9585: trace2_cmd_error_va_fl (trace2.c:213)
==33024==    by 0x2D42D9: error (usage.c:213)
==33024==    by 0x1865E1: push_with_options (push.c:362)
==33024==    by 0x1873AB: do_push (push.c:427)
==33024==    by 0x1873AB: cmd_push (push.c:637)
==33024==    by 0x1232C5: run_builtin (git.c:490)
==33024==    by 0x1232C5: handle_builtin (git.c:724)
==33024==    by 0x12432E: run_argv (git.c:792)
==33024==    by 0x12432E: cmd_main (git.c:914)
==33024==    by 0x122DF1: main (common-main.c:46)

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@jeffhostetler The problem is that vsnprintf mutates the va_args as it executes. I verified this by swapping the order of the vreportf and the trace2_cmd_error_va in error_builtin. If I swap them, then your error message appears and the segfault happens during the vreportf.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I omitted the va_copy() on the va_list args when I moved code over from my SLOG version.
I just pushed an update to fix this.

usage.c Outdated
* TODO It would be nice to update the call sites to pass both
* the static usage string and the detailed error message.
*/

exit(129);
}

static NORETURN void die_builtin(const char *err, va_list params)
{
vreportf("fatal: ", err, params);
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

copy params before this vreportf or else they will be mutated. Same with error_builtin below.

Create a test-tool helper to create the server side of
a windows named pipe, wait for a client connection, and
copy data written to the pipe to stdout.

Create t0051 test to route GIT_TRACE output of a command
to a named pipe using the above test-tool helper.

Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com>
Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com>
trace2.c Outdated
for_each_wanted_builtin(j, tgt_j) {
if (tgt_j->pfn_region_enter_printf_va_fl) {
va_list copy_ap;
va_copy(copy_ap, ap);
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

if (ap)
	va_copy(copy_ap, ap);

or else nullrefs when called form trace2_region_enter_f1.

trace2.c Outdated
for_each_wanted_builtin(j, tgt_j) {
if (tgt_j->pfn_region_leave_printf_va_fl) {
va_list copy_ap;
va_copy(copy_ap, ap);
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

if (ap)
	va_copy(copy_ap, ap);

or else nullrefs when called form trace2_region_leave_f1.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

(there are two more that need to be protected.)

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks! I just ran some tests on Linux and I saw some of these failures. They don't seem to be a problem on Windows.

I'm pushing a better fix for this.

@derrickstolee
Copy link
Collaborator

I'm running make coverage-test using all your trace2 environment variables. When that's done, I'll share the coverage-diff to see if we are missing any coverage.

@derrickstolee
Copy link
Collaborator

Uncovered lines in trace2.c:

    #####:  125:static void tr2main_signal_handler(int signo)
    #####:  132:        us_now = getnanotime() / 1000;
    #####:  133:        us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
    #####:  135:        for_each_wanted_builtin(j, tgt_j) {
    #####:  136:                if (tgt_j->pfn_signal)
    #####:  137:                        tgt_j->pfn_signal(us_elapsed_absolute, signo);
    #####:  140:        sigchain_pop(signo);
    #####:  141:        raise(signo);
    #####:  142:}
    #####:  154:                return;
    #####:  211:        for_each_wanted_builtin(j, tgt_j) {
    #####:  212:                if (tgt_j->pfn_error_va_fl) {
    #####:  214:                        if (ap)
    #####:  215:                                va_copy(copy_ap, ap);
    #####:  216:                        tgt_j->pfn_error_va_fl(file, line, fmt, copy_ap);
    #####:  217:                        va_end(copy_ap);
    #####:  222:void trace2_cmd_path_fl(const char *file, int line, const char *pathname)
    #####:  227:        if (!trace2_enabled)
    #####:  228:                return;
    #####:  230:        for_each_wanted_builtin(j, tgt_j) {
    #####:  231:                if (tgt_j->pfn_command_path_fl)
    #####:  232:                        tgt_j->pfn_command_path_fl(file, line, pathname);
    #####:  244:        for_each_wanted_builtin(j, tgt_j) {
    #####:  245:                if (tgt_j->pfn_command_verb_fl)
    #####:  246:                        tgt_j->pfn_command_verb_fl(file, line, command_verb);
    #####:  259:        for_each_wanted_builtin(j, tgt_j) {
    #####:  260:                if (tgt_j->pfn_alias_fl)
    #####:  261:                        tgt_j->pfn_alias_fl(file, line, alias, argv);
    #####:  270:        tr2_cfg_list_config_fl(file, line);
    #####:  279:        tr2_cfg_set_fl(file, line, key, value);
    #####:  293:        us_now = getnanotime() / 1000;
    #####:  294:        us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
    #####:  296:        cmd->trace2_child_id = tr2tls_locked_increment(&tr2_next_child_id);
    #####:  297:        cmd->trace2_child_us_start = us_now;
    #####:  299:        for_each_wanted_builtin(j, tgt_j) {
    #####:  300:                if (tgt_j->pfn_child_start_fl)
    #####:  301:                        tgt_j->pfn_child_start_fl(file, line,
    #####:  319:        us_now = getnanotime() / 1000;
    #####:  320:        us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
    #####:  322:        if (cmd->trace2_child_us_start)
    #####:  323:                us_elapsed_child = us_now - cmd->trace2_child_us_start;
    #####:  325:                us_elapsed_child = 0;
    #####:  327:        for_each_wanted_builtin(j, tgt_j) {
    #####:  328:                if (tgt_j->pfn_child_exit_fl)
    #####:  329:                        tgt_j->pfn_child_exit_fl(
    #####:  347:        us_now = getnanotime() / 1000;
    #####:  348:        us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
    #####:  350:        for_each_wanted_builtin(j, tgt_j) {
    #####:  351:                if (tgt_j->pfn_exec_fl)
    #####:  352:                        tgt_j->pfn_exec_fl(file, line, us_elapsed_absolute,
    #####:  367:        us_now = getnanotime() / 1000;
    #####:  368:        us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
    #####:  370:        for_each_wanted_builtin(j, tgt_j) {
    #####:  371:                if (tgt_j->pfn_exec_result_fl)
    #####:  372:                        tgt_j->pfn_exec_result_fl(file, line,
    #####:  378:void trace2_thread_start_fl(const char *file, int line,
    #####:  386:        if (!trace2_enabled)
    #####:  387:                return;
    #####:  389:        if (tr2tls_is_main_thread())
    #####:  400:                trace2_region_enter_printf_fl(file, line, NULL, NULL, NULL,
    #####:  403:                return;
    #####:  406:        us_now = getnanotime() / 1000;
    #####:  407:        us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
    #####:  409:        tr2tls_create_self(thread_name);
    #####:  411:        for_each_wanted_builtin(j, tgt_j) {
    #####:  412:                if (tgt_j->pfn_thread_start_fl)
    #####:  413:                        tgt_j->pfn_thread_start_fl(file, line,
    #####:  418:void trace2_thread_exit_fl(const char *file, int line)
    #####:  426:        if (!trace2_enabled)
    #####:  427:                return;
    #####:  429:        if (tr2tls_is_main_thread())
    #####:  440:                trace2_region_leave_printf_fl(file, line, NULL, NULL, NULL,
    #####:  442:                return;
    #####:  445:        us_now = getnanotime() / 1000;
    #####:  446:        us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
    #####:  453:        tr2tls_pop_unwind_self();
    #####:  454:        us_elapsed_thread = tr2tls_region_elasped_self(us_now);
    #####:  456:        for_each_wanted_builtin(j, tgt_j) {
    #####:  457:                if (tgt_j->pfn_thread_exit_fl)
    #####:  458:                        tgt_j->pfn_thread_exit_fl(file, line,
    #####:  463:        tr2tls_unset_self();
    #####:  466:void trace2_def_param_fl(const char *file, int line,
    #####:  472:        if (!trace2_enabled)
    #####:  473:                return;
    #####:  475:        for_each_wanted_builtin(j, tgt_j) {
    #####:  476:                if (tgt_j->pfn_param_fl)
    #####:  477:                        tgt_j->pfn_param_fl(file, line, param, value);
    #####:  490:        if (repo->trace2_repo_id)
    #####:  491:                return;
    #####:  493:        repo->trace2_repo_id = tr2tls_locked_increment(&tr2_next_repo_id);
    #####:  495:        for_each_wanted_builtin(j, tgt_j) {
    #####:  496:                if (tgt_j->pfn_repo_fl)
    #####:  497:                        tgt_j->pfn_repo_fl(file, line, repo);
    #####:  515:        us_now = getnanotime() / 1000;
    #####:  516:        us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
    #####:  522:        for_each_wanted_builtin(j, tgt_j) {
    #####:  523:                if (tgt_j->pfn_region_enter_printf_va_fl) {
    #####:  525:                        if (ap)
    #####:  526:                                va_copy(copy_ap, ap);
    #####:  527:                        tgt_j->pfn_region_enter_printf_va_fl(
    #####:  530:                        va_end(copy_ap);
    #####:  534:        tr2tls_push_self(us_now);
    #####:  592:        us_now = getnanotime() / 1000;
    #####:  593:        us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
    #####:  601:        us_elapsed_region = tr2tls_region_elasped_self(us_now);
    #####:  603:        tr2tls_pop_self();
    #####:  605:        for_each_wanted_builtin(j, tgt_j) {
    #####:  606:                if (tgt_j->pfn_region_leave_printf_va_fl) {
    #####:  608:                        if (ap)
    #####:  609:                                va_copy(copy_ap, ap);
    #####:  610:                        tgt_j->pfn_region_leave_printf_va_fl(
    #####:  615:                        va_end(copy_ap);
    #####:  675:        us_now = getnanotime() / 1000;
    #####:  676:        us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
    #####:  677:        us_elapsed_region = tr2tls_region_elasped_self(us_now);
    #####:  679:        for_each_wanted_builtin(j, tgt_j) {
    #####:  680:                if (tgt_j->pfn_data_fl)
    #####:  681:                        tgt_j->pfn_data_fl(file, line, us_elapsed_absolute,
    #####:  698:        strbuf_addf(&buf_string, "%"PRIdMAX, value);
    #####:  699:        trace2_data_string_fl(file, line, category, repo, key, buf_string.buf);
    #####:  700:        strbuf_release(&buf_string);
    #####:  703:void trace2_printf_va_fl(const char *file, int line,
    #####:  711:        if (!trace2_enabled)
    #####:  712:                return;
    #####:  714:        us_now = getnanotime() / 1000;
    #####:  715:        us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
    #####:  717:        for_each_wanted_builtin(j, tgt_j) {
    #####:  718:                if (tgt_j->pfn_printf_va_fl) {
    #####:  720:                        if (ap)
    #####:  721:                                va_copy(copy_ap, ap);
    #####:  722:                        tgt_j->pfn_printf_va_fl(file, line, us_elapsed_absolute,
    #####:  724:                        va_end(copy_ap);
    #####:  729:void trace2_printf_fl(const char *file, int line,
    #####:  734:        va_start(ap, fmt);
    #####:  735:        trace2_printf_va_fl(file, line, fmt, ap);
    #####:  736:        va_end(ap);
    #####:  737:}

Looks like there are a lot of methods that we haven't used in enough places to feel they are exercised.

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.

Calls to trace2 functions log to any of the 3 output targets enabled
without the need to call different trace_printf* or trace_performance*
routines.

Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com>
Add trace2_region_enter() and trace2_region_leave() calls around the
various phases of a status scan.  This gives elapsed time for each
phase in the GIT_TR2_PERF and GIT_TR2_EVENT trace target.

Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com>
Classify editor, pager, and sub-process child processes.

The former two can be used to identify interactive commands,
for example.  A later effort could classify other types of
commands, such as "gc", "hook", and etc.

Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com>
Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com>
Add trace2 events when reading and writing the index.

Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com>
Add trace2 region and data events describing attempts to deserialize
status data using a status cache.

A category:status, label:deserialize region is pushed around the
deserialize code.

Deserialization results when reading from a file are:
    category:status, path   = <path>
    category:status, polled = <number_of_attempts>
    category:status, result = "ok" | "reject"

When reading from STDIN are:
    category:status, path   = "STDIN"
    category:status, result = "ok" | "reject"

Status will fallback and run a normal status scan when a "reject"
is reported (unless "--deserialize-wait=fail").  If "ok" is reported,
status was able to use the status cache and avoid scanning the workdir.

Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com>
Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com>
@jeffhostetler
Copy link
Author

@derrickstolee I'm not surprised that we don't have coverage on some of those functions. I omitted thread-start/-exit calls for now. I'll address this more when I add unit tests for trace2.

Copy link
Member

@kewillford kewillford left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Haven't looked this over thoroughly.

@jeffhostetler jeffhostetler merged commit 6ee82ac into microsoft:gvfs-2.19.0 Oct 10, 2018
*/
static int mingw_is_local_named_pipe_path(const char *filename)
{
return (IS_SBS(filename[0]) &&
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Check filename length before indexing?

derrickstolee added a commit to microsoft/VFSForGit that referenced this pull request Oct 12, 2018
…racked files

Update the package for GitForWindows to include tracing information.

Includes the following Git PRs:

* [36 Avoid `sane_execvp` in `git rebase` and `git stash`](microsoft/git#36)
* [34 Add Trace2 regions to 'pack-objects'](microsoft/git#34)
* [28 Trace2 base plus GVFS extensions](microsoft/git#28)
* [33 virtualfilesystem: check if directory is included](microsoft/git#33)
* [31 Revert "gvfs: add a perf test for reading the index"](microsoft/git#31)
* [32 compat/poll: prepare for targeting Windows Vista](microsoft/git#32)
* [22 Enable the filesystem cache (fscache) in refresh_index()](microsoft/git#22)
* [27 virtualfilesystem: fix bug with symlinks being ignored](microsoft/git#27)
* [23 Unpack trees with cache tree gvfs](microsoft/git#23)
* [15 virtualfilesystem: don't run the virtual file system hook if the index has been redirected](microsoft/git#15)
* Includes Git 2.19.0.

This also includes VFS for Git updates from Kevin Willford's work:

**Fix missing untracked files when created in subfolder**

Add to the test to create multiple level of folders and files in those folder to make sure they show up as untracked files.

Update the git for windows version that has the fix.

Fixes #358
dscho pushed a commit that referenced this pull request Oct 15, 2018
(Experimental) Trace2 base plus GVFS extensions
dscho pushed a commit that referenced this pull request Oct 18, 2018
(Experimental) Trace2 base plus GVFS extensions
dscho pushed a commit that referenced this pull request Nov 21, 2018
(Experimental) Trace2 base plus GVFS extensions
dscho pushed a commit that referenced this pull request Nov 26, 2018
(Experimental) Trace2 base plus GVFS extensions
dscho pushed a commit that referenced this pull request Dec 2, 2018
(Experimental) Trace2 base plus GVFS extensions
dscho pushed a commit that referenced this pull request Dec 10, 2018
(Experimental) Trace2 base plus GVFS extensions
derrickstolee pushed a commit that referenced this pull request Dec 17, 2018
(Experimental) Trace2 base plus GVFS extensions
@jeffhostetler jeffhostetler deleted the gvfs-trace2-v1 branch August 16, 2019 21:46
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants