urbit/shrub
1
1
Fork 0
mirror of https://github.com/urbit/shrub.git synced 2024-12-01 06:35:32 +03:00
Code Issues Packages Projects Releases Wiki Activity

Add support for trace_event files.

Browse Source 
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.
This commit is contained in:
Elliot Glaysher 2018-11-28 16:34:32 -08:00
parent 56c3f080bd
commit 8b9680072a
11 changed files with 275 additions and 15 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

1
include/noun/allocate.h
View File

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

3
include/noun/options.h
View File

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

21
include/noun/trace.h
View File

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

2
include/vere/vere.h
View File

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

55
noun/jets.c
View File

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

3
noun/manage.c
View File

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

181
noun/trace.c
View File

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

3
noun/vortex.c
View File

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

14
vere/main.c
View File

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

5
vere/raft.c
View File

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

2
vere/reck.c
View File

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