From 891682094bf1db038cdf9addffe0b107f40ab6ec Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bj=C3=B6rn-Egil=20Dahlberg?= Date: Thu, 29 Apr 2010 14:52:18 +0200 Subject: Add return_time trace and PSD deletions --- erts/emulator/beam/beam_bp.c | 287 +++++++++++++++++++++++++++++++------ erts/emulator/beam/beam_bp.h | 12 +- erts/emulator/beam/beam_emu.c | 69 +++++++-- erts/emulator/beam/erl_bif_trace.c | 22 ++- erts/emulator/beam/erl_process.c | 25 +++- erts/emulator/beam/global.h | 1 + 6 files changed, 350 insertions(+), 66 deletions(-) (limited to 'erts') diff --git a/erts/emulator/beam/beam_bp.c b/erts/emulator/beam/beam_bp.c index 7c85885fa2..48e7b6675a 100644 --- a/erts/emulator/beam/beam_bp.c +++ b/erts/emulator/beam/beam_bp.c @@ -630,70 +630,233 @@ static void bp_time_diff(bp_data_time_item_t *item, /* out */ ds = s - pbt->s; dus = us - pbt->us; - if (dms > 0) { - item->s_time = (ds + dms * 1000000); - } else { - item->s_time = ds; + /* get_sys_now may return zero difftime, + * this is ok. + */ + + ASSERT(dms >= 0 || ds >= 0 || dus >= 0); + + if (dus < 0) { + dus += 1000000; + ds -= 1; } - if ( dus < 0 ) { - item->us_time = (dus + 1000000); - item->s_time -= 1; - } else { - item->us_time = dus; + if (ds < 0) { + ds += 1000000; } + + item->s_time = ds; + item->us_time = dus; } -void erts_do_time_break(Process *p, BpDataTime *bdt) { +void erts_schedule_time_break(Process *p, Uint schedule) { + Uint ms, s, us; + process_breakpoint_time_t *pbt = NULL; + Uint ix = 0; + bp_data_time_item_t sitem, *item = NULL; + bp_time_hash_t *h = NULL; + + ASSERT(p); + + pbt = ERTS_PROC_GET_CALL_TIME(p); + + ASSERT( (p->status == P_RUNNING) || + (p->status == P_WAITING) || + (p->status == P_RUNABLE)); + + if (pbt) { + get_sys_now(&ms,&s,&us); + + switch(schedule) { + case ERTS_BP_CALL_TIME_SCHEDULE_EXITING : + case ERTS_BP_CALL_TIME_SCHEDULE_OUT : + /* When a process is scheduled _out_, + * timestamp it and add its delta to + * the previous breakpoint. + */ + +#ifdef ERTS_SMP + ix = p->scheduler_data->no - 1; +#else + ix = 0; +#endif + bp_time_diff(&sitem, pbt, ms, s, us); + sitem.pid = p->id; + sitem.count = 1; + /*count is set to 0 if out and 1 if exiting */ + + h = &(pbt->bdt->hash[ix]); + + ASSERT(h->item); + + item = bp_hash_get(h, &sitem); + if (!item) { + item = bp_hash_put(h, &sitem); + } else { + BP_TIME_ADD(item, &sitem); + } + break; + case ERTS_BP_CALL_TIME_SCHEDULE_IN : + /* When a process is scheduled _in_, + * timestamp it and remove the previous + * timestamp in the psd. + */ + sitem.pid = p->id; + sitem.count = -1; + sitem.us_time = 0; + sitem.s_time = 0; + + h = &(pbt->bdt->hash[ix]); + + ASSERT(h->item); + + item = bp_hash_get(h, &sitem); + if (!item) { + item = bp_hash_put(h, &sitem); + } else { + BP_TIME_ADD(item, &sitem); + } + pbt->ms = ms; + pbt->s = s; + pbt->us = us; + break; + default : + ASSERT(0); + /* will never happen */ + break; + } +#ifdef DEBUG + } else { + /* if pbt is null, then the process has just been spawned + * and status should be runnable. + */ + ASSERT( (p->status == P_RUNABLE) || + (p->status == P_WAITING)); +#endif + } /* pbt */ +} + +/* call_time breakpoint + * Accumulated times are added to the previous bp, + * not the current one. The current one is saved + * for future reference. + * The previous breakpoint is stored in the process it self, the psd. + * We do not need to store in a stack frame. + * There is no need for locking, each thread has its own + * area in each bp to save data. + * Since we need to diffrentiate between processes for each bp, + * every bp has a hash (per thread) to process-bp statistics. + * - egil + */ + +void erts_do_time_break(Process *p, BpDataTime *bdt, Uint type) { Uint ms,s,us; process_breakpoint_time_t *pbt = NULL; int ix = 0; + bp_data_time_item_t sitem, *item = NULL; + bp_time_hash_t *h = NULL; + + ASSERT(p); + ASSERT(bdt); + ASSERT(p->status == P_RUNNING); /* get previous timestamp and breakpoint - * from the process' psd */ + * from the process psd */ + pbt = ERTS_PROC_GET_CALL_TIME(p); get_sys_now(&ms,&s,&us); - if (pbt) { - bp_data_time_item_t sitem, *item; - bp_time_hash_t *h; + switch(type) { + case ERTS_BP_CALL_TIME_CALL: + /* get pbt + * timestamp = t0 + * set ts0 to pbt + * add call count here? + */ + if (!pbt) { + pbt = Alloc(sizeof(process_breakpoint_time_t)); + (void *) ERTS_PROC_SET_CALL_TIME(p, ERTS_PROC_LOCK_MAIN, pbt); + } + + pbt->bdt = bdt; /* needed for schedule? */ + + pbt->ms = ms; + pbt->s = s; + pbt->us = us; + + + break; + case ERTS_BP_CALL_TIME_TAIL_CALL: + + ASSERT(pbt); #ifdef ERTS_SMP - ix = p->scheduler_data->no - 1; + ix = p->scheduler_data->no - 1; #else - ix = 0; + ix = 0; #endif - bp_time_diff(&sitem, pbt, ms, s, us); - sitem.pid = p->id; - sitem.count = 1; + bp_time_diff(&sitem, pbt, ms, s, us); + sitem.pid = p->id; + sitem.count = 1; - h = &(pbt->bdt->hash[ix]); + h = &(bdt->hash[ix]); - item = bp_hash_get(h, &sitem); - if (!item) { - bp_hash_put(h, &sitem); - } else { - BP_TIME_ADD(item, &sitem); - } + ASSERT(h->item); - pbt->bdt = bdt; - pbt->ms = ms; - pbt->s = s; - pbt->us = us; + item = bp_hash_get(h, &sitem); + if (!item) { + item = bp_hash_put(h, &sitem); + } else { + BP_TIME_ADD(item, &sitem); + } - } else { - pbt = Alloc(sizeof(process_breakpoint_time_t)); - pbt->bdt = bdt; - pbt->ms = ms; - pbt->s = s; - pbt->us = us; + pbt->bdt = bdt; /* needed for schedule? */ - (void *) ERTS_PROC_SET_CALL_TIME(p, ERTS_PROC_LOCK_MAIN, pbt); - } + pbt->ms = ms; + pbt->s = s; + pbt->us = us; + break; - /* timestamp start of this call - * save ms, s, us, and bdt to the process. - */ + + case ERTS_BP_CALL_TIME_RETURN: + /* get pbt + * timestamp = t1 + * get ts0 from pbt + * get item from bdt->hash[bp_hash(p->id)] + * ack diff (t1, t0) to item + */ + + if(pbt) { + /* might have been removed due to + * trace_pattern(false) + */ +#ifdef ERTS_SMP + ix = p->scheduler_data->no - 1; +#else + ix = 0; +#endif + bp_time_diff(&sitem, pbt, ms, s, us); + sitem.pid = p->id; + sitem.count = 1; + + h = &(bdt->hash[ix]); + + ASSERT(h->item); + + item = bp_hash_get(h, &sitem); + if (!item) { + item = bp_hash_put(h, &sitem); + } else { + BP_TIME_ADD(item, &sitem); + } + + pbt->bdt = NULL; + pbt->ms = ms; + pbt->s = s; + pbt->us = us; + } + break; + } } @@ -814,10 +977,14 @@ static int set_function_break(Module *modp, BeamInstr *pc, Uint i = 0; /*XXX: must block system */ - - for (i = 0; i < bdt->n; i++) { - bp_hash_delete(&(bdt->hash[i])); - bp_hash_init(&(bdt->hash[i]), 32); + if (count_op == erts_break_stop) { + bdt->pause = 1; + } else { + bdt->pause = 0; + for (i = 0; i < bdt->n; i++) { + bp_hash_delete(&(bdt->hash[i])); + bp_hash_init(&(bdt->hash[i]), 32); + } } } else { @@ -904,8 +1071,9 @@ static int set_function_break(Module *modp, BeamInstr *pc, BpDataTime *bdt = (BpDataTime *) bd; Uint i = 0; - bdt->n = erts_no_schedulers; - bdt->hash = Alloc(sizeof(bp_time_hash_t)*(bdt->n)); + bdt->pause = 0; + bdt->n = erts_no_schedulers; + bdt->hash = Alloc(sizeof(bp_time_hash_t)*(bdt->n)); for (i = 0; i < bdt->n; i++) { bp_hash_init(&(bdt->hash[i]), 32); @@ -1034,10 +1202,35 @@ static int clear_function_break(Module *m, BeamInstr *pc, BeamInstr break_op) { if (op == (BeamInstr) BeamOp(op_i_time_breakpoint)) { BpDataTime *bdt = (BpDataTime *) bd; Uint i = 0; + Uint j = 0; + Process *h_p = NULL; + bp_data_time_item_t *item = NULL; + process_breakpoint_time_t *pbt = NULL; + + /* remove all psd associated with the hash + * and then delete the hash. + * ... sigh ... + */ + for( i = 0; i < bdt->n; ++i) { + if (bdt->hash[i].used) { + for (j = 0; j < bdt->hash[i].n; ++j) { + item = &(bdt->hash[i].item[j]); + if (item->pid != NIL) { + h_p = process_tab[internal_pid_index(item->pid)]; + if (h_p) { + pbt = ERTS_PROC_SET_CALL_TIME(h_p, ERTS_PROC_LOCK_MAIN, NULL); + if (pbt) { + Free(pbt); + } + } + } + } + } bp_hash_delete(&(bdt->hash[i])); } Free(bdt->hash); + bdt->hash = NULL; bdt->n = 0; } Free(bd); diff --git a/erts/emulator/beam/beam_bp.h b/erts/emulator/beam/beam_bp.h index 58fd65399d..515a06e220 100644 --- a/erts/emulator/beam/beam_bp.h +++ b/erts/emulator/beam/beam_bp.h @@ -24,7 +24,6 @@ #include "sys.h" #include "erl_vm.h" #include "global.h" -//#include "hash.h" @@ -93,6 +92,7 @@ typedef struct bp_data_time { /* Call time */ struct bp_data *next; struct bp_data *prev; Uint orig_instr; + Uint pause; Uint n; bp_time_hash_t *hash; } BpDataTime; @@ -106,6 +106,13 @@ typedef struct { extern erts_smp_spinlock_t erts_bp_lock; +#define ERTS_BP_CALL_TIME_SCHEDULE_IN (0) +#define ERTS_BP_CALL_TIME_SCHEDULE_OUT (1) +#define ERTS_BP_CALL_TIME_SCHEDULE_EXITING (2) + +#define ERTS_BP_CALL_TIME_CALL (0) +#define ERTS_BP_CALL_TIME_RETURN (1) +#define ERTS_BP_CALL_TIME_TAIL_CALL (2) #ifdef ERTS_SMP #define ErtsSmpBPLock(BDC) erts_smp_spin_lock(&erts_bp_lock) @@ -214,7 +221,8 @@ int erts_is_native_break(BeamInstr *pc); int erts_is_count_break(BeamInstr *pc, Sint *count_ret); int erts_is_time_break(Process *p, BeamInstr *pc, Eterm *call_time); -void erts_do_time_break(Process *p, BpDataTime *bdt); +void erts_do_time_break(Process *p, BpDataTime *bdt, Uint type); +void erts_schedule_time_break(Process *p, Uint out); 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 145ae48590..8661d7cbf5 100644 --- a/erts/emulator/beam/beam_emu.c +++ b/erts/emulator/beam/beam_emu.c @@ -228,9 +228,10 @@ BeamInstr* em_call_traced_function; ** for the refering variable (one of these), and rouge references ** will most likely cause chaos. */ -BeamInstr beam_return_to_trace[1]; /* OpCode(i_return_to_trace) */ -BeamInstr beam_return_trace[1]; /* OpCode(i_return_trace) */ -BeamInstr beam_exception_trace[1]; /* UGLY also OpCode(i_return_trace) */ +BeamInstr beam_return_to_trace[1]; /* OpCode(i_return_to_trace) */ +BeamInstr beam_return_trace[1]; /* OpCode(i_return_trace) */ +BeamInstr beam_exception_trace[1]; /* UGLY also OpCode(i_return_trace) */ +BeamInstr beam_time_return_trace[1]; /* OpCode(i_time_return_trace) */ /* * All Beam instructions in numerical order. @@ -4411,6 +4412,7 @@ apply_bif_or_nif_epilogue: OpCase(i_time_breakpoint): { BeamInstr real_I; BpDataTime *bdt = (BpDataTime *) (I)[-4]; + Uint tail_call = 0; ASSERT((I)[-5] == (Uint) BeamOp(op_i_func_info_IaaI)); ASSERT(bdt); @@ -4418,12 +4420,53 @@ apply_bif_or_nif_epilogue: ASSERT(bdt); (I)[-4] = (Uint) bdt; real_I = bdt->orig_instr; - erts_do_time_break(c_p, bdt); - ASSERT(VALID_INSTR(real_I)); + + if (IS_TRACED_FL(c_p, F_TRACE_CALLS) && !(bdt->pause)) { + if (*cp_val((Eterm)c_p->cp) == (BeamInstr) OpCode(i_time_return_trace)) { + tail_call = 1; + } + + if (tail_call) { + /* This _IS_ a tail recursive call */ + SWAPOUT; + erts_do_time_break(c_p, bdt, ERTS_BP_CALL_TIME_TAIL_CALL); + SWAPIN; + } else { + SWAPOUT; + erts_do_time_break(c_p, bdt, ERTS_BP_CALL_TIME_CALL); + + ASSERT(c_p->htop <= E && E <= c_p->hend); + if (E - 2 < HTOP) { + PROCESS_MAIN_CHK_LOCKS(c_p); + FCALLS -= erts_garbage_collect(c_p, 2, reg, I[-1]); + PROCESS_MAIN_CHK_LOCKS(c_p); + } + SWAPIN; + + ASSERT(c_p->htop <= E && E <= c_p->hend); + + E -= 2; + E[1] = make_cp(c_p->cp); /* original return address */ + E[0] = make_cp((Uint *)bdt); /* make sure bdt is allocated in low mem (for halfword) */ + c_p->cp = (Eterm *) make_cp(beam_time_return_trace); + } + } + Goto(real_I); } + OpCase(i_time_return_trace): { + BpDataTime *bdt = (BpDataTime *) cp_val((E)[0]); + SWAPOUT; + erts_do_time_break(c_p, bdt, ERTS_BP_CALL_TIME_RETURN); + SWAPIN; + c_p->cp = NULL; + SET_I((Eterm *) E[1]); + E += 2; + Goto(*I); + } + OpCase(i_trace_breakpoint): if (! IS_TRACED_FL(c_p, F_TRACE_CALLS)) { BeamInstr real_I; @@ -4973,13 +5016,15 @@ apply_bif_or_nif_epilogue: em_call_error_handler = OpCode(call_error_handler); em_call_traced_function = OpCode(call_traced_function); em_apply_bif = OpCode(apply_bif); - beam_apply[0] = (BeamInstr) OpCode(i_apply); - beam_apply[1] = (BeamInstr) OpCode(normal_exit); - beam_exit[0] = (BeamInstr) OpCode(error_action_code); - beam_continue_exit[0] = (BeamInstr) OpCode(continue_exit); - beam_return_to_trace[0] = (BeamInstr) OpCode(i_return_to_trace); - beam_return_trace[0] = (BeamInstr) OpCode(return_trace); - beam_exception_trace[0] = (BeamInstr) OpCode(return_trace); /* UGLY */ + + beam_apply[0] = (BeamInstr) OpCode(i_apply); + beam_apply[1] = (BeamInstr) OpCode(normal_exit); + beam_exit[0] = (BeamInstr) OpCode(error_action_code); + beam_continue_exit[0] = (BeamInstr) OpCode(continue_exit); + beam_return_to_trace[0] = (BeamInstr) OpCode(i_return_to_trace); + beam_return_trace[0] = (BeamInstr) OpCode(return_trace); + beam_exception_trace[0] = (BeamInstr) OpCode(return_trace); /* UGLY */ + beam_time_return_trace[0] = (BeamInstr) OpCode(i_time_return_trace); /* * Enter all BIFs into the export table. diff --git a/erts/emulator/beam/erl_bif_trace.c b/erts/emulator/beam/erl_bif_trace.c index 26390d397c..1e626533a4 100644 --- a/erts/emulator/beam/erl_bif_trace.c +++ b/erts/emulator/beam/erl_bif_trace.c @@ -41,11 +41,11 @@ #define DECL_AM(S) Eterm AM_ ## S = am_atom_put(#S, sizeof(#S) - 1) static erts_smp_mtx_t trace_pattern_mutex; -const struct trace_pattern_flags erts_trace_pattern_flags_off = {0, 0, 0, 0}; +const struct trace_pattern_flags erts_trace_pattern_flags_off = {0, 0, 0, 0, 0}; static int erts_default_trace_pattern_is_on; static Binary *erts_default_match_spec; static Binary *erts_default_meta_match_spec; -static struct trace_pattern_flags erts_default_trace_pattern_flags; +struct trace_pattern_flags erts_default_trace_pattern_flags; static Eterm erts_default_meta_tracer_pid; static void new_seq_trace_token(Process* p); /* help func for seq_trace_2*/ @@ -1058,7 +1058,22 @@ trace_info_func(Process* p, Eterm func_spec, Eterm key) mfa[1] = tp[2]; mfa[2] = signed_val(tp[3]); +#ifdef ERTS_SMP + if ( (key == am_call_time) || (key == am_all)) { + erts_smp_proc_unlock(p, ERTS_PROC_LOCK_MAIN); + erts_smp_block_system(0); + } +#endif + r = function_is_traced(p, mfa, &ms, &ms_meta, &meta, &count, &call_time); + +#ifdef ERTS_SMP + if ( (key == am_call_time) || (key == am_all)) { + erts_smp_release_system(); + erts_smp_proc_lock(p, ERTS_PROC_LOCK_MAIN); + } +#endif + switch (r) { case FUNC_TRACE_NOEXIST: UnUseTmpHeap(3,p); @@ -1429,6 +1444,7 @@ erts_set_trace_pattern(Eterm* mfa, int specified, erts_clear_trace_break(mfa, specified); erts_clear_mtrace_break(mfa, specified); erts_clear_count_break(mfa, specified); + erts_clear_time_break(mfa, specified); } else { int m = 0; if (flags.local) { @@ -1460,7 +1476,7 @@ erts_set_trace_pattern(Eterm* mfa, int specified, if (flags.call_count) { m = erts_clear_count_break(mfa, specified); } - if (flags.call_count) { + if (flags.call_time) { m = erts_clear_time_break(mfa, specified); } /* All assignments to 'm' above should give the same value, diff --git a/erts/emulator/beam/erl_process.c b/erts/emulator/beam/erl_process.c index 4befa0aca9..5293fabe87 100644 --- a/erts/emulator/beam/erl_process.c +++ b/erts/emulator/beam/erl_process.c @@ -38,6 +38,7 @@ #include "erl_instrument.h" #include "erl_threads.h" #include "erl_binary.h" +#include "beam_bp.h" #define ERTS_RUNQ_CHECK_BALANCE_REDS_PER_SCHED (2000*CONTEXT_REDS) #define ERTS_RUNQ_CALL_CHECK_BALANCE_REDS \ @@ -5877,6 +5878,11 @@ Process *schedule(Process *p, int calls) } if (IS_TRACED(p)) { + if (IS_TRACED_FL(p, F_TRACE_CALLS) && + erts_default_trace_pattern_flags.call_time && + p->status != P_FREE) { + erts_schedule_time_break(p, ERTS_BP_CALL_TIME_SCHEDULE_OUT); + } switch (p->status) { case P_EXITING: if (ARE_TRACE_FLAGS_ON(p, F_TRACE_SCHED_EXIT)) @@ -6313,7 +6319,11 @@ Process *schedule(Process *p, int calls) trace_virtual_sched(p, am_in); break; } + if (IS_TRACED_FL(p, F_TRACE_CALLS) && erts_default_trace_pattern_flags.call_time) { + erts_schedule_time_break(p, ERTS_BP_CALL_TIME_SCHEDULE_IN); + } } + if (p->status != P_EXITING) p->status = P_RUNNING; @@ -8056,8 +8066,13 @@ erts_do_exit_process(Process* p, Eterm reason) ERTS_SMP_MSGQ_MV_INQ2PRIVQ(p); #endif - if (IS_TRACED_FL(p,F_TRACE_PROCS)) - trace_proc(p, p, am_exit, reason); + if (IS_TRACED(p)) { + if (IS_TRACED_FL(p, F_TRACE_CALLS) && erts_default_trace_pattern_flags.call_time) + erts_schedule_time_break(p, ERTS_BP_CALL_TIME_SCHEDULE_EXITING); + + if (IS_TRACED_FL(p,F_TRACE_PROCS)) + trace_proc(p, p, am_exit, reason); + } erts_trace_check_exiting(p->id); @@ -8106,6 +8121,8 @@ continue_exit_process(Process *p Eterm reason = p->fvalue; DistEntry *dep; struct saved_calls *scb; + process_breakpoint_time_t *pbt; + #ifdef DEBUG int yield_allowed = 1; #endif @@ -8245,6 +8262,7 @@ continue_exit_process(Process *p ? ERTS_PROC_SET_DIST_ENTRY(p, ERTS_PROC_LOCKS_ALL, NULL) : NULL); scb = ERTS_PROC_SET_SAVED_CALLS_BUF(p, ERTS_PROC_LOCKS_ALL, NULL); + pbt = ERTS_PROC_SET_CALL_TIME(p, ERTS_PROC_LOCKS_ALL, NULL); erts_smp_proc_unlock(p, ERTS_PROC_LOCKS_ALL); processes_busy--; @@ -8287,6 +8305,9 @@ continue_exit_process(Process *p if (scb) erts_free(ERTS_ALC_T_CALLS_BUF, (void *) scb); + if (pbt) + erts_free(ERTS_ALC_T_BPD, (void *) pbt); + delete_process(p); erts_smp_proc_lock(p, ERTS_PROC_LOCK_MAIN); diff --git a/erts/emulator/beam/global.h b/erts/emulator/beam/global.h index 711b613028..8d087fd7d6 100644 --- a/erts/emulator/beam/global.h +++ b/erts/emulator/beam/global.h @@ -1744,6 +1744,7 @@ struct trace_pattern_flags { unsigned int call_time : 1; /* Fast call time breakpoint */ }; extern const struct trace_pattern_flags erts_trace_pattern_flags_off; +extern struct trace_pattern_flags erts_default_trace_pattern_flags; /* used with blocksystem */ int erts_set_trace_pattern(Eterm* mfa, int specified, Binary* match_prog_set, Binary *meta_match_prog_set, int on, struct trace_pattern_flags, -- cgit v1.2.3