4 files changed, 125 insertions, 0 deletions

diff --git a/src/util/support/ChangeLog b/src/util/support/ChangeLog
index 2c2a3252d..a49aa78cb 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 e17b46a6e..61188db4e 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 5e8208306..9a415acf7 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 7b061fdd7..c78751bd0 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