From 2d5996ac603391ddbd618425f88eb13e5e0e2cc0 Mon Sep 17 00:00:00 2001 From: Howard Chu Date: Wed, 28 Oct 2015 14:22:58 +0000 Subject: [PATCH] ITS#8054 Cleanup duration patch Don't need op->o_hr_time, just use o_tincr, that's what it was intended for anyway. Use "etime=" like other products do. Simplify ifdefs. Use gettimeofday, it's always available now. --- servers/slapd/operation.c | 35 ++++++---- servers/slapd/result.c | 140 +++++++++----------------------------- servers/slapd/slap.h | 7 +- 3 files changed, 59 insertions(+), 123 deletions(-) diff --git a/servers/slapd/operation.c b/servers/slapd/operation.c index fe025a154e..eeb3125600 100644 --- a/servers/slapd/operation.c +++ b/servers/slapd/operation.c @@ -38,8 +38,7 @@ #endif static ldap_pvt_thread_mutex_t slap_op_mutex; -static time_t last_time; -static int last_incr; +static struct timeval last_time; void slap_op_init(void) { @@ -159,16 +158,31 @@ slap_op_free( Operation *op, void *ctx ) void slap_op_time(time_t *t, int *nop) { - *t = slap_get_time(); + struct timeval tv; +#if SLAP_STATS_ETIME + gettimeofday( &tv, NULL ); +#else + tv.tv_sec = slap_get_time(); + tv.tv_usec = 0; +#endif ldap_pvt_thread_mutex_lock( &slap_op_mutex ); - if ( *t == last_time ) { - *nop = ++last_incr; - } else { - last_time = *t; - last_incr = 0; - *nop = 0; + /* Usually tv.tv_sec cannot be < last_time.tv_sec + * but it might happen if we wrapped around tv_usec. + */ + if ( tv.tv_sec <= last_time.tv_sec && + tv.tv_usec <= last_time.tv_usec ) { + tv.tv_sec = last_time.tv_sec; + tv.tv_usec = last_time.tv_usec + 1; + if (tv.tv_usec >= 1000000) { + tv.tv_usec -= 1000000; + tv.tv_sec++; + last_time.tv_sec = tv.tv_sec; + } } + last_time.tv_usec = tv.tv_usec; ldap_pvt_thread_mutex_unlock( &slap_op_mutex ); + *t = tv.tv_sec; + *nop = tv.tv_usec; } Operation * @@ -204,9 +218,6 @@ slap_op_alloc( op->o_tag = tag; slap_op_time( &op->o_time, &op->o_tincr ); -#ifdef HAVE_GETTIMEOFDAY - (void) gettimeofday( &op->o_hr_time, NULL ); -#endif op->o_opid = id; #if defined( LDAP_SLAPI ) diff --git a/servers/slapd/result.c b/servers/slapd/result.c index 3d7e12969b..d958b97953 100644 --- a/servers/slapd/result.c +++ b/servers/slapd/result.c @@ -36,19 +36,24 @@ #include #include "slap.h" -#include "ldap_log.h" - -/* BSD seems to guarantee that this will be a macro, so... */ -#ifndef timersub -# define timersub(a,b,res) do { \ - (res)->tv_sec = (a)->tv_sec - (b)->tv_sec; \ - (res)->tv_usec = (a)->tv_usec - (b)->tv_usec; \ - if ((res)->tv_usec < 0) { \ - --(res)->tv_sec; \ - (res)->tv_usec += 1000000; \ - } \ - } while (0) -#endif + +#if SLAP_STATS_ETIME +#define ETIME_SETUP \ + struct timeval now; \ + (void) gettimeofday( &now, NULL ); \ + now.tv_sec -= op->o_time; \ + now.tv_usec -= op->o_tincr; \ + if ( now.tv_usec < 0 ) { \ + --now.tv_sec; now.tv_usec += 1000000; \ + } +#define ETIME_LOGFMT "etime=%d.%06d " +#define StatslogEtime(lvl,fmt,pfx,tag,err,etxt,xtra) \ + Statslog7(lvl,fmt,pfx,tag,err,(int)now.tv_sec,(int)now.tv_usec,etxt,xtra) +#else +#define ETIME_SETUP +#define ETIME_LOGFMT "" +#define StatslogEtime Statslog +#endif /* SLAP_STATS_ETIME */ const struct berval slap_dummy_bv = BER_BVNULL; @@ -832,27 +837,11 @@ send_ldap_disconnect( Operation *op, SlapReply *rs ) } if ( send_ldap_response( op, rs ) == SLAP_CB_CONTINUE ) { -#ifdef HAVE_GETTIMEOFDAY - struct timeval now; - struct timeval duration; - time_t msec; - - (void) gettimeofday( &now, NULL ); - timersub( &now, &op->o_hr_time, &duration ); - msec = duration.tv_usec / 1000 + duration.tv_sec * 1000; - - Statslog6( LDAP_DEBUG_STATS, - "%s DISCONNECT tag=%lu err=%d duration=%d.%03dms text=%s\n", - op->o_log_prefix, rs->sr_tag, rs->sr_err, - msec, - duration.tv_usec % 1000, - rs->sr_text ? rs->sr_text : "" ); -#else - Statslog( LDAP_DEBUG_STATS, - "%s DISCONNECT tag=%lu err=%d text=%s\n", + ETIME_SETUP; + StatslogEtime( LDAP_DEBUG_STATS, + "%s DISCONNECT tag=%lu err=%d "ETIME_LOGFMT"text=%s\n", op->o_log_prefix, rs->sr_tag, rs->sr_err, rs->sr_text ? rs->sr_text : "", 0 ); -#endif } } @@ -914,49 +903,18 @@ abandon: } if ( send_ldap_response( op, rs ) == SLAP_CB_CONTINUE ) { - -#ifdef HAVE_GETTIMEOFDAY - struct timeval now; - struct timeval duration; - time_t msec; - - (void) gettimeofday( &now, NULL ); - timersub( &now, &op->o_hr_time, &duration ); - msec = duration.tv_usec / 1000 + duration.tv_sec * 1000; - - if ( op->o_tag == LDAP_REQ_SEARCH ) { - Statslog7( LDAP_DEBUG_STATS, - "%s SEARCH RESULT tag=%lu err=%d duration=%d.%03dms nentries=%d text=%s\n", - op->o_log_prefix, - rs->sr_tag, - rs->sr_err, - msec, - duration.tv_usec % 1000, - rs->sr_nentries, - rs->sr_text ? rs->sr_text : ""); - } else { - Statslog6( LDAP_DEBUG_STATS, - "%s RESULT tag=%lu err=%d duration=%d.%03dms text=%s\n", - op->o_log_prefix, - rs->sr_tag, - rs->sr_err, - msec, - duration.tv_usec % 1000, - rs->sr_text ? rs->sr_text : ""); - } -#else + ETIME_SETUP; if ( op->o_tag == LDAP_REQ_SEARCH ) { - Statslog( LDAP_DEBUG_STATS, - "%s SEARCH RESULT tag=%lu err=%d nentries=%d text=%s\n", + StatslogEtime( LDAP_DEBUG_STATS, + "%s SEARCH RESULT tag=%lu err=%d "ETIME_LOGFMT"nentries=%d text=%s\n", op->o_log_prefix, rs->sr_tag, rs->sr_err, rs->sr_nentries, rs->sr_text ? rs->sr_text : "" ); } else { - Statslog( LDAP_DEBUG_STATS, - "%s RESULT tag=%lu err=%d text=%s\n", + StatslogEtime( LDAP_DEBUG_STATS, + "%s RESULT tag=%lu err=%d "ETIME_LOGFMT"text=%s\n", op->o_log_prefix, rs->sr_tag, rs->sr_err, rs->sr_text ? rs->sr_text : "", 0 ); } -#endif } if( tmp != NULL ) ch_free(tmp); @@ -979,27 +937,11 @@ send_ldap_sasl( Operation *op, SlapReply *rs ) rs->sr_msgid = (rs->sr_tag != LBER_SEQUENCE) ? op->o_msgid : 0; if ( send_ldap_response( op, rs ) == SLAP_CB_CONTINUE ) { -#ifdef HAVE_GETTIMEOFDAY - struct timeval now; - struct timeval duration; - time_t msec; - - (void) gettimeofday( &now, NULL ); - timersub( &now, &op->o_hr_time, &duration ); - msec = duration.tv_usec / 1000 + duration.tv_sec * 1000; - - Statslog6( LDAP_DEBUG_STATS, - "%s RESULT tag=%lu err=%d duration=%d.%03dms text=%s\n", - op->o_log_prefix, rs->sr_tag, rs->sr_err, - msec, - duration.tv_usec % 1000, - rs->sr_text ? rs->sr_text : "" ); -#else - Statslog( LDAP_DEBUG_STATS, - "%s RESULT tag=%lu err=%d text=%s\n", + ETIME_SETUP; + StatslogEtime( LDAP_DEBUG_STATS, + "%s RESULT tag=%lu err=%d "ETIME_LOGFMT"text=%s\n", op->o_log_prefix, rs->sr_tag, rs->sr_err, rs->sr_text ? rs->sr_text : "", 0 ); -#endif } } @@ -1020,29 +962,11 @@ slap_send_ldap_extended( Operation *op, SlapReply *rs ) rs->sr_msgid = (rs->sr_tag != LBER_SEQUENCE) ? op->o_msgid : 0; if ( send_ldap_response( op, rs ) == SLAP_CB_CONTINUE ) { -#ifdef HAVE_GETTIMEOFDAY - struct timeval now; - struct timeval duration; - time_t msec; - - (void) gettimeofday( &now, NULL ); - timersub( &now, &op->o_hr_time, &duration ); - msec = duration.tv_usec / 1000 + duration.tv_sec * 1000; - - Statslog6( LDAP_DEBUG_STATS, - "%s RESULT oid=%s err=%d duration=%d.%03dms text=%s\n", - op->o_log_prefix, - rs->sr_rspoid ? rs->sr_rspoid : "", - rs->sr_err, - msec, - duration.tv_usec % 1000, - rs->sr_text ? rs->sr_text : "" ); -#else - Statslog( LDAP_DEBUG_STATS, - "%s RESULT oid=%s err=%d text=%s\n", + ETIME_SETUP; + StatslogEtime( LDAP_DEBUG_STATS, + "%s RESULT oid=%s err=%d "ETIME_LOGFMT"text=%s\n", op->o_log_prefix, rs->sr_rspoid ? rs->sr_rspoid : "", rs->sr_err, rs->sr_text ? rs->sr_text : "", 0 ); -#endif } } diff --git a/servers/slapd/slap.h b/servers/slapd/slap.h index 0850702947..c9c7007148 100644 --- a/servers/slapd/slap.h +++ b/servers/slapd/slap.h @@ -74,6 +74,10 @@ LDAP_BEGIN_DECL #define SLAP_CONTROL_X_SESSION_TRACKING #define SLAP_DISTPROC +#ifndef SLAP_STATS_ETIME +#define SLAP_STATS_ETIME 1 /* microsecond op timing */ +#endif + #ifdef ENABLE_REWRITE #define SLAP_AUTH_REWRITE 1 /* use librewrite for sasl-regexp */ #endif @@ -2618,9 +2622,6 @@ struct Operation { #define o_log_prefix o_hdr->oh_log_prefix ber_tag_t o_tag; /* tag of the request */ -#ifdef HAVE_GETTIMEOFDAY - struct timeval o_hr_time; /* high-resolution time of op start*/ -#endif time_t o_time; /* time op was initiated */ int o_tincr; /* counter for multiple ops with same o_time */ -- 2.39.5