From 8b9680072a6c2e38be5ae1f87e531c222cdc4b81 Mon Sep 17 00:00:00 2001 From: Elliot Glaysher Date: Wed, 28 Nov 2018 16:34:32 -0800 Subject: [PATCH] Add support for trace_event files. This adds a -j parameter which writes traces of your Urbit's function call stack to a json file, readable by Chrome's about://tracing or the standalone trace-viewer webapp. --- include/noun/allocate.h | 1 + include/noun/options.h | 3 +- include/noun/trace.h | 21 +++++ include/vere/vere.h | 2 + noun/jets.c | 55 +++++++++--- noun/manage.c | 3 + noun/trace.c | 181 +++++++++++++++++++++++++++++++++++++++- noun/vortex.c | 3 + vere/main.c | 14 +++- vere/raft.c | 5 ++ vere/reck.c | 2 + 11 files changed, 275 insertions(+), 15 deletions(-) diff --git a/include/noun/allocate.h b/include/noun/allocate.h index 11199014d1..32a8e8d37a 100644 --- a/include/noun/allocate.h +++ b/include/noun/allocate.h @@ -146,6 +146,7 @@ c3_d nox_d; // nock steps c3_d cel_d; // cell allocations u3_noun don; // (list batt) + u3_noun trace; // (list trace) u3_noun day; // doss, only in u3H (moveme) } pro; diff --git a/include/noun/options.h b/include/noun/options.h index 7eb5d540b8..9ac90512ea 100644 --- a/include/noun/options.h +++ b/include/noun/options.h @@ -25,7 +25,8 @@ u3o_verbose = 0x10, // be remarkably wordy u3o_dryrun = 0x20, // don't touch checkpoint u3o_quiet = 0x40, // disable ~& - u3o_hashless = 0x80 // disable hashboard + u3o_hashless = 0x80, // disable hashboard + u3o_trace = 0x100 // enables trace dumping }; /** Globals. diff --git a/include/noun/trace.h b/include/noun/trace.h index 838ce835f3..049c552181 100644 --- a/include/noun/trace.h +++ b/include/noun/trace.h @@ -83,6 +83,27 @@ void u3t_flee(void); + /* u3t_trace_open(): opens the path for writing tracing information. + */ + void + u3t_trace_open(c3_c*); + + /* u3t_nock_trace_push(): pushes a frame ont o the trace stack; + * return yes if active push. + */ + c3_o + u3t_nock_trace_push(u3_noun lab); + + /* u3t_nock_trace_pop(): pop off trace stack. + */ + void + u3t_nock_trace_pop(); + + /* u3t_even_trace(): record a lifecycle event. + */ + void + u3t_event_trace(const char* name, char type); + /* u3t_damp(): print and clear profile data. */ void diff --git a/include/vere/vere.h b/include/vere/vere.h index 4e59a01e83..79cc76b7ec 100644 --- a/include/vere/vere.h +++ b/include/vere/vere.h @@ -591,6 +591,7 @@ c3_c* gen_c; // -G, czar generator c3_o gab; // -g, test garbage collection c3_c* dns_c; // -H, ames bootstrap domain + c3_c* json_file_c; // -j, json trace c3_w kno_w; // -K, kernel version c3_c* key_c; // -k, private key file c3_o net; // -L, local-only networking @@ -631,6 +632,7 @@ c3_o liv; // if u3_no, shut down c3_i xit_i; // exit code for shutdown void* tls_u; // server SSL_CTX* + FILE* trace_file; // trace file to write to } u3_host; // host == computer == process # define u3L u3_Host.lup_u // global event loop diff --git a/noun/jets.c b/noun/jets.c index 8e37f8d4e7..3fb353f707 100644 --- a/noun/jets.c +++ b/noun/jets.c @@ -1243,18 +1243,27 @@ u3j_kick(u3_noun cor, u3_noun axe) u3x_qual(act, &jax_l, &hap, &bal, &jit); if ( u3_none == (inx = u3kdb_get(u3k(hap), u3k(axe))) ) { - u3t_off(glu_o); + u3t_off(glu_o); { c3_o pof_o = __(u3C.wag_w & u3o_debug_cpu); + c3_o trc_o = __(u3C.wag_w & u3o_trace); if ( _(pof_o) ) { pof_o = u3t_come(bal); } + if ( _(trc_o) ) { + trc_o = u3t_nock_trace_push(bal); + } u3z(act); - if ( _(pof_o) ) { + if ( _(pof_o) || _(trc_o) ) { u3_noun pro = _cj_sink(cor, u3k(axe)); - u3t_flee(); + if (_(pof_o)) { + u3t_flee(); + } + if ( _(trc_o) ) { + u3t_nock_trace_pop(); + } return pro; } else { @@ -1267,28 +1276,39 @@ u3j_kick(u3_noun cor, u3_noun axe) c3_l inx_l = inx; u3j_harm* ham_u = &cop_u->arm_u[inx_l]; c3_o pof_o = __(u3C.wag_w & u3o_debug_cpu); + c3_o trc_o = __(u3C.wag_w & u3o_trace); u3_noun pro; if ( _(pof_o) ) { pof_o = u3t_come(bal); } + if ( _(trc_o) ) { + trc_o = u3t_nock_trace_push(bal); + } u3z(act); u3t_off(glu_o); pro = _cj_kick_z(cor, cop_u, ham_u, axe); - + if ( u3_none == pro ) { - if ( _(pof_o) ) { + if ( _(pof_o) || _(trc_o) ) { pro = _cj_sink(cor, u3k(axe)); - u3t_flee(); - return pro; - } - else return u3_none; + if (_(pof_o)) { + u3t_flee(); + } + if ( _(trc_o) ) { + u3t_nock_trace_pop(); + } + } + return pro; } else { if ( _(pof_o) ) { u3t_flee(); } + if ( _(trc_o) ) { + u3t_nock_trace_pop(); + } return pro; } } @@ -1470,7 +1490,9 @@ _cj_site_kick_hot(u3_noun loc, u3_noun cor, u3j_site* sit_u, c3_o lok_o) u3_weak pro = u3_none; c3_o jet_o = sit_u->jet_o; c3_o pof_o = __(u3C.wag_w & u3o_debug_cpu); - if ( c3n == pof_o ) { + c3_o trc_o = __(u3C.wag_w & u3o_trace); + + if ( c3n == pof_o && c3n == trc_o ) { if ( c3y == jet_o ) { u3t_off(glu_o); pro = _cj_kick_z(cor, sit_u->cop_u, sit_u->ham_u, sit_u->axe); @@ -1483,7 +1505,13 @@ _cj_site_kick_hot(u3_noun loc, u3_noun cor, u3j_site* sit_u, c3_o lok_o) } } else { - pof_o = u3t_come(sit_u->lab); + if ( _(pof_o) ) { + pof_o = u3t_come(sit_u->lab); + } + if ( _(trc_o) ) { + trc_o = u3t_nock_trace_push(sit_u->lab); + } + if ( c3y == jet_o ) { u3t_off(glu_o); pro = _cj_kick_z(cor, sit_u->cop_u, sit_u->ham_u, sit_u->axe); @@ -1495,10 +1523,15 @@ _cj_site_kick_hot(u3_noun loc, u3_noun cor, u3j_site* sit_u, c3_o lok_o) } pro = _cj_burn(sit_u->pog_p, cor); } + if ( c3y == pof_o ) { u3t_flee(); } + if ( c3y == trc_o ) { + u3t_nock_trace_pop(); + } } + return pro; } diff --git a/noun/manage.c b/noun/manage.c index 3e30b75be4..efe295e127 100644 --- a/noun/manage.c +++ b/noun/manage.c @@ -500,6 +500,7 @@ u3m_mark(void) tot_w += u3a_mark_noun(u3R->bug.tax); tot_w += u3a_mark_noun(u3R->bug.mer); tot_w += u3a_mark_noun(u3R->pro.don); + tot_w += u3a_mark_noun(u3R->pro.trace); tot_w += u3a_mark_noun(u3R->pro.day); tot_w += u3h_mark(u3R->cax.har_p); return tot_w; @@ -1014,6 +1015,7 @@ u3m_soft_run(u3_noun gul, { u3R->ski.gul = u3nc(gul, u3to(u3_road, u3R->par_p)->ski.gul); u3R->pro.don = u3to(u3_road, u3R->par_p)->pro.don; + u3R->pro.trace = u3to(u3_road, u3R->par_p)->pro.trace; u3R->bug.tax = 0; } u3t_on(coy_o); @@ -1107,6 +1109,7 @@ u3m_soft_esc(u3_noun ref, u3_noun sam) { u3R->ski.gul = u3t(u3to(u3_road, u3R->par_p)->ski.gul); u3R->pro.don = u3to(u3_road, u3R->par_p)->pro.don; + u3R->pro.trace = u3to(u3_road, u3R->par_p)->pro.trace; u3R->bug.tax = 0; } diff --git a/noun/trace.c b/noun/trace.c index 0fbe833243..6d4d2f4a7e 100644 --- a/noun/trace.c +++ b/noun/trace.c @@ -210,7 +210,10 @@ u3t_samp(void) // it can cause memory errors. return; } + + c3_w old_wag = u3C.wag_w; u3C.wag_w &= ~u3o_debug_cpu; + u3C.wag_w &= ~u3o_trace; static int home = 0; static int away = 0; @@ -265,7 +268,7 @@ u3t_samp(void) away++; // fprintf(stderr,"home: %06d away: %06d\r\n", home, away); } - u3C.wag_w |= u3o_debug_cpu; + u3C.wag_w = old_wag; } /* u3t_come(): push on profile stack; return yes if active push. RETAIN. @@ -279,7 +282,7 @@ u3t_come(u3_noun lab) u3R->pro.don = u3nc(lab, u3R->pro.don); _ct_lop_o = c3n; return c3y; - } + } else return c3n; } @@ -295,6 +298,180 @@ u3t_flee(void) u3z(don); } +static FILE* trace_file = NULL; +static int nock_pid = 0; + +/* u3t_trace_open(): opens a trace file and writes the preamble. +*/ +void +u3t_trace_open(c3_c* trace_file_name) +{ + printf("trace: tracing to %s\n", trace_file_name); + trace_file = fopen(trace_file_name, "w"); + nock_pid = (int)getpid(); + fprintf(trace_file, "[ "); + + // We have two "threads", the event processing and the nock stuff. + // tid 1 = event processing + // tid 2 = nock processing + fprintf( + trace_file, + "{\"name\": \"process_name\", \"ph\": \"M\", \"pid\": %d, \"args\": " + "{\"name\": \"urbit\"}},\n", + nock_pid); + fprintf(trace_file, + "{\"name\": \"thread_name\", \"ph\": \"M\", \"pid\": %d, \"tid\": 1, " + "\"args\": {\"name\": \"Event Processing\"}},\n", + nock_pid); + fprintf(trace_file, + "{\"name\": \"thread_sort_index\", \"ph\": \"M\", \"pid\": %d, " + "\"tid\": 1, \"args\": {\"sort_index\": 1}},\n", + nock_pid); + fprintf(trace_file, + "{\"name\": \"thread_name\", \"ph\": \"M\", \"pid\": %d, \"tid\": 2, " + "\"args\": {\"name\": \"Nock\"}},\n", + nock_pid); + fprintf(trace_file, + "{\"name\": \"thread_sort_index\", \"ph\": \"M\", \"pid\": %d, " + "\"tid\": 2, \"args\": {\"sort_index\": 2}},\n", + nock_pid); +} + +/* u3t_trace_time(): microsecond clock +*/ +uint64_t u3t_trace_time() +{ + struct timeval tim_tv; + gettimeofday(&tim_tv, 0); + return 1000000ULL * tim_tv.tv_sec + tim_tv.tv_usec; +} + +/* u3t_nock_trace_push(): push a trace onto the trace stack; returns yes if pushed. + * + * The trace stack is a stack of [path time-entered]. + */ +c3_o +u3t_nock_trace_push(u3_noun lab) +{ + if (!trace_file) + return c3n; + + if ( (u3_nul == u3R->pro.trace) || + !_(u3r_sing(lab, u3h(u3h(u3R->pro.trace)))) ) { + u3a_gain(lab); + c3_d time = u3t_trace_time(); + u3R->pro.trace = u3nc(u3nc(lab, u3i_chubs(1, &time)), u3R->pro.trace); + return c3y; + } + else { + return c3n; + } +} + +/* _in_trace_pretty: measure/cut prettyprint. + * + * Modeled after _cm_in_pretty(), the backend to u3m_p(), but with the + * assumption that we're always displaying a path. + */ +static c3_w +_in_trace_pretty(u3_noun som, c3_c* str_c) +{ + if ( _(u3du(som)) ) { + c3_w sel_w, one_w, two_w; + if ( str_c ) { + *(str_c++) = '/'; + } + sel_w = 1; + + one_w = _in_trace_pretty(u3h(som), str_c); + if ( str_c ) { + str_c += one_w; + } + + two_w = _in_trace_pretty(u3t(som), str_c); + if ( str_c ) { + str_c += two_w; + } + + return sel_w + one_w + two_w; + } + else { + c3_w len_w = u3r_met(3, som); + if ( str_c && len_w ) { + u3r_bytes(0, len_w, (c3_y *)str_c, som); + str_c += len_w; + } + return len_w; + } +} + +static c3_c* +trace_pretty(u3_noun som) +{ + c3_w len_w = _in_trace_pretty(som, NULL); + c3_c* pre_c = malloc(len_w + 1); + + _in_trace_pretty(som, pre_c); + pre_c[len_w] = 0; + return pre_c; +} + +/* u3t_nock_trace_pop(): pops a trace from the trace stack. + * + * When we remove the trace from the stack, we check to see if the sample is + * large enough to process, as we'll otherwise keep track of individual +add + * calls. If it is, we write it out to the tracefile. + */ +void +u3t_nock_trace_pop() +{ + if (!trace_file) + return; + + u3_noun trace = u3R->pro.trace; + u3R->pro.trace = u3k(u3t(trace)); + + u3_noun item = u3h(trace); + u3_noun lab = u3h(item); + c3_d start_time = u3r_chub(0, u3t(item)); + + // 33microseconds (a 30th of a millisecond). + uint64_t duration = u3t_trace_time() - start_time; + if (duration > 33) { + c3_c* name = trace_pretty(lab); + + fprintf(trace_file, + "{\"cat\": \"nock\", \"name\": \"%s\", \"ph\":\"%c\", \"pid\": %d, " + "\"tid\": 2, \"ts\": %" PRIu64 ", \"dur\": %" PRIu64 "}, \n", + name, + 'X', + nock_pid, + start_time, + duration); + + free(name); + } + + u3z(trace); +} + +/* u3t_event_trace(): dumps a simple event from outside nock. +*/ +void +u3t_event_trace(const char* name, char type) +{ + if (!trace_file) + return; + + fprintf(trace_file, + "{\"cat\": \"event\", \"name\": \"%s\", \"ph\":\"%c\", \"pid\": %d, " + "\"tid\": 1, \"ts\": %" PRIu64 ", \"id\": \"0x100\"}, \n", + name, + type, + nock_pid, + u3t_trace_time()); +} + extern FILE* u3_term_io_hija(void); diff --git a/noun/vortex.c b/noun/vortex.c index 46538a5d33..bcbaf3d4f1 100644 --- a/noun/vortex.c +++ b/noun/vortex.c @@ -93,6 +93,7 @@ u3v_start(u3_noun now) u3_noun u3v_wish(const c3_c* str_c) { + u3t_event_trace("u3v_wish", 'b'); u3_noun txt = u3i_string(str_c); u3_weak exp = u3kdb_get(u3k(u3A->yot), u3k(txt)); @@ -107,6 +108,8 @@ u3v_wish(const c3_c* str_c) } } + u3t_event_trace("u3v_wish", 'e'); + u3z(txt); return exp; } diff --git a/vere/main.c b/vere/main.c index 0ae11fca2c..1768136ae8 100644 --- a/vere/main.c +++ b/vere/main.c @@ -94,7 +94,7 @@ _main_getopt(c3_i argc, c3_c** argv) u3_Host.ops_u.raf_c = 0; u3_Host.ops_u.nam_c = 0; - while ( (ch_i=getopt(argc, argv,"G:B:K:A:H:w:u:e:E:f:F:k:p:LabcdgqstvxPDRS")) != -1 ) { + while ( (ch_i=getopt(argc, argv,"G:B:K:A:H:w:u:j:e:E:f:F:k:p:LabcdgqstvxPDRS")) != -1 ) { switch ( ch_i ) { case 'B': { u3_Host.ops_u.pil_c = strdup(optarg); @@ -133,6 +133,10 @@ _main_getopt(c3_i argc, c3_c** argv) u3_Host.ops_u.url_c = strdup(optarg); break; } + case 'j': { + u3_Host.ops_u.json_file_c = strdup(optarg); + break; + } case 'x': { u3_Host.ops_u.tex = c3y; break; @@ -335,6 +339,7 @@ u3_ve_usage(c3_i argc, c3_c** argv) "-F ship Fake keys; also disables networking\n", "-f Fuzz testing\n", "-g Set GC flag\n", + "-j file Create json trace file\n", "-K stage Start at Hoon kernel version stage\n", "-k keys Private key file\n", "-L local networking only\n", @@ -598,6 +603,13 @@ main(c3_i argc, if ( _(u3_Host.ops_u.has) ) { u3C.wag_w |= u3o_hashless; } + + /* Set tracing flag + */ + if ( u3_Host.ops_u.json_file_c ) { + u3C.wag_w |= u3o_trace; + u3t_trace_open(u3_Host.ops_u.json_file_c); + } } u3m_boot(u3_Host.ops_u.nuu, u3_Host.ops_u.gab, diff --git a/vere/raft.c b/vere/raft.c index 8452102a8f..e14e065233 100644 --- a/vere/raft.c +++ b/vere/raft.c @@ -1567,7 +1567,10 @@ _raft_punk(u3_noun ovo) } #endif + // TODO: Embed event number here? + u3t_event_trace("Running", 'b'); gon = u3m_soft(sec_w, u3v_poke, u3k(ovo)); + u3t_event_trace("Running", 'e'); #ifdef GHETTO c3_w ms_w; @@ -1656,7 +1659,9 @@ _raft_push(u3_raft* raf_u, c3_w* bob_w, c3_w len_w) if ( 1 == raf_u->pop_w ) { c3_assert(u3_raty_lead == raf_u->typ_e); + u3t_event_trace("Recording", 'b'); raf_u->ent_d = u3_sist_pack(raf_u->tem_w, c3__ov, bob_w, len_w); + u3t_event_trace("Recording", 'e'); raf_u->lat_w = raf_u->tem_w; // XX if ( !uv_is_active((uv_handle_t*)&raf_u->tim_u) ) { diff --git a/vere/reck.c b/vere/reck.c index 4a47270810..0a98887f80 100644 --- a/vere/reck.c +++ b/vere/reck.c @@ -365,6 +365,7 @@ _reck_kick_norm(u3_noun pox, u3_noun fav) void u3_reck_kick(u3_noun ovo) { + u3t_event_trace("Effect", 'b'); if ( (c3n == _reck_kick_spec(u3k(u3h(ovo)), u3k(u3t(ovo)))) && (c3n == _reck_kick_norm(u3k(u3h(ovo)), u3k(u3t(ovo)))) ) { @@ -399,4 +400,5 @@ u3_reck_kick(u3_noun ovo) #endif } u3z(ovo); + u3t_event_trace("Effect", 'e'); }