erts: Add histogram to lcnt

1 files changed, 82 insertions, 67 deletions

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);