Skip to content

Commit

Permalink
Add cross-thread write debug logging.
Browse files Browse the repository at this point in the history
Enabled by setting MVM_CROSS_THREAD_WRITE_LOG in the environment. Uses
bytecode instrumentation and squeals when one thread does a write to
an object allocated by another thread, and isn't under lock. (You may
set MVM_CROSS_THREAD_WRITE_LOG_INCLUDE_LOCKED in order to include the
writes done while holding a lock also). Does not yet deal with binds
to lexicals in a frame entered by another thread, but gets object,
array, and hash mutations nailed.
  • Loading branch information
jnthn committed Jul 15, 2015
1 parent 07daf04 commit 5227f5e
Show file tree
Hide file tree
Showing 15 changed files with 278 additions and 11 deletions.
2 changes: 2 additions & 0 deletions build/Makefile.in
Original file line number Diff line number Diff line change
Expand Up @@ -194,6 +194,7 @@ OBJECTS = src/core/callsite@obj@ \
src/profiler/instrument@obj@ \
src/profiler/log@obj@ \
src/profiler/profile@obj@ \
src/instrument/crossthreadwrite@obj@ \
src/moar@obj@ \
@platform@ \
@jit@
Expand Down Expand Up @@ -337,6 +338,7 @@ HEADERS = src/moar.h \
src/jit/graph.h \
src/jit/compile.h \
src/jit/log.h \
src/instrument/crossthreadwrite.h \
src/gen/config.h \
3rdparty/uthash.h

Expand Down
16 changes: 11 additions & 5 deletions lib/MAST/Ops.nqp
Original file line number Diff line number Diff line change
Expand Up @@ -745,7 +745,8 @@ BEGIN {
1844,
1844,
1845,
1845);
1845,
1846);
MAST::Ops.WHO<@counts> := nqp::list_i(0,
2,
2,
Expand Down Expand Up @@ -1488,7 +1489,8 @@ BEGIN {
0,
1,
0,
1);
1,
2);
MAST::Ops.WHO<@values> := nqp::list_i(10,
8,
18,
Expand Down Expand Up @@ -3334,7 +3336,9 @@ BEGIN {
34,
65,
128,
65);
65,
65,
16);
MAST::Ops.WHO<%codes> := nqp::hash('no_op', 0,
'const_i8', 1,
'const_i16', 2,
Expand Down Expand Up @@ -4077,7 +4081,8 @@ BEGIN {
'prof_enterspesh', 739,
'prof_enterinline', 740,
'prof_exit', 741,
'prof_allocated', 742);
'prof_allocated', 742,
'ctw_check', 743);
MAST::Ops.WHO<@names> := nqp::list('no_op',
'const_i8',
'const_i16',
Expand Down Expand Up @@ -4820,5 +4825,6 @@ BEGIN {
'prof_enterspesh',
'prof_enterinline',
'prof_exit',
'prof_allocated');
'prof_allocated',
'ctw_check');
}
2 changes: 2 additions & 0 deletions src/6model/reprs/ReentrantMutex.c
Original file line number Diff line number Diff line change
Expand Up @@ -127,6 +127,7 @@ void MVM_reentrantmutex_lock(MVMThreadContext *tc, MVMReentrantMutex *rm) {
});
MVM_store(&rm->body.holder_id, tc->thread_id);
MVM_store(&rm->body.lock_count, 1);
tc->num_locks++;
}
}

