hooks for recording statistics on locking behavior

Finish the hooks (left disabled by default) for logging somewhere the recorded
timing behavior relating to the use of locks in the krb5 code.

Currently, "reporting" means writing to /dev/tty or stderr, and the data is the
number of times a mutex is locked, file and line where it was created,
min/avg/max/stddev wait times to acquire the lock and hold times, and stats are
only written out for locks that were locked a certain minimum number of times
and with a minimum average wait time.

The criteria are all controlled in threads.c, and k5-thread.h just has the
hooks for gathering data.  So turning on/off the data gathering requires a full
rebuild, but tweaking the reporting is mostly just a relinking pass.  (May also
require adding a dependence on the math library to the support library; for a
static build that may impact a lot of makefiles.)

* include/k5-thread.h [DEBUG_THREADS_STATS]: Include string.h and inttypes.h.
(get_current_time) [DEBUG_THREADS_STATS]: Define as inline.
(k5_mutex_init_stats) [DEBUG_THREADS_STATS]: Save away current time as creation
time.
(k5_mutex_stats_tmp): New typedef, k5_debug_time_t if recording stats, dummy
int otherwise.
(k5_mutex_stats_start): New macro, get current time if recording, zero
otherwise.
(krb5int_mutex_lock_update_stats, krb5int_mutex_unlock_update_stats,
krb5int_mutex_report_stats) [DEBUG_THREADS_STATS]: Declare.
(krb5int_mutex_report_stats) [! DEBUG_THREADS_STATS]: New macro, does nothing.
(k5_mutex_lock_update_stats, k5_mutex_unlock_update_stats): New macros, map to
krb5int_ functions if recording, dummy statements otherwise.
(k5_mutex_destroy): Call krb5int_mutex_report_stats.
(k5_mutex_lock, k5_mutex_lock_1): Call k5_mutex_stats_start and
k5_mutex_lock_update_stats.
(k5_mutex_unlock_1): Call k5_mutex_unlock_update_stats.

* util/support/threads.c [DEBUG_THREADS_STATS]: Include stdio.h.
(stats_logfile) [DEBUG_THREADS_STATS]: New variable.
(krb5int_thread_support_init) [DEBUG_THREADS_STATS]: Set it to point to a file
on /dev/tty or stderr.
(krb5int_thread_support_fini) [DEBUG_THREADS_STATS]: Flush it.
(k5_mutex_lock_update_stats, krb5int_mutex_unlock_update_stats, get_stddev,
krb5int_mutex_report_stats) [DEBUG_THREADS_STATS]: New functions.
* util/support/libkrb5support.exports: Add krb5int_mutex_*_stats.

ticket: new

git-svn-id: svn://anonsvn.mit.edu/krb5/trunk@16913 dc483132-0cff-0310-8789-dd5450dbe970

4 files changed, 125 insertions, 0 deletions

diff --git a/src/util/support/ChangeLog b/src/util/support/ChangeLog
index 2c2a3252da..a49aa78cb3 100644
--- a/src/util/support/ChangeLog
+++ b/src/util/support/ChangeLog
@@ -1,3 +1,15 @@
+2004-12-06  Ken Raeburn  <raeburn@mit.edu>
+
+	* threads.c [DEBUG_THREADS_STATS]: Include stdio.h.
+	(stats_logfile) [DEBUG_THREADS_STATS]: New variable.
+	(krb5int_thread_support_init) [DEBUG_THREADS_STATS]: Set it to
+	point to a file on /dev/tty or stderr.
+	(krb5int_thread_support_fini) [DEBUG_THREADS_STATS]: Flush it.
+	(k5_mutex_lock_update_stats, krb5int_mutex_unlock_update_stats,
+	get_stddev, krb5int_mutex_report_stats) [DEBUG_THREADS_STATS]: New
+	functions.
+	* libkrb5support.exports: Add krb5int_mutex_*_stats.
+
 2004-11-19  Ken Raeburn  <raeburn@mit.edu>
 
 	* fake-addrinfo.c (HAVE_GETADDRINFO, HAVE_GETNAMEINFO)[_WIN32]:
diff --git a/src/util/support/Makefile.in b/src/util/support/Makefile.in
index e17b46a6e6..61188db4e6 100644
--- a/src/util/support/Makefile.in
+++ b/src/util/support/Makefile.in
@@ -43,6 +43,7 @@ SRCS=\
 	$(srcdir)/init-addrinfo.c \
 	$(srcdir)/fake-addrinfo.c
 SHLIB_EXPDEPS =
+# Add -lm if dumping thread stats, for sqrt.
 SHLIB_EXPLIBS= $(LIBS)
 SHLIB_DIRS=
 SHLIB_RDIRS=$(KRB5_LIBDIR)
diff --git a/src/util/support/libkrb5support.exports b/src/util/support/libkrb5support.exports
index 5e8208306d..9a415acf7e 100644
--- a/src/util/support/libkrb5support.exports
+++ b/src/util/support/libkrb5support.exports
@@ -2,6 +2,9 @@ krb5int_key_register
 krb5int_key_delete
 krb5int_getspecific
 krb5int_setspecific
