From bbfc75ea8795d26a2fe9254f3f646e761f2ad61e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bj=C3=B6rn-Egil=20Dahlberg?= Date: Fri, 4 Jul 2014 19:34:24 +0200 Subject: erts: Add histogram to lcnt --- erts/emulator/beam/erl_bif_info.c | 48 +++++++----- erts/emulator/beam/erl_lock_count.c | 149 ++++++++++++++++++++---------------- erts/emulator/beam/erl_lock_count.h | 20 ++++- erts/emulator/beam/io.c | 2 +- 4 files changed, 129 insertions(+), 90 deletions(-) diff --git a/erts/emulator/beam/erl_bif_info.c b/erts/emulator/beam/erl_bif_info.c index 4d5e55aaf5..6915765dab 100644 --- a/erts/emulator/beam/erl_bif_info.c +++ b/erts/emulator/beam/erl_bif_info.c @@ -3856,16 +3856,19 @@ static Eterm lcnt_build_lock_stats_term(Eterm **hpp, Uint *szp, erts_lcnt_lock_s Uint tries = 0, colls = 0; unsigned long timer_s = 0, timer_ns = 0, timer_n = 0; unsigned int line = 0; + unsigned int i; Eterm af, uil; Eterm uit, uic; Eterm uits, uitns, uitn; Eterm tt, tstat, tloc, t; + Eterm thist, vhist[ERTS_LCNT_HISTOGRAM_SLOT_SIZE]; /* term: - * [{{file, line}, {tries, colls, {seconds, nanoseconds, n_blocks}}}] + * [{{file, line}, {tries, colls, {seconds, nanoseconds, n_blocks}}, + * { .. histogram .. }] */ - + tries = (Uint) ethr_atomic_read(&stats->tries); colls = (Uint) ethr_atomic_read(&stats->colls); @@ -3874,23 +3877,27 @@ static Eterm lcnt_build_lock_stats_term(Eterm **hpp, Uint *szp, erts_lcnt_lock_s timer_ns = stats->timer.ns; timer_n = stats->timer_n; - af = erts_atom_put(stats->file, strlen(stats->file), ERTS_ATOM_ENC_LATIN1, 1); + af = erts_atom_put((byte *)stats->file, strlen(stats->file), ERTS_ATOM_ENC_LATIN1, 1); uil = erts_bld_uint( hpp, szp, line); tloc = erts_bld_tuple(hpp, szp, 2, af, uil); - uit = erts_bld_uint( hpp, szp, tries); - uic = erts_bld_uint( hpp, szp, colls); - + uit = erts_bld_uint( hpp, szp, tries); + uic = erts_bld_uint( hpp, szp, colls); + uits = erts_bld_uint( hpp, szp, timer_s); uitns = erts_bld_uint( hpp, szp, timer_ns); uitn = erts_bld_uint( hpp, szp, timer_n); tt = erts_bld_tuple(hpp, szp, 3, uits, uitns, uitn); tstat = erts_bld_tuple(hpp, szp, 3, uit, uic, tt); - - t = erts_bld_tuple(hpp, szp, 2, tloc, tstat); - - res = erts_bld_cons( hpp, szp, t, res); + + for(i = 0; i < ERTS_LCNT_HISTOGRAM_SLOT_SIZE; i++) { + vhist[i] = erts_bld_uint(hpp, szp, stats->hist.ns[i]); + } + thist = erts_bld_tuplev(hpp, szp, ERTS_LCNT_HISTOGRAM_SLOT_SIZE, vhist); + + t = erts_bld_tuple(hpp, szp, 3, tloc, tstat, thist); + res = erts_bld_cons( hpp, szp, t, res); return res; } @@ -3911,13 +3918,13 @@ static Eterm lcnt_build_lock_term(Eterm **hpp, Uint *szp, erts_lcnt_lock_t *lock ASSERT(ltype); - type = erts_atom_put(ltype, strlen(ltype), ERTS_ATOM_ENC_LATIN1, 1); - name = erts_atom_put(lock->name, strlen(lock->name), ERTS_ATOM_ENC_LATIN1, 1); + type = erts_atom_put((byte *)ltype, strlen(ltype), ERTS_ATOM_ENC_LATIN1, 1); + name = erts_atom_put((byte *)lock->name, strlen(lock->name), ERTS_ATOM_ENC_LATIN1, 1); if (lock->flag & ERTS_LCNT_LT_ALLOC) { /* use allocator types names as id's for allocator locks */ ltype = (char *) ERTS_ALC_A2AD(signed_val(lock->id)); - id = erts_atom_put(ltype, strlen(ltype), ERTS_ATOM_ENC_LATIN1, 1); + id = erts_atom_put((byte *)ltype, strlen(ltype), ERTS_ATOM_ENC_LATIN1, 1); } else if (lock->flag & ERTS_LCNT_LT_PROCLOCK) { /* use registered names as id's for process locks if available */ proc = erts_proc_lookup(lock->id); @@ -3928,16 +3935,15 @@ static Eterm lcnt_build_lock_term(Eterm **hpp, Uint *szp, erts_lcnt_lock_t *lock id = lock->id; } } else { - id = lock->id; + id = lock->id; } - + for (i = 0; i < lock->n_stats; i++) { stats = lcnt_build_lock_stats_term(hpp, szp, &(lock->stats[i]), stats); } - - t = erts_bld_tuple(hpp, szp, 4, name, id, type, stats); - - res = erts_bld_cons( hpp, szp, t, res); + + t = erts_bld_tuple(hpp, szp, 4, name, id, type, stats); + res = erts_bld_cons( hpp, szp, t, res); return res; } @@ -3957,12 +3963,12 @@ static Eterm lcnt_build_result_term(Eterm **hpp, Uint *szp, erts_lcnt_data_t *da dtns = erts_bld_uint( hpp, szp, data->duration.ns); tdt = erts_bld_tuple(hpp, szp, 2, dts, dtns); - adur = erts_atom_put(str_duration, strlen(str_duration), ERTS_ATOM_ENC_LATIN1, 1); + adur = erts_atom_put((byte *)str_duration, strlen(str_duration), ERTS_ATOM_ENC_LATIN1, 1); tdur = erts_bld_tuple(hpp, szp, 2, adur, tdt); /* lock tuple */ - aloc = erts_atom_put(str_locks, strlen(str_locks), ERTS_ATOM_ENC_LATIN1, 1); + aloc = erts_atom_put((byte *)str_locks, strlen(str_locks), ERTS_ATOM_ENC_LATIN1, 1); for (lock = data->current_locks->head; lock != NULL ; lock = lock->next ) { lloc = lcnt_build_lock_term(hpp, szp, lock, lloc); diff --git a/erts/emulator/beam/erl_lock_count.c b/erts/emulator/beam/erl_lock_count.c index 6f44bf097b..17ddfdc8ae 100644 --- a/erts/emulator/beam/erl_lock_count.c +++ b/erts/emulator/beam/erl_lock_count.c @@ -61,6 +61,25 @@ static ERTS_INLINE void lcnt_unlock(void) { ethr_mutex_unlock(&lcnt_data_lock); } +const int log2_tab64[64] = { + 63, 0, 58, 1, 59, 47, 53, 2, + 60, 39, 48, 27, 54, 33, 42, 3, + 61, 51, 37, 40, 49, 18, 28, 20, + 55, 30, 34, 11, 43, 14, 22, 4, + 62, 57, 46, 52, 38, 26, 32, 41, + 50, 36, 17, 19, 29, 10, 13, 21, + 56, 45, 25, 31, 35, 16, 9, 12, + 44, 24, 15, 8, 23, 7, 6, 5}; + +static ERTS_INLINE int lcnt_log2(Uint64 v) { + v |= v >> 1; + v |= v >> 2; + v |= v >> 4; + v |= v >> 8; + v |= v >> 16; + v |= v >> 32; + return log2_tab64[((Uint64)((v - (v >> 1))*0x07EDD5E59A4E28C2)) >> 58]; +} static char* lcnt_lock_type(Uint16 flag) { switch(flag & ERTS_LCNT_LT_ALL) { @@ -81,19 +100,20 @@ static void lcnt_clear_stats(erts_lcnt_lock_stats_t *stats) { stats->timer_n = 0; stats->file = (char *)str_undefined; stats->line = 0; + sys_memzero(stats->hist.ns, sizeof(stats->hist.ns)); } static void lcnt_time(erts_lcnt_time_t *time) { -#ifdef HAVE_GETHRTIME +#if 0 || defined(HAVE_GETHRTIME) SysHrTime hr_time; hr_time = sys_gethrtime(); time->s = (unsigned long)(hr_time / 1000000000LL); time->ns = (unsigned long)(hr_time - 1000000000LL*time->s); -#else - SysTimeval tv; - sys_gettimeofday(&tv); - time->s = tv.tv_sec; - time->ns = tv.tv_usec*1000LL; +#else + SysTimeval tv; + sys_gettimeofday(&tv); + time->s = tv.tv_sec; + time->ns = tv.tv_usec*1000LL; #endif } @@ -111,22 +131,20 @@ static void lcnt_time_diff(erts_lcnt_time_t *d, erts_lcnt_time_t *t1, erts_lcnt_ dns += 1000000000LL; } + ASSERT(ds >= 0); + d->s = ds; d->ns = dns; } -/* difference d must be positive */ +/* difference d must be non-negative */ static void lcnt_time_add(erts_lcnt_time_t *t, erts_lcnt_time_t *d) { - unsigned long ngns = 0; - t->s += d->s; t->ns += d->ns; - ngns = t->ns / 1000000000LL; + t->s += t->ns / 1000000000LL; t->ns = t->ns % 1000000000LL; - - t->s += ngns; } static erts_lcnt_thread_data_t *lcnt_thread_data_alloc(void) { @@ -158,59 +176,64 @@ static char* lock_opt(Uint16 flag) { return "--"; } -static void print_lock_x(erts_lcnt_lock_t *lock, Uint16 flag, char *action, char *extra) { - erts_aint_t colls, tries, w_state, r_state; - erts_lcnt_lock_stats_t *stats = NULL; - +static void print_lock_x(erts_lcnt_lock_t *lock, Uint16 flag, char *action) { + erts_aint_t w_state, r_state; char *type; - int i; - + + if (strcmp(lock->name, "run_queue") != 0) return; type = lcnt_lock_type(lock->flag); r_state = ethr_atomic_read(&lock->r_state); w_state = ethr_atomic_read(&lock->w_state); - if (lock->flag & flag) { - erts_printf("%20s [%30s] [r/w state %4ld/%4ld] id %T %s\r\n", - action, - lock->name, - r_state, - w_state, - lock->id, - extra); + erts_fprintf(stderr,"%10s [%24s] [r/w state %4ld/%4ld] %2s id %T\r\n", + action, + lock->name, + r_state, + w_state, + type, + lock->id); } } - -static void print_lock(erts_lcnt_lock_t *lock, char *action) { - if (strcmp(lock->name, "proc_main") == 0) { - print_lock_x(lock, ERTS_LCNT_LT_ALL, action, ""); - } -} - #endif static erts_lcnt_lock_stats_t *lcnt_get_lock_stats(erts_lcnt_lock_t *lock, char *file, unsigned int line) { unsigned int i; erts_lcnt_lock_stats_t *stats = NULL; - - for (i = 0; i < lock->n_stats; i++) { - if ((lock->stats[i].file == file) && (lock->stats[i].line == line)) { - return &(lock->stats[i]); - } - } - if (lock->n_stats < ERTS_LCNT_MAX_LOCK_LOCATIONS) { - stats = &lock->stats[lock->n_stats]; - lock->n_stats++; - stats->file = file; - stats->line = line; - return stats; + if (erts_lcnt_rt_options & ERTS_LCNT_OPT_LOCATION) { + for (i = 0; i < lock->n_stats; i++) { + if ((lock->stats[i].file == file) && (lock->stats[i].line == line)) { + return &(lock->stats[i]); + } + } + if (lock->n_stats < ERTS_LCNT_MAX_LOCK_LOCATIONS) { + stats = &lock->stats[lock->n_stats]; + lock->n_stats++; + stats->file = file; + stats->line = line; + return stats; + } } return &lock->stats[0]; +} + +static void lcnt_update_stats_hist(erts_lcnt_hist_t *hist, erts_lcnt_time_t *time_wait) { + int idx; + unsigned long r; + if (time_wait->s > 0 || time_wait->ns > ERTS_LCNT_HISTOGRAM_MAX_NS) { + idx = ERTS_LCNT_HISTOGRAM_SLOT_SIZE - 1; + } else { + r = time_wait->ns >> ERTS_LCNT_HISTOGRAM_RSHIFT; + if (r) idx = lcnt_log2(r); + else idx = 0; + } + hist->ns[idx]++; } -static void lcnt_update_stats(erts_lcnt_lock_stats_t *stats, int lock_in_conflict, erts_lcnt_time_t *time_wait) { +static void lcnt_update_stats(erts_lcnt_lock_stats_t *stats, int lock_in_conflict, + erts_lcnt_time_t *time_wait) { ethr_atomic_inc(&stats->tries); @@ -220,6 +243,7 @@ static void lcnt_update_stats(erts_lcnt_lock_stats_t *stats, int lock_in_conflic if (time_wait) { lcnt_time_add(&(stats->timer), time_wait); stats->timer_n++; + lcnt_update_stats_hist(&stats->hist,time_wait); } } @@ -330,8 +354,9 @@ void erts_lcnt_list_delete(erts_lcnt_lock_list_t *list, erts_lcnt_lock_t *lock) /* interface to erl_threads.h */ /* only lock on init and destroy, all others should use atomics */ void erts_lcnt_init_lock(erts_lcnt_lock_t *lock, char *name, Uint16 flag ) { - erts_lcnt_init_lock_x(lock, name, flag, am_undefined); + erts_lcnt_init_lock_x(lock, name, flag, NIL); } + void erts_lcnt_init_lock_x(erts_lcnt_lock_t *lock, char *name, Uint16 flag, Eterm id) { int i; if (!name) { @@ -360,7 +385,6 @@ void erts_lcnt_init_lock_x(erts_lcnt_lock_t *lock, char *name, Uint16 flag, Eter } erts_lcnt_list_insert(erts_lcnt_data->current_locks, lock); - lcnt_unlock(); } @@ -417,8 +441,9 @@ void erts_lcnt_lock_opt(erts_lcnt_lock_t *lock, Uint16 option) { if ((w_state > 0) || (r_state > 0)) { eltd->lock_in_conflict = 1; - if (eltd->timer_set == 0) + if (eltd->timer_set == 0) { lcnt_time(&eltd->timer); + } eltd->timer_set++; } else { eltd->lock_in_conflict = 0; @@ -433,7 +458,7 @@ void erts_lcnt_lock(erts_lcnt_lock_t *lock) { if (!ERTS_LCNT_LOCK_TYPE(lock)) return; w_state = ethr_atomic_read(&lock->w_state); - ethr_atomic_inc( &lock->w_state); + ethr_atomic_inc(&lock->w_state); eltd = lcnt_get_thread_data(); @@ -446,10 +471,10 @@ void erts_lcnt_lock(erts_lcnt_lock_t *lock) { * 'atomicly'. All other locks will block the thread if w_state > 0 * i.e. locked. */ - if (eltd->timer_set == 0) + if (eltd->timer_set == 0) { lcnt_time(&eltd->timer); + } eltd->timer_set++; - } else { eltd->lock_in_conflict = 0; } @@ -459,11 +484,10 @@ void erts_lcnt_lock(erts_lcnt_lock_t *lock) { void erts_lcnt_lock_unaquire(erts_lcnt_lock_t *lock) { /* should check if this thread was "waiting" */ - if (erts_lcnt_rt_options & ERTS_LCNT_OPT_SUSPEND) return; if (!ERTS_LCNT_LOCK_TYPE(lock)) return; - ethr_atomic_dec( &lock->w_state); + ethr_atomic_dec(&lock->w_state); } /* erts_lcnt_lock_post @@ -491,7 +515,7 @@ void erts_lcnt_lock_post_x(erts_lcnt_lock_t *lock, char *file, unsigned int line if (!(lock->flag & (ERTS_LCNT_LT_RWMUTEX | ERTS_LCNT_LT_RWSPINLOCK))) { flowstate = ethr_atomic_read(&lock->flowstate); ASSERT(flowstate == 0); - ethr_atomic_inc( &lock->flowstate); + ethr_atomic_inc(&lock->flowstate); } #endif @@ -500,19 +524,12 @@ void erts_lcnt_lock_post_x(erts_lcnt_lock_t *lock, char *file, unsigned int line ASSERT(eltd); /* if lock was in conflict, time it */ - - if (erts_lcnt_rt_options & ERTS_LCNT_OPT_LOCATION) { - stats = lcnt_get_lock_stats(lock, file, line); - } else { - stats = &lock->stats[0]; - } - + stats = lcnt_get_lock_stats(lock, file, line); if (eltd->timer_set) { lcnt_time(&timer); lcnt_time_diff(&time_wait, &timer, &(eltd->timer)); lcnt_update_stats(stats, eltd->lock_in_conflict, &time_wait); - eltd->timer_set--; ASSERT(eltd->timer_set >= 0); } else { @@ -541,11 +558,11 @@ void erts_lcnt_unlock(erts_lcnt_lock_t *lock) { /* flowstate */ flowstate = ethr_atomic_read(&lock->flowstate); ASSERT(flowstate == 1); - ethr_atomic_dec( &lock->flowstate); + ethr_atomic_dec(&lock->flowstate); /* write state */ w_state = ethr_atomic_read(&lock->w_state); - ASSERT(w_state > 0) + ASSERT(w_state > 0); #endif ethr_atomic_dec(&lock->w_state); } @@ -582,9 +599,7 @@ void erts_lcnt_trylock(erts_lcnt_lock_t *lock, int res) { ethr_atomic_inc( &lock->flowstate); #endif ethr_atomic_inc(&lock->w_state); - lcnt_update_stats(&(lock->stats[0]), 0, NULL); - } else { ethr_atomic_inc(&lock->stats[0].tries); ethr_atomic_inc(&lock->stats[0].colls); diff --git a/erts/emulator/beam/erl_lock_count.h b/erts/emulator/beam/erl_lock_count.h index 75f7cd028b..ffbb93da1b 100644 --- a/erts/emulator/beam/erl_lock_count.h +++ b/erts/emulator/beam/erl_lock_count.h @@ -35,6 +35,10 @@ * | | | - collisions (including trylock busy) * | | | - timer (time spent in waiting for lock) * | | | - n_timer (collisions excluding trylock busy) + * | | | - histogram + * | | | | - # 0 = log2(lock wait_time ns) + * | | | | - ... + * | | | | - # n = log2(lock wait_time ns) * * Each instance of a lock is the unique lock, i.e. set and id in that set. * For each lock there is a set of statistics with where and what impact @@ -68,8 +72,17 @@ #include "ethread.h" +#define ERTS_LCNT_MAX_LOCK_LOCATIONS (10) -#define ERTS_LCNT_MAX_LOCK_LOCATIONS (10) +/* histogram */ +#define ERTS_LCNT_HISTOGRAM_MAX_NS (((unsigned long)1LL << 28) - 1) +#if 0 || defined(HAVE_GETHRTIME) +#define ERTS_LCNT_HISTOGRAM_SLOT_SIZE (30) +#define ERTS_LCNT_HISTOGRAM_RSHIFT (0) +#else +#define ERTS_LCNT_HISTOGRAM_SLOT_SIZE (20) +#define ERTS_LCNT_HISTOGRAM_RSHIFT (10) +#endif #define ERTS_LCNT_LT_SPINLOCK (((Uint16) 1) << 0) #define ERTS_LCNT_LT_RWSPINLOCK (((Uint16) 1) << 1) @@ -104,6 +117,10 @@ typedef struct { extern erts_lcnt_time_t timer_start; +typedef struct { + Uint32 ns[ERTS_LCNT_HISTOGRAM_SLOT_SIZE]; /* log2 array of nano seconds occurences */ +} erts_lcnt_hist_t; + typedef struct erts_lcnt_lock_stats_s { /* "tries" and "colls" needs to be atomic since * trylock busy does not aquire a lock and there @@ -118,6 +135,7 @@ typedef struct erts_lcnt_lock_stats_s { unsigned long timer_n; /* #times waited for lock */ erts_lcnt_time_t timer; /* total wait time for lock */ + erts_lcnt_hist_t hist; } erts_lcnt_lock_stats_t; /* rw locks uses both states, other locks only uses w_state */ diff --git a/erts/emulator/beam/io.c b/erts/emulator/beam/io.c index edf4a28784..d028737664 100644 --- a/erts/emulator/beam/io.c +++ b/erts/emulator/beam/io.c @@ -6129,7 +6129,7 @@ driver_pdl_create(ErlDrvPort dp) return NULL; pdl = erts_alloc(ERTS_ALC_T_PORT_DATA_LOCK, sizeof(struct erl_drv_port_data_lock)); - erts_mtx_init(&pdl->mtx, "port_data_lock"); + erts_mtx_init_x(&pdl->mtx, "port_data_lock", pp->common.id, 1); pdl_init_refc(pdl); erts_port_inc_refc(pp); pdl->prt = pp; -- cgit v1.2.3