Expand All @@ -138,6 +139,7 @@ void MVM_reentrantmutex_unlock(MVMThreadContext *tc, MVMReentrantMutex *rm) {
/* Decremented the last recursion count; really unlock. */
MVM_store(&rm->body.holder_id, 0);
uv_mutex_unlock(rm->body.mutex);
tc->num_locks--;
}
}
else {
Expand Down
2 changes: 2 additions & 0 deletions src/core/frame.c
Original file line number Diff line number Diff line change
Expand Up @@ -52,6 +52,8 @@ static void instrumentation_level_barrier(MVMThreadContext *tc, MVMStaticFrame *
/* Add profiling instrumentation if needed. */
if (tc->instance->profiling)
MVM_profile_instrument(tc, static_frame);
else if (tc->instance->cross_thread_write_logging)
MVM_cross_thread_write_instrument(tc, static_frame);
else
MVM_profile_ensure_uninstrumented(tc, static_frame);
}
Expand Down
6 changes: 6 additions & 0 deletions src/core/instance.h
Original file line number Diff line number Diff line change
Expand Up @@ -338,6 +338,12 @@ struct MVMInstance {
/* Whether profiling is turned on or not. */
MVMuint32 profiling;

/* Whether cross-thread write logging is turned on or not, and an output
* mutex for it. */
MVMuint32 cross_thread_write_logging;
MVMuint32 cross_thread_write_logging_include_locked;
uv_mutex_t mutex_cross_thread_write_logging;

/* Cached backend config hash. */
MVMObject *cached_backend_config;
};
Expand Down
4 changes: 4 additions & 0 deletions src/core/interp.c
Original file line number Diff line number Diff line change
Expand Up @@ -5093,6 +5093,10 @@ void MVM_interp_run(MVMThreadContext *tc, void (*initial_invoke)(MVMThreadContex
MVM_profile_log_allocated(tc, GET_REG(cur_op, 0).o);
cur_op += 2;
goto NEXT;
OP(ctw_check):
MVM_cross_thread_write_check(tc, GET_REG(cur_op, 0).o, GET_I16(cur_op, 2));
cur_op += 4;
goto NEXT;
#if MVM_CGOTO
OP_CALL_EXTOP: {
/* Bounds checking? Never heard of that. */
Expand Down
2 changes: 1 addition & 1 deletion src/core/oplabels.h
Original file line number Diff line number Diff line change
Expand Up @@ -744,7 +744,7 @@ static const void * const LABELS[] = {
&&OP_prof_enterinline,
&&OP_prof_exit,
&&OP_prof_allocated,
NULL,
&&OP_ctw_check,
NULL,
NULL,
NULL,
Expand Down
3 changes: 3 additions & 0 deletions src/core/oplist
Original file line number Diff line number Diff line change
Expand Up @@ -835,3 +835,6 @@ prof_exit
# Recording of allocated types (may not give full picture of allocations, but
# is at least enough to get a picture).
prof_allocated .s r(obj)

# Cross-thread write analysis logging instruction.
ctw_check .s r(obj) int16
13 changes: 12 additions & 1 deletion src/core/ops.c
Original file line number Diff line number Diff line change
Expand Up @@ -8162,9 +8162,20 @@ static const MVMOpInfo MVM_op_infos[] = {
0,
{ MVM_operand_read_reg | MVM_operand_obj }
},
{
MVM_OP_ctw_check,
"ctw_check",
".s",
2,
0,
0,
0,
0,
{ MVM_operand_read_reg | MVM_operand_obj, MVM_operand_int16 }
},
};

static const unsigned short MVM_op_counts = 743;
static const unsigned short MVM_op_counts = 744;

MVM_PUBLIC const MVMOpInfo * MVM_op_get_op(unsigned short op) {
if (op >= MVM_op_counts)
Expand Down
1 change: 1 addition & 0 deletions src/core/ops.h
Original file line number Diff line number Diff line change
Expand Up @@ -744,6 +744,7 @@
#define MVM_OP_prof_enterinline 740
#define MVM_OP_prof_exit 741
#define MVM_OP_prof_allocated 742
#define MVM_OP_ctw_check 743

#define MVM_OP_EXT_BASE 1024
#define MVM_OP_EXT_CU_LIMIT 1024
Expand Down
3 changes: 3 additions & 0 deletions src/core/threadcontext.h
Original file line number Diff line number Diff line change
Expand Up @@ -192,6 +192,9 @@ struct MVMThreadContext {
MVMint64 *nfa_longlit;
MVMint64 nfa_longlit_len;

/* The number of locks the thread is holding. */
MVMint64 num_locks;

/* Profiling data collected for this thread, if profiling is on. */
MVMProfileThreadData *prof_data;
};
Expand Down
196 changes: 196 additions & 0 deletions src/instrument/crossthreadwrite.c
Original file line number Diff line number Diff line change
@@ -0,0 +1,196 @@
#include "moar.h"

/* Walk graph and insert write check instructions. */
static void prepend_ctw_check(MVMThreadContext *tc, MVMSpeshGraph *g, MVMSpeshBB *bb,
MVMSpeshIns *before_ins, MVMSpeshOperand check_reg,
MVMint16 guilty) {
MVMSpeshIns *ctw_ins = MVM_spesh_alloc(tc, g, sizeof(MVMSpeshIns));
ctw_ins->info = MVM_op_get_op(MVM_OP_ctw_check);
ctw_ins->operands = MVM_spesh_alloc(tc, g, 2 * sizeof(MVMSpeshOperand));
ctw_ins->operands[0] = check_reg;
ctw_ins->operands[1].lit_i16 = guilty;
MVM_spesh_manipulate_insert_ins(tc, bb, before_ins->prev, ctw_ins);
}
static void instrument_graph(MVMThreadContext *tc, MVMSpeshGraph *g) {
MVMSpeshBB *bb = g->entry->linear_next;
while (bb) {
MVMSpeshIns *ins = bb->first_ins;
while (ins) {
switch (ins->info->opcode) {
case MVM_OP_rebless:
prepend_ctw_check(tc, g, bb, ins, ins->operands[0], MVM_CTW_REBLESS);
case MVM_OP_bindattr_i:
case MVM_OP_bindattr_n:
case MVM_OP_bindattr_s:
case MVM_OP_bindattr_o:
case MVM_OP_bindattrs_i:
case MVM_OP_bindattrs_n:
case MVM_OP_bindattrs_s:
case MVM_OP_bindattrs_o:
prepend_ctw_check(tc, g, bb, ins, ins->operands[0], MVM_CTW_BIND_ATTR);
break;
case MVM_OP_bindpos_i:
case MVM_OP_bindpos_n:
case MVM_OP_bindpos_s:
case MVM_OP_bindpos_o:
prepend_ctw_check(tc, g, bb, ins, ins->operands[0], MVM_CTW_BIND_POS);
break;
case MVM_OP_push_i:
case MVM_OP_push_n:
case MVM_OP_push_s:
case MVM_OP_push_o:
prepend_ctw_check(tc, g, bb, ins, ins->operands[0], MVM_CTW_PUSH);
break;
case MVM_OP_pop_i:
case MVM_OP_pop_n:
case MVM_OP_pop_s:
case MVM_OP_pop_o:
prepend_ctw_check(tc, g, bb, ins, ins->operands[1], MVM_CTW_POP);
break;
case MVM_OP_shift_i:
case MVM_OP_shift_n:
case MVM_OP_shift_s:
case MVM_OP_shift_o:
prepend_ctw_check(tc, g, bb, ins, ins->operands[1], MVM_CTW_SHIFT);
break;
case MVM_OP_unshift_i:
case MVM_OP_unshift_n:
case MVM_OP_unshift_s:
case MVM_OP_unshift_o:
prepend_ctw_check(tc, g, bb, ins, ins->operands[0], MVM_CTW_UNSHIFT);
break;
case MVM_OP_splice:
prepend_ctw_check(tc, g, bb, ins, ins->operands[0], MVM_CTW_SPLICE);
break;
case MVM_OP_bindkey_i:
case MVM_OP_bindkey_n:
case MVM_OP_bindkey_s:
case MVM_OP_bindkey_o:
prepend_ctw_check(tc, g, bb, ins, ins->operands[0], MVM_CTW_BIND_KEY);
break;
case MVM_OP_deletekey:
prepend_ctw_check(tc, g, bb, ins, ins->operands[0], MVM_CTW_DELETE_KEY);
break;
case MVM_OP_assign:
case MVM_OP_assignunchecked:
case MVM_OP_assign_i:
case MVM_OP_assign_n:
case MVM_OP_assign_s:
prepend_ctw_check(tc, g, bb, ins, ins->operands[0], MVM_CTW_ASSIGN);
break;
case MVM_OP_bindpos2d_i:
case MVM_OP_bindpos2d_n:
case MVM_OP_bindpos2d_s:
case MVM_OP_bindpos2d_o:
case MVM_OP_bindpos3d_i:
case MVM_OP_bindpos3d_n:
case MVM_OP_bindpos3d_s:
case MVM_OP_bindpos3d_o:
case MVM_OP_bindposnd_i:
case MVM_OP_bindposnd_n:
case MVM_OP_bindposnd_s:
case MVM_OP_bindposnd_o:
prepend_ctw_check(tc, g, bb, ins, ins->operands[0], MVM_CTW_BIND_POS);
break;
}
ins = ins->next;
}
bb = bb->linear_next;
}
}

/* Adds instrumented version of the unspecialized bytecode. */
static void add_instrumentation(MVMThreadContext *tc, MVMStaticFrame *sf) {
MVMSpeshCode *sc;
MVMSpeshGraph *sg = MVM_spesh_graph_create(tc, sf, 1);
instrument_graph(tc, sg);
sc = MVM_spesh_codegen(tc, sg);
sf->body.instrumented_bytecode = sc->bytecode;
sf->body.instrumented_handlers = sc->handlers;
sf->body.instrumented_bytecode_size = sc->bytecode_size;
sf->body.uninstrumented_bytecode = sf->body.bytecode;
sf->body.uninstrumented_handlers = sf->body.handlers;
sf->body.uninstrumented_bytecode_size = sf->body.bytecode_size;
MVM_spesh_graph_destroy(tc, sg);
MVM_free(sc);
}

/* Instruments code with detection and reporting of cross-thread writes. */
void MVM_cross_thread_write_instrument(MVMThreadContext *tc, MVMStaticFrame *sf) {
if (sf->body.bytecode != sf->body.instrumented_bytecode) {
/* Handle main, non-specialized, bytecode. */
if (!sf->body.instrumented_bytecode)
add_instrumentation(tc, sf);
sf->body.bytecode = sf->body.instrumented_bytecode;
sf->body.handlers = sf->body.instrumented_handlers;
sf->body.bytecode_size = sf->body.instrumented_bytecode_size;

/* Throw away any specializations; we'll need to reproduce them as
* instrumented versions. */
sf->body.num_spesh_candidates = 0;
sf->body.spesh_candidates = NULL;
}
}

/* Filter out some special cases to reduce noise. */
static MVMint64 filtered_out(MVMThreadContext *tc, MVMObject *written) {
/* If we're holding locks, exclude by default (unless we were asked to
* also include these). */
if (tc->num_locks && !tc->instance->cross_thread_write_logging_include_locked)
return 1;

/* Operations on a concurrent queue are fine 'cus it's concurrent. */
if (REPR(written)->ID == MVM_REPR_ID_ConcBlockingQueue)
return 1;

/* Otherwise, may be relevant. */
return 0;
}

/* Squeal if the target of the write wasn't allocated by us. */
void MVM_cross_thread_write_check(MVMThreadContext *tc, MVMObject *written, MVMint16 guilty) {
if (written->header.owner != tc->thread_id && !filtered_out(tc, written)) {
char *guilty_desc = "did something to";
switch (guilty) {
case MVM_CTW_BIND_ATTR:
guilty_desc = "bound to an attribute of";
break;
case MVM_CTW_BIND_POS:
guilty_desc = "bound to an array slot of";
break;
case MVM_CTW_PUSH:
guilty_desc = "pushed to";
break;
case MVM_CTW_POP:
guilty_desc = "popped";
break;
case MVM_CTW_SHIFT:
guilty_desc = "shifted";
break;
case MVM_CTW_UNSHIFT:
guilty_desc = "unshifted to";
break;
case MVM_CTW_SPLICE:
guilty_desc = "spliced";
break;
case MVM_CTW_BIND_KEY:
guilty_desc = "bound to a hash key of";
break;
case MVM_CTW_DELETE_KEY:
guilty_desc = "deleted a hash key of";
break;
case MVM_CTW_ASSIGN:
guilty_desc = "assigned to";
break;
case MVM_CTW_REBLESS:
guilty_desc = "reblessed";
break;
}
uv_mutex_lock(&(tc->instance->mutex_cross_thread_write_logging));
fprintf(stderr, "Thread %d %s an object allocated by thread %d\n",
tc->thread_id, guilty_desc, written->header.owner);
MVM_dump_backtrace(tc);
printf("\n");
uv_mutex_unlock(&(tc->instance->mutex_cross_thread_write_logging));
}
}
15 changes: 15 additions & 0 deletions src/instrument/crossthreadwrite.h
Original file line number Diff line number Diff line change
@@ -0,0 +1,15 @@
void MVM_cross_thread_write_instrument(MVMThreadContext *tc, MVMStaticFrame *static_frame);
void MVM_cross_thread_write_check(MVMThreadContext *tc, MVMObject *written, MVMint16 guilty);

/* Mutating operations one thread may do on an object it didn't create. */
#define MVM_CTW_BIND_ATTR 1
#define MVM_CTW_BIND_POS 2
#define MVM_CTW_PUSH 3
#define MVM_CTW_POP 4
#define MVM_CTW_SHIFT 5
#define MVM_CTW_UNSHIFT 6
#define MVM_CTW_SPLICE 7
#define MVM_CTW_BIND_KEY 8
#define MVM_CTW_DELETE_KEY 9
#define MVM_CTW_ASSIGN 10
#define MVM_CTW_REBLESS 11
Loading

0 comments on commit 5227f5e

Please sign in to comment.