+krb5int_mutex_lock_update_stats
+krb5int_mutex_unlock_update_stats
+krb5int_mutex_report_stats
 krb5int_getaddrinfo
 krb5int_freeaddrinfo
 krb5int_gai_strerror
diff --git a/src/util/support/threads.c b/src/util/support/threads.c
index 7b061fdd74..c78751bd08 100644
--- a/src/util/support/threads.c
+++ b/src/util/support/threads.c
@@ -324,10 +324,22 @@ int krb5int_call_thread_support_init (void)
 
 #include "cache-addrinfo.h"
 
+#ifdef DEBUG_THREADS_STATS
+#include <stdio.h>
+static FILE *stats_logfile;
+#endif
+
 int krb5int_thread_support_init (void)
 {
     int err;
 
+#ifdef DEBUG_THREADS_STATS
+    /*    stats_logfile = stderr; */
+    stats_logfile = fopen("/dev/tty", "w+");
+    if (stats_logfile == NULL)
+      stats_logfile = stderr;
+#endif
+
 #ifndef ENABLE_THREADS
 
     /* Nothing to do for TLS initialization.  */
@@ -384,6 +396,103 @@ void krb5int_thread_support_fini (void)
 
 #endif
 
+#ifdef DEBUG_THREADS_STATS
+    fflush(stats_logfile);
+    /* XXX Should close if not stderr, in case unloading library but
+       not exiting.  */
+#endif
+
     krb5int_fini_fac();
 }
 
+#ifdef DEBUG_THREADS_STATS
+void
+k5_mutex_lock_update_stats(k5_debug_mutex_stats *m,
+			   k5_mutex_stats_tmp startwait)
+{
+  k5_debug_time_t now;
+  k5_debug_timediff_t tdiff, tdiff2;
+
+  now = get_current_time();
+  (void) krb5int_call_thread_support_init();
+  m->count++;
+  m->time_acquired = now;
+  tdiff = timediff(now, startwait);
+  tdiff2 = tdiff * tdiff;
+  if (m->count == 1 || m->lockwait.valmin > tdiff)
+    m->lockwait.valmin = tdiff;
+  if (m->count == 1 || m->lockwait.valmax < tdiff)
+    m->lockwait.valmax = tdiff;
+  m->lockwait.valsum += tdiff;
+  m->lockwait.valsqsum += tdiff2;
+}
+
+void
+krb5int_mutex_unlock_update_stats(k5_debug_mutex_stats *m)
+{
+  k5_debug_time_t now = get_current_time();
+  k5_debug_timediff_t tdiff, tdiff2;
+  tdiff = timediff(now, m->time_acquired);
+  tdiff2 = tdiff * tdiff;
+  if (m->count == 1 || m->lockheld.valmin > tdiff)
+    m->lockheld.valmin = tdiff;
+  if (m->count == 1 || m->lockheld.valmax < tdiff)
+    m->lockheld.valmax = tdiff;
+  m->lockheld.valsum += tdiff;
+  m->lockheld.valsqsum += tdiff2;
+}
+
+#include <math.h>
+static inline double
+get_stddev(struct k5_timediff_stats sp, int count)
+{
+  long double mu, mu_squared, rho_squared;
+  mu = (long double) sp.valsum / count;
+  mu_squared = mu * mu;
+  /* SUM((x_i - mu)^2)
+     = SUM(x_i^2 - 2*mu*x_i + mu^2)
+     = SUM(x_i^2) - 2*mu*SUM(x_i) + N*mu^2
+
+     Standard deviation rho^2 = SUM(...) / N.  */
+  rho_squared = (sp.valsqsum - 2 * mu * sp.valsum + count * mu_squared) / count;
+  return sqrt(rho_squared);
+}
+
+void
+krb5int_mutex_report_stats(k5_mutex_t *m)
+{
+  char *p;
+
+  /* Tweak this to only record data on "interesting" locks.  */
+  if (m->stats.count < 10)
+    return;
+  if (m->stats.lockwait.valsum < 10 * m->stats.count)
+    return;
+
+  p = strrchr(m->loc_created.filename, '/');
+  if (p == NULL)
+    p = m->loc_created.filename;
+  else
+    p++;
+  fprintf(stats_logfile, "mutex @%p: created at line %d of %s\n",
+	  (void *) m, m->loc_created.lineno, p);
+  if (m->stats.count == 0)
+    fprintf(stats_logfile, "\tnever locked\n");
+  else {
+    double sd_wait, sd_hold;
+    sd_wait = get_stddev(m->stats.lockwait, m->stats.count);
+    sd_hold = get_stddev(m->stats.lockheld, m->stats.count);
+    fprintf(stats_logfile,
+	    "\tlocked %d time%s; wait %lu/%f/%lu/%fus, hold %lu/%f/%lu/%fus\n",
+	    m->stats.count, m->stats.count == 1 ? "" : "s",
+	    (unsigned long) m->stats.lockwait.valmin,
+	    (double) m->stats.lockwait.valsum / m->stats.count,
+	    (unsigned long) m->stats.lockwait.valmax,
+	    sd_wait,
+	    (unsigned long) m->stats.lockheld.valmin,
+	    (double) m->stats.lockheld.valsum / m->stats.count,
+	    (unsigned long) m->stats.lockheld.valmax,
+	    sd_hold);
+  }
+}
+#endif