[WIP] [do not merge] Trace2 part v2

[jeffhostetler]

This patch series contains additional (v2) trace2 features since the jeffhostetler/gvfs-trace2-v1 branch was merged into v2.19.1.gvfs.1.

The first 2 commits are already upstream, but needed to fix the test suite.

The v2 changes here add to the v1 changes already present in the tree. Some of these commits
are refinements/refactorings that could/should be squashed into the v1 series when we upstream
both parts.

This series adds additional fields and cleans up some existing fields.

It includes some unit tests, but more work is needed here.

[derrickstolee]

I got a warning as I built this, not sure of the impact:

from run-command.c:1:                                                                                            
run-command.c: In function ‘sane_execvp’:                                                                                         
trace2.h:180:44: warning: passing argument 4 of ‘trace2_exec_fl’ from incompatible pointer type [-Wincompatible-pointer-types]    
  trace2_exec_fl(__FILE__, __LINE__, (exe), (argv))                                                                               
                                            ^                                                                                     
run-command.c:232:16: note: in expansion of macro ‘trace2_exec’                                                                   
  int exec_id = trace2_exec(file, argv);                                                                                          
                ^~~~~~~~~~~                                                                                                       
trace2.h:176:5: note: expected ‘const char **’ but argument is of type ‘char * const*’                                            
 int trace2_exec_fl(const char *file, int line,                                                                                   
     ^~~~~~~~~~~~~~                                                                                                               
    CC send-pack.o                                                                                                                
    CC sequencer.o                                                                                                                
sequencer.c: In function ‘write_basic_state’:                                                                                     
sequencer.c:2375:37: warning: zero-length gnu_printf format string [-Wformat-zero-length]                                         
   write_file(rebase_path_verbose(), "");                                                                                         
                                     ^~                                                                                           

[derrickstolee]

It might be nice to have a test verifying this hierarchy is logged correctly.

I'll be sure to run my test suite with GIT_TR2_PERF=/dev/null to ensure we cover these bits.

[jeffhostetler]

I have a few in t0212, but it's a bit inconclusive since i use the same exe and have it invoke itself,
so it looks like "trace2/trace2/trace2".

We should run with GIT_TR2, GIT_TR2_PERF, and GIT_TR2_EVENT all set when we do a coverage
run so that we get all three drivers active.

[derrickstolee]

@jeffhostetler @benpeart @kewillford I edited the PR build definition to have an extra mode that tests with some extra GIT_TEST_* variables, along with GIT_TR2* variables (piped to /dev/null). Here is the build for this PR. I'll keep an eye on this to see if it gives us any trouble.

[derrickstolee]

Also, here is a build for the target branch.

It appears we have something going wrong in the tests when we run with the tracing variables:

(in t0001-init.sh, I think)
expecting success: 
	write_script script <<-\EOF &&
	env |
		sed -n \
			-e "/^GIT_PREFIX=/d" \
			-e "/^GIT_TEXTDOMAINDIR=/d" \
			-e "/^GIT_/s/=.*//p" |
		sort
	EOF
	./script >expected &&
	git config alias.script \!./script &&
	( mkdir sub && cd sub && git script >../actual ) &&
	test_cmp expected actual

+ write_script script
+ echo #!/bin/sh
+ cat
+ chmod +x script
+ ./script
+ git config alias.script !./script
+ mkdir sub
+ cd sub
+ git script
+ test_cmp expected actual
+ GIT_ALLOC_LIMIT=0 diff -u expected actual
--- expected	2018-12-05 19:39:45.457322621 +0000
+++ actual	2018-12-05 19:39:45.469322744 +0000
@@ -19,5 +19,7 @@
 GIT_TEST_VALIDATE_INDEX_CACHE_ENTRIES
 GIT_TR2
 GIT_TR2_EVENT
+GIT_TR2_PARENT_SID
+GIT_TR2_PARENT_VERB
 GIT_TR2_PERF
 GIT_TRACE_BARE
error: last command exited with $?=1
not ok 6 - No extra GIT_* on alias scripts

[derrickstolee]

I got a little farther this time, and hit failures on some submodule tests. Good enough for now.

builtin/commit.c
3d69c5ecab9 builtin/commit.c 1394) reject_implicit = 1;
3d69c5ecab9 builtin/commit.c 1557) trace2_cmd_subverb("implicit-deserialize");
3d69c5ecab9 builtin/commit.c 1558) trace2_data_string("status", the_repository, "deserialize/reject",

builtin/rebase.c
5abf164116f 1150) if (trace2_is_enabled()) {
5abf164116f 1151) if (is_interactive(&options))
5abf164116f 1152) trace2_cmd_subverb("interactive");
5abf164116f 1153) else if (exec.nr)
5abf164116f 1154) trace2_cmd_subverb("interactive-exec");
5abf164116f 1156) trace2_cmd_subverb(action_names[action]);

