Skip to content

Commit b6f80d2

Browse files
yamtyamt
committed
separate per-instruction tracing
1 parent 070a518 commit b6f80d2

File tree

11 files changed

+66
-53
lines changed

11 files changed

+66
-53
lines changed

‎CMakeLists.txt‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -36,6 +36,7 @@ endif()
3636
option(TOYWASM_USE_SEPARATE_EXECUTE "Use separate execute callback" ON)
3737
option(TOYWASM_USE_TAILCALL "Use tailcall" ON)
3838
option(TOYWASM_ENABLE_TRACING "Enable xlog_trace" OFF)
39+
option(TOYWASM_ENABLE_TRACING_INSN "Enable per-instruction xlog_trace" OFF)
3940
option(TOYWASM_USE_JUMP_BINARY_SEARCH "Enable binary search for jump tables" ON)
4041
option(TOYWASM_USE_JUMP_CACHE "Enable single-entry cache for jump tables" OFF)
4142
if(NOT TOYWASM_JUMP_CACHE2_SIZE)

‎cli/main.c‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -88,7 +88,7 @@ const struct option longopts[] = {
8888
},
8989
{
9090
"trace",
91-
no_argument,
91+
required_argument,
9292
NULL,
9393
opt_trace,
9494
},
@@ -186,7 +186,7 @@ main(int argc, char *const *argv)
186186
opts->print_stats = true;
187187
break;
188188
case opt_trace:
189-
xlog_tracing = 1;
189+
xlog_tracing = atoi(optarg);
190190
break;
191191
case opt_version:
192192
toywasm_repl_print_version();

‎cli/toywasm_config.c.in‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,7 @@ const char *toywasm_config_string =
22
"\tTOYWASM_USE_SEPARATE_EXECUTE = @TOYWASM_USE_SEPARATE_EXECUTE@\n"
33
"\tTOYWASM_USE_TAILCALL = @TOYWASM_USE_TAILCALL@\n"
44
"\tTOYWASM_ENABLE_TRACING = @TOYWASM_ENABLE_TRACING@\n"
5+
"\tTOYWASM_ENABLE_TRACING_INSN = @TOYWASM_ENABLE_TRACING_INSN@\n"
56
"\tTOYWASM_USE_JUMP_BINARY_SEARCH = @TOYWASM_USE_JUMP_BINARY_SEARCH@\n"
67
"\tTOYWASM_USE_JUMP_CACHE = @TOYWASM_USE_JUMP_CACHE@\n"
78
"\tTOYWASM_JUMP_CACHE2_SIZE = @TOYWASM_JUMP_CACHE2_SIZE@\n"

‎lib/exec.c‎

