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.

diff --git a/servers/slapd/operation.c b/servers/slapd/operation.c
index fe025a154e4409965b461153b00d332771b23a74..eeb312560041b5af9e23beb1fafd5c8f1cdc61cb 100644 (file)
--- 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 3d7e12969b9703bdb6b79a1d69c1a5c906e26a67..d958b979533c3ade5beda1ce2929a6cdcf3b0385 100644 (file)
--- a/servers/slapd/result.c
+++ b/servers/slapd/result.c
@@ -36,19 +36,24 @@
 #include <ac/unistd.h>
 
 #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 0850702947b08a6df8bbb6cdfd2f6ee5375db6a5..c9c7007148b3bd3a9e1d084606f544ea1d325ef8 100644 (file)
--- 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 */