From 2f532f889a6bd31f74122bd223277d7c609f7bdc Mon Sep 17 00:00:00 2001 From: Scott Lystig Fritchie Date: Thu, 17 Nov 2011 00:45:50 -0600 Subject: Add DTrace support for OS X, Solaris, and Linux (via SystemTap), 3/4 Add probes to the virtual machine, except (mostly) the efile_drv.c driver and other file I/O-related source files. --- erts/emulator/beam/beam_emu.c | 228 +++++++++- erts/emulator/beam/copy.c | 9 + erts/emulator/beam/dist.c | 129 ++++++ erts/emulator/beam/erl_async.c | 26 ++ erts/emulator/beam/erl_bif_ddll.c | 2 + erts/emulator/beam/erl_bif_info.c | 3 + erts/emulator/beam/erl_bif_port.c | 27 ++ erts/emulator/beam/erl_gc.c | 46 +- erts/emulator/beam/erl_lock_check.c | 3 + erts/emulator/beam/erl_message.c | 74 +++- erts/emulator/beam/erl_nif.c | 6 + erts/emulator/beam/erl_node_tables.c | 9 + erts/emulator/beam/erl_node_tables.h | 2 +- erts/emulator/beam/erl_port_task.c | 18 +- erts/emulator/beam/erl_process.c | 38 +- erts/emulator/beam/erlang_dtrace.d | 716 ++++++++++++++++++++++++++++++++ erts/emulator/beam/io.c | 118 ++++++ erts/emulator/sys/common/erl_check_io.c | 8 + 18 files changed, 1456 insertions(+), 6 deletions(-) create mode 100644 erts/emulator/beam/erlang_dtrace.d (limited to 'erts/emulator') diff --git a/erts/emulator/beam/beam_emu.c b/erts/emulator/beam/beam_emu.c index c65b2be106..d0beccfda2 100644 --- a/erts/emulator/beam/beam_emu.c +++ b/erts/emulator/beam/beam_emu.c @@ -42,6 +42,9 @@ #include "hipe_bif1.h" #endif +#include +#include "dtrace-wrapper.h" + /* #define HARDDEBUG 1 */ #if defined(NO_JUMP_TABLE) @@ -1050,6 +1053,143 @@ init_emulator(void) # define REG_tmp_arg2 #endif +ERTS_INLINE void +dtrace_proc_str(Process *process, char *process_buf) +{ + dtrace_pid_str(process->id, process_buf); +} + +ERTS_INLINE void +dtrace_pid_str(Eterm pid, char *process_buf) +{ + snprintf(process_buf, DTRACE_TERM_BUF_SIZE, "<%lu.%lu.%lu>", + pid_channel_no(pid), + pid_number(pid), + pid_serial(pid)); +} + +ERTS_INLINE void +dtrace_port_str(Port *port, char *port_buf) +{ + snprintf(port_buf, DTRACE_TERM_BUF_SIZE, "#Port<%lu.%lu>", + port_channel_no(port->id), + port_number(port->id)); +} + +ERTS_INLINE void +dtrace_drvport_str(ErlDrvPort drvport, char *port_buf) +{ + Port *port = erts_drvport2port(drvport); + + snprintf(port_buf, DTRACE_TERM_BUF_SIZE, "#Port<%lu.%lu>", + port_channel_no(port->id), + port_number(port->id)); +} + +ERTS_INLINE void +dtrace_fun_decode(Process *process, + Eterm module, Eterm function, int arity, + char *process_buf, char *mfa_buf) +{ + char funbuf[DTRACE_TERM_BUF_SIZE]; + char *funptr = funbuf; + char *p = NULL; + + if (process_buf) { + dtrace_proc_str(process, process_buf); + } + + erts_snprintf(funbuf, sizeof(funbuf), "%T", function); + /* + * I'm not quite sure how these function names are synthesized, + * but they almost always seem to be in the form of + * '-name/arity-fun-0-' so I'm chopping them up when it's -fun-0- + * (which seems to be the toplevel) + */ + if (funbuf[0] == '\'' && funbuf[1] == '-' + && strlen(funbuf) > 3 && funbuf[strlen(funbuf) - 3] == '0') { + p = strchr(funbuf, '/'); + if (p) { + *p = 0; + } + funptr += 2; + } + + erts_snprintf(mfa_buf, DTRACE_TERM_BUF_SIZE, "%T:%s/%d", + module, funptr, arity); +} + +#ifdef HAVE_DTRACE + +#define DTRACE_CALL(p, m, f, a) \ + if (DTRACE_ENABLED(function_entry)) { \ + DTRACE_CHARBUF(process_name, DTRACE_TERM_BUF_SIZE); \ + DTRACE_CHARBUF(mfa, DTRACE_TERM_BUF_SIZE); \ + int depth = (STACK_START(p) - STACK_TOP(p)) \ + / sizeof(Eterm*); \ + dtrace_fun_decode(p, m, f, a, \ + process_name, mfa); \ + DTRACE3(function_entry, process_name, mfa, depth); \ + } + +#define DTRACE_RETURN(p, m, f, a) \ + if (DTRACE_ENABLED(function_return)) { \ + DTRACE_CHARBUF(process_name, DTRACE_TERM_BUF_SIZE); \ + DTRACE_CHARBUF(mfa, DTRACE_TERM_BUF_SIZE); \ + int depth = (STACK_START(p) - STACK_TOP(p)) \ + / sizeof(Eterm*); \ + dtrace_fun_decode(p, m, f, a, \ + process_name, mfa); \ + DTRACE3(function_return, process_name, mfa, depth); \ + } + +#define DTRACE_BIF_ENTRY(p, m, f, a) \ + if (DTRACE_ENABLED(bif_entry)) { \ + DTRACE_CHARBUF(process_name, DTRACE_TERM_BUF_SIZE); \ + DTRACE_CHARBUF(mfa, DTRACE_TERM_BUF_SIZE); \ + dtrace_fun_decode(p, m, f, a, \ + process_name, mfa); \ + DTRACE2(bif_entry, process_name, mfa); \ + } + +#define DTRACE_BIF_RETURN(p, m, f, a) \ + if (DTRACE_ENABLED(bif_return)) { \ + DTRACE_CHARBUF(process_name, DTRACE_TERM_BUF_SIZE); \ + DTRACE_CHARBUF(mfa, DTRACE_TERM_BUF_SIZE); \ + dtrace_fun_decode(p, m, f, a, \ + process_name, mfa); \ + DTRACE2(bif_return, process_name, mfa); \ + } + +#define DTRACE_NIF_ENTRY(p, m, f, a) \ + if (DTRACE_ENABLED(nif_entry)) { \ + DTRACE_CHARBUF(process_name, DTRACE_TERM_BUF_SIZE); \ + DTRACE_CHARBUF(mfa, DTRACE_TERM_BUF_SIZE); \ + dtrace_fun_decode(p, m, f, a, \ + process_name, mfa); \ + DTRACE2(nif_entry, process_name, mfa); \ + } + +#define DTRACE_NIF_RETURN(p, m, f, a) \ + if (DTRACE_ENABLED(nif_return)) { \ + DTRACE_CHARBUF(process_name, DTRACE_TERM_BUF_SIZE); \ + DTRACE_CHARBUF(mfa, DTRACE_TERM_BUF_SIZE); \ + dtrace_fun_decode(p, m, f, a, \ + process_name, mfa); \ + DTRACE2(nif_return, process_name, mfa); \ + } + +#else /* HAVE_DTRACE */ + +#define DTRACE_CALL(p, m, f, a) do {} while (0) +#define DTRACE_RETURN(p, m, f, a) do {} while (0) +#define DTRACE_BIF_ENTRY(p, m, f, a) do {} while (0) +#define DTRACE_BIF_RETURN(p, m, f, a) do {} while (0) +#define DTRACE_NIF_ENTRY(p, m, f, a) do {} while (0) +#define DTRACE_NIF_RETURN(p, m, f, a) do {} while (0) + +#endif /* HAVE_DTRACE */ + /* * process_main() is called twice: * The first call performs some initialisation, including exporting @@ -1221,6 +1361,28 @@ void process_main(void) #endif SWAPIN; ASSERT(VALID_INSTR(next)); + + if (DTRACE_ENABLED(process_scheduled)) { + DTRACE_CHARBUF(process_buf, DTRACE_TERM_BUF_SIZE); + DTRACE_CHARBUF(fun_buf, DTRACE_TERM_BUF_SIZE); + dtrace_proc_str(c_p, process_buf); + + if (ERTS_PROC_IS_EXITING(c_p)) { + strcpy(fun_buf, ""); + } else { + BeamInstr *fptr = find_function_from_pc(c_p->i); + if (fptr) { + dtrace_fun_decode(c_p, (Eterm)fptr[0], + (Eterm)fptr[1], (Uint)fptr[2], + NULL, fun_buf); + } else { + snprintf(fun_buf, sizeof(fun_buf), "", next); + } + } + + DTRACE2(process_scheduled, process_buf, fun_buf); + } + Goto(next); } @@ -1486,7 +1648,13 @@ void process_main(void) OpCase(return): { + BeamInstr* fptr; SET_I(c_p->cp); + + if (DTRACE_ENABLED(function_return) && (fptr = find_function_from_pc(c_p->cp))) { + DTRACE_RETURN(c_p, (Eterm)fptr[0], (Eterm)fptr[1], (Uint)fptr[2]); + } + /* * We must clear the CP to make sure that a stale value do not * create a false module dependcy preventing code upgrading. @@ -1755,6 +1923,7 @@ void process_main(void) * remove it... */ ASSERT(!msgp->data.attached); + /* TODO: Add DTrace probe for this bad message situation? */ UNLINK_MESSAGE(c_p, msgp); free_message(msgp); goto loop_rec__; @@ -1798,6 +1967,22 @@ void process_main(void) seq_trace_output(SEQ_TRACE_TOKEN(c_p), msg, SEQ_TRACE_RECEIVE, c_p->id, c_p); } + if (DTRACE_ENABLED(message_receive)) { + Eterm token2 = NIL; + DTRACE_CHARBUF(receiver_name, DTRACE_TERM_BUF_SIZE); + Sint tok_label = 0, tok_lastcnt = 0, tok_serial = 0; + + dtrace_proc_str(c_p, receiver_name); + token2 = SEQ_TRACE_TOKEN(c_p); + if (token2 != NIL) { + tok_label = signed_val(SEQ_TRACE_T_LABEL(token2)); + tok_lastcnt = signed_val(SEQ_TRACE_T_LASTCNT(token2)); + tok_serial = signed_val(SEQ_TRACE_T_SERIAL(token2)); + } + DTRACE6(message_receive, + receiver_name, size_object(ERL_MESSAGE_TERM(msgp)), + c_p->msg.len - 1, tok_label, tok_lastcnt, tok_serial); + } UNLINK_MESSAGE(c_p, msgp); JOIN_MESSAGE(c_p); CANCEL_TIMER(c_p); @@ -3157,6 +3342,8 @@ void process_main(void) */ BifFunction vbf; + DTRACE_NIF_ENTRY(c_p, (Eterm)I[-3], (Eterm)I[-2], (Uint)I[-1]); + c_p->current = I-3; /* current and vbf set to please handle_error */ SWAPOUT; c_p->fcalls = FCALLS - 1; @@ -3178,6 +3365,9 @@ void process_main(void) ASSERT(!ERTS_PROC_IS_EXITING(c_p) || is_non_value(nif_bif_result)); PROCESS_MAIN_CHK_LOCKS(c_p); ERTS_VERIFY_UNUSED_TEMP_ALLOC(c_p); + + DTRACE_NIF_RETURN(c_p, (Eterm)I[-3], (Eterm)I[-2], (Uint)I[-1]); + goto apply_bif_or_nif_epilogue; OpCase(apply_bif): @@ -3197,6 +3387,8 @@ void process_main(void) c_p->arity = 0; /* To allow garbage collection on ourselves * (check_process_code/2). */ + DTRACE_BIF_ENTRY(c_p, (Eterm)I[-3], (Eterm)I[-2], (Uint)I[-1]); + SWAPOUT; c_p->fcalls = FCALLS - 1; vbf = (BifFunction) Arg(0); @@ -3216,6 +3408,8 @@ void process_main(void) PROCESS_MAIN_CHK_LOCKS(c_p); } + DTRACE_BIF_RETURN(c_p, (Eterm)I[-3], (Eterm)I[-2], (Uint)I[-1]); + apply_bif_or_nif_epilogue: ERTS_SMP_REQ_PROC_MAIN_LOCK(c_p); ERTS_HOLE_CHECK(c_p); @@ -5899,6 +6093,13 @@ apply(Process* p, Eterm module, Eterm function, Eterm args, Eterm* reg) save_calls(p, ep); } + if (DTRACE_ENABLED(function_entry) && ep->address) { + BeamInstr *fptr = find_function_from_pc(ep->address); + if (fptr) { + DTRACE_CALL(p, (Eterm)fptr[0], (Eterm)fptr[1], (Uint)fptr[2]); + } + } + return ep->address; } @@ -5948,6 +6149,13 @@ fixed_apply(Process* p, Eterm* reg, Uint arity) save_calls(p, ep); } + if (DTRACE_ENABLED(function_entry)) { + BeamInstr *fptr = find_function_from_pc(ep->address); + if (fptr) { + DTRACE_CALL(p, (Eterm)fptr[0], (Eterm)fptr[1], (Uint)fptr[2]); + } + } + return ep->address; } @@ -5997,6 +6205,14 @@ erts_hibernate(Process* c_p, Eterm module, Eterm function, Eterm args, Eterm* re c_p->max_arg_reg = sizeof(c_p->def_arg_reg)/sizeof(c_p->def_arg_reg[0]); } + if (DTRACE_ENABLED(process_hibernate)) { + DTRACE_CHARBUF(process_name, DTRACE_TERM_BUF_SIZE); + DTRACE_CHARBUF(mfa, DTRACE_TERM_BUF_SIZE); + dtrace_fun_decode(c_p, module, function, arity, + process_name, mfa); + DTRACE2(process_hibernate, process_name, mfa); + } + /* * Arrange for the process to be resumed at the given MFA with * the stack cleared. @@ -6071,6 +6287,14 @@ call_fun(Process* p, /* Current process. */ code_ptr = fe->address; actual_arity = (int) code_ptr[-1]; + if (DTRACE_ENABLED(function_entry)) { + BeamInstr *fptr = find_function_from_pc(code_ptr); + + if (fptr) { + DTRACE_CALL(p, fe->module, (Eterm)fptr[1], actual_arity); + } + } + if (actual_arity == arity+num_free) { if (num_free == 0) { return code_ptr; @@ -6089,7 +6313,7 @@ call_fun(Process* p, /* Current process. */ } else { /* * Something wrong here. First build a list of the arguments. - */ + */ if (is_non_value(args)) { Uint sz = 2 * arity; @@ -6164,6 +6388,7 @@ call_fun(Process* p, /* Current process. */ actual_arity = (int) ep->code[2]; if (arity == actual_arity) { + DTRACE_CALL(p, ep->code[0], ep->code[1], (Uint)ep->code[2]); return ep->address; } else { /* @@ -6239,6 +6464,7 @@ call_fun(Process* p, /* Current process. */ reg[1] = function; reg[2] = args; } + DTRACE_CALL(p, module, function, arity); return ep->address; } else { badfun: diff --git a/erts/emulator/beam/copy.c b/erts/emulator/beam/copy.c index 1d968fb147..4ee60807d9 100644 --- a/erts/emulator/beam/copy.c +++ b/erts/emulator/beam/copy.c @@ -30,6 +30,7 @@ #include "big.h" #include "erl_binary.h" #include "erl_bits.h" +#include "dtrace-wrapper.h" #ifdef HYBRID MA_STACK_DECLARE(src); @@ -59,6 +60,12 @@ copy_object(Eterm obj, Process* to) Eterm* hp = HAlloc(to, size); Eterm res; + if (DTRACE_ENABLED(copy_object)) { + DTRACE_CHARBUF(proc_name, 64); + + erts_snprintf(proc_name, sizeof(proc_name), "%T", to->id); + DTRACE2(copy_object, proc_name, size); + } res = copy_struct(obj, size, &hp, &to->off_heap); #ifdef DEBUG if (eq(obj, res) == 0) { @@ -213,6 +220,8 @@ Eterm copy_struct(Eterm obj, Uint sz, Eterm** hpp, ErlOffHeap* off_heap) if (IS_CONST(obj)) return obj; + DTRACE1(copy_struct, (int32_t)sz); + hp = htop = *hpp; hbot = htop + sz; hstart = (char *)htop; diff --git a/erts/emulator/beam/dist.c b/erts/emulator/beam/dist.c index bee61e7273..6f6b04d278 100644 --- a/erts/emulator/beam/dist.c +++ b/erts/emulator/beam/dist.c @@ -42,6 +42,7 @@ #include "external.h" #include "erl_binary.h" #include "erl_thr_progress.h" +#include "dtrace-wrapper.h" /* Turn this on to get printouts of all distribution messages * which go on the line @@ -740,6 +741,11 @@ erts_dsig_send_msg(ErtsDSigData *dsdp, Eterm remote, Eterm message) Eterm token = NIL; Process *sender = dsdp->proc; int res; + Sint tok_label = 0, tok_lastcnt = 0, tok_serial = 0; + Uint msize = 0; + DTRACE_CHARBUF(node_name, 64); + DTRACE_CHARBUF(sender_name, 64); + DTRACE_CHARBUF(receiver_name, 64); UseTmpHeapNoproc(5); if (SEQ_TRACE_TOKEN(sender) != NIL) { @@ -747,12 +753,28 @@ erts_dsig_send_msg(ErtsDSigData *dsdp, Eterm remote, Eterm message) token = SEQ_TRACE_TOKEN(sender); seq_trace_output(token, message, SEQ_TRACE_SEND, remote, sender); } + *node_name = *sender_name = *receiver_name = '\0'; + if (DTRACE_ENABLED(message_send) || DTRACE_ENABLED(message_send_remote)) { + erts_snprintf(node_name, sizeof(node_name), "%T", dsdp->dep->sysname); + erts_snprintf(sender_name, sizeof(sender_name), "%T", sender->id); + erts_snprintf(receiver_name, sizeof(receiver_name), "%T", remote); + msize = size_object(message); + if (token != NIL) { + tok_label = signed_val(SEQ_TRACE_T_LABEL(token)); + tok_lastcnt = signed_val(SEQ_TRACE_T_LASTCNT(token)); + tok_serial = signed_val(SEQ_TRACE_T_SERIAL(token)); + } + } if (token != NIL) ctl = TUPLE4(&ctl_heap[0], make_small(DOP_SEND_TT), am_Cookie, remote, token); else ctl = TUPLE3(&ctl_heap[0], make_small(DOP_SEND), am_Cookie, remote); + DTRACE6(message_send, sender_name, receiver_name, + msize, tok_label, tok_lastcnt, tok_serial); + DTRACE7(message_send_remote, sender_name, node_name, receiver_name, + msize, tok_label, tok_lastcnt, tok_serial); res = dsig_send(dsdp, ctl, message, 0); UnUseTmpHeapNoproc(5); return res; @@ -766,6 +788,11 @@ erts_dsig_send_reg_msg(ErtsDSigData *dsdp, Eterm remote_name, Eterm message) Eterm token = NIL; Process *sender = dsdp->proc; int res; + Sint tok_label = 0, tok_lastcnt = 0, tok_serial = 0; + Uint32 msize = 0; + DTRACE_CHARBUF(node_name, 64); + DTRACE_CHARBUF(sender_name, 64); + DTRACE_CHARBUF(receiver_name, 128); UseTmpHeapNoproc(6); if (SEQ_TRACE_TOKEN(sender) != NIL) { @@ -773,6 +800,19 @@ erts_dsig_send_reg_msg(ErtsDSigData *dsdp, Eterm remote_name, Eterm message) token = SEQ_TRACE_TOKEN(sender); seq_trace_output(token, message, SEQ_TRACE_SEND, remote_name, sender); } + *node_name = *sender_name = *receiver_name = '\0'; + if (DTRACE_ENABLED(message_send) || DTRACE_ENABLED(message_send_remote)) { + erts_snprintf(node_name, sizeof(node_name), "%T", dsdp->dep->sysname); + erts_snprintf(sender_name, sizeof(sender_name), "%T", sender->id); + erts_snprintf(receiver_name, sizeof(receiver_name), + "{%T,%s}", remote_name, node_name); + msize = size_object(message); + if (token != NIL) { + tok_label = signed_val(SEQ_TRACE_T_LABEL(token)); + tok_lastcnt = signed_val(SEQ_TRACE_T_LASTCNT(token)); + tok_serial = signed_val(SEQ_TRACE_T_SERIAL(token)); + } + } if (token != NIL) ctl = TUPLE5(&ctl_heap[0], make_small(DOP_REG_SEND_TT), @@ -780,6 +820,10 @@ erts_dsig_send_reg_msg(ErtsDSigData *dsdp, Eterm remote_name, Eterm message) else ctl = TUPLE4(&ctl_heap[0], make_small(DOP_REG_SEND), sender->id, am_Cookie, remote_name); + DTRACE6(message_send, sender_name, receiver_name, + msize, tok_label, tok_lastcnt, tok_serial); + DTRACE7(message_send_remote, sender_name, node_name, receiver_name, + msize, tok_label, tok_lastcnt, tok_serial); res = dsig_send(dsdp, ctl, message, 0); UnUseTmpHeapNoproc(6); return res; @@ -793,6 +837,12 @@ erts_dsig_send_exit_tt(ErtsDSigData *dsdp, Eterm local, Eterm remote, Eterm ctl; DeclareTmpHeapNoproc(ctl_heap,6); int res; + Process *sender = dsdp->proc; + Sint tok_label = 0, tok_lastcnt = 0, tok_serial = 0; + DTRACE_CHARBUF(node_name, 64); + DTRACE_CHARBUF(sender_name, 64); + DTRACE_CHARBUF(remote_name, 128); + DTRACE_CHARBUF(reason_str, 128); UseTmpHeapNoproc(6); if (token != NIL) { @@ -803,6 +853,21 @@ erts_dsig_send_exit_tt(ErtsDSigData *dsdp, Eterm local, Eterm remote, } else { ctl = TUPLE4(&ctl_heap[0], make_small(DOP_EXIT), local, remote, reason); } + *node_name = *sender_name = *remote_name = '\0'; + if (DTRACE_ENABLED(process_exit_signal_remote)) { + erts_snprintf(node_name, sizeof(node_name), "%T", dsdp->dep->sysname); + erts_snprintf(sender_name, sizeof(sender_name), "%T", sender->id); + erts_snprintf(remote_name, sizeof(remote_name), + "{%T,%s}", remote, node_name); + erts_snprintf(reason_str, sizeof(reason), "%T", reason); + if (token != NIL) { + tok_label = signed_val(SEQ_TRACE_T_LABEL(token)); + tok_lastcnt = signed_val(SEQ_TRACE_T_LASTCNT(token)); + tok_serial = signed_val(SEQ_TRACE_T_SERIAL(token)); + } + } + DTRACE7(process_exit_signal_remote, sender_name, node_name, + remote_name, reason_str, tok_label, tok_lastcnt, tok_serial); /* forced, i.e ignore busy */ res = dsig_send(dsdp, ctl, THE_NON_VALUE, 1); UnUseTmpHeapNoproc(6); @@ -1619,6 +1684,16 @@ dsig_send(ErtsDSigData *dsdp, Eterm ctl, Eterm msg, int force_busy) if (!(dep->qflgs & ERTS_DE_QFLG_BUSY)) { if (suspended) resume = 1; /* was busy when we started, but isn't now */ + if (resume && DTRACE_ENABLED(dist_port_not_busy)) { + DTRACE_CHARBUF(port_str, 64); + DTRACE_CHARBUF(remote_str, 64); + + erts_snprintf(port_str, sizeof(port_str), "%T", cid); + erts_snprintf(remote_str, sizeof(remote_str), + "%T", dep->sysname); + DTRACE3(dist_port_not_busy, erts_this_node_sysname, + port_str, remote_str); + } } else { /* Enqueue suspended process on dist entry */ @@ -1668,6 +1743,17 @@ dsig_send(ErtsDSigData *dsdp, Eterm ctl, Eterm msg, int force_busy) } if (suspended) { + if (!resume && DTRACE_ENABLED(dist_port_busy)) { + DTRACE_CHARBUF(port_str, 64); + DTRACE_CHARBUF(remote_str, 64); + DTRACE_CHARBUF(pid_str, 16); + + erts_snprintf(port_str, sizeof(port_str), "%T", cid); + erts_snprintf(remote_str, sizeof(remote_str), "%T", dep->sysname); + erts_snprintf(pid_str, sizeof(pid_str), "%T", c_p->id); + DTRACE4(dist_port_busy, erts_this_node_sysname, + port_str, remote_str, pid_str); + } if (!resume && erts_system_monitor_flags.busy_dist_port) monitor_generic(c_p, am_busy_dist_port, cid); return ERTS_DSIG_SEND_YIELD; @@ -1691,6 +1777,16 @@ dist_port_command(Port *prt, ErtsDistOutputBuf *obuf) "(%beu bytes) passed.\n", size); + if (DTRACE_ENABLED(dist_output)) { + DTRACE_CHARBUF(port_str, 64); + DTRACE_CHARBUF(remote_str, 64); + + erts_snprintf(port_str, sizeof(port_str), "%T", prt->id); + erts_snprintf(remote_str, sizeof(remote_str), + "%T", prt->dist_entry->sysname); + DTRACE4(dist_output, erts_this_node_sysname, port_str, + remote_str, size); + } prt->caller = NIL; fpe_was_unmasked = erts_block_fpe(); (*prt->drv_ptr->output)((ErlDrvData) prt->drv_data, @@ -1733,6 +1829,16 @@ dist_port_commandv(Port *prt, ErtsDistOutputBuf *obuf) ASSERT(prt->drv_ptr->outputv); + if (DTRACE_ENABLED(dist_outputv)) { + DTRACE_CHARBUF(port_str, 64); + DTRACE_CHARBUF(remote_str, 64); + + erts_snprintf(port_str, sizeof(port_str), "%T", prt->id); + erts_snprintf(remote_str, sizeof(remote_str), + "%T", prt->dist_entry->sysname); + DTRACE4(dist_outputv, erts_this_node_sysname, port_str, + remote_str, size); + } prt->caller = NIL; fpe_was_unmasked = erts_block_fpe(); (*prt->drv_ptr->outputv)((ErlDrvData) prt->drv_data, &eiov); @@ -2052,6 +2158,16 @@ erts_dist_command(Port *prt, int reds_limit) void erts_dist_port_not_busy(Port *prt) { + if (DTRACE_ENABLED(dist_port_not_busy)) { + DTRACE_CHARBUF(port_str, 64); + DTRACE_CHARBUF(remote_str, 64); + + erts_snprintf(port_str, sizeof(port_str), "%T", prt->id); + erts_snprintf(remote_str, sizeof(remote_str), + "%T", prt->dist_entry->sysname); + DTRACE3(dist_port_not_busy, erts_this_node_sysname, + port_str, remote_str); + } erts_schedule_dist_command(prt, NULL); } @@ -2985,6 +3101,19 @@ send_nodes_mon_msgs(Process *c_p, Eterm what, Eterm node, Eterm type, Eterm reas ASSERT(is_immed(what)); ASSERT(is_immed(node)); ASSERT(is_immed(type)); + if (DTRACE_ENABLED(dist_monitor)) { + DTRACE_CHARBUF(what_str, 12); + DTRACE_CHARBUF(node_str, 64); + DTRACE_CHARBUF(type_str, 12); + DTRACE_CHARBUF(reason_str, 64); + + erts_snprintf(what_str, sizeof(what_str), "%T", what); + erts_snprintf(node_str, sizeof(node_str), "%T", node); + erts_snprintf(type_str, sizeof(type_str), "%T", type); + erts_snprintf(reason_str, sizeof(reason_str), "%T", reason); + DTRACE5(dist_monitor, erts_this_node_sysname, + what_str, node_str, type_str, reason_str); + } ERTS_SMP_LC_ASSERT(!c_p || (erts_proc_lc_my_proc_locks(c_p) diff --git a/erts/emulator/beam/erl_async.c b/erts/emulator/beam/erl_async.c index 8bca9ae582..72dcc99f4f 100644 --- a/erts/emulator/beam/erl_async.c +++ b/erts/emulator/beam/erl_async.c @@ -26,6 +26,7 @@ #include "erl_threads.h" #include "erl_thr_queue.h" #include "erl_async.h" +#include "dtrace-wrapper.h" #define ERTS_MAX_ASYNC_READY_CALLS_IN_SEQ 20 @@ -121,6 +122,14 @@ typedef struct { #endif } ErtsAsyncData; +/* + * Some compilers, e.g. GCC 4.2.1 and -O3, will optimize away DTrace + * calls if they're the last thing in the function. :-( + * Many thanks to Trond Norbye, via: + * https://github.com/memcached/memcached/commit/6298b3978687530bc9d219b6ac707a1b681b2a46 + */ +static unsigned gcc_optimizer_hack = 0; + int erts_async_max_threads; /* Initialized by erl_init.c */ int erts_async_thread_suggested_stack_size; /* Initialized by erl_init.c */ @@ -244,6 +253,9 @@ erts_get_async_ready_queue(Uint sched_id) static ERTS_INLINE void async_add(ErtsAsync *a, ErtsAsyncQ* q) { + /* DTRACE TODO: Get the queue length from erts_thr_q_enqueue() */ + int len = -1; + if (is_internal_port(a->port)) { #if ERTS_USE_ASYNC_READY_Q ErtsAsyncReadyQ *arq = async_ready_q(a->sched_id); @@ -259,6 +271,13 @@ static ERTS_INLINE void async_add(ErtsAsync *a, ErtsAsyncQ* q) #endif erts_thr_q_enqueue(&q->thr_q, a); + if (DTRACE_ENABLED(aio_pool_add)) { + DTRACE_CHARBUF(port_str, 16); + + erts_snprintf(port_str, sizeof(port_str), "%T", a->port); + DTRACE2(aio_pool_add, port_str, len); + } + gcc_optimizer_hack++; } static ERTS_INLINE ErtsAsync *async_get(ErtsThrQ_t *q, @@ -269,6 +288,8 @@ static ERTS_INLINE ErtsAsync *async_get(ErtsThrQ_t *q, int saved_fin_deq = 0; ErtsThrQFinDeQ_t fin_deq; #endif + /* DTRACE TODO: Get the queue length from erts_thr_q_dequeue() somehow? */ + int len = -1; while (1) { ErtsAsync *a = (ErtsAsync *) erts_thr_q_dequeue(q); @@ -280,7 +301,12 @@ static ERTS_INLINE ErtsAsync *async_get(ErtsThrQ_t *q, if (saved_fin_deq) erts_thr_q_append_finalize_dequeue_data(&a->q.fin_deq, &fin_deq); #endif + if (DTRACE_ENABLED(aio_pool_get)) { + DTRACE_CHARBUF(port_str, 16); + erts_snprintf(port_str, sizeof(port_str), "%T", a->port); + DTRACE2(aio_pool_get, port_str, len); + } return a; } diff --git a/erts/emulator/beam/erl_bif_ddll.c b/erts/emulator/beam/erl_bif_ddll.c index 37d540b41b..3326fd84df 100644 --- a/erts/emulator/beam/erl_bif_ddll.c +++ b/erts/emulator/beam/erl_bif_ddll.c @@ -45,6 +45,7 @@ #include "big.h" #include "dist.h" #include "erl_version.h" +#include "dtrace-wrapper.h" #ifdef ERTS_SMP #define DDLL_SMP 1 @@ -1647,6 +1648,7 @@ static int do_unload_driver_entry(DE_Handle *dh, Eterm *save_name) diver_list lock here!*/ if (q->finish) { int fpe_was_unmasked = erts_block_fpe(); + DTRACE1(driver_finish, q->name); (*(q->finish))(); erts_unblock_fpe(fpe_was_unmasked); } diff --git a/erts/emulator/beam/erl_bif_info.c b/erts/emulator/beam/erl_bif_info.c index ebd475f73a..90bbb34927 100644 --- a/erts/emulator/beam/erl_bif_info.c +++ b/erts/emulator/beam/erl_bif_info.c @@ -114,6 +114,9 @@ static char erts_system_version[] = ("Erlang " ERLANG_OTP_RELEASE #endif #ifdef VALGRIND " [valgrind-compiled]" +#endif +#ifdef HAVE_DTRACE + " [dtrace]" #endif "\n"); diff --git a/erts/emulator/beam/erl_bif_port.c b/erts/emulator/beam/erl_bif_port.c index cd423eb200..8caa64b97d 100644 --- a/erts/emulator/beam/erl_bif_port.c +++ b/erts/emulator/beam/erl_bif_port.c @@ -40,6 +40,7 @@ #include "external.h" #include "packet_parser.h" #include "erl_bits.h" +#include "dtrace-wrapper.h" static int open_port(Process* p, Eterm name, Eterm settings, int *err_nump); static byte* convert_environment(Process* p, Eterm env); @@ -343,6 +344,14 @@ port_call(Process* c_p, Eterm arg1, Eterm arg2, Eterm arg3) __FILE__, __LINE__, endp - (bytes + size)); } erts_smp_proc_unlock(c_p, ERTS_PROC_LOCK_MAIN); + if (DTRACE_ENABLED(driver_call)) { + DTRACE_CHARBUF(process_str, DTRACE_TERM_BUF_SIZE); + DTRACE_CHARBUF(port_str, DTRACE_TERM_BUF_SIZE); + + dtrace_pid_str(p->connected, process_str); + dtrace_port_str(p, port_str); + DTRACE5(driver_call, process_str, port_str, p->name, op, real_size); + } prc = (char *) port_resp; fpe_was_unmasked = erts_block_fpe(); ret = drv->call((ErlDrvData)p->drv_data, @@ -539,6 +548,16 @@ BIF_RETTYPE port_connect_2(BIF_ALIST_2) prt->connected = pid; /* internal pid */ erts_smp_port_unlock(prt); + if (DTRACE_ENABLED(port_connect)) { + DTRACE_CHARBUF(process_str, DTRACE_TERM_BUF_SIZE); + DTRACE_CHARBUF(port_str, DTRACE_TERM_BUF_SIZE); + DTRACE_CHARBUF(newprocess_str, DTRACE_TERM_BUF_SIZE); + + dtrace_pid_str(prt->connected, process_str); + erts_snprintf(port_str, sizeof(port_str), "%T", prt->id); + dtrace_proc_str(rp, newprocess_str); + DTRACE4(port_connect, process_str, port_str, prt->name, newprocess_str); + } BIF_RET(am_true); } @@ -904,6 +923,14 @@ open_port(Process* p, Eterm name, Eterm settings, int *err_nump) erts_smp_proc_unlock(p, ERTS_PROC_LOCK_MAIN); port_num = erts_open_driver(driver, p->id, name_buf, &opts, err_nump); + if (port_num >= 0 && DTRACE_ENABLED(port_open)) { + DTRACE_CHARBUF(process_str, DTRACE_TERM_BUF_SIZE); + DTRACE_CHARBUF(port_str, DTRACE_TERM_BUF_SIZE); + + dtrace_proc_str(p, process_str); + erts_snprintf(port_str, sizeof(port_str), "%T", erts_port[port_num].id); + DTRACE3(port_open, process_str, name_buf, port_str); + } erts_smp_proc_lock(p, ERTS_PROC_LOCK_MAIN); diff --git a/erts/emulator/beam/erl_gc.c b/erts/emulator/beam/erl_gc.c index bde87b8346..858ae32ad5 100644 --- a/erts/emulator/beam/erl_gc.c +++ b/erts/emulator/beam/erl_gc.c @@ -35,6 +35,7 @@ #include "hipe_stack.h" #include "hipe_mode_switch.h" #endif +#include "dtrace-wrapper.h" #define ERTS_INACT_WR_PB_LEAVE_MUCH_LIMIT 1 #define ERTS_INACT_WR_PB_LEAVE_MUCH_PERCENTAGE 20 @@ -349,6 +350,7 @@ erts_garbage_collect(Process* p, int need, Eterm* objv, int nobj) Uint reclaimed_now = 0; int done = 0; Uint ms1, s1, us1; + DTRACE_CHARBUF(pidbuf, DTRACE_TERM_BUF_SIZE); if (IS_TRACED_FL(p, F_TRACE_GC)) { trace_gc(p, am_gc_start); @@ -370,14 +372,26 @@ erts_garbage_collect(Process* p, int need, Eterm* objv, int nobj) FLAGS(p) |= F_NEED_FULLSWEEP; } + *pidbuf = '\0'; + if (DTRACE_ENABLED(gc_major_start) + || DTRACE_ENABLED(gc_major_end) + || DTRACE_ENABLED(gc_minor_start) + || DTRACE_ENABLED(gc_minor_end)) { + dtrace_proc_str(p, pidbuf); + } + /* * Test which type of GC to do. */ while (!done) { if ((FLAGS(p) & F_NEED_FULLSWEEP) != 0) { + DTRACE2(gc_major_start, pidbuf, need); done = major_collection(p, need, objv, nobj, &reclaimed_now); + DTRACE2(gc_major_end, pidbuf, reclaimed_now); } else { + DTRACE2(gc_minor_start, pidbuf, need); done = minor_collection(p, need, objv, nobj, &reclaimed_now); + DTRACE2(gc_minor_end, pidbuf, reclaimed_now); } } @@ -1118,6 +1132,13 @@ do_minor(Process *p, Uint new_sz, Eterm* objv, int nobj) sys_memcpy(n_heap + new_sz - n, p->stop, n * sizeof(Eterm)); p->stop = n_heap + new_sz - n; + if (HEAP_SIZE(p) != new_sz && DTRACE_ENABLED(process_heap_grow)) { + DTRACE_CHARBUF(pidbuf, DTRACE_TERM_BUF_SIZE); + + dtrace_proc_str(p, pidbuf); + DTRACE3(process_heap_grow, pidbuf, HEAP_SIZE(p), new_sz); + } + ERTS_HEAP_FREE(ERTS_ALC_T_HEAP, (void*)HEAP_START(p), HEAP_SIZE(p) * sizeof(Eterm)); @@ -1339,6 +1360,13 @@ major_collection(Process* p, int need, Eterm* objv, int nobj, Uint *recl) sys_memcpy(n_heap + new_sz - n, p->stop, n * sizeof(Eterm)); p->stop = n_heap + new_sz - n; + if (HEAP_SIZE(p) != new_sz && DTRACE_ENABLED(process_heap_grow)) { + DTRACE_CHARBUF(pidbuf, DTRACE_TERM_BUF_SIZE); + + dtrace_proc_str(p, pidbuf); + DTRACE3(process_heap_grow, pidbuf, HEAP_SIZE(p), new_sz); + } + ERTS_HEAP_FREE(ERTS_ALC_T_HEAP, (void *) HEAP_START(p), (HEAP_END(p) - HEAP_START(p)) * sizeof(Eterm)); @@ -2009,6 +2037,14 @@ grow_new_heap(Process *p, Uint new_sz, Eterm* objv, int nobj) HEAP_TOP(p) = new_heap + heap_size; HEAP_START(p) = new_heap; } + + if (DTRACE_ENABLED(process_heap_grow)) { + DTRACE_CHARBUF(pidbuf, DTRACE_TERM_BUF_SIZE); + + dtrace_proc_str(p, pidbuf); + DTRACE3(process_heap_grow, pidbuf, HEAP_SIZE(p), new_sz); + } + HEAP_SIZE(p) = new_sz; } @@ -2018,8 +2054,8 @@ shrink_new_heap(Process *p, Uint new_sz, Eterm *objv, int nobj) Eterm* new_heap; Uint heap_size = HEAP_TOP(p) - HEAP_START(p); Sint offs; - Uint stack_size = p->hend - p->stop; + char pidbuf[DTRACE_TERM_BUF_SIZE]; ASSERT(new_sz < p->heap_sz); sys_memmove(p->heap + new_sz - stack_size, p->stop, stack_size * @@ -2047,6 +2083,14 @@ shrink_new_heap(Process *p, Uint new_sz, Eterm *objv, int nobj) HEAP_TOP(p) = new_heap + heap_size; HEAP_START(p) = new_heap; } + + if (DTRACE_ENABLED(process_heap_shrink)) { + DTRACE_CHARBUF(pidbuf, DTRACE_TERM_BUF_SIZE); + + dtrace_proc_str(p, pidbuf); + DTRACE3(process_heap_shrink, pidbuf, HEAP_SIZE(p), new_sz); + } + HEAP_SIZE(p) = new_sz; } diff --git a/erts/emulator/beam/erl_lock_check.c b/erts/emulator/beam/erl_lock_check.c index 09e85893c3..561570c30e 100644 --- a/erts/emulator/beam/erl_lock_check.c +++ b/erts/emulator/beam/erl_lock_check.c @@ -182,6 +182,9 @@ static erts_lc_lock_order_t erts_lock_order[] = { #ifdef DEBUG { "save_ops_lock", NULL }, #endif +#endif +#ifdef HAVE_DTRACE + { "efile_drv dtrace mutex", NULL }, #endif { "mtrace_buf", NULL }, { "erts_alloc_hard_debug", NULL } diff --git a/erts/emulator/beam/erl_message.c b/erts/emulator/beam/erl_message.c index ab1ab7b1ea..8489353c9e 100644 --- a/erts/emulator/beam/erl_message.c +++ b/erts/emulator/beam/erl_message.c @@ -31,6 +31,7 @@ #include "erl_process.h" #include "erl_nmgc.h" #include "erl_binary.h" +#include "dtrace-wrapper.h" ERTS_SCHED_PREF_QUICK_ALLOC_IMPL(message, ErlMessage, @@ -335,6 +336,7 @@ erts_queue_dist_message(Process *rcvr, Eterm token) { ErlMessage* mp; + Sint tok_label = 0, tok_lastcnt = 0, tok_serial = 0; #ifdef ERTS_SMP ErtsProcLocks need_locks; #endif @@ -376,6 +378,19 @@ erts_queue_dist_message(Process *rcvr, message_free(mp); msg = erts_msg_distext2heap(rcvr, rcvr_locks, &mbuf, &token, dist_ext); if (is_value(msg)) + if (DTRACE_ENABLED(message_queued)) { + DTRACE_CHARBUF(receiver_name, DTRACE_TERM_BUF_SIZE); + + dtrace_proc_str(rcvr, receiver_name); + if (token != NIL) { + tok_label = signed_val(SEQ_TRACE_T_LABEL(token)); + tok_lastcnt = signed_val(SEQ_TRACE_T_LASTCNT(token)); + tok_serial = signed_val(SEQ_TRACE_T_SERIAL(token)); + } + DTRACE6(message_queued, + receiver_name, size_object(msg), rcvr->msg.len, + tok_label, tok_lastcnt, tok_serial); + } erts_queue_message(rcvr, rcvr_locks, mbuf, msg, token); } else { @@ -385,6 +400,22 @@ erts_queue_dist_message(Process *rcvr, ERL_MESSAGE_TOKEN(mp) = token; mp->next = NULL; + if (DTRACE_ENABLED(message_queued)) { + DTRACE_CHARBUF(receiver_name, DTRACE_TERM_BUF_SIZE); + + dtrace_proc_str(rcvr, receiver_name); + if (token != NIL) { + tok_label = signed_val(SEQ_TRACE_T_LABEL(token)); + tok_lastcnt = signed_val(SEQ_TRACE_T_LASTCNT(token)); + tok_serial = signed_val(SEQ_TRACE_T_SERIAL(token)); + } + /* + * TODO: We don't know the real size of the external message here. + * -1 will appear to a D script as 4294967295. + */ + DTRACE6(message_queued, receiver_name, -1, rcvr->msg.len + 1, + tok_label, tok_lastcnt, tok_serial); + } mp->data.dist_ext = dist_ext; LINK_MESSAGE(rcvr, mp); @@ -462,12 +493,27 @@ erts_queue_message(Process* receiver, LINK_MESSAGE(receiver, mp); #endif + if (DTRACE_ENABLED(message_queued)) { + DTRACE_CHARBUF(receiver_name, DTRACE_TERM_BUF_SIZE); + Sint tok_label = 0, tok_lastcnt = 0, tok_serial = 0; + + dtrace_proc_str(receiver, receiver_name); + if (seq_trace_token != NIL && is_tuple(seq_trace_token)) { + tok_label = signed_val(SEQ_TRACE_T_LABEL(seq_trace_token)); + tok_lastcnt = signed_val(SEQ_TRACE_T_LASTCNT(seq_trace_token)); + tok_serial = signed_val(SEQ_TRACE_T_SERIAL(seq_trace_token)); + } + DTRACE6(message_queued, + receiver_name, size_object(message), receiver->msg.len, + tok_label, tok_lastcnt, tok_serial); + } + notify_new_message(receiver); if (IS_TRACED_FL(receiver, F_TRACE_RECEIVE)) { trace_receive(receiver, message); } - + #ifndef ERTS_SMP ERTS_HOLE_CHECK(receiver); #endif @@ -774,11 +820,19 @@ erts_send_message(Process* sender, Uint msize; ErlHeapFragment* bp = NULL; Eterm token = NIL; + DTRACE_CHARBUF(sender_name, 64); + DTRACE_CHARBUF(receiver_name, 64); + Sint tok_label = 0, tok_lastcnt = 0, tok_serial = 0; BM_STOP_TIMER(system); BM_MESSAGE(message,sender,receiver); BM_START_TIMER(send); + *sender_name = *receiver_name = '\0'; + if (DTRACE_ENABLED(message_send)) { + erts_snprintf(sender_name, sizeof(sender_name), "%T", sender->id); + erts_snprintf(receiver_name, sizeof(receiver_name), "%T", receiver->id); + } if (SEQ_TRACE_TOKEN(sender) != NIL && !(flags & ERTS_SND_FLG_NO_SEQ_TRACE)) { Eterm* hp; @@ -802,6 +856,16 @@ erts_send_message(Process* sender, BM_MESSAGE_COPIED(msize); BM_SWAP_TIMER(copy,send); + if (DTRACE_ENABLED(message_send)) { + Eterm token2 = NIL; + + token2 = SEQ_TRACE_TOKEN(sender); + tok_label = signed_val(SEQ_TRACE_T_LABEL(token2)); + tok_lastcnt = signed_val(SEQ_TRACE_T_LASTCNT(token2)); + tok_serial = signed_val(SEQ_TRACE_T_SERIAL(token2)); + DTRACE6(message_send, sender_name, receiver_name, + msize, tok_label, tok_lastcnt, tok_serial); + } erts_queue_message(receiver, receiver_locks, bp, @@ -835,6 +899,8 @@ erts_send_message(Process* sender, #endif LAZY_COPY(sender,message); BM_SWAP_TIMER(copy,send); + DTRACE6(message_send, sender_name, receiver_name, + size_object(message)msize, tok_label, tok_lastcnt, tok_serial); ERL_MESSAGE_TERM(mp) = message; ERL_MESSAGE_TOKEN(mp) = NIL; mp->next = NULL; @@ -874,6 +940,8 @@ erts_send_message(Process* sender, { ErlMessage* mp = message_alloc(); + DTRACE6(message_send, sender_name, receiver_name, + size_object(message), tok_label, tok_lastcnt, tok_serial); mp->data.attached = NULL; ERL_MESSAGE_TERM(mp) = message; ERL_MESSAGE_TOKEN(mp) = NIL; @@ -908,6 +976,8 @@ erts_send_message(Process* sender, message = copy_struct(message, msize, &hp, ohp); BM_MESSAGE_COPIED(msz); BM_SWAP_TIMER(copy,send); + DTRACE6(message_send, sender_name, receiver_name, + msize, tok_label, tok_lastcnt, tok_serial); erts_queue_message(receiver, receiver_locks, bp, message, token); BM_SWAP_TIMER(send,system); #else @@ -928,6 +998,8 @@ erts_send_message(Process* sender, message = copy_struct(message, msize, &hp, &receiver->off_heap); BM_MESSAGE_COPIED(msize); BM_SWAP_TIMER(copy,send); + DTRACE6(message_send, sender_name, receiver_name, + (uint32_t)msize, tok_label, tok_lastcnt, tok_serial); ERL_MESSAGE_TERM(mp) = message; ERL_MESSAGE_TOKEN(mp) = NIL; mp->next = NULL; diff --git a/erts/emulator/beam/erl_nif.c b/erts/emulator/beam/erl_nif.c index 58a09986d2..dc4049327d 100644 --- a/erts/emulator/beam/erl_nif.c +++ b/erts/emulator/beam/erl_nif.c @@ -66,6 +66,7 @@ static void add_readonly_check(ErlNifEnv*, unsigned char* ptr, unsigned sz); static int is_offheap(const ErlOffHeap* off_heap); #endif +void dtrace_nifenv_str(ErlNifEnv *, char *); #define MIN_HEAP_FRAG_SZ 200 static Eterm* alloc_heap_heavy(ErlNifEnv* env, unsigned need, Eterm* hp); @@ -1779,6 +1780,11 @@ void erl_nif_init() resource_type_list.name = THE_NON_VALUE; } +void dtrace_nifenv_str(ErlNifEnv *env, char *process_buf) +{ + dtrace_pid_str(env->proc->id, process_buf); +} + #ifdef READONLY_CHECK /* Use checksums to assert that NIFs do not write into inspected binaries */ diff --git a/erts/emulator/beam/erl_node_tables.c b/erts/emulator/beam/erl_node_tables.c index 908ba755ed..1481f66b55 100644 --- a/erts/emulator/beam/erl_node_tables.c +++ b/erts/emulator/beam/erl_node_tables.c @@ -27,6 +27,7 @@ #include "big.h" #include "error.h" #include "erl_thr_progress.h" +#include "dtrace-wrapper.h" Hash erts_dist_table; Hash erts_node_table; @@ -42,6 +43,8 @@ Sint erts_no_of_not_connected_dist_entries; DistEntry *erts_this_dist_entry; ErlNode *erts_this_node; +char erts_this_node_sysname_BUFFER[256], + *erts_this_node_sysname = "uninitialized yet"; static Uint node_entries; static Uint dist_entries; @@ -702,6 +705,9 @@ erts_set_this_node(Eterm sysname, Uint creation) (void) hash_erase(&erts_node_table, (void *) erts_this_node); erts_this_node->sysname = sysname; erts_this_node->creation = creation; + erts_this_node_sysname = erts_this_node_sysname_BUFFER; + erts_snprintf(erts_this_node_sysname, sizeof(erts_this_node_sysname), + "%T", sysname); (void) hash_put(&erts_node_table, (void *) erts_this_node); erts_smp_rwmtx_rwunlock(&erts_dist_table_rwmtx); @@ -789,6 +795,9 @@ void erts_init_node_tables(void) erts_this_node->sysname = am_Noname; erts_this_node->creation = 0; erts_this_node->dist_entry = erts_this_dist_entry; + erts_this_node_sysname = erts_this_node_sysname_BUFFER; + erts_snprintf(erts_this_node_sysname, sizeof(erts_this_node_sysname), + "%T", erts_this_node->sysname); (void) hash_put(&erts_node_table, (void *) erts_this_node); diff --git a/erts/emulator/beam/erl_node_tables.h b/erts/emulator/beam/erl_node_tables.h index 8abb748a78..5cfd0ac641 100644 --- a/erts/emulator/beam/erl_node_tables.h +++ b/erts/emulator/beam/erl_node_tables.h @@ -169,7 +169,7 @@ extern Sint erts_no_of_not_connected_dist_entries; extern DistEntry *erts_this_dist_entry; extern ErlNode *erts_this_node; -extern char erts_this_node_sysname[256]; /* must match erl_node_tables.c */ +extern char *erts_this_node_sysname; /* must match erl_node_tables.c */ DistEntry *erts_channel_no_to_dist_entry(Uint); DistEntry *erts_sysname_to_connected_dist_entry(Eterm); diff --git a/erts/emulator/beam/erl_port_task.c b/erts/emulator/beam/erl_port_task.c index a2b08fcf56..25bba5cf17 100644 --- a/erts/emulator/beam/erl_port_task.c +++ b/erts/emulator/beam/erl_port_task.c @@ -32,6 +32,7 @@ #include "global.h" #include "erl_port_task.h" #include "dist.h" +#include "dtrace-wrapper.h" #if defined(DEBUG) && 0 #define HARD_DEBUG @@ -61,6 +62,16 @@ do { \ (P)->sched.next = NULL; \ } while (0) +#define DTRACE_DRIVER(PROBE_NAME, PP) \ + if (DTRACE_ENABLED(driver_ready_input)) { \ + DTRACE_CHARBUF(process_str, DTRACE_TERM_BUF_SIZE); \ + DTRACE_CHARBUF(port_str, DTRACE_TERM_BUF_SIZE); \ + \ + dtrace_pid_str(PP->connected, process_str); \ + dtrace_port_str(PP, port_str); \ + DTRACE3(PROBE_NAME, process_str, port_str, PP->name); \ + } + erts_smp_atomic_t erts_port_task_outstanding_io_tasks; struct ErtsPortTaskQueue_ { @@ -823,12 +834,15 @@ erts_port_task_execute(ErtsRunQueue *runq, Port **curr_port_pp) goto tasks_done; case ERTS_PORT_TASK_TIMEOUT: reds += ERTS_PORT_REDS_TIMEOUT; - if (!(pp->status & ERTS_PORT_SFLGS_DEAD)) + if (!(pp->status & ERTS_PORT_SFLGS_DEAD)) { + DTRACE_DRIVER(driver_timeout, pp); (*pp->drv_ptr->timeout)((ErlDrvData) pp->drv_data); + } break; case ERTS_PORT_TASK_INPUT: reds += ERTS_PORT_REDS_INPUT; ASSERT((pp->status & ERTS_PORT_SFLGS_DEAD) == 0); + DTRACE_DRIVER(driver_ready_input, pp); /* NOTE some windows drivers use ->ready_input for input and output */ (*pp->drv_ptr->ready_input)((ErlDrvData) pp->drv_data, ptp->event); io_tasks_executed++; @@ -836,12 +850,14 @@ erts_port_task_execute(ErtsRunQueue *runq, Port **curr_port_pp) case ERTS_PORT_TASK_OUTPUT: reds += ERTS_PORT_REDS_OUTPUT; ASSERT((pp->status & ERTS_PORT_SFLGS_DEAD) == 0); + DTRACE_DRIVER(driver_ready_output, pp); (*pp->drv_ptr->ready_output)((ErlDrvData) pp->drv_data, ptp->event); io_tasks_executed++; break; case ERTS_PORT_TASK_EVENT: reds += ERTS_PORT_REDS_EVENT; ASSERT((pp->status & ERTS_PORT_SFLGS_DEAD) == 0); + DTRACE_DRIVER(driver_event, pp); (*pp->drv_ptr->event)((ErlDrvData) pp->drv_data, ptp->event, ptp->event_data); io_tasks_executed++; break; diff --git a/erts/emulator/beam/erl_process.c b/erts/emulator/beam/erl_process.c index 45f6dc800c..1173624f51 100644 --- a/erts/emulator/beam/erl_process.c +++ b/erts/emulator/beam/erl_process.c @@ -42,6 +42,7 @@ #include "erl_thr_progress.h" #include "erl_thr_queue.h" #include "erl_async.h" +#include "dtrace-wrapper.h" #define ERTS_RUNQ_CHECK_BALANCE_REDS_PER_SCHED (2000*CONTEXT_REDS) #define ERTS_RUNQ_CALL_CHECK_BALANCE_REDS \ @@ -6214,6 +6215,13 @@ Process *schedule(Process *p, int calls) int actual_reds; int reds; + if (p != NULL && DTRACE_ENABLED(process_unscheduled)) { + DTRACE_CHARBUF(process_buf, DTRACE_TERM_BUF_SIZE); + + dtrace_proc_str(p, process_buf); + DTRACE1(process_unscheduled, process_buf); + } + if (ERTS_USE_MODIFIED_TIMING()) { context_reds = ERTS_MODIFIED_TIMING_CONTEXT_REDS; input_reductions = ERTS_MODIFIED_TIMING_INPUT_REDS; @@ -7384,6 +7392,14 @@ erl_create_process(Process* parent, /* Parent of process (default group leader). VERBOSE(DEBUG_PROCESSES, ("Created a new process: %T\n",p->id)); + if (DTRACE_ENABLED(process_spawn)) { + DTRACE_CHARBUF(process_name, DTRACE_TERM_BUF_SIZE); + DTRACE_CHARBUF(mfa, DTRACE_TERM_BUF_SIZE); + + dtrace_fun_decode(p, mod, func, arity, process_name, mfa); + DTRACE2(process_spawn, process_name, mfa); + } + error: erts_smp_proc_unlock(parent, ERTS_PROC_LOCKS_ALL_MINOR); @@ -7952,6 +7968,17 @@ send_exit_signal(Process *c_p, /* current process if and only ASSERT(reason != THE_NON_VALUE); + if(DTRACE_ENABLED(process_exit_signal) && is_pid(from)) { + DTRACE_CHARBUF(sender_str, DTRACE_TERM_BUF_SIZE); + DTRACE_CHARBUF(receiver_str, DTRACE_TERM_BUF_SIZE); + DTRACE_CHARBUF(reason_buf, DTRACE_TERM_BUF_SIZE); + + dtrace_pid_str(from, sender_str); + dtrace_proc_str(rp, receiver_str); + erts_snprintf(reason_buf, sizeof(reason_buf) - 1, "%T", reason); + DTRACE3(process_exit_signal, sender_str, receiver_str, reason_buf); + } + if (ERTS_PROC_IS_TRAPPING_EXITS(rp) && (reason != am_kill || (flags & ERTS_XSIG_FLG_IGN_KILL))) { if (is_not_nil(token) && token_update) @@ -8378,7 +8405,16 @@ erts_do_exit_process(Process* p, Eterm reason) p->arity = 0; /* No live registers */ p->fvalue = reason; - + + if (DTRACE_ENABLED(process_exit)) { + DTRACE_CHARBUF(process_buf, DTRACE_TERM_BUF_SIZE); + DTRACE_CHARBUF(reason_buf, 256); + + dtrace_proc_str(p, process_buf); + erts_snprintf(reason_buf, sizeof(reason_buf) - 1, "%T", reason); + DTRACE2(process_exit, process_buf, reason_buf); + } + #ifdef ERTS_SMP ERTS_SMP_CHK_HAVE_ONLY_MAIN_PROC_LOCK(p); /* By locking all locks (main lock is already locked) when going diff --git a/erts/emulator/beam/erlang_dtrace.d b/erts/emulator/beam/erlang_dtrace.d new file mode 100644 index 0000000000..d8508426f4 --- /dev/null +++ b/erts/emulator/beam/erlang_dtrace.d @@ -0,0 +1,716 @@ +/* + * %CopyrightBegin% + * + * Copyright Dustin Sallings, Michal Ptaszek, Scott Lystig Fritchie 2011. + * All Rights Reserved. + * + * The contents of this file are subject to the Erlang Public License, + * Version 1.1, (the "License"); you may not use this file except in + * compliance with the License. You should have received a copy of the + * Erlang Public License along with this software. If not, it can be + * retrieved online at http://www.erlang.org/. + * + * Software distributed under the License is distributed on an "AS IS" + * basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See + * the License for the specific language governing rights and limitations + * under the License. + * + * %CopyrightEnd% + */ + +/* + * A note on probe naming: if "__" appears in a provider probe + * definition, then two things happen during compilation: + * + * 1. The "__" will turn into a hypen, "-", for the probe name. + * 2. The "__" will turn into a single underscore, "_", for the + * macro names and function definitions that the compiler and + * C developers will see. + * + * We'll try to use the following naming convention. We're a bit + * limited because, as a USDT probe, we can only specify the 4th part + * of the probe name, e.g. erlang*:::mumble. The 2nd part of the + * probe name is always going to be "beam" or "beam.smp", and the 3rd + * part of the probe name will always be the name of the function + * that's calling the probe. + * + * So, all probes will be have names defined in this file using the + * convention category__name or category__sub_category__name. This + * will translate to probe names of category-name or + * category-sub_category-name. + * + * Each of "category", "sub_category", and "name" may have underscores + * but may not have hyphens. + */ + +provider erlang { + /** + * Fired when a message is sent from one local process to another. + * + * NOTE: The 'size' parameter is in machine-dependent words and + * that the actual size of any binary terms in the message + * are not included. + * + * @param sender the PID (string form) of the sender + * @param receiver the PID (string form) of the receiver + * @param size the size of the message being delivered (words) + * @param token_label for the sender's sequential trace token + * @param token_previous count for the sender's sequential trace token + * @param token_current count for the sender's sequential trace token + */ + probe message__send(char *sender, char *receiver, uint32_t size, + int token_label, int token_previous, int token_current); + + /** + * Fired when a message is sent from a local process to a remote process. + * + * NOTE: The 'size' parameter is in machine-dependent words and + * that the actual size of any binary terms in the message + * are not included. + * + * @param sender the PID (string form) of the sender + * @param node_name the Erlang node name (string form) of the receiver + * @param receiver the PID/name (string form) of the receiver + * @param size the size of the message being delivered (words) + * @param token_label for the sender's sequential trace token + * @param token_previous count for the sender's sequential trace token + * @param token_current count for the sender's sequential trace token + */ + probe message__send__remote(char *sender, char *node_name, char *receiver, + uint32_t size, + int token_label, int token_previous, int token_current); + + /** + * Fired when a message is queued to a local process. This probe + * will not fire if the sender's pid == receiver's pid. + * + * NOTE: The 'size' parameter is in machine-dependent words and + * that the actual size of any binary terms in the message + * are not included. + * + * NOTE: In cases of messages in external format (i.e. from another + * Erlang node), we probably don't know the message size + * without performing substantial extra computation. To + * avoid the extra CPU overhead, the message size may be + * reported as -1, which can appear to a D script as 4294967295. + * + * @param receiver the PID (string form) of the receiver + * @param size the size of the message being delivered (words) + * @param queue_len length of the queue of the receiving process + * @param token_label for the sender's sequential trace token + * @param token_previous count for the sender's sequential trace token + * @param token_current count for the sender's sequential trace token + */ + probe message__queued(char *receiver, uint32_t size, uint32_t queue_len, + int token_label, int token_previous, int token_current); + + /** + * Fired when a message is 'receive'd by a local process and removed + * from its mailbox. + * + * NOTE: The 'size' parameter is in machine-dependent words and + * that the actual size of any binary terms in the message + * are not included. + * + * NOTE: In cases of messages in external format (i.e. from another + * Erlang node), we probably don't know the message size + * without performing substantial extra computation. To + * avoid the extra CPU overhead, the message size may be + * reported as -1, which can appear to a D script as 4294967295. + * + * @param receiver the PID (string form) of the receiver + * @param size the size of the message being delivered (words) + * @param queue_len length of the queue of the receiving process + * @param token_label for the sender's sequential trace token + * @param token_previous count for the sender's sequential trace token + * @param token_current count for the sender's sequential trace token + */ + probe message__receive(char *receiver, uint32_t size, uint32_t queue_len, + int token_label, int token_previous, int token_current); + + /** + * Fired when an Eterm structure is being copied. + * + * NOTE: Due to the placement of this probe, the process ID of + * owner of the Eterm is not available. + * + * @param size the size of the structure + */ + probe copy__struct(uint32_t size); + + /** + * Fired when an Eterm is being copied onto a process. + * + * @param proc the PID (string form) of the recipient process + * @param size the size of the structure + */ + probe copy__object(char *proc, uint32_t size); + + /* PID, Module, Function, Arity */ + + /** + * Fired whenever a user function is being called. + * + * @param p the PID (string form) of the process + * @param mfa the m:f/a of the function + * @param depth the stack depth + */ + probe function__entry(char *p, char *mfa, int depth); + + /** + * Fired whenever a user function returns. + * + * @param p the PID (string form) of the process + * @param mfa the m:f/a of the function + * @param depth the stack depth + */ + probe function__return(char *p, char *mfa, int depth); + + /** + * Fired whenever a Built In Function is called. + * + * @param p the PID (string form) of the process + * @param mfa the m:f/a of the function + */ + probe bif__entry(char *p, char *mfa); + + /** + * Fired whenever a Built In Function returns. + * + * @param p the PID (string form) of the process + * @param mfa the m:f/a of the function + */ + probe bif__return(char *p, char *mfa); + + /** + * Fired whenever a Native Function is called. + * + * @param p the PID (string form) of the process + * @param mfa the m:f/a of the function + */ + probe nif__entry(char *p, char *mfa); + + /** + * Fired whenever a Native Function returns. + * + * @param p the PID (string form) of the process + * @param mfa the m:f/a of the function + */ + probe nif__return(char *p, char *mfa); + + /** + * Fired when a major GC is starting. + * + * @param p the PID (string form) of the exiting process + * @param need the number of words needed on the heap + */ + probe gc_major__start(char *p, int need); + + /** + * Fired when a minor GC is starting. + * + * @param p the PID (string form) of the exiting process + * @param need the number of words needed on the heap + */ + probe gc_minor__start(char *p, int need); + + /** + * Fired when a major GC is starting. + * + * @param p the PID (string form) of the exiting process + * @param reclaimed the amount of space reclaimed + */ + probe gc_major__end(char *p, int reclaimed); + + /** + * Fired when a minor GC is starting. + * + * @param p the PID (string form) of the exiting process + * @param reclaimed the amount of space reclaimed + */ + probe gc_minor__end(char *p, int reclaimed); + + /** + * Fired when a process is spawned. + * + * @param p the PID (string form) of the new process. + * @param mfa the m:f/a of the function + */ + probe process__spawn(char *p, char *mfa); + + /** + * Fired when a process is exiting. + * + * @param p the PID (string form) of the exiting process + * @param reason the reason for the exit (may be truncated) + */ + probe process__exit(char *p, char *reason); + + /** + * Fired when exit signal is delivered to a local process. + * + * @param sender the PID (string form) of the exiting process + * @param receiver the PID (string form) of the process receiving EXIT signal + * @param reason the reason for the exit (may be truncated) + */ + probe process__exit_signal(char *sender, char *receiver, char *reason); + + /** + * Fired when exit signal is delivered to a remote process. + * + * @param sender the PID (string form) of the exiting process + * @param node_name the Erlang node name (string form) of the receiver + * @param receiver the PID (string form) of the process receiving EXIT signal + * @param reason the reason for the exit (may be truncated) + * @param token_label for the sender's sequential trace token + * @param token_previous count for the sender's sequential trace token + * @param token_current count for the sender's sequential trace token + */ + probe process__exit_signal__remote(char *sender, char *node_name, + char *receiver, char *reason, + int token_label, int token_previous, int token_current); + + /** + * Fired when a process is scheduled. + * + * @param p the PID (string form) of the newly scheduled process + * @param mfa the m:f/a of the function it should run next + */ + probe process__scheduled(char *p, char *mfa); + + /** + * Fired when a process is unscheduled. + * + * @param p the PID (string form) of the process that has been + * unscheduled. + */ + probe process__unscheduled(char *p); + + /** + * Fired when a process goes into hibernation. + * + * @param p the PID (string form) of the process entering hibernation + * @param mfa the m:f/a of the location to resume + */ + probe process__hibernate(char *p, char *mfa); + + /** + * Fired when a process is unblocked after a port has been unblocked. + * + * @param p the PID (string form) of the process that has been + * unscheduled. + * @param port the port that is no longer busy (i.e., is now unblocked) + */ + probe process__port_unblocked(char *p, char *port); + + /** + * Fired when process' heap is growing. + * + * @param p the PID (string form) + * @param old_size the size of the old heap + * @param new_size the size of the new heap + */ + probe process__heap_grow(char *p, int old_size, int new_size); + + /** + * Fired when process' heap is shrinking. + * + * @param p the PID (string form) + * @param old_size the size of the old heap + * @param new_size the size of the new heap + */ + probe process__heap_shrink(char *p, int old_size, int new_size); + + /* network distribution */ + + /** + * Fired when network distribution event monitor events are triggered. + * + * @param node the name of the reporting node + * @param what the type of event, e.g., nodeup, nodedown + * @param monitored_node the name of the monitored node + * @param type the type of node, e.g., visible, hidden + * @param reason the reason term, e.g., normal, connection_closed, term() + */ + probe dist__monitor(char *node, char *what, char *monitored_node, + char *type, char *reason); + + /** + * Fired when network distribution port is busy (i.e. blocked), + * usually due to the remote node not consuming distribution + * data quickly enough. + * + * @param node the name of the reporting node + * @param port the port ID of the busy port + * @param remote_node the name of the remote node. + * @param pid the PID (string form) of the local process that has + * become unschedulable until the port becomes unblocked. + */ + probe dist__port_busy(char *node, char *port, char *remote_node, + char *pid); + + /** + * Fired when network distribution's driver's "output" callback is called + * + * @param node the name of the reporting node + * @param port the port ID of the busy port + * @param remote_node the name of the remote node. + * @param bytes the number of bytes written + */ + probe dist__output(char *node, char *port, char *remote_node, int bytes); + + /** + * Fired when network distribution's driver's "outputv" callback is called + * + * @param node the name of the reporting node + * @param port the port ID of the busy port + * @param remote_node the name of the remote node. + * @param bytes the number of bytes written + */ + probe dist__outputv(char *node, char *port, char *remote_node, int bytes); + + /** + * Fired when network distribution port is no longer busy (i.e. blocked). + * + * NOTE: This probe may fire multiple times after the same single + * dist-port_busy probe firing. + * + * @param node the name of the reporting node + * @param port the port ID of the busy port + * @param remote_node the name of the remote node. + */ + probe dist__port_not_busy(char *node, char *port, char *remote_node); + + /* ports */ + + /** + * Fired when new port is opened. + * + * @param process the PID (string form) + * @param port_name the string used when the port was opened + * @param port the Port (string form) of the new port + */ + probe port__open(char *process, char *port_name, char *port); + + /** + * Fired when port_command is issued. + * + * @param process the PID (string form) + * @param port the Port (string form) + * @param port_name the string used when the port was opened + * @param command_type type of the issued command, one of: "close", "command" or "connect" + */ + probe port__command(char *process, char *port, char *port_name, char *command_type); + + /** + * Fired when port_control is issued. + * + * @param process the PID (string form) + * @param port the Port (string form) + * @param port_name the string used when the port was opened + * @param command_no command number that has been issued to the port + */ + probe port__control(char *process, char *port, char *port_name, int command_no); + + /** + * Fired when port is closed via port_close/1 (reason = 'normal') + * or is sent an exit signal. + * + * @param process the PID (string form) + * @param port the Port (string form) + * @param port_name the string used when the port was opened + * @param reason Erlang term representing the exit signal, e.g. 'normal' + */ + probe port__exit(char *process, char *port, char *port_name, + char *new_process); + + /** + * Fired when port_connect is issued. + * + * @param process the PID (string form) of the current port owner + * @param port the Port (string form) + * @param port_name the string used when the port was opened + * @param new_process the PID (string form) of the new port owner + */ + probe port__connect(char *process, char *port, char *port_name, + char *new_process); + + /** + * Fired when a port is busy (i.e. blocked) + * + * @param port the port ID of the busy port + */ + probe port__busy(char *port); + + /** + * Fired when a port is no longer busy (i.e. no longer blocked) + * + * @param port the port ID of the not busy port + */ + probe port__not_busy(char *port); + + /* drivers */ + + /** + * Fired when drivers's "init" callback is called. + * + * @param name the name of the driver + * @param major the major version number + * @param minor the minor version number + * @param flags the flags argument + */ + probe driver__init(char *name, int major, int minor, int flags); + + /** + * Fired when drivers's "start" callback is called. + * + * @param process the PID (string form) of the calling process + * @param name the name of the driver + * @param port the Port (string form) of the driver's port + */ + probe driver__start(char *process, char *name, char *port); + + /** + * Fired when drivers's "stop" callback is called. + * + * @param process the PID (string form) of the calling process + * @param name the name of the driver + * @param port the Port (string form) of the driver's port + */ + probe driver__stop(char *process, char *name, char *port); + + /** + * Fired when drivers's "finish" callback is called. + * + * @param name the name of the driver + */ + probe driver__finish(char *name); + + /** + * Fired when drivers's "flush" callback is called. + * + * @param process the PID (string form) + * @param port the Port (string form) + * @param port_name the string used when the port was opened + */ + probe driver__flush(char *process, char *port, char *port_name); + + /** + * Fired when driver's "output" callback is called + * + * @param process the PID (string form) + * @param port the Port (string form) + * @param port_name the string used when the port was opened + * @param bytes the number of bytes written + */ + probe driver__output(char *node, char *port, char *port_name, int bytes); + + /** + * Fired when driver's "outputv" callback is called + * + * @param process the PID (string form) + * @param port the Port (string form) + * @param port_name the string used when the port was opened + * @param bytes the number of bytes written + */ + probe driver__outputv(char *node, char *port, char *port_name, int bytes); + + /** + * Fired when driver's "control" callback is called + * + * @param process the PID (string form) + * @param port the Port (string form) + * @param port_name the string used when the port was opened + * @param command the command # + * @param bytes the number of bytes written + */ + probe driver__control(char *node, char *port, char *port_name, + int command, int bytes); + + /** + * Fired when driver's "call" callback is called + * + * @param process the PID (string form) + * @param port the Port (string form) + * @param port_name the string used when the port was opened + * @param command the command # + * @param bytes the number of bytes written + */ + probe driver__call(char *node, char *port, char *port_name, + int command, int bytes); + + /** + * Fired when driver's "event" callback is called + * + * @param process the PID (string form) + * @param port the Port (string form) + * @param port_name the string used when the port was opened + */ + probe driver__event(char *node, char *port, char *port_name); + + /** + * Fired when driver's "ready_input" callback is called + * + * @param process the PID (string form) + * @param port the Port (string form) + * @param port_name the string used when the port was opened + */ + probe driver__ready_input(char *node, char *port, char *port_name); + + /** + * Fired when driver's "read_output" callback is called + * + * @param process the PID (string form) + * @param port the Port (string form) + * @param port_name the string used when the port was opened + */ + probe driver__ready_output(char *node, char *port, char *port_name); + + /** + * Fired when driver's "timeout" callback is called + * + * @param process the PID (string form) + * @param port the Port (string form) + * @param port_name the string used when the port was opened + */ + probe driver__timeout(char *node, char *port, char *port_name); + + /** + * Fired when drivers's "ready_async" callback is called. + * + * @param process the PID (string form) + * @param port the Port (string form) + * @param port_name the string used when the port was opened + */ + probe driver__ready_async(char *process, char *port, char *port_name); + + /** + * Fired when driver's "process_exit" callback is called + * + * @param process the PID (string form) + * @param port the Port (string form) + * @param port_name the string used when the port was opened + */ + probe driver__process_exit(char *node, char *port, char *port_name); + + /** + * Fired when driver's "stop_select" callback is called + * + * @param name the name of the driver + */ + probe driver__stop_select(char *name); + + + /* Async driver pool */ + + /** + * Show the post-add length of the async driver thread pool member's queue. + * + * NOTE: The port name is not available: additional lock(s) must + * be acquired in order to get the port name safely in an SMP + * environment. The same is true for the aio__pool_get probe. + * + * @param port the Port (string form) + * @param new queue length + */ + probe aio_pool__add(char *, int); + + /** + * Show the post-get length of the async driver thread pool member's queue. + * + * @param port the Port (string form) + * @param new queue length + */ + probe aio_pool__get(char *, int); + + /* Probes for efile_drv.c */ + + /** + * Entry into the efile_drv.c file I/O driver + * + * For a list of command numbers used by this driver, see the section + * "Guide to probe arguments" in ../../../README.md. That section + * also contains explanation of the various integer and string + * arguments that may be present when any particular probe fires. + * + * NOTE: Not all Linux platforms (using SystemTap) can support + * arguments beyond arg9. + * + * + * TODO: Adding the port string, args[10], is a pain. Making that + * port string available to all the other efile_drv.c probes + * will be more pain. Is the pain worth it? If yes, then + * add them everywhere else and grit our teeth. If no, then + * rip it out. + * + * @param thread-id number of the scheduler Pthread arg0 + * @param tag number: {thread-id, tag} uniquely names a driver operation + * @param user-tag string arg2 + * @param command number arg3 + * @param string argument 1 arg4 + * @param string argument 2 arg5 + * @param integer argument 1 arg6 + * @param integer argument 2 arg7 + * @param integer argument 3 arg8 + * @param integer argument 4 arg9 + * @param port the port ID of the busy port args[10] + */ + probe efile_drv__entry(int, int, char *, int, char *, char *, + int64_t, int64_t, int64_t, int64_t, char *); + + /** + * Entry into the driver's internal work function. Computation here + * is performed by a async worker pool Pthread. + * + * @param thread-id number + * @param tag number + * @param command number + */ + probe efile_drv__int_entry(int, int, int); + + /** + * Return from the driver's internal work function. + * + * @param thread-id number + * @param tag number + * @param command number + */ + probe efile_drv__int_return(int, int, int); + + /** + * Return from the efile_drv.c file I/O driver + * + * @param thread-id number arg0 + * @param tag number arg1 + * @param user-tag string arg2 + * @param command number arg3 + * @param Success? 1 is success, 0 is failure arg4 + * @param If failure, the errno of the error. arg5 + */ + probe efile_drv__return(int, int, char *, int, int, int); + +/* + * NOTE: + * For formatting int64_t arguments within a D script, see: + * + * http://mail.opensolaris.org/pipermail/dtrace-discuss/2006-November/002830.html + * Summary: + * "1) you don't need the 'l' printf() modifiers with DTrace ever" + */ + +/* + * NOTE: For file_drv_return + SMP + R14B03 (and perhaps other + * releases), the sched-thread-id will be the same as the + * work-thread-id: erl_async.c's async_main() function + * will call the asynchronous invoke function and then + * immediately call the drivers ready_async function while + * inside the same I/O worker pool thread. + * For R14B03's source, see erl_async.c lines 302-317. + */ +}; + +#pragma D attributes Evolving/Evolving/Common provider erlang provider +#pragma D attributes Private/Private/Common provider erlang module +#pragma D attributes Private/Private/Common provider erlang function +#pragma D attributes Evolving/Evolving/Common provider erlang name +#pragma D attributes Evolving/Evolving/Common provider erlang args diff --git a/erts/emulator/beam/io.c b/erts/emulator/beam/io.c index fb1514a147..81f79b8f85 100644 --- a/erts/emulator/beam/io.c +++ b/erts/emulator/beam/io.c @@ -43,6 +43,7 @@ #include "erl_version.h" #include "error.h" #include "erl_async.h" +#include "dtrace-wrapper.h" extern ErlDrvEntry fd_driver_entry; extern ErlDrvEntry vanilla_driver_entry; @@ -180,6 +181,19 @@ typedef struct line_buf_context { #define LINEBUF_INITIAL 100 +#define DTRACE_FORMAT_COMMON_PID_AND_PORT(PID, PORT) \ + DTRACE_CHARBUF(process_str, DTRACE_TERM_BUF_SIZE); \ + DTRACE_CHARBUF(port_str, DTRACE_TERM_BUF_SIZE); \ + \ + dtrace_pid_str((PID), process_str); \ + dtrace_port_str((PORT), port_str); +#define DTRACE_FORMAT_COMMON_PROC_AND_PORT(PID, PORT) \ + DTRACE_CHARBUF(process_str, DTRACE_TERM_BUF_SIZE); \ + DTRACE_CHARBUF(port_str, DTRACE_TERM_BUF_SIZE); \ + \ + dtrace_proc_str((PID), process_str); \ + dtrace_port_str((PORT), port_str); + /* The 'number' field in a port now has two parts: the lowest bits contain the index in the port table, and the higher bits are a counter @@ -639,6 +653,10 @@ erts_open_driver(erts_driver_t* driver, /* Pointer to driver. */ trace_sched_ports_where(port, am_in, am_start); } port->caller = pid; + if (DTRACE_ENABLED(driver_start)) { + DTRACE_FORMAT_COMMON_PID_AND_PORT(pid, port) + DTRACE3(driver_start, process_str, driver->name, port_str); + } fpe_was_unmasked = erts_block_fpe(); drv_data = (*driver->start)((ErlDrvPort)(port_ix), name, opts); @@ -1170,6 +1188,10 @@ int erts_write_to_port(Eterm caller_id, Port *p, Eterm list) ev.size = size; /* total size */ ev.iov = ivp; ev.binv = bvp; + if (DTRACE_ENABLED(driver_outputv)) { + DTRACE_FORMAT_COMMON_PID_AND_PORT(caller_id, p) + DTRACE4(driver_outputv, process_str, port_str, p->name, size); + } fpe_was_unmasked = erts_block_fpe(); (*drv->outputv)((ErlDrvData)p->drv_data, &ev); erts_unblock_fpe(fpe_was_unmasked); @@ -1189,8 +1211,17 @@ int erts_write_to_port(Eterm caller_id, Port *p, Eterm list) buf = erts_alloc(ERTS_ALC_T_TMP, size+1); r = io_list_to_buf(list, buf, size); + if(DTRACE_ENABLED(port_command)) { + DTRACE_FORMAT_COMMON_PID_AND_PORT(caller_id, p) + DTRACE4(port_command, process_str, port_str, p->name, "command"); + } + if (r >= 0) { size -= r; + if (DTRACE_ENABLED(driver_output)) { + DTRACE_FORMAT_COMMON_PID_AND_PORT(caller_id, p) + DTRACE4(driver_output, process_str, port_str, p->name, size); + } fpe_was_unmasked = erts_block_fpe(); (*drv->output)((ErlDrvData)p->drv_data, buf, size); erts_unblock_fpe(fpe_was_unmasked); @@ -1214,6 +1245,10 @@ int erts_write_to_port(Eterm caller_id, Port *p, Eterm list) */ buf = erts_alloc(ERTS_ALC_T_TMP, size+1); r = io_list_to_buf(list, buf, size); + if (DTRACE_ENABLED(driver_output)) { + DTRACE_FORMAT_COMMON_PID_AND_PORT(caller_id, p) + DTRACE4(driver_output, process_str, port_str, p->name, size); + } fpe_was_unmasked = erts_block_fpe(); (*drv->output)((ErlDrvData)p->drv_data, buf, size); erts_unblock_fpe(fpe_was_unmasked); @@ -1810,6 +1845,10 @@ static void flush_port(Port *p) ERTS_SMP_LC_ASSERT(erts_lc_is_port_locked(p)); if (p->drv_ptr->flush != NULL) { + if (DTRACE_ENABLED(driver_flush)) { + DTRACE_FORMAT_COMMON_PID_AND_PORT(p->connected, p) + DTRACE3(driver_flush, process_str, port_str, p->name); + } if (IS_TRACED_FL(p, F_TRACE_SCHED_PORTS)) { trace_sched_ports_where(p, am_in, am_flush); } @@ -1865,6 +1904,10 @@ terminate_port(Port *prt) drv = prt->drv_ptr; if ((drv != NULL) && (drv->stop != NULL)) { int fpe_was_unmasked = erts_block_fpe(); + if (DTRACE_ENABLED(driver_stop)) { + DTRACE_FORMAT_COMMON_PID_AND_PORT(prt->connected, prt) + DTRACE3(driver_stop, process_str, drv->name, port_str); + } (*drv->stop)((ErlDrvData)prt->drv_data); erts_unblock_fpe(fpe_was_unmasked); #ifdef ERTS_SMP @@ -2026,6 +2069,17 @@ erts_do_exit_port(Port *p, Eterm from, Eterm reason) rreason = (reason == am_kill) ? am_killed : reason; + if (DTRACE_ENABLED(port_exit)) { + DTRACE_CHARBUF(from_str, DTRACE_TERM_BUF_SIZE); + DTRACE_CHARBUF(port_str, DTRACE_TERM_BUF_SIZE); + DTRACE_CHARBUF(rreason_str, 64); + + erts_snprintf(from_str, sizeof(from_str), "%T", from); + dtrace_port_str(p, port_str); + erts_snprintf(rreason_str, sizeof(rreason_str), "%T", rreason); + DTRACE4(port_exit, from_str, port_str, p->name, rreason_str); + } + if ((p->status & (ERTS_PORT_SFLGS_DEAD | ERTS_PORT_SFLG_EXITING | ERTS_PORT_SFLG_IMMORTAL)) @@ -2126,6 +2180,11 @@ void erts_port_command(Process *proc, if (tp[2] == am_close) { erts_port_status_bor_set(port, ERTS_PORT_SFLG_SEND_CLOSED); erts_do_exit_port(port, pid, am_normal); + + if(DTRACE_ENABLED(port_command)) { + DTRACE_FORMAT_COMMON_PROC_AND_PORT(proc, port) + DTRACE4(port_command, process_str, port_str, port->name, "close"); + } goto done; } else if (is_tuple_arity(tp[2], 2)) { tp = tuple_val(tp[2]); @@ -2133,6 +2192,10 @@ void erts_port_command(Process *proc, if (erts_write_to_port(caller_id, port, tp[2]) == 0) goto done; } else if ((tp[1] == am_connect) && is_internal_pid(tp[2])) { + if(DTRACE_ENABLED(port_command)) { + DTRACE_FORMAT_COMMON_PROC_AND_PORT(proc, port) + DTRACE4(port_command, process_str, port_str, port->name, "connect"); + } port->connected = tp[2]; deliver_result(port->id, pid, am_connected); goto done; @@ -2235,6 +2298,13 @@ erts_port_control(Process* p, Port* prt, Uint command, Eterm iolist) erts_smp_proc_unlock(p, ERTS_PROC_LOCK_MAIN); ERTS_SMP_CHK_NO_PROC_LOCKS; + if (DTRACE_ENABLED(port_control) || DTRACE_ENABLED(driver_control)) { + DTRACE_FORMAT_COMMON_PROC_AND_PORT(p, prt); + DTRACE4(port_control, process_str, port_str, prt->name, command); + DTRACE5(driver_control, process_str, port_str, prt->name, + command, to_len); + } + /* * Call the port's control routine. */ @@ -2375,6 +2445,8 @@ print_port_info(int to, void *arg, int i) void set_busy_port(ErlDrvPort port_num, int on) { + DTRACE_CHARBUF(port_str, 16); + ERTS_SMP_CHK_NO_PROC_LOCKS; ERTS_SMP_LC_ASSERT(erts_lc_is_port_locked(&erts_port[port_num])); @@ -2382,12 +2454,22 @@ set_busy_port(ErlDrvPort port_num, int on) if (on) { erts_port_status_bor_set(&erts_port[port_num], ERTS_PORT_SFLG_PORT_BUSY); + if (DTRACE_ENABLED(port_busy)) { + erts_snprintf(port_str, sizeof(port_str), + "%T", erts_port[port_num].id); + DTRACE1(port_busy, port_str); + } } else { ErtsProcList* plp = erts_port[port_num].suspended; erts_port_status_band_set(&erts_port[port_num], ~ERTS_PORT_SFLG_PORT_BUSY); erts_port[port_num].suspended = NULL; + if (DTRACE_ENABLED(port_not_busy)) { + erts_snprintf(port_str, sizeof(port_str), + "%T", erts_port[port_num].id); + DTRACE1(port_not_busy, port_str); + } if (erts_port[port_num].dist_entry) { /* * Processes suspended on distribution ports are @@ -2405,6 +2487,26 @@ set_busy_port(ErlDrvPort port_num, int on) */ if (plp) { + /* + * Hrm, for blocked dist ports, plp always seems to be NULL. + * That's not so fun. + * Well, another way to get the same info is using a D + * script to correlate an earlier process-port_blocked+pid + * event with a later process-scheduled event. That's + * subject to the multi-CPU races with how events are + * handled, but hey, that way works most of the time. + */ + if (DTRACE_ENABLED(process_port_unblocked)) { + DTRACE_CHARBUF(pid_str, 16); + ErtsProcList* plp2 = plp; + + erts_snprintf(port_str, sizeof(port_str), + "%T", erts_port[port_num]); + while (plp2 != NULL) { + erts_snprintf(pid_str, sizeof(pid_str), "%T", plp2->pid); + DTRACE2(process_port_unblocked, pid_str, port_str); + } + } /* First proc should be resumed last */ if (plp->next) { erts_resume_processes(plp->next); @@ -2451,6 +2553,12 @@ void erts_raw_port_command(Port* p, byte* buf, Uint len) p->drv_ptr->name ? p->drv_ptr->name : "unknown"); p->caller = NIL; + if (DTRACE_ENABLED(driver_output)) { + DTRACE_CHARBUF(port_str, DTRACE_TERM_BUF_SIZE); + + dtrace_port_str(p, port_str); + DTRACE4(driver_output, "-raw-", port_str, p->name, len); + } fpe_was_unmasked = erts_block_fpe(); (*p->drv_ptr->output)((ErlDrvData)p->drv_data, (char*) buf, (int) len); erts_unblock_fpe(fpe_was_unmasked); @@ -2466,6 +2574,10 @@ int async_ready(Port *p, void* data) ERTS_SMP_LC_ASSERT(erts_lc_is_port_locked(p)); ASSERT(!(p->status & ERTS_PORT_SFLGS_DEAD)); if (p->drv_ptr->ready_async != NULL) { + if (DTRACE_ENABLED(driver_ready_async)) { + DTRACE_FORMAT_COMMON_PID_AND_PORT(p->connected, p) + DTRACE3(driver_ready_async, process_str, port_str, p->name); + } (*p->drv_ptr->ready_async)((ErlDrvData)p->drv_data, data); need_free = 0; #ifdef ERTS_SMP @@ -4441,6 +4553,10 @@ void erts_fire_port_monitor(Port *prt, Eterm ref) ASSERT(callback != NULL); ref_to_driver_monitor(ref,&drv_monitor); DRV_MONITOR_UNLOCK_PDL(prt); + if (DTRACE_ENABLED(driver_process_exit)) { + DTRACE_FORMAT_COMMON_PID_AND_PORT(prt->connected, prt) + DTRACE3(driver_process_exit, process_str, port_str, prt->name); + } fpe_was_unmasked = erts_block_fpe(); (*callback)((ErlDrvData) (prt->drv_data), &drv_monitor); erts_unblock_fpe(fpe_was_unmasked); @@ -4884,6 +5000,8 @@ init_driver(erts_driver_t *drv, ErlDrvEntry *de, DE_Handle *handle) else { int res; int fpe_was_unmasked = erts_block_fpe(); + DTRACE4(driver_init, drv->name, drv->version.major, drv->version.minor, + drv->flags); res = (*de->init)(); erts_unblock_fpe(fpe_was_unmasked); return res; diff --git a/erts/emulator/sys/common/erl_check_io.c b/erts/emulator/sys/common/erl_check_io.c index 23a4bf1b04..cb7ef95f00 100644 --- a/erts/emulator/sys/common/erl_check_io.c +++ b/erts/emulator/sys/common/erl_check_io.c @@ -36,6 +36,7 @@ #include "global.h" #include "erl_check_io.h" #include "erl_thr_progress.h" +#include "dtrace-wrapper.h" #ifdef ERTS_SYS_CONTINOUS_FD_NUMBERS # define ERTS_DRV_EV_STATE_EXTRA_SIZE 128 @@ -314,6 +315,7 @@ forget_removed(struct pollset_info* psi) erts_smp_mtx_unlock(mtx); if (drv_ptr) { int was_unmasked = erts_block_fpe(); + DTRACE1(driver_stop_select, drv_ptr->name); (*drv_ptr->stop_select) ((ErlDrvEvent) fd, NULL); erts_unblock_fpe(was_unmasked); if (drv_ptr->handle) { @@ -496,6 +498,7 @@ ERTS_CIO_EXPORT(driver_select)(ErlDrvPort ix, ErtsDrvEventState *state; int wake_poller; int ret; + DTRACE_CHARBUF(name, 64); ERTS_SMP_LC_ASSERT(erts_drvport2port(ix) && erts_lc_is_port_locked(erts_drvport2port(ix))); @@ -525,6 +528,8 @@ ERTS_CIO_EXPORT(driver_select)(ErlDrvPort ix, if (IS_FD_UNKNOWN(state)) { /* fast track to stop_select callback */ stop_select_fn = erts_drvport2port(ix)->drv_ptr->stop_select; + strncpy(name, erts_drvport2port(ix)->drv_ptr->name, sizeof(name)-1); + name[sizeof(name)-1] = '\0'; ret = 0; goto done_unknown; } @@ -661,6 +666,8 @@ ERTS_CIO_EXPORT(driver_select)(ErlDrvPort ix, /* Safe to close fd now as it is not in pollset or there was no need to eject fd (kernel poll) */ stop_select_fn = drv_ptr->stop_select; + strncpy(name, erts_drvport2port(ix)->drv_ptr->name, sizeof(name)-1); + name[sizeof(name)-1] = '\0'; } else { /* Not safe to close fd, postpone stop_select callback. */ @@ -686,6 +693,7 @@ done_unknown: erts_smp_mtx_unlock(fd_mtx(fd)); if (stop_select_fn) { int was_unmasked = erts_block_fpe(); + DTRACE1(driver_stop_select, name); (*stop_select_fn)(e, NULL); erts_unblock_fpe(was_unmasked); } -- cgit v1.2.3