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

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;