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

diff --git a/src/include/ChangeLog b/src/include/ChangeLog
index 4646329bd2700004f8dd88fc74258dc567cc0de1..b4d1f4bbff41278ce8679dfd8b950e48431c3e4f 100644 (file)
--- a/src/include/ChangeLog
+++ b/src/include/ChangeLog
@@ -1,3 +1,27 @@
+2004-12-06  Ken Raeburn  <raeburn@mit.edu>
+
+       * 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.
+
 2004-11-19  Ken Raeburn  <raeburn@mit.edu>
 
        * win-mac.h (HAVE_GETADDRINFO, HAVE_GETNAMEINFO): Define.

diff --git a/src/include/k5-thread.h b/src/include/k5-thread.h
index 5fecf082757f5cbe858a920dc3e733eb117e1ec0..88b6bf3b9a8de1a31caf6b3a2f721c80db2f49c3 100644 (file)
--- a/src/include/k5-thread.h
+++ b/src/include/k5-thread.h
@@ -193,14 +193,23 @@ typedef char k5_debug_loc;
 #ifdef HAVE_STDINT_H
 # include <stdint.h>
 #endif
+/* for memset */
+#include <string.h>
+/* for uint64_t */
 #include <inttypes.h>
-typedef uint64_t k5_debug_timediff_t;
+typedef uint64_t k5_debug_timediff_t; /* or long double */
 typedef struct timeval k5_debug_time_t;
 static inline k5_debug_timediff_t
 timediff(k5_debug_time_t t2, k5_debug_time_t t1)
 {
     return (t2.tv_sec - t1.tv_sec) * 1000000 + (t2.tv_usec - t1.tv_usec);
 }
+static inline k5_debug_time_t get_current_time(void)
+{
+    struct timeval tv;
+    if (gettimeofday(&tv,0) < 0) { tv.tv_sec = tv.tv_usec = 0; }
+    return tv;
+}
 struct k5_timediff_stats {
     k5_debug_timediff_t valmin, valmax, valsum, valsqsum;
 };
@@ -209,10 +218,20 @@ typedef struct {
     k5_debug_time_t time_acquired, time_created;
     struct k5_timediff_stats lockwait, lockheld;
 } k5_debug_mutex_stats;
-#define k5_mutex_init_stats(S) \
-       (memset((S), 0, sizeof(struct k5_debug_mutex_stats)), 0)
+#define k5_mutex_init_stats(S)                                 \
+       (memset((S), 0, sizeof(k5_debug_mutex_stats)),  \
+        (S)->time_created = get_current_time(),                \
+        0)
 #define k5_mutex_finish_init_stats(S)  (0)
 #define K5_MUTEX_STATS_INIT    { 0, {0}, {0}, {0}, {0} }
+typedef k5_debug_time_t k5_mutex_stats_tmp;
+#define k5_mutex_stats_start() get_current_time()
+extern void krb5int_mutex_lock_update_stats(k5_debug_mutex_stats *m,
+                                           k5_mutex_stats_tmp startwait);
+extern void krb5int_mutex_unlock_update_stats(k5_debug_mutex_stats *m);
+#define k5_mutex_lock_update_stats     krb5int_mutex_lock_update_stats
+#define k5_mutex_unlock_update_stats   krb5int_mutex_unlock_update_stats
+extern void krb5int_mutex_report_stats();
 
 #else
 
@@ -220,6 +239,11 @@ typedef char k5_debug_mutex_stats;
 #define k5_mutex_init_stats(S)         (*(S) = 's', 0)
 #define k5_mutex_finish_init_stats(S)  (0)
 #define K5_MUTEX_STATS_INIT            's'
+typedef int k5_mutex_stats_tmp;
+#define k5_mutex_stats_start()         (0)
+#define k5_mutex_lock_update_stats(M,S)        (S)
+#define k5_mutex_unlock_update_stats(M)        (*(M) = 's')
+#define krb5int_mutex_report_stats(M)  ((M)->stats = 'd')
 
 #endif
 
@@ -614,25 +638,30 @@ static inline int k5_mutex_finish_init_1(k5_mutex_t *m, k5_debug_loc l)
 #define k5_mutex_finish_init(M)        k5_mutex_finish_init_1((M), K5_DEBUG_LOC)
 #define k5_mutex_destroy(M)                    \
        (k5_os_mutex_assert_unlocked(&(M)->os), \
+        krb5int_mutex_report_stats(M),         \
         (M)->loc_last = K5_DEBUG_LOC,          \
         k5_os_mutex_destroy(&(M)->os))
 #ifdef __GNUC__
-#define k5_mutex_lock(M)                               \
-       __extension__ ({                                \
-           int _err = 0;                               \
-           k5_mutex_t *_m = (M);                       \
-           _err = k5_os_mutex_lock(&_m->os);           \
-           if (_err == 0) _m->loc_last = K5_DEBUG_LOC; \
-           _err;                                       \
+#define k5_mutex_lock(M)                                                \
+       __extension__ ({                                                 \
+           int _err = 0;                                                \
+           k5_mutex_stats_tmp _stats = k5_mutex_stats_start();          \
+           k5_mutex_t *_m = (M);                                        \
+           _err = k5_os_mutex_lock(&_m->os);                            \
+           if (_err == 0) _m->loc_last = K5_DEBUG_LOC;                  \
+           if (_err == 0) k5_mutex_lock_update_stats(&_m->stats, _stats); \
+           _err;                                                        \
        })
 #else
 static inline int k5_mutex_lock_1(k5_mutex_t *m, k5_debug_loc l)
 {
     int err = 0;
+    k5_mutex_stats_tmp stats = k5_mutex_stats_start();
     err = k5_os_mutex_lock(&m->os);
     if (err)
        return err;
     m->loc_last = l;
+    k5_mutex_lock_update_stats(&m->stats, stats);
     return err;
 }
 #define k5_mutex_lock(M)       k5_mutex_lock_1(M, K5_DEBUG_LOC)
@@ -640,6 +669,7 @@ static inline int k5_mutex_lock_1(k5_mutex_t *m, k5_debug_loc l)
 static inline int k5_mutex_unlock_1(k5_mutex_t *m, k5_debug_loc l)
 {
     int err = 0;
+    k5_mutex_unlock_update_stats(&m->stats);
     err = k5_os_mutex_unlock(&m->os);
     if (err)
        return err;

diff --git a/src/util/support/ChangeLog b/src/util/support/ChangeLog
index 2c2a3252da27b490884f06b8887fb0adfc0566ec..a49aa78cb398b6bd22b879d30c740c8185a3f1e5 100644 (file)
--- 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 e17b46a6e6340af54af0d10a1bdfa430316eb720..61188db4e6d2208dcbbf53f2c9de25bdb2159ddf 100644 (file)
--- 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 5e8208306d33f5fc7ce91881526a41c114180c71..9a415acf7e43e1c69645ad3829ef0c4f9fe45cb5 100644 (file)
--- 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 7b061fdd74d48bcb1efa4d60ac54753966084427..c78751bd089f70d9f69654ab0d21defe4d8432be 100644 (file)
--- 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