From 16f278f40c94de0c8e7be80ac665e8126d7ba793 Mon Sep 17 00:00:00 2001 From: Ken Raeburn Date: Mon, 6 Dec 2004 22:00:26 +0000 Subject: [PATCH] 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 --- src/include/ChangeLog | 24 ++++++ src/include/k5-thread.h | 50 ++++++++--- src/util/support/ChangeLog | 12 +++ src/util/support/Makefile.in | 1 + src/util/support/libkrb5support.exports | 3 + src/util/support/threads.c | 109 ++++++++++++++++++++++++ 6 files changed, 189 insertions(+), 10 deletions(-) diff --git a/src/include/ChangeLog b/src/include/ChangeLog index 4646329bd..b4d1f4bbf 100644 --- a/src/include/ChangeLog +++ b/src/include/ChangeLog @@ -1,3 +1,27 @@ +2004-12-06 Ken Raeburn + + * 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 * win-mac.h (HAVE_GETADDRINFO, HAVE_GETNAMEINFO): Define. diff --git a/src/include/k5-thread.h b/src/include/k5-thread.h index 5fecf0827..88b6bf3b9 100644 --- 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 #endif +/* for memset */ +#include +/* for uint64_t */ #include -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 2c2a3252d..a49aa78cb 100644 --- a/src/util/support/ChangeLog +++ b/src/util/support/ChangeLog @@ -1,3 +1,15 @@ +2004-12-06 Ken Raeburn + + * 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 * 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 +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 +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 -- 2.26.2