exec-cmd.c
adee7958928 exec-cmd.c 340) trace_printf("trace: exec failed: %s\n", strerror(errno));

git.c
adee7958928 942) return 1;

run-command.c
adee7958928  240) int ec = errno;
adee7958928  241) trace2_exec_result(exec_id, ec);
adee7958928  242) errno = ec;

trace2.c
adee7958928 178) int trace2_is_enabled(void)
adee7958928 180) return trace2_enabled;
adee7958928 403) void trace2_exec_result_fl(const char *file, int line, int exec_id, int code)
1cfe11dfe09 746) void trace2_data_json_fl(const char *file, int line,
1cfe11dfe09 758) if (!trace2_enabled)
1cfe11dfe09 759) return;
1cfe11dfe09 761) us_now = getnanotime() / 1000;
1cfe11dfe09 762) us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
1cfe11dfe09 763) us_elapsed_region = tr2tls_region_elasped_self(us_now);
1cfe11dfe09 765) for_each_wanted_builtin(j, tgt_j) {
1cfe11dfe09 766) if (tgt_j->pfn_data_fl)
1cfe11dfe09 767) tgt_j->pfn_data_json_fl(file, line, us_elapsed_absolute,

trace2/tr2_tgt_event.c
adee7958928 403) jw_object_intmax(&jw, "exec_id", exec_id);
1cfe11dfe09 530) static void fn_data_json_fl(const char *file, int line,
1cfe11dfe09 538) const char *event_name = "data_json";
1cfe11dfe09 539) struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
1cfe11dfe09 540) if (ctx->nr_open_regions <= tr2env_event_nesting_wanted) {
1cfe11dfe09 541) struct json_writer jw = JSON_WRITER_INIT;
1cfe11dfe09 542) double t_abs = (double)us_elapsed_absolute / 1000000.0;
1cfe11dfe09 543) double t_rel = (double)us_elapsed_region / 1000000.0;
1cfe11dfe09 545) jw_object_begin(&jw, 0);
1cfe11dfe09 546) event_fmt_prepare(event_name, file, line, repo, &jw);
1cfe11dfe09 547) jw_object_double(&jw, "t_abs", 6, t_abs);
1cfe11dfe09 548) jw_object_double(&jw, "t_rel", 6, t_rel);
1cfe11dfe09 549) jw_object_intmax(&jw, "nesting", ctx->nr_open_regions);
1cfe11dfe09 550) jw_object_string(&jw, "category", category);
1cfe11dfe09 551) jw_object_string(&jw, "key", key);
1cfe11dfe09 552) jw_object_sub_jw(&jw, "value", value);
1cfe11dfe09 553) jw_end(&jw);
1cfe11dfe09 555) tr2_dst_write_line(&tr2dst_event, &jw.json);
1cfe11dfe09 556) jw_release(&jw);
1cfe11dfe09 558) }

trace2/tr2_tgt_normal.c
adee7958928 266) strbuf_addf(&buf_payload, "exec_result[%d] code:%d", exec_id, code);

trace2/tr2_tgt_perf.c
adee7958928 411) strbuf_addf(&buf_payload, "id:%d code:%d", exec_id, code);
1cfe11dfe09 510) static void fn_data_json_fl(const char *file, int line,
1cfe11dfe09 518) const char *event_name = "data_json";
1cfe11dfe09 519) struct strbuf buf_payload = STRBUF_INIT;
1cfe11dfe09 521) strbuf_addf(&buf_payload, "%s:%s", key, value->json.buf);
1cfe11dfe09 523) perf_io_write_fl(file, line, event_name, repo,
1cfe11dfe09 526) strbuf_release(&buf_payload);
1cfe11dfe09 527) }