Lines changed: 18 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -71,9 +71,10 @@ memory_getptr2(struct exec_context *ctx, uint32_t memidx, uint32_t ptr,
7171
goto do_trap;
7272
}
7373
uint32_t need = ea + size;
74-
xlog_trace("memory access: at %04" PRIx32 " %08" PRIx32 " + %08" PRIx32
75-
", size %" PRIu32 ", meminst size %" PRIu32,
76-
memidx, ptr, offset, size, meminst->size_in_pages);
74+
xlog_trace_insn("memory access: at %04" PRIx32 " %08" PRIx32
75+
" + %08" PRIx32 ", size %" PRIu32
76+
", meminst size %" PRIu32,
77+
memidx, ptr, offset, size, meminst->size_in_pages);
7778
uint32_t need_in_pages =
7879
((uint64_t)need + WASM_PAGE_SIZE - 1) / WASM_PAGE_SIZE;
7980
if (need_in_pages > meminst->size_in_pages) {
@@ -313,19 +314,19 @@ frame_enter(struct exec_context *ctx, struct instance *inst, uint32_t funcidx,
313314
#endif
314315
cells_zero(locals + nparams, nlocals - nparams);
315316

316-
xlog_trace("frame enter: maxlabels %u maxvals %u", ei->maxlabels,
317-
ei->maxvals);
317+
xlog_trace_insn("frame enter: maxlabels %u maxvals %u", ei->maxlabels,
318+
ei->maxvals);
318319
uint32_t i;
319320
for (i = 0; i < nlocals; i++) {
320321
if (i == nparams) {
321-
xlog_trace("-- ^-params v-locals");
322+
xlog_trace_insn("-- ^-params v-locals");
322323
}
323324
#if defined(TOYWASM_USE_SMALL_CELLS)
324-
xlog_trace("local [%" PRIu32 "] %08" PRIx32, i,
325-
frame_locals(ctx, frame)[i].x);
325+
xlog_trace_insn("local [%" PRIu32 "] %08" PRIx32, i,
326+
frame_locals(ctx, frame)[i].x);
326327
#else
327-
xlog_trace("local [%" PRIu32 "] %08" PRIx64, i,
328-
frame_locals(ctx, frame)[i].x);
328+
xlog_trace_insn("local [%" PRIu32 "] %08" PRIx64, i,
329+
frame_locals(ctx, frame)[i].x);
329330
#endif
330331
}
331332

@@ -610,7 +611,7 @@ do_branch(struct exec_context *ctx, uint32_t labelidx, bool goto_else)
610611
}
611612
if (ctx->labels.lsize - labelidx == frame->labelidx) {
612613
/* exit the function */
613-
xlog_trace("do_branch: exiting function");
614+
xlog_trace_insn("do_branch: exiting function");
614615
frame_exit(ctx);
615616
height = frame->height;
616617
arity = frame->nresults;
@@ -640,7 +641,7 @@ do_branch(struct exec_context *ctx, uint32_t labelidx, bool goto_else)
640641
*/
641642
const struct expr_exec_info *ei = ctx->ei;
642643
if (ei->jumps != NULL) {
643-
xlog_trace("jump w/ table");
644+
xlog_trace_insn("jump w/ table");
644645
bool stay_in_block = false;
645646
const struct jump *jump;
646647
jump = jump_lookup(ctx, ei, blockpc);
@@ -663,7 +664,7 @@ do_branch(struct exec_context *ctx, uint32_t labelidx, bool goto_else)
663664
goto_else, true, 0,
664665
0, ctx->p);
665666
#endif
666-
xlog_trace("jump inside a block");
667+
xlog_trace_insn("jump inside a block");
667668
return;
668669
}
669670
}
@@ -686,7 +687,7 @@ do_branch(struct exec_context *ctx, uint32_t labelidx, bool goto_else)
686687
* do a jump. (w/o jump table)
687688
*/
688689
if (ei->jumps == NULL) {
689-
xlog_trace("jump w/o table");
690+
xlog_trace_insn("jump w/o table");
690691
if (op == FRAME_OP_LOOP) {
691692
ctx->p = blockp;
692693
} else {
@@ -747,13 +748,13 @@ fetch_exec_next_insn(const uint8_t *p, struct cell *stack,
747748
#endif
748749
assert(ctx->event == EXEC_EVENT_NONE);
749750
assert(ctx->frames.lsize > 0);
750-
#if defined(TOYWASM_ENABLE_TRACING)
751+
#if defined(TOYWASM_ENABLE_TRACING_INSN)
751752
uint32_t pc = ptr2pc(ctx->instance->module, p);
752753
#endif
753754
uint32_t op = *p++;
754755
#if defined(TOYWASM_USE_SEPARATE_EXECUTE)
755-
xlog_trace("exec %06" PRIx32 ": %s (%02" PRIx32 ")", pc,
756-
instructions[op].name, op);
756+
xlog_trace_insn("exec %06" PRIx32 ": %s (%02" PRIx32 ")", pc,
757+
instructions[op].name, op);
757758
const struct exec_instruction_desc *desc = &exec_instructions[op];
758759
#if defined(TOYWASM_USE_TAILCALL)
759760
__musttail

‎lib/expr.c‎

Lines changed: 11 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -126,15 +126,15 @@ read_expr_common(const uint8_t **pp, const uint8_t *ep, struct expr *expr,
126126
while (true) {
127127
const struct instruction_desc *desc;
128128

129-
#if defined(TOYWASM_ENABLE_TRACING)
129+
#if defined(TOYWASM_ENABLE_TRACING_INSN)
130130
uint32_t pc = ptr2pc(vctx->module, p);
131131
#endif
132132
ret = read_op(&p, ep, &desc);
133133
if (ret != 0) {
134134
goto fail;
135135
}
136-
xlog_trace("inst %06" PRIx32 " %s", pc, desc->name);
137-
#if defined(TOYWASM_ENABLE_TRACING)
136+
xlog_trace_insn("inst %06" PRIx32 " %s", pc, desc->name);
137+
#if defined(TOYWASM_ENABLE_TRACING_INSN)
138138
uint32_t orig_n = vctx->nvaltypes;
139139
#endif
140140
if (const_expr && (desc->flags & INSN_FLAG_CONST) == 0) {
@@ -153,17 +153,17 @@ read_expr_common(const uint8_t **pp, const uint8_t *ep, struct expr *expr,
153153
if (vctx->ncframes == 0) {
154154
break;
155155
}
156-
xlog_trace("inst %s %u %u: %u -> %u", desc->name,
157-
vctx->ncframes,
158-
vctx->cframes[vctx->ncframes - 1].height, orig_n,
159-
vctx->nvaltypes);
156+
xlog_trace_insn("inst %s %u %u: %u -> %u", desc->name,
157+
vctx->ncframes,
158+
vctx->cframes[vctx->ncframes - 1].height,
159+
orig_n, vctx->nvaltypes);
160160
}
161-
#if defined(TOYWASM_ENABLE_TRACING)
161+
#if defined(TOYWASM_ENABLE_TRACING_INSN)
162162
for (i = 0; i < ei->njumps; i++) {
163163
const struct jump *j = &ei->jumps[i];
164-
xlog_trace("jump table [%" PRIu32 "] %06" PRIx32
165-
" -> %06" PRIx32,
166-
i, j->pc, j->targetpc);
164+
xlog_trace_insn("jump table [%" PRIu32 "] %06" PRIx32
165+
" -> %06" PRIx32,
166+
i, j->pc, j->targetpc);
167167
}
168168
#endif
169169
*pp = p;

‎lib/insn.c‎

Lines changed: 10 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -35,7 +35,7 @@ stack_push_val(const struct exec_context *ctx, const struct val *val,
3535
{
3636
assert(ctx->stack.p <= *stackp);
3737
assert(*stackp + csz <= ctx->stack.p + ctx->stack.psize);
38-
xlog_trace("stack push %016" PRIx64, val->u.i64);
38+
xlog_trace_insn("stack push %016" PRIx64, val->u.i64);
3939
val_to_cells(val, *stackp, csz);
4040
*stackp += csz;
4141
}
@@ -48,7 +48,7 @@ stack_pop_val(const struct exec_context *ctx, struct val *val,
4848
assert(*stackp <= ctx->stack.p + ctx->stack.psize);
4949
*stackp -= csz;
5050
val_from_cells(val, *stackp, csz);
51-
xlog_trace("stack pop %016" PRIx64, val->u.i64);
51+
xlog_trace_insn("stack pop %016" PRIx64, val->u.i64);
5252
}
5353
#endif
5454

@@ -57,7 +57,7 @@ push_val(const struct val *val, uint32_t csz, struct exec_context *ctx)
5757
{
5858
val_to_cells(val, &VEC_NEXTELEM(ctx->stack), csz);
5959
ctx->stack.lsize += csz;
60-
xlog_trace("stack push %016" PRIx64, val->u.i64);
60+
xlog_trace_insn("stack push %016" PRIx64, val->u.i64);
6161
}
6262

6363
static void
@@ -66,7 +66,7 @@ pop_val(struct val *val, uint32_t csz, struct exec_context *ctx)
6666
assert(ctx->stack.lsize >= csz);
6767
ctx->stack.lsize -= csz;
6868
val_from_cells(val, &VEC_NEXTELEM(ctx->stack), csz);
69-
xlog_trace("stack pop %016" PRIx64, val->u.i64);
69+
xlog_trace_insn("stack pop %016" PRIx64, val->u.i64);
7070
}
7171

7272
static void
@@ -433,13 +433,13 @@ fetch_exec_next_insn_fc(const uint8_t *p, struct cell *stack,
433433
#endif
434434
assert(ctx->event == EXEC_EVENT_NONE);
435435
assert(ctx->frames.lsize > 0);
436-
#if defined(TOYWASM_ENABLE_TRACING)
436+
#if defined(TOYWASM_ENABLE_TRACING_INSN)
437437
uint32_t pc = ptr2pc(ctx->instance->module, p);
438438
#endif
439439
uint32_t op = read_leb_u32_nocheck(&p);
440440
const struct exec_instruction_desc *desc = &exec_instructions_fc[op];
441-
xlog_trace("exec %06" PRIx32 ": %s (2nd byte %02" PRIx32 ")", pc,
442-
instructions[op].name, op);
441+
xlog_trace_insn("exec %06" PRIx32 ": %s (2nd byte %02" PRIx32 ")", pc,
442+
instructions[op].name, op);
443443
#if defined(TOYWASM_USE_TAILCALL)
444444
__musttail
445445
#endif
@@ -463,13 +463,13 @@ fetch_exec_next_insn_fe(const uint8_t *p, struct cell *stack,
463463
#endif
464464
assert(ctx->event == EXEC_EVENT_NONE);
465465
assert(ctx->frames.lsize > 0);
466-
#if defined(TOYWASM_ENABLE_TRACING)
466+
#if defined(TOYWASM_ENABLE_TRACING_INSN)
467467
uint32_t pc = ptr2pc(ctx->instance->module, p);
468468
#endif
469469
uint32_t op = read_leb_u32_nocheck(&p);
470470
const struct exec_instruction_desc *desc = &exec_instructions_fe[op];
471-
xlog_trace("exec %06" PRIx32 ": %s (2nd byte %02" PRIx32 ")", pc,
472-
instructions[op].name, op);
471+
xlog_trace_insn("exec %06" PRIx32 ": %s (2nd byte %02" PRIx32 ")", pc,
472+
instructions[op].name, op);
473473
#if defined(TOYWASM_USE_TAILCALL)
474474
__musttail
475475
#endif

‎lib/insn_impl_control.h‎

Lines changed: 7 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -173,8 +173,8 @@ INSN_IMPL(end)
173173
struct exec_context *ectx = ECTX;
174174
assert(ectx->frames.lsize > 0);
175175
struct funcframe *frame = &VEC_LASTELEM(ectx->frames);
176-
xlog_trace("end: nlabels %" PRIu32 " labelidx %" PRIu32,
177-
ectx->labels.lsize, frame->labelidx);
176+
xlog_trace_insn("end: nlabels %" PRIu32 " labelidx %" PRIu32,
177+
ectx->labels.lsize, frame->labelidx);
178178
if (ectx->labels.lsize > frame->labelidx) {
179179
VEC_POP_DROP(ectx->labels);
180180
} else {
@@ -197,7 +197,7 @@ INSN_IMPL(end)
197197
}
198198
if (cframe.op == FRAME_OP_IF) {
199199
/* no "else" is same as an empty "else" */
200-
xlog_trace("emulating an empty else");
200+
xlog_trace_insn("emulating an empty else");
201201
ret = push_ctrlframe(pc, FRAME_OP_EMPTY_ELSE, 0,
202202
cframe.start_types,
203203
cframe.end_types, vctx);
@@ -382,7 +382,7 @@ INSN_IMPL(return )
382382
assert(ectx->frames.lsize > 0);
383383
const struct funcframe *frame = &VEC_LASTELEM(ectx->frames);
384384
uint32_t nlabels = ectx->labels.lsize - frame->labelidx;
385-
xlog_trace("return as tr %" PRIu32, nlabels);
385+
xlog_trace_insn("return as tr %" PRIu32, nlabels);
386386
ectx->event_u.branch.index = nlabels;
387387
ectx->event_u.branch.goto_else = false;
388388
ectx->event = EXEC_EVENT_BRANCH;
@@ -494,8 +494,9 @@ INSN_IMPL(call_indirect)
494494
ectx->event = EXEC_EVENT_CALL;
495495
} else if (VALIDATING) {
496496
struct validation_context *vctx = VCTX;
497-
xlog_trace("call_indirect (table %u type %u) %u %u", tableidx,
498-
typeidx, ft->parameter.ntypes, ft->result.ntypes);
497+
xlog_trace_insn("call_indirect (table %u type %u) %u %u",
498+
tableidx, typeidx, ft->parameter.ntypes,
499+
ft->result.ntypes);
499500
ret = pop_valtypes(&ft->parameter, vctx);
500501
if (ret != 0) {
501502
goto fail;

‎lib/toywasm_config.h.in‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@
44
#cmakedefine TOYWASM_USE_SEPARATE_EXECUTE
55
#cmakedefine TOYWASM_USE_TAILCALL
66
#cmakedefine TOYWASM_ENABLE_TRACING
7+
#cmakedefine TOYWASM_ENABLE_TRACING_INSN
78
#cmakedefine TOYWASM_USE_JUMP_BINARY_SEARCH
89
#cmakedefine TOYWASM_USE_JUMP_CACHE
910
#define TOYWASM_JUMP_CACHE2_SIZE @TOYWASM_JUMP_CACHE2_SIZE@

‎lib/validation.c‎

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -140,9 +140,9 @@ push_ctrlframe(uint32_t pc, enum ctrlframe_op op, uint32_t jumpslot,
140140
struct ctrlframe *cframe;
141141
int ret;
142142

143-
xlog_trace("push_ctrlframe (op %02x) %u %u", (unsigned int)op,
144-
start_types != NULL ? start_types->ntypes : 0,
145-
end_types->ntypes);
143+
xlog_trace_insn("push_ctrlframe (op %02x) %u %u", (unsigned int)op,
144+
start_types != NULL ? start_types->ntypes : 0,
145+
end_types->ntypes);
146146
struct expr_exec_info *ei = ctx->ei;
147147
uint32_t nslots = 1;
148148
/*

‎lib/xlog.c‎

Lines changed: 0 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -66,9 +66,6 @@ xlog_printf_raw(const char *fmt, ...)
6666
void
6767
xlog__trace(const char *fmt, ...)
6868
{
69-
if (!xlog_tracing) {
70-
return;
71-
}
7269
va_list ap;
7370
va_start(ap, fmt);
7471
flockfile(stderr);

0 commit comments

Comments
 (0)