From 16f278f40c94de0c8e7be80ac665e8126d7ba793 Mon Sep 17 00:00:00 2001 From: Ken Raeburn Date: Mon, 6 Dec 2004 22:00:26 +0000 Subject: 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 +++++++++++++++++++++++++++++++++++++++---------- 2 files changed, 64 insertions(+), 10 deletions(-) (limited to 'src/include') 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; -- cgit