wt-status-deserialize.c
3d69c5ecab9  17) set_deserialize_reject_reason("status-cache/access");
3d69c5ecab9  68) set_deserialize_reject_reason("index/not-found");
3d69c5ecab9 103) set_deserialize_reject_reason("excludes/changed");
3d69c5ecab9 163) set_deserialize_reject_reason("v1-header/invalid-index-mtime");
3d69c5ecab9 247) set_deserialize_reject_reason("v1-header/invalid-commit-sha");
3d69c5ecab9 263) set_deserialize_reject_reason("v1-header/unexpected-line");
3d69c5ecab9 269) set_deserialize_reject_reason("v1-header/missing-index-mtime");
3d69c5ecab9 274) set_deserialize_reject_reason("v1-header/missing-core-excludes");
3d69c5ecab9 279) set_deserialize_reject_reason("v1-header/missing-repo-excludes");
3d69c5ecab9 501) set_deserialize_reject_reason("args/untracked-files");
3d69c5ecab9 543) set_deserialize_reject_reason("v1-data/unexpected-line");
3d69c5ecab9 565) set_deserialize_reject_reason("status-cache/unsupported-version");
3d69c5ecab9 586) set_deserialize_reject_reason("args/multiple-pathspecs");
3d69c5ecab9 614) set_deserialize_reject_reason("args/is-initial-changed");
3d69c5ecab9 619) set_deserialize_reject_reason("args/branch-changed");
3d69c5ecab9 624) set_deserialize_reject_reason("args/reference-changed");
3d69c5ecab9 631) set_deserialize_reject_reason("args/whence-changed");
3d69c5ecab9 665) set_deserialize_reject_reason("args/detect-rename-changed");
3d69c5ecab9 670) set_deserialize_reject_reason("args/rename-score-changed");
3d69c5ecab9 675) set_deserialize_reject_reason("args/rename-limit-changed");
3d69c5ecab9 681) set_deserialize_reject_reason("args/commit-changed");

Commits introducing uncovered code:
Jeff Hostetler      1cfe11dfe0: trace2: add data_json event type
Jeff Hostetler      3d69c5ecab: gvfs:trace2: add status cache deserialization failure reasons
Jeff Hostetler      5abf164116: trace2: add subverb for rebase
Jeff Hostetler      adee795892: trace2: general cleanup/refactoring after v1

[derrickstolee]

My comments are minor so far. Mostly fix the build breaks, and then I want to run my coverage tool on it to see what we are missing.

[benpeart]

I see a ./technical/api-trace.txt but was unable to find any documentation on trace2. I'd like to see a document that covers the design, motivations/requirements, how to use it, etc. It should include descriptions of how to use the built in trace handlers as well as the API definition and how to write a custom one. Apologies if that is all there and I just missed it.

[benpeart]

I got build errors with this as well:

t/helper/test-trace2.c:47:5: error: no previous prototype for 'ut_001return' [-Werror=missing-prototypes]
int ut_001return(int argc, const char **argv)
^~~~~~~~~~~~
t/helper/test-trace2.c:66:5: error: no previous prototype for 'ut_002exit' [-Werror=missing-prototypes]
int ut_002exit(int argc, const char **argv)
^~~~~~~~~~
t/helper/test-trace2.c:86:5: error: no previous prototype for 'ut_003error' [-Werror=missing-prototypes]
int ut_003error(int argc, const char **argv)
^~~~~~~~~~~
t/helper/test-trace2.c:132:5: error: no previous prototype for 'ut_004child' [-Werror=missing-prototypes]
int ut_004child(int argc, const char **argv)
^~~~~~~~~~~
t/helper/test-trace2.c:168:5: error: no previous prototype for 'ut_005exec' [-Werror=missing-prototypes]
int ut_005exec(int argc, const char **argv)
^~~~~~~~~~
t/helper/test-trace2.c:179:5: error: no previous prototype for 'ut_006data' [-Werror=missing-prototypes]
int ut_006data(int argc, const char **argv)
^~~~~~~~~~

[jeffhostetler]

I do want to add some tests that demonstrate the nested regions and data in the perf view.
And some multi-threading tests demonstrating that regions and data are isolated by thread.
That will probably also pop out of the coverage report.

[jeffhostetler]

@benpeart yeah, the ut_* compiler warnings are from DEVELOPER mode. I'm pushing up a fix for them now.

[jeffhostetler]

@derrickstolee I just pushed a fix for t0001, so hopefully the coverage run will get a little further.

[jeffhostetler]

Since 2.20.* is out, I'm going to deprecate this PR against 2.19 and open a new one after rebasing.

[jeffhostetler]

closing in favor of #100