Merge branch 'egil/lcnt-histogram/OTP-12059' into maint

7 files changed, 450 insertions, 281 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;
diff --git a/lib/tools/src/lcnt.erl b/lib/tools/src/lcnt.erl
index 20ee32c861..f1251fddab 100644
--- a/lib/tools/src/lcnt.erl
+++ b/lib/tools/src/lcnt.erl
@@ -61,6 +61,8 @@
 	locations/1,
 	inspect/1,
 	inspect/2,
+	histogram/1,
+	histogram/2,
 	information/0,
 	swap_pid_keys/0,
 	% set options
@@ -89,14 +91,14 @@
 	duration   = 0
     }).
 
-
 -record(stats, {
-	file,
-	line,
-	tries,
-	colls,
-	time,	  % us
-	nt	  % #timings collected
+	file  :: atom(),
+	line  :: non_neg_integer(),
+	tries :: non_neg_integer(),
+	colls :: non_neg_integer(),
+	time  :: non_neg_integer(), % us
+	nt    :: non_neg_integer(), % #timings collected
+	hist  :: tuple()            % histogram
     }).
 
 -record(lock, {
@@ -115,7 +117,9 @@
 	colls,
 	cr,     % collision ratio
 	time,
-	dtr     % time duration ratio
+	dtr,    % time duration ratio
+	%% new
+	hist    % log2 histogram of lock wait_time
     }).
 
 
@@ -127,7 +131,7 @@
 %% -------------------------------------------------------------------- %%
 
 start()  -> gen_server:start({local, ?MODULE}, ?MODULE, [], []).
-stop()   -> gen_server:cast(?MODULE, stop).
+stop()   -> gen_server:call(?MODULE, stop, infinity).
 init([]) -> {ok, #state{ locks = [], duration = 0 } }.
 
 %% -------------------------------------------------------------------- %%
@@ -171,6 +175,8 @@ conflicts()          -> call({conflicts, []}).
 conflicts(Opts)      -> call({conflicts, Opts}).
 inspect(Lock)        -> call({inspect, Lock, []}).
 inspect(Lock, Opts)  -> call({inspect, Lock, Opts}).
+histogram(Lock)      -> call({histogram, Lock, []}).
+histogram(Lock, Opts)-> call({histogram, Lock, Opts}).
 information()        -> call(information).
 swap_pid_keys()      -> call(swap_pid_keys).
 raw()                -> call(raw).
@@ -283,14 +289,14 @@ handle_call({locations, InOpts}, _From, #state{ locks = Locks } = State) when is
 
     {reply, ok, State};
 
-handle_call({inspect, Lockname, InOpts}, _From, #state{ duration = Duration, locks = Locks } = State) when is_list(InOpts) ->
+handle_call({inspect, Lockname, InOpts}, _From, #state{ duration=Duration, locks=Locks } = State) when is_list(InOpts) ->
     Default = [
 	{sort,       time},
 	{reverse,    false},
-	{print,      [name,id,tries,colls,ratio,time,duration]},
+	{print,      [name,id,tries,colls,ratio,time,duration,histogram]},
 	{max_locks,  20},
 	{combine,    false},
-	{thresholds, [] },
+	{thresholds, []},
 	{locations,  false}],
 
     Opts      = options(InOpts, Default),
@@ -299,7 +305,7 @@ handle_call({inspect, Lockname, InOpts}, _From, #state{ duration = Duration, loc
 	{true, true} -> locks_ids(Filtered);
 	_            -> []
     end,
-    Combos    =  combine_classes(Filtered, proplists:get_value(combine, Opts)),
+    Combos =  combine_classes(Filtered, proplists:get_value(combine, Opts)),
     case proplists:get_value(locations, Opts) of
 	true ->
 	    lists:foreach(fun
@@ -313,17 +319,14 @@ handle_call({inspect, Lockname, InOpts}, _From, #state{ duration = Duration, loc
 			    [] ->
 				ok;
 			    _  ->
-				%io:format("Combined ~p~n", [Combined]),
 				print("lock: " ++ term2string(Name)),
 				print("id:   " ++ IdString),
 				print("type: " ++ term2string(Type)),
 				Ps = stats2print(Combined, Duration),
-				Opts1 = options([{print, [entry, tries,colls,ratio,time,duration]},
+				Opts1 = options([{print, [entry, tries,colls,ratio,time,duration,histogram]},
 					{thresholds, [{tries, -1}, {colls, -1}, {time, -1}]}], Opts),
 				print_lock_information(filter_print(Ps, Opts1), proplists:get_value(print, Opts1))
 			end
-		   % (#lock{ name = Name, id = Id}) ->
-		%	io:format("Empty lock ~p ~p~n", [Name, Id])
 		end, Combos);
 	_ ->
 	    Print1 = locks2print(Combos, Duration),
@@ -332,6 +335,34 @@ handle_call({inspect, Lockname, InOpts}, _From, #state{ duration = Duration, loc
     end,
     {reply, ok, State};
 
+%% histogram
+
+handle_call({histogram, Lockname, InOpts}, _From, #state{ duration=Duration, locks=Locks} = State)->
+    Default = [
+	{sort,       time},
+	{reverse,    false},
+	{print,      [name,id,tries,colls,ratio,time,duration,histogram]},
+	{max_locks,  20},
+	{combine,    true},
+	{thresholds, []},
+	{locations,  false}],
+
+    Opts     = options(InOpts, Default),
+    Filtered = filter_locks(Locks, Lockname),
+    Combos   = combine_classes(Filtered, proplists:get_value(combine, Opts)),
+    lists:foreach(fun
+	    (#lock{ stats = Stats }=L) ->
+		SumStats = summate_stats(Stats),
+		Opts1 = options([{print, [name,id,tries,colls,ratio,time,duration]},
+			{thresholds, [{tries, -1}, {colls, -1}, {time, -1}]}], Opts),
+		Prints = locks2print([L], Duration),
+		print_lock_information(Prints, proplists:get_value(print, Opts1)),
+		print_full_histogram(SumStats#stats.hist),
+		io:format("~n")
+	end, Combos),
+
+    {reply, ok, State};
+
 handle_call(raw, _From, #state{ locks = Locks} = State)->
     {reply, Locks, State};
 
@@ -347,7 +378,6 @@ handle_call(swap_pid_keys, _From, #state{ locks = Locks } = State)->
 	(L) ->
 	    L
     end, Locks),
-
     {reply, ok, State#state{ locks = SwappedLocks}};
 
 % settings
@@ -380,6 +410,8 @@ handle_call({save, Filename}, _From, State) ->
 	    {reply, {error, Error}, State}
     end;
 
+handle_call(stop, _From, State) ->
+    {stop, normal, ok, State};
 
 handle_call(Command, _From, State) ->
     {reply, {error, {undefined, Command}}, State}.
@@ -390,8 +422,6 @@ handle_call(Command, _From, State) ->
 %%
 %% -------------------------------------------------------------------- %%
 
-handle_cast(stop, State) ->
-    {stop, normal, State};
 handle_cast(_, State) ->
     {noreply, State}.
 
@@ -432,15 +462,32 @@ code_change(_OldVsn, State, _Extra) ->
 
 summate_locks(Locks) -> summate_locks(Locks, #stats{ tries = 0, colls = 0, time = 0, nt = 0}).
 summate_locks([], Stats) -> Stats;
-summate_locks([L|Ls], #stats{ tries = Tries, colls = Colls, time = Time, nt = Nt}) ->
+summate_locks([L|Ls], #stats{ tries = Tries, colls = Colls, time = Time, nt = Nt, hist = Hist}) ->
     S = summate_stats(L#lock.stats),
-    summate_locks(Ls, #stats{ tries = Tries + S#stats.tries, colls = Colls + S#stats.colls, time = Time + S#stats.time, nt = Nt + S#stats.nt}).
+    summate_locks(Ls, #stats{
+	    tries = Tries + S#stats.tries,
+	    colls = Colls + S#stats.colls,
+	    time  = Time + S#stats.time,
+	    nt    = Nt + S#stats.nt,
+	    hist  = summate_histogram(Hist, S#stats.hist)
+	}).
 
 summate_stats(Stats) -> summate_stats(Stats, #stats{ tries = 0, colls = 0, time = 0, nt = 0}).
 summate_stats([], Stats) -> Stats;
-summate_stats([S|Ss], #stats{ tries = Tries, colls = Colls, time = Time, nt = Nt}) ->
-    summate_stats(Ss, #stats{ tries = Tries + S#stats.tries, colls = Colls + S#stats.colls, time = Time + S#stats.time, nt = Nt + S#stats.nt}).
-
+summate_stats([S|Ss], #stats{ tries = Tries, colls = Colls, time = Time, nt = Nt, hist = Hist}) ->
+    summate_stats(Ss, #stats{
+	    tries = Tries + S#stats.tries,
+	    colls = Colls + S#stats.colls,
+	    time  = Time + S#stats.time,
+	    nt    = Nt + S#stats.nt,
+	    hist  = summate_histogram(Hist, S#stats.hist)
+	}).
+
+%% first call is undefined
+summate_histogram(Tup,undefined) when is_tuple(Tup) -> Tup;
+summate_histogram(undefined,Tup) when is_tuple(Tup) -> Tup;
+summate_histogram(Hs1,Hs2) ->
+    list_to_tuple([ A + B || {A,B} <- lists:zip(tuple_to_list(Hs1),tuple_to_list(Hs2))]).
 
 %% manipulators
 filter_locks_type(Locks, undefined) -> Locks;
@@ -465,17 +512,16 @@ filter_print(PLs, Opts) ->
     TLs = threshold_locks(PLs, proplists:get_value(thresholds, Opts, [])),
     SLs =      sort_locks(TLs, proplists:get_value(sort,       Opts, time)),
     CLs =       cut_locks(SLs, proplists:get_value(max_locks,  Opts, none)),
-	    reverse_locks(CLs, proplists:get_value(reverse,    Opts, false)).
-
-sort_locks(Locks, Type)   -> lists:reverse(sort_locks0(Locks, Type)).
-sort_locks0(Locks, name)  -> lists:keysort(#print.name, Locks);
-sort_locks0(Locks, id)    -> lists:keysort(#print.id, Locks);
-sort_locks0(Locks, type)  -> lists:keysort(#print.type, Locks);
-sort_locks0(Locks, tries) -> lists:keysort(#print.tries, Locks);
-sort_locks0(Locks, colls) -> lists:keysort(#print.colls, Locks);
-sort_locks0(Locks, ratio) -> lists:keysort(#print.cr, Locks);
-sort_locks0(Locks, time)  -> lists:keysort(#print.time, Locks);
-sort_locks0(Locks, _)     -> sort_locks0(Locks, time).
+	    reverse_locks(CLs, not proplists:get_value(reverse,Opts, false)).
+
+sort_locks(Locks, name)  -> lists:keysort(#print.name, Locks);
+sort_locks(Locks, id)    -> lists:keysort(#print.id, Locks);
+sort_locks(Locks, type)  -> lists:keysort(#print.type, Locks);
+sort_locks(Locks, tries) -> lists:keysort(#print.tries, Locks);
+sort_locks(Locks, colls) -> lists:keysort(#print.colls, Locks);
+sort_locks(Locks, ratio) -> lists:keysort(#print.cr, Locks);
+sort_locks(Locks, time)  -> lists:keysort(#print.time, Locks);
+sort_locks(Locks, _)     -> sort_locks(Locks, time).
 
 % cut locks not above certain thresholds
 threshold_locks(Locks, Thresholds) ->
@@ -556,45 +602,61 @@ locks_ids(Locks) -> locks_ids(Locks, []).
 locks_ids([], Out) -> Out;
 locks_ids([#lock{ name = Key } = L|Ls], Out) ->
     case proplists:get_value(Key, Out) of
-	undefined ->
-	    locks_ids(Ls, [{Key, [L#lock.id] } | Out]);
-	Ids ->
-	    locks_ids(Ls, [{Key, [L#lock.id | Ids] } | proplists:delete(Key,Out)])
+	undefined -> locks_ids(Ls, [{Key, [L#lock.id]}|Out]);
+	Ids ->       locks_ids(Ls, [{Key, [L#lock.id|Ids]}|proplists:delete(Key,Out)])
     end.
 
 stats2print(Stats, Duration) ->
     lists:map(fun
 	(S) ->
-	    #print{
-		entry = term2string("~tp:~p", [S#stats.file, S#stats.line]),
-		colls = S#stats.colls,
-		tries = S#stats.tries,
-		cr    = percent(S#stats.colls, S#stats.tries),
-		time  = S#stats.time,
-		dtr   = percent(S#stats.time,  Duration)
-	    }
+	    #print{entry = term2string("~tp:~p", [S#stats.file, S#stats.line]),
+		   colls = S#stats.colls,
+		   tries = S#stats.tries,
+		   cr    = percent(S#stats.colls, S#stats.tries),
+		   time  = S#stats.time,
+		   dtr   = percent(S#stats.time,  Duration),
+		   hist  = format_histogram(S#stats.hist)}
 	end, Stats).
 
 locks2print(Locks, Duration) ->
     lists:map( fun
 	(L) ->
-	    Tries = lists:sum([T || #stats{ tries = T} <- L#lock.stats]),
-	    Colls = lists:sum([C || #stats{ colls = C} <- L#lock.stats]),
-	    Time  = lists:sum([T || #stats{ time  = T} <- L#lock.stats]),
-	    Cr    = percent(Colls, Tries),
-	    Dtr   = percent(Time,  Duration),
-	    #print{
-		name  = L#lock.name,
-		id    = L#lock.id,
-		type  = L#lock.type,
-		tries = Tries,
-		colls = Colls,
-		cr    = Cr,
-		time  = Time,
-		dtr   = Dtr
-	    }
+	    #stats{tries = Tries,
+		   colls = Colls,
+		   time  = Time,
+		   hist  = Hist} = summate_stats(L#lock.stats),
+	    Cr  = percent(Colls, Tries),
+	    Dtr = percent(Time,  Duration),
+	    #print{name  = L#lock.name,
+		   id    = L#lock.id,
+		   type  = L#lock.type,
+		   tries = Tries,
+		   colls = Colls,
+		   hist  = format_histogram(Hist),
+		   cr    = Cr,
+		   time  = Time,
+		   dtr   = Dtr}
 	end, Locks).
 
+
+format_histogram(Tup) when is_tuple(Tup) ->
+    Vs   = tuple_to_list(Tup),
+    Max  = lists:max(Vs),
+    case Max of
+	0 -> string_histogram(Vs);
+	_ -> string_histogram([case V of 0 -> 0; _ -> V/Max end || V <- Vs])
+    end.
+
+string_histogram([0|Vs]) ->
+    [$\s|string_histogram(Vs)];
+string_histogram([V|Vs]) when V > 0.66 ->
+    [$X|string_histogram(Vs)];
+string_histogram([V|Vs]) when V > 0.33 ->
+    [$x|string_histogram(Vs)];
+string_histogram([_|Vs]) ->
+    [$.|string_histogram(Vs)];
+string_histogram([]) -> [].
+
 %% state making
 
 data2state(Data, State) ->
@@ -606,22 +668,32 @@ data2state(Data, State) ->
 	locks    = Locks
     }.
 
-locks2records(Locks) -> locks2records(Locks, []).
-locks2records([], Out) -> Out;
-locks2records([{Name, Id, Type, Stats}|Locks], Out) ->
-    Lock = #lock{
-	    name  = Name,
-	    id    = clean_id_creation(Id),
-	    type  = Type,
-	    stats = [ #stats{
-		file  = File,
-		line  = Line,
-		tries = Tries,
-		colls = Colls,
-		time  = time2us({S, Ns}),
-		nt    = N
-	    } || {{File, Line}, {Tries, Colls, {S, Ns, N}}} <- Stats] },
-    locks2records(Locks, [Lock|Out]).
+locks2records([{Name, Id, Type, Stats}|Locks]) ->
+    [#lock{name  = Name,
+	   id    = clean_id_creation(Id),
+	   type  = Type,
+	   stats = stats2record(Stats)}|locks2records(Locks)];
+locks2records([]) -> [].
+
+%% new stats with histogram
+stats2record([{{File,Line},{Tries,Colls,{S,Ns,N}},Hist}|Stats]) ->
+    [#stats{file  = File,
+	    line  = Line,
+	    hist  = Hist,
+	    tries = Tries,
+	    colls = Colls,
+	    time  = time2us({S, Ns}),
+	    nt    = N} | stats2record(Stats)];
+%% old stats without histogram
+stats2record([{{File,Line},{Tries,Colls,{S,Ns,N}}}|Stats]) ->
+    [#stats{file  = File,
+	    line  = Line,
+	    hist  = {},
+	    tries = Tries,
+	    colls = Colls,
+	    time  = time2us({S, Ns}),
+	    nt    = N} | stats2record(Stats)];
+stats2record([]) -> [].
 
 clean_id_creation(Id) when is_pid(Id) ->
     Bin = term_to_binary(Id),
@@ -647,22 +719,45 @@ state2list(State) ->
 	(X, Y) -> {X,Y}
     end, record_info(fields, state), Values).
 
-list2state(List) -> list2state(record_info(fields, state), List, [state]).
-list2state([], _, Out) -> list_to_tuple(lists:reverse(Out));
-list2state([locks|Fs], List, Out) ->
-    Locks = [ list2lock(Lock) || Lock <- proplists:get_value(locks, List, [])],
-    list2state(Fs, List, [Locks|Out]);
-list2state([F|Fs], List, Out) -> list2state(Fs, List, [proplists:get_value(F, List, state_default(F))|Out]).
-
 lock_default(Field) -> proplists:get_value(Field, lock2list(#lock{})).
 
 lock2list(Lock) ->
     [_|Values] = tuple_to_list(Lock),
     lists:zip(record_info(fields, lock), Values).
 
-list2lock(List) -> list2lock(record_info(fields, lock), List, [lock]).
-list2lock([], _, Out) -> list_to_tuple(lists:reverse(Out));
-list2lock([F|Fs], List, Out) -> list2lock(Fs, List, [proplists:get_value(F, List, lock_default(F))|Out]).
+
+list2state(List) ->
+    list_to_tuple([state|list2state(record_info(fields, state), List)]).
+list2state([], _) -> [];
+list2state([locks|Fs], List) ->
+    Locks = [list2lock(Lock) || Lock <- proplists:get_value(locks, List, [])],
+    [Locks|list2state(Fs,List)];
+list2state([F|Fs], List) ->
+    [proplists:get_value(F, List, state_default(F))|list2state(Fs, List)].
+
+list2lock(Ls) ->
+    list_to_tuple([lock|list2lock(record_info(fields, lock), Ls)]).
+
+list2lock([],_) -> [];
+list2lock([stats=F|Fs], Ls) ->
+    Stats = stats2stats(proplists:get_value(F, Ls, lock_default(F))),
+    [Stats|list2lock(Fs, Ls)];
+list2lock([F|Fs], Ls) ->
+    [proplists:get_value(F, Ls, lock_default(F))|list2lock(Fs, Ls)].
+
+%% process old stats (hack)
+%% old stats had no histograms
+%% in future versions stats should be serialized as a list, not a record
+
+stats2stats([]) -> [];
+stats2stats([Stat|Stats]) ->
+    Sz = tuple_size(#stats{}),
+    [stat2stat(Stat,Sz)|stats2stats(Stats)].
+
+stat2stat(Stat,Sz) when tuple_size(Stat) =:= Sz -> Stat;
+stat2stat(Stat,_) ->
+    %% assume no histogram at the end
+    list_to_tuple(tuple_to_list(Stat) ++ [{0}]).
 
 %% printing
 
@@ -683,7 +778,7 @@ auto_print_width(Locks, Print) ->
 		    ({print,print}, Out) -> [print|Out];
 		    ({Str, Len}, Out)    -> [erlang:min(erlang:max(length(s(Str))+1,Len),80)|Out]
 		end, [], lists:zip(tuple_to_list(L), tuple_to_list(Max)))))
-	end, #print{ id = 4, type = 5, entry = 5, name = 6, tries = 8, colls = 13, cr = 16, time = 11, dtr = 14 },
+	end, #print{ id = 4, type = 5, entry = 5, name = 6, tries = 8, colls = 13, cr = 16, time = 11, dtr = 14, hist=20 },
 	Locks),
     % Setup the offsets for later pruning
     Offsets = [
@@ -695,7 +790,9 @@ auto_print_width(Locks, Print) ->
 	{colls, R#print.colls},
 	{ratio, R#print.cr},
 	{time, R#print.time},
-	{duration, R#print.dtr}],
+	{duration, R#print.dtr},
+	{histogram, R#print.hist}
+    ],
     % Prune offsets to only allow specified print options
     lists:foldr(fun
 	    ({Type, W}, Out) -> [{Type, W}|Out];
@@ -705,9 +802,7 @@ auto_print_width(Locks, Print) ->
 print_lock_information(Locks, Print) ->
     % remake Print to autosize entries
     AutoPrint = auto_print_width(Locks, Print),
-
     print_header(AutoPrint),
-
     lists:foreach(fun
 	(L) ->
 	    print_lock(L, AutoPrint)
@@ -724,7 +819,8 @@ print_header(Opts) ->
 	colls = "#collisions",
 	cr    = "collisions [%]",
 	time  = "time [us]",
-	dtr   = "duration [%]"
+	dtr   = "duration [%]",
+	hist  = "histogram"
     },
     Divider = #print{
 	name  = lists:duplicate(1 + length(Header#print.name),  45),
@@ -735,39 +831,44 @@ print_header(Opts) ->
 	colls = lists:duplicate(1 + length(Header#print.colls), 45),
 	cr    = lists:duplicate(1 + length(Header#print.cr),    45),
 	time  = lists:duplicate(1 + length(Header#print.time),  45),
-	dtr   = lists:duplicate(1 + length(Header#print.dtr),   45)
+	dtr   = lists:duplicate(1 + length(Header#print.dtr),   45),
+	hist  = lists:duplicate(1 + length(Header#print.hist),  45)
     },
     print_lock(Header, Opts),
     print_lock(Divider, Opts),
     ok.
 
 
-print_lock(L, Opts) -> print_lock(L, Opts, []).
-print_lock(_, [],  Formats) -> print(strings(lists:reverse(Formats)));
-print_lock(L, [Opt|Opts], Formats) ->
+print_lock(L, Opts) ->
+    print(strings(format_lock(L, Opts))).
+
+format_lock(_, []) -> [];
+format_lock(L, [Opt|Opts]) ->
     case Opt of
-	id            -> print_lock(L, Opts, [{space, 25, s(L#print.id)   } | Formats]);
-	{id, W}       -> print_lock(L, Opts, [{space,  W, s(L#print.id)   } | Formats]);
-	type          -> print_lock(L, Opts, [{space, 18, s(L#print.type) } | Formats]);
-	{type, W}     -> print_lock(L, Opts, [{space,  W, s(L#print.type) } | Formats]);
-	entry         -> print_lock(L, Opts, [{space, 30, s(L#print.entry)} | Formats]);
-	{entry, W}    -> print_lock(L, Opts, [{space,  W, s(L#print.entry)} | Formats]);
-	name          -> print_lock(L, Opts, [{space, 22, s(L#print.name) } | Formats]);
-	{name, W}     -> print_lock(L, Opts, [{space,  W, s(L#print.name) } | Formats]);
-	tries         -> print_lock(L, Opts, [{space, 12, s(L#print.tries)} | Formats]);
-	{tries, W}    -> print_lock(L, Opts, [{space,  W, s(L#print.tries)} | Formats]);
-	colls         -> print_lock(L, Opts, [{space, 14, s(L#print.colls)} | Formats]);
-	{colls, W}    -> print_lock(L, Opts, [{space,  W, s(L#print.colls)} | Formats]);
-	ratio         -> print_lock(L, Opts, [{space, 20, s(L#print.cr)   } | Formats]);
-	{ratio, W}    -> print_lock(L, Opts, [{space,  W, s(L#print.cr)   } | Formats]);
-	time          -> print_lock(L, Opts, [{space, 15, s(L#print.time) } | Formats]);
-	{time, W}     -> print_lock(L, Opts, [{space,  W, s(L#print.time) } | Formats]);
-	duration      -> print_lock(L, Opts, [{space, 20, s(L#print.dtr)  } | Formats]);
-	{duration, W} -> print_lock(L, Opts, [{space,  W, s(L#print.dtr)  } | Formats]);
-	_             -> print_lock(L, Opts, Formats)
+	id             -> [{space, 25, s(L#print.id)   } | format_lock(L, Opts)];
+	{id, W}        -> [{space,  W, s(L#print.id)   } | format_lock(L, Opts)];
+	type           -> [{space, 18, s(L#print.type) } | format_lock(L, Opts)];
+	{type, W}      -> [{space,  W, s(L#print.type) } | format_lock(L, Opts)];
+	entry          -> [{space, 30, s(L#print.entry)} | format_lock(L, Opts)];
+	{entry, W}     -> [{space,  W, s(L#print.entry)} | format_lock(L, Opts)];
+	name           -> [{space, 22, s(L#print.name) } | format_lock(L, Opts)];
+	{name, W}      -> [{space,  W, s(L#print.name) } | format_lock(L, Opts)];
+	tries          -> [{space, 12, s(L#print.tries)} | format_lock(L, Opts)];
+	{tries, W}     -> [{space,  W, s(L#print.tries)} | format_lock(L, Opts)];
+	colls          -> [{space, 14, s(L#print.colls)} | format_lock(L, Opts)];
+	{colls, W}     -> [{space,  W, s(L#print.colls)} | format_lock(L, Opts)];
+	ratio          -> [{space, 20, s(L#print.cr)   } | format_lock(L, Opts)];
+	{ratio, W}     -> [{space,  W, s(L#print.cr)   } | format_lock(L, Opts)];
+	time           -> [{space, 15, s(L#print.time) } | format_lock(L, Opts)];
+	{time, W}      -> [{space,  W, s(L#print.time) } | format_lock(L, Opts)];
+	duration       -> [{space, 20, s(L#print.dtr)  } | format_lock(L, Opts)];
+	{duration, W}  -> [{space,  W, s(L#print.dtr)  } | format_lock(L, Opts)];
+	histogram      -> [{space,  0, s(L#print.hist) } | format_lock(L, Opts)];
+	{histogram, W} -> [{space,  W, s(L#print.hist) } | format_lock(L, Opts)];
+	_              ->                                  format_lock(L, Opts)
     end.
 
-print_state_information(#state{ locks = Locks} = State) ->
+print_state_information(#state{locks = Locks} = State) ->
     Stats = summate_locks(Locks),
     print("information:"),
     print(kv("#locks",          s(length(Locks)))),
@@ -779,9 +880,25 @@ print_state_information(#state{ locks = Locks} = State) ->
     print(kv("percent of duration", s(Stats#stats.time/State#state.duration*100) ++ " %")),
     ok.
 
+
+print_full_histogram(T) when is_tuple(T) ->
+    Vs = tuple_to_list(T),
+    Max = lists:max(Vs),
+    W = 60,
+    print_full_histogram(0,Vs,Max,W).
+
+print_full_histogram(_,[],_,_) -> ok;
+print_full_histogram(Ix,[V|Vs],0,W) ->
+    io:format("~2w = log2 : ~8w |~n", [Ix,V]),
+    print_full_histogram(Ix+1,Vs,0,W);
+print_full_histogram(Ix,[V|Vs],Max,W) ->
+    io:format("~2w = log2 : ~8w | ~s~n", [Ix,V,lists:duplicate(trunc(W*(V/Max)), $#)]),
+    print_full_histogram(Ix+1,Vs,Max,W).
+
+
 %% AUX
 
-time2us({S, Ns}) -> round(S*1000000 + Ns/1000).
+time2us({S, Ns}) -> S*1000000 + (Ns div 1000).
 
 percent(_,0) -> 0.0;
 percent(T,N) -> T/N*100.
@@ -808,7 +925,7 @@ s(T)                  -> term2string(T).
 
 strings(Strings) -> strings(Strings, []).
 strings([], Out) -> Out;
-strings([{space,  N,      S} | Ss], Out) -> strings(Ss, Out ++ term2string(term2string("~~~ps", [N]), [S]));
+strings([{space,  N,      S} | Ss], Out) -> strings(Ss, Out ++ term2string(term2string("~~~ws", [N]), [S]));
 strings([{format, Format, S} | Ss], Out) -> strings(Ss, Out ++ term2string(Format, [S]));
 strings([S|Ss], Out) -> strings(Ss, Out ++ term2string("~ts", [S])).
 
@@ -825,7 +942,7 @@ term2string(Term) when is_pid(Term) ->
 term2string(Term) -> term2string("~w", [Term]).
 term2string(Format, Terms) -> lists:flatten(io_lib:format(Format, Terms)).
 
-%%% AUD id binary
+%%% AUX id binary
 
 bytes16(Value) ->
     B0 =  Value band 255,
diff --git a/lib/tools/test/lcnt_SUITE.erl b/lib/tools/test/lcnt_SUITE.erl
index 1bee6021ab..010dffe138 100644
--- a/lib/tools/test/lcnt_SUITE.erl
+++ b/lib/tools/test/lcnt_SUITE.erl
@@ -27,11 +27,11 @@
 
 %% Test cases
 -export([
-	load_v1/1,
-	conflicts/1,
-	locations/1,
-	swap_keys/1
-	]).
+	t_load/1,
+	t_conflicts/1,
+	t_locations/1,
+	t_swap_keys/1
+    ]).
 
 %% Default timetrap timeout (set in init_per_testcase)
 -define(default_timeout, ?t:minutes(4)).
@@ -54,48 +54,52 @@ end_per_testcase(_Case, Config) ->
 
 suite() -> [{ct_hooks,[ts_install_cth]}].
 
-all() -> 
-    [load_v1, conflicts, locations, swap_keys].
+all() -> [t_load, t_conflicts, t_locations, t_swap_keys].
 
-groups() -> 
-    [].
+groups() -> [].
 
-init_per_group(_GroupName, Config) ->
-    Config.
+init_per_group(_GroupName, Config) -> Config.
 
-end_per_group(_GroupName, Config) ->
-    Config.
+end_per_group(_GroupName, Config) -> Config.
 
 
 %%----------------------------------------------------------------------
 %% Tests
 %%----------------------------------------------------------------------
 
-load_v1(suite) ->
-    [];
-load_v1(doc) ->
-    ["Load data from file."];
-load_v1(Config) when is_list(Config) ->
-    ?line {ok, _} = lcnt:start(),
-    ?line Path = ?config(data_dir, Config),
-    ?line File = filename:join([Path,"big_bang_40.lcnt"]),
-    ?line ok = lcnt:load(File),
-    ?line ok = lcnt:stop(),
+t_load(suite) -> [];
+t_load(doc) -> ["Load data from file."];
+t_load(Config) when is_list(Config) ->
+    Path = ?config(data_dir, Config),
+    Files = [filename:join([Path,"big_bang_40.lcnt"]),
+	     filename:join([Path,"ehb_3_3_hist.lcnt"])],
+    ok = t_load_file(Files),
     ok.
 
-conflicts(suite) ->
-    [];
-conflicts(doc) ->
-    ["API: conflicts"];
-conflicts(Config) when is_list(Config) ->
-    ?line {ok, _} = lcnt:start(),
-    ?line Path = ?config(data_dir, Config),
-    ?line File = filename:join([Path,"big_bang_40.lcnt"]),
-    ?line ok = lcnt:load(File),
-    ?line ok = lcnt:conflicts(),
-    THs      = [-1, 0, 100, 1000],
-    Print    = [name , id , type , entry , tries , colls , ratio , time , duration],
-    Opts     = [
+t_load_file([]) -> ok;
+t_load_file([File|Files]) ->
+    {ok, _} = lcnt:start(),
+    ok = lcnt:load(File),
+    ok = lcnt:stop(),
+    t_load_file(Files).
+
+t_conflicts(suite) -> [];
+t_conflicts(doc) -> ["API: conflicts"];
+t_conflicts(Config) when is_list(Config) ->
+    Path = ?config(data_dir, Config),
+    Files = [filename:join([Path,"big_bang_40.lcnt"]),
+	     filename:join([Path,"ehb_3_3_hist.lcnt"])],
+    ok = t_conflicts_file(Files),
+    ok.
+
+t_conflicts_file([]) -> ok;
+t_conflicts_file([File|Files]) ->
+    {ok, _} = lcnt:start(),
+    ok = lcnt:load(File),
+    ok = lcnt:conflicts(),
+    THs   = [-1, 0, 100, 1000],
+    Print = [name , id , type , entry , tries , colls , ratio , time , duration],
+    Opts  = [
 	[{sort, Sort}, {reverse, Rev}, {max_locks, ML}, {combine, Combine}, {thresholds, [TH]}, {print, [Print]}] ||
 	    Sort    <- [name , id , type , tries , colls , ratio , time , entry],
 	    ML      <- [none, 1 , 32,  4096],
@@ -103,28 +107,33 @@ conflicts(Config) when is_list(Config) ->
 	    TH      <- [{tries, Tries} || Tries <- THs] ++ [{colls, Colls} || Colls <- THs] ++ [{time, Time} || Time <- THs],
 	    Rev     <- [true, false]
 	],
-    ?line ok = test_conflicts_opts(Opts),
-    ?line ok = lcnt:stop(),
-    ok.
+    ok = test_conflicts_opts(Opts),
+    ok = lcnt:stop(),
+    t_conflicts_file(Files).
+
 
 test_conflicts_opts([]) -> ok;
 test_conflicts_opts([Opt|Opts]) ->
-    ?line ok = lcnt:conflicts(Opt),
+    ok = lcnt:conflicts(Opt),
     test_conflicts_opts(Opts).
 
-locations(suite) ->
-    [];
-locations(doc) ->
-    ["API: locations"];
-locations(Config) when is_list(Config) ->
-    ?line {ok, _} = lcnt:start(),
-    ?line Path = ?config(data_dir, Config),
-    ?line File = filename:join([Path,"big_bang_40.lcnt"]),
-    ?line ok = lcnt:load(File),
-    ?line ok = lcnt:locations(),
-    THs      = [-1, 0, 100, 1000],
-    Print    = [name , id , type , entry , tries , colls , ratio , time , duration],
-    Opts     = [
+t_locations(suite) -> [];
+t_locations(doc) -> ["API: locations"];
+t_locations(Config) when is_list(Config) ->
+    Path = ?config(data_dir, Config),
+    Files = [filename:join([Path,"big_bang_40.lcnt"]),
+	     filename:join([Path,"ehb_3_3_hist.lcnt"])],
+    ok = t_locations_file(Files),
+    ok.
+
+t_locations_file([]) -> ok;
+t_locations_file([File|Files]) ->
+    {ok, _} = lcnt:start(),
+    ok = lcnt:load(File),
+    ok = lcnt:locations(),
+    THs   = [-1, 0, 100, 1000],
+    Print = [name , id , type , entry , tries , colls , ratio , time , duration],
+    Opts  = [
 	[{full_id, Id}, {sort, Sort}, {max_locks, ML}, {combine, Combine}, {thresholds, [TH]}, {print, Print}] ||
 	    Sort    <- [name , id , type , tries , colls , ratio , time , entry],
 	    ML      <- [none, 1 , 64],
@@ -132,30 +141,34 @@ locations(Config) when is_list(Config) ->
 	    TH      <- [{tries, Tries} || Tries <- THs] ++ [{colls, Colls} || Colls <- THs] ++ [{time, Time} || Time <- THs],
 	    Id      <- [true, false]
 	],
-    ?line ok = test_locations_opts(Opts),
-    ?line ok = lcnt:stop(),
-    ok.
+    ok = test_locations_opts(Opts),
+    ok = lcnt:stop(),
+    t_locations_file(Files).
 
 test_locations_opts([]) -> ok;
 test_locations_opts([Opt|Opts]) ->
-    ?line ok = lcnt:locations(Opt),
+    ok = lcnt:locations(Opt),
     test_locations_opts(Opts).
 
-swap_keys(suite) ->
-    [];
-swap_keys(doc) ->
-    ["Test interchanging port/process id with class"];
-swap_keys(Config) when is_list(Config) ->
-    ?line {ok, _} = lcnt:start(),
-    ?line Path = ?config(data_dir, Config),
-    ?line File = filename:join([Path,"big_bang_40.lcnt"]),
-    ?line ok = lcnt:load(File),
-    ?line ok = lcnt:conflicts(),
-    ?line ok = lcnt:swap_pid_keys(),
-    ?line ok = lcnt:conflicts(),
-    ?line ok = lcnt:stop(),
+t_swap_keys(suite) -> [];
+t_swap_keys(doc) -> ["Test interchanging port/process id with class"];
+t_swap_keys(Config) when is_list(Config) ->
+    Path = ?config(data_dir, Config),
+    Files = [filename:join([Path,"big_bang_40.lcnt"]),
+	     filename:join([Path,"ehb_3_3_hist.lcnt"])],
+    ok = t_swap_keys_file(Files),
     ok.
 
+t_swap_keys_file([]) -> ok;
+t_swap_keys_file([File|Files]) ->
+    {ok, _} = lcnt:start(),
+    ok = lcnt:load(File),
+    ok = lcnt:conflicts(),
+    ok = lcnt:swap_pid_keys(),
+    ok = lcnt:conflicts(),
+    ok = lcnt:stop(),
+    t_swap_keys_file(Files).
+
 
 %%----------------------------------------------------------------------
 %% Auxiliary tests
diff --git a/lib/tools/test/lcnt_SUITE_data/ehb_3_3_hist.lcnt b/lib/tools/test/lcnt_SUITE_data/ehb_3_3_hist.lcnt
new file mode 100644
index 0000000000..ff5bdcbdaa
--- /dev/null
+++ b/lib/tools/test/lcnt_SUITE_data/ehb_3_3_hist.lcnt