From b937b42d2f98c4e0024418dbbd55ff545bcf65d6 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bj=C3=B6rn-Egil=20Dahlberg?= Date: Sat, 10 Apr 2010 17:27:24 +0200 Subject: Call time breakpoint tracing framework Initial commit with a new breakpoint instruction and PSD areas for temporary time storage during tracing. --- erts/emulator/beam/atom.names | 1 + erts/emulator/beam/beam_bp.c | 94 +++++++++++++++++++++++++++++++++++++- erts/emulator/beam/beam_bp.h | 41 +++++++++++++++++ erts/emulator/beam/beam_emu.c | 16 +++++++ erts/emulator/beam/erl_bif_trace.c | 70 +++++++++++++++++++++++----- erts/emulator/beam/erl_process.h | 9 +++- erts/emulator/beam/global.h | 1 + erts/emulator/beam/ops.tab | 1 + 8 files changed, 220 insertions(+), 13 deletions(-) (limited to 'erts/emulator/beam') diff --git a/erts/emulator/beam/atom.names b/erts/emulator/beam/atom.names index 1138c0c871..28f69b9460 100644 --- a/erts/emulator/beam/atom.names +++ b/erts/emulator/beam/atom.names @@ -123,6 +123,7 @@ atom busy_dist_port atom busy_port atom call atom call_count +atom call_time atom caller atom capture atom case_clause diff --git a/erts/emulator/beam/beam_bp.c b/erts/emulator/beam/beam_bp.c index 6278ff6bad..a78645a9c7 100644 --- a/erts/emulator/beam/beam_bp.c +++ b/erts/emulator/beam/beam_bp.c @@ -191,7 +191,12 @@ erts_set_count_break(Eterm mfa[3], int specified, enum erts_break_op count_op) { (BeamInstr) BeamOp(op_i_count_breakpoint), count_op, NIL); } - +int +erts_set_time_break(Eterm mfa[3], int specified, enum erts_break_op count_op) { + ERTS_SMP_LC_ASSERT(erts_smp_is_system_blocked(0)); + return set_break(mfa, specified, NULL, + (BeamInstr) BeamOp(op_i_time_breakpoint), count_op, NIL); +} int erts_clear_trace_break(Eterm mfa[3], int specified) { @@ -236,6 +241,13 @@ erts_clear_count_break(Eterm mfa[3], int specified) { (BeamInstr) BeamOp(op_i_count_breakpoint)); } +int +erts_clear_time_break(Eterm mfa[3], int specified) { + ERTS_SMP_LC_ASSERT(erts_smp_is_system_blocked(0)); + return clear_break(mfa, specified, + (BeamInstr) BeamOp(op_i_time_breakpoint)); +} + int erts_clear_break(Eterm mfa[3], int specified) { ERTS_SMP_LC_ASSERT(erts_smp_is_system_blocked(0)); @@ -408,6 +420,31 @@ erts_is_count_break(BeamInstr *pc, Sint *count_ret) { return 0; } +int +erts_is_time_break(Uint *pc, Sint *count, Uint *s_time, Uint *us_time) { + BpDataTime *bdt = + (BpDataTime *) is_break(pc, (BeamInstr) BeamOp(op_i_time_breakpoint)); + Uint i; + + if (bdt) { + if (count && s_time && us_time) { + *count = 0; + *s_time = 0; + *us_time = 0; + ErtsSmpBPLock(bdt); + for (i = 0; i < bdt->n; i++) { + *count += bdt->items[i].count; + *s_time += bdt->items[i].s_time; + *us_time += bdt->items[i].us_time; + } + ErtsSmpBPUnlock(bdt); + } + return !0; + } + return 0; +} + + BeamInstr * erts_find_local_func(Eterm mfa[3]) { Module *modp; @@ -432,6 +469,22 @@ erts_find_local_func(Eterm mfa[3]) { return NULL; } +void erts_do_time_break(Process *p, BpDataTime *bdt) { + Uint ms,s,u; + ErtsSchedulerData *esdp; + int ix = 0; + + esdp = erts_get_scheduler_data(); + ix = esdp->no - 1; + + get_sys_now(&ms,&s,&u); + //ErtsSmpBPLock(bdt); + // + bdt->items[ix].count++; + bdt->items[ix].s_time = 1; + bdt->items[ix].us_time = 1; + //ErtsSmpBPUnlock(bdt); +} /* ************************************************************************* @@ -519,6 +572,7 @@ static int set_function_break(Module *modp, BeamInstr *pc, if ( (bd = is_break(pc, break_op))) { if (break_op == (BeamInstr) BeamOp(op_i_trace_breakpoint) || break_op == (BeamInstr) BeamOp(op_i_mtrace_breakpoint)) { + BpDataTrace *bdt = (BpDataTrace *) bd; Binary *old_match_spec; @@ -545,6 +599,18 @@ static int set_function_break(Module *modp, BeamInstr *pc, bdc->count = 0; /* Reset call counter */ } ErtsSmpBPUnlock(bdc); + } else if (break_op == (Uint) BeamOp(op_i_count_breakpoint)) { + BpDataTime *bdt = (BpDataTime *) bd; + Uint i = 0; + + ErtsSmpBPLock(bdt); + for (i = 0; i < bdt->n; i++) { + bdt->items[i].count = 0; + bdt->items[i].s_time = 0; + bdt->items[i].us_time = 0; + } + ErtsSmpBPUnlock(bdt); + } else { ASSERT (! count_op); } @@ -564,6 +630,12 @@ static int set_function_break(Module *modp, BeamInstr *pc, return 1; } size = sizeof(BpDataCount); + } else if (break_op == (BeamInstr) BeamOp(op_i_time_breakpoint)) { + if (count_op == erts_break_reset || count_op == erts_break_stop) { + /* Do not insert a new breakpoint */ + return 1; + } + size = sizeof(BpDataTime); } else { ASSERT(! count_op); ASSERT(break_op == (BeamInstr) BeamOp(op_i_debug_breakpoint)); @@ -576,6 +648,7 @@ static int set_function_break(Module *modp, BeamInstr *pc, ASSERT(*pc != (BeamInstr) BeamOp(op_i_mtrace_breakpoint)); ASSERT(*pc != (BeamInstr) BeamOp(op_i_debug_breakpoint)); ASSERT(*pc != (BeamInstr) BeamOp(op_i_count_breakpoint)); + ASSERT(*pc != (BeamInstr) BeamOp(op_i_time_breakpoint)); /* First breakpoint; create singleton ring */ bd = Alloc(size); BpInit(bd, *pc); @@ -585,6 +658,7 @@ static int set_function_break(Module *modp, BeamInstr *pc, ASSERT(*pc == (BeamInstr) BeamOp(op_i_trace_breakpoint) || *pc == (BeamInstr) BeamOp(op_i_mtrace_breakpoint) || *pc == (BeamInstr) BeamOp(op_i_debug_breakpoint) || + *pc == (BeamInstr) BeamOp(op_i_time_breakpoint) || *pc == (BeamInstr) BeamOp(op_i_count_breakpoint)); if (*pc == (BeamInstr) BeamOp(op_i_debug_breakpoint)) { /* Debug bp must be last, so if it is also first; @@ -617,6 +691,18 @@ static int set_function_break(Module *modp, BeamInstr *pc, MatchSetRef(match_spec); bdt->match_spec = match_spec; bdt->tracer_pid = tracer_pid; + } else if (break_op == (BeamInstr) BeamOp(op_i_time_breakpoint)) { + BpDataTime *bdt = (BpDataTime *) bd; + Uint i = 0; + + bdt->n = erts_no_schedulers; + bdt->items = Alloc(sizeof(bp_data_time_item_t)*(bdt->n)); + + for (i = 0; i < bdt->n; i++) { + bdt->items[i].count = 0; + bdt->items[i].s_time = 0; + bdt->items[i].us_time = 0; + } } else if (break_op == (BeamInstr) BeamOp(op_i_count_breakpoint)) { BpDataCount *bdc = (BpDataCount *) bd; @@ -739,6 +825,12 @@ static int clear_function_break(Module *m, BeamInstr *pc, BeamInstr break_op) { MatchSetUnref(bdt->match_spec); } + if (op == (BeamInstr) BeamOp(op_i_time_breakpoint)) { + BpDataTime *bdt = (BpDataTrace *) bd; + + Free(bdt->items); + bdt->n = 0; + } Free(bd); ASSERT(((BeamInstr) code_base[MI_NUM_BREAKPOINTS]) > 0); --(*(BeamInstr*)&code_base[MI_NUM_BREAKPOINTS]); diff --git a/erts/emulator/beam/beam_bp.h b/erts/emulator/beam/beam_bp.h index 786cbbe9d9..3fac85348f 100644 --- a/erts/emulator/beam/beam_bp.h +++ b/erts/emulator/beam/beam_bp.h @@ -75,6 +75,21 @@ typedef struct bp_data_count { /* Call count */ Sint count; } BpDataCount; +typedef struct { + Sint count; + Uint s_time; + Uint us_time; +} bp_data_time_item_t; + +typedef struct bp_data_time { /* Call time */ + struct bp_data *next; + struct bp_data *prev; + Uint orig_instr; + Uint n; + bp_data_time_item_t *items; +} BpDataTime; + + extern erts_smp_spinlock_t erts_bp_lock; #ifdef ERTS_SMP @@ -100,6 +115,27 @@ do { \ *(instr_result) = bdc->orig_instr; \ } while (0) +#define ErtsTimeBreak(pc,instr_result) \ +do { \ + BpDataTime *bdt = (BpDataTime *) (pc)[-4]; \ + Uint ms,s,u; \ + \ + ASSERT((pc)[-5] == (Uint) BeamOp(op_i_func_info_IaaI)); \ + ASSERT(bdt); \ + bdt = (BpDataTime *) bdt->next; \ + ASSERT(bdc); \ + (pc)[-4] = (Uint) bdt; \ + get_now(&ms,&s,&u); \ + ErtsSmpBPLock(bdt); \ + if (bdt->count >= 0) \ + bdt->count++; \ + bdt->s_time = 1; \ + bdt->us_time = 1; \ + ErtsSmpBPUnlock(bdt); \ + *(instr_result) = bdt->orig_instr; \ +} while (0) + + #define ErtsBreakSkip(pc,instr_result) \ do { \ BpData *bd = (BpData *) (pc)[-4]; \ @@ -140,6 +176,8 @@ int erts_set_debug_break(Eterm mfa[3], int specified); int erts_clear_debug_break(Eterm mfa[3], int specified); int erts_set_count_break(Eterm mfa[3], int specified, enum erts_break_op); int erts_clear_count_break(Eterm mfa[3], int specified); +int erts_set_time_break(Eterm mfa[3], int specified, enum erts_break_op); +int erts_clear_time_break(Eterm mfa[3], int specified); int erts_clear_break(Eterm mfa[3], int specified); @@ -159,6 +197,9 @@ int erts_is_mtrace_bif(BeamInstr *pc, Binary **match_spec_ret, Eterm *tracer_pid_ret); int erts_is_native_break(BeamInstr *pc); int erts_is_count_break(BeamInstr *pc, Sint *count_ret); +int erts_is_time_break(BeamInstr *pc, Sint *count, Uint *s_time, Uint *us_time); + +void erts_do_time_break(Process *p, BpDataTime *bdt); BeamInstr *erts_find_local_func(Eterm mfa[3]); diff --git a/erts/emulator/beam/beam_emu.c b/erts/emulator/beam/beam_emu.c index d42e74ccc9..145ae48590 100644 --- a/erts/emulator/beam/beam_emu.c +++ b/erts/emulator/beam/beam_emu.c @@ -4408,6 +4408,22 @@ apply_bif_or_nif_epilogue: Goto(real_I); } + OpCase(i_time_breakpoint): { + BeamInstr real_I; + BpDataTime *bdt = (BpDataTime *) (I)[-4]; + + ASSERT((I)[-5] == (Uint) BeamOp(op_i_func_info_IaaI)); + ASSERT(bdt); + bdt = (BpDataTime *) bdt->next; + ASSERT(bdt); + (I)[-4] = (Uint) bdt; + real_I = bdt->orig_instr; + erts_do_time_break(c_p, bdt); + + ASSERT(VALID_INSTR(real_I)); + Goto(real_I); + } + OpCase(i_trace_breakpoint): if (! IS_TRACED_FL(c_p, F_TRACE_CALLS)) { BeamInstr real_I; diff --git a/erts/emulator/beam/erl_bif_trace.c b/erts/emulator/beam/erl_bif_trace.c index 7fe4410e0d..20a58e5ed9 100644 --- a/erts/emulator/beam/erl_bif_trace.c +++ b/erts/emulator/beam/erl_bif_trace.c @@ -186,6 +186,14 @@ trace_pattern_3(Process* p, Eterm MFA, Eterm Pattern, Eterm flaglist) flags.breakpoint = 1; flags.call_count = 1; break; + case am_call_time: + if (is_global) { + goto error; + } + flags.breakpoint = 1; + flags.call_time = 1; + break; + default: goto error; } @@ -235,6 +243,8 @@ trace_pattern_3(Process* p, Eterm MFA, Eterm Pattern, Eterm flaglist) |= flags.meta; erts_default_trace_pattern_flags.call_count |= (on == 1) ? flags.call_count : 0; + erts_default_trace_pattern_flags.call_time + |= (on == 1) ? flags.call_time : 0; } else { erts_default_trace_pattern_flags.local &= ~flags.local; @@ -242,10 +252,13 @@ trace_pattern_3(Process* p, Eterm MFA, Eterm Pattern, Eterm flaglist) &= ~flags.meta; erts_default_trace_pattern_flags.call_count &= ~flags.call_count; + erts_default_trace_pattern_flags.call_time + &= ~flags.call_time; if (! (erts_default_trace_pattern_flags.breakpoint = erts_default_trace_pattern_flags.local | erts_default_trace_pattern_flags.meta | - erts_default_trace_pattern_flags.call_count)) { + erts_default_trace_pattern_flags.call_count | + erts_default_trace_pattern_flags.call_time)) { erts_default_trace_pattern_is_on = !!on; /* i.e off */ } } @@ -267,8 +280,9 @@ trace_pattern_3(Process* p, Eterm MFA, Eterm Pattern, Eterm flaglist) if (on) { if (on != 1) { flags.call_count = 0; + flags.call_time = 0; } - flags.breakpoint = flags.local | flags.meta | flags.call_count; + flags.breakpoint = flags.local | flags.meta | flags.call_count | flags.call_time; erts_default_trace_pattern_flags = flags; /* Struct copy */ erts_default_trace_pattern_is_on = !!flags.breakpoint; } @@ -352,7 +366,6 @@ erts_get_default_trace_pattern(int *trace_pattern_is_on, - Uint erts_trace_flag2bit(Eterm flag) { @@ -380,7 +393,7 @@ erts_trace_flag2bit(Eterm flag) default: return 0; } } - + /* Scan the argument list and sort out the trace flags. ** ** Returns !0 on success, 0 on failure. @@ -931,6 +944,7 @@ trace_info_pid(Process* p, Eterm pid_spec, Eterm key) #define FUNC_TRACE_LOCAL_TRACE (1<<2) #define FUNC_TRACE_META_TRACE (1<<3) #define FUNC_TRACE_COUNT_TRACE (1<<4) +#define FUNC_TRACE_TIME_TRACE (1<<5) /* * Returns either FUNC_TRACE_NOEXIST, FUNC_TRACE_UNTRACED, * FUNC_TRACE_GLOBAL_TRACE, or, @@ -946,10 +960,12 @@ trace_info_pid(Process* p, Eterm pid_spec, Eterm key) * If the return value contains FUNC_TRACE_COUNT_TRACE, *count is set. */ static int function_is_traced(Eterm mfa[3], - Binary **ms, /* out */ - Binary **ms_meta, /* out */ + Binary **ms, /* out */ + Binary **ms_meta, /* out */ Eterm *tracer_pid_meta, /* out */ - Sint *count) /* out */ + Sint *count, /* out */ + Uint *s_time, /* out */ + Uint *us_time) /* out */ { Export e; Export* ep; @@ -1001,7 +1017,9 @@ static int function_is_traced(Eterm mfa[3], | (erts_is_mtrace_break(code, ms_meta, tracer_pid_meta) ? FUNC_TRACE_META_TRACE : 0) | (erts_is_count_break(code, count) - ? FUNC_TRACE_COUNT_TRACE : 0); + ? FUNC_TRACE_COUNT_TRACE : 0) + | (erts_is_time_break(code, count, s_time, us_time) + ? FUNC_TRACE_TIME_TRACE : 0); return r ? r : FUNC_TRACE_UNTRACED; } @@ -1016,6 +1034,7 @@ trace_info_func(Process* p, Eterm func_spec, Eterm key) DeclareTmpHeap(mfa,3,p); /* Not really heap here, but might be when setting pattern */ Binary *ms = NULL, *ms_meta = NULL; Sint count = 0; + Uint s_time = 0, us_time = 0; Eterm traced = am_false; Eterm match_spec = am_false; Eterm retval = am_false; @@ -1039,7 +1058,7 @@ trace_info_func(Process* p, Eterm func_spec, Eterm key) mfa[1] = tp[2]; mfa[2] = signed_val(tp[3]); - r = function_is_traced(mfa, &ms, &ms_meta, &meta, &count); + r = function_is_traced(mfa, &ms, &ms_meta, &meta, &count, &s_time, &us_time); switch (r) { case FUNC_TRACE_NOEXIST: UnUseTmpHeap(3,p); @@ -1092,8 +1111,17 @@ trace_info_func(Process* p, Eterm func_spec, Eterm key) erts_make_integer(count, p); } break; + case am_call_time: + if (r & FUNC_TRACE_TIME_TRACE) { + hp = HAlloc(p, 4); + retval = TUPLE3(hp, + erts_make_integer(count, p), + erts_make_integer(s_time, p), + erts_make_integer(us_time,p)); hp += 4; + } + break; case am_all: { - Eterm match_spec_meta = am_false, c = am_false, t; + Eterm match_spec_meta = am_false, c = am_false, t, ct; if (ms) { match_spec = MatchSetGetSource(ms); @@ -1111,10 +1139,16 @@ trace_info_func(Process* p, Eterm func_spec, Eterm key) erts_make_integer(-count-1, p) : erts_make_integer(count, p); } - hp = HAlloc(p, (3+2)*5); + if (r & FUNC_TRACE_TIME_TRACE) { + hp = HAlloc(p, 4); + ct = TUPLE3(hp, erts_make_integer(count, p), erts_make_integer(s_time, p), erts_make_integer(us_time,p)); hp += 4; + } + hp = HAlloc(p, (3+2)*6); retval = NIL; t = TUPLE2(hp, am_call_count, c); hp += 3; retval = CONS(hp, t, retval); hp += 2; + t = TUPLE2(hp, am_call_time, ct); hp += 3; + retval = CONS(hp, t, retval); hp += 2; t = TUPLE2(hp, am_meta_match_spec, match_spec_meta); hp += 3; retval = CONS(hp, t, retval); hp += 2; t = TUPLE2(hp, am_meta, meta); hp += 3; @@ -1210,6 +1244,13 @@ trace_info_on_load(Process* p, Eterm key) } else { return TUPLE2(hp, key, am_false); } + case am_call_time: + hp = HAlloc(p, 3); + if (erts_default_trace_pattern_flags.call_time) { + return TUPLE2(hp, key, am_true); + } else { + return TUPLE2(hp, key, am_false); + } case am_all: { Eterm match_spec = am_false, meta_match_spec = am_false, r = NIL, t; @@ -1284,6 +1325,7 @@ erts_set_trace_pattern(Eterm* mfa, int specified, for (j = 0; j < specified && mfa[j] == ep->code[j]; j++) { /* Empty loop body */ } + if (j == specified) { if (on) { if (! flags.breakpoint) @@ -1405,6 +1447,9 @@ erts_set_trace_pattern(Eterm* mfa, int specified, if (flags.call_count) { m = erts_set_count_break(mfa, specified, on); } + if (flags.call_time) { + m = erts_set_time_break(mfa, specified, on); + } /* All assignments to 'm' above should give the same value, * so just use the last */ matches += m; @@ -1420,6 +1465,9 @@ erts_set_trace_pattern(Eterm* mfa, int specified, if (flags.call_count) { m = erts_clear_count_break(mfa, specified); } + if (flags.call_count) { + m = erts_clear_time_break(mfa, specified); + } /* All assignments to 'm' above should give the same value, * so just use the last */ matches += m; diff --git a/erts/emulator/beam/erl_process.h b/erts/emulator/beam/erl_process.h index e2cb523cf5..bacaa25d23 100644 --- a/erts/emulator/beam/erl_process.h +++ b/erts/emulator/beam/erl_process.h @@ -397,8 +397,9 @@ extern ErtsSchedulerData *erts_scheduler_data; #define ERTS_PSD_SAVED_CALLS_BUF 1 #define ERTS_PSD_SCHED_ID 2 #define ERTS_PSD_DIST_ENTRY 3 +#define ERTS_PSD_CALL_TIME_BP 4 -#define ERTS_PSD_SIZE 4 +#define ERTS_PSD_SIZE 5 typedef struct { void *data[ERTS_PSD_SIZE]; @@ -1208,6 +1209,12 @@ erts_psd_set(Process *p, ErtsProcLocks plocks, int ix, void *data) #define ERTS_PROC_SET_SAVED_CALLS_BUF(P, L, SCB) \ ((struct saved_calls *) erts_psd_set((P), (L), ERTS_PSD_SAVED_CALLS_BUF, (void *) (SCB))) +#define ERTS_PROC_GET_CALL_TIME(P) \ + ((process_breakpoint_time_t *) erts_psd_get((P), ERTS_PSD_CALL_TIME_BP)) +#define ERTS_PROC_SET_CALL_TIME(P, L, PBT) \ + ((process_breakpoint_time_t *) erts_psd_set((P), (L), ERTS_PSD_CALL_TIME_BP, (void *) (PBT))) + + ERTS_GLB_INLINE Eterm erts_proc_get_error_handler(Process *p); ERTS_GLB_INLINE Eterm erts_proc_set_error_handler(Process *p, ErtsProcLocks plocks, diff --git a/erts/emulator/beam/global.h b/erts/emulator/beam/global.h index 19dd3d6f97..711b613028 100644 --- a/erts/emulator/beam/global.h +++ b/erts/emulator/beam/global.h @@ -1741,6 +1741,7 @@ struct trace_pattern_flags { unsigned int local : 1; /* Local call trace breakpoint */ unsigned int meta : 1; /* Metadata trace breakpoint */ unsigned int call_count : 1; /* Fast call count breakpoint */ + unsigned int call_time : 1; /* Fast call time breakpoint */ }; extern const struct trace_pattern_flags erts_trace_pattern_flags_off; int erts_set_trace_pattern(Eterm* mfa, int specified, diff --git a/erts/emulator/beam/ops.tab b/erts/emulator/beam/ops.tab index 42c84989c6..32abdccd7b 100644 --- a/erts/emulator/beam/ops.tab +++ b/erts/emulator/beam/ops.tab @@ -84,6 +84,7 @@ i_trace_breakpoint i_mtrace_breakpoint i_debug_breakpoint i_count_breakpoint +i_time_breakpoint i_return_to_trace i_yield i_global_cons -- cgit v1.2.3