ITS#8054 add queue time to log

Show time spent in conn+threadpool queues before an op actually executes.
Also clean up timestamp handling

diff --git a/servers/slapd/connection.c b/servers/slapd/connection.c
index 6dec6455e8e4faa3a0f60f4fe650bc8745c643e8..5fe8d148fd7462fd904233162f2eecc5a34cdfe7 100644 (file)
--- a/servers/slapd/connection.c
+++ b/servers/slapd/connection.c
@@ -1053,6 +1053,13 @@ connection_operation( void *ctx, void *arg_v )
        void *memctx_null = NULL;
        ber_len_t memsiz;
 
+       gettimeofday( &op->o_qtime, NULL );
+       op->o_qtime.tv_usec -= op->o_tusec;
+       if ( op->o_qtime.tv_usec < 0 ) {
+               op->o_qtime.tv_usec += 1000000;
+               op->o_qtime.tv_sec--;
+       }
+       op->o_qtime.tv_sec -= op->o_time;
        conn_counter_init( op, ctx );
        ldap_pvt_thread_mutex_lock( &op->o_counters->sc_mutex );
        /* FIXME: returns 0 in case of failure */

diff --git a/servers/slapd/operation.c b/servers/slapd/operation.c
index 7e855049cc2d0708c6a6e2b0df4e78b0f40962d5..ebedbde8faf4d1ccd56291d6a95f146253b46253 100644 (file)
--- a/servers/slapd/operation.c
+++ b/servers/slapd/operation.c
@@ -38,7 +38,8 @@
 #endif
 
 static ldap_pvt_thread_mutex_t slap_op_mutex;
-static struct timeval last_time;
+static time_t last_time;
+static int last_incr;
 
 void slap_op_init(void)
 {
@@ -159,30 +160,18 @@ void
 slap_op_time(time_t *t, int *nop)
 {
        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 );
-       /* 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;
+       gettimeofday( &tv, NULL );
+       *t = tv.tv_sec;
+       if ( *t == last_time ) {
+               *nop = ++last_incr;
+       } else {
+               last_time = *t;
+               last_incr = 0;
+               *nop = 0;
        }
-       last_time.tv_usec = tv.tv_usec;
        ldap_pvt_thread_mutex_unlock( &slap_op_mutex );
-       *t = tv.tv_sec;
-       *nop = tv.tv_usec;
+       nop[1] = tv.tv_usec;
 }
 
 Operation *

diff --git a/servers/slapd/result.c b/servers/slapd/result.c
index 466b2a9adf900f5fa97749c25d7b7f94ed1370f3..4c0304e7cb43cbd5f0b1d26e48e4b7d0b683a726 100644 (file)
--- a/servers/slapd/result.c
+++ b/servers/slapd/result.c
@@ -40,15 +40,19 @@
 #if SLAP_STATS_ETIME
 #define ETIME_SETUP \
        struct timeval now; \
+       char timestr[64]; \
        (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 "
+       } \
+       sprintf(timestr, "qtime=%d.%06d etime=%d.%06d", \
+               (int)op->o_qtime.tv_sec, (int)op->o_qtime.tv_usec, \
+               (int)now.tv_sec, (int)now.tv_usec);
+#define ETIME_LOGFMT   "%s "
 #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)
+       Statslog6(lvl,fmt,pfx,tag,err,timestr,etxt,xtra)
 #else
 #define ETIME_SETUP
 #define ETIME_LOGFMT   ""

diff --git a/servers/slapd/slap.h b/servers/slapd/slap.h
index 1d2c2b5aa28af312cd17f707b2a58a4e97ff26cb..9959aa4b3907690976150efa5115d63d27372898 100644 (file)
--- a/servers/slapd/slap.h
+++ b/servers/slapd/slap.h
@@ -2625,6 +2625,8 @@ struct Operation {
        ber_tag_t       o_tag;          /* tag of the request */
        time_t          o_time;         /* time op was initiated */
        int                     o_tincr;        /* counter for multiple ops with same o_time */
+       int                     o_tusec;        /* microsecond timestamp */
+       struct timeval o_qtime; /* time spent in queues before execution */
 
        BackendDB       *o_bd;  /* backend DB processing this op */
        struct berval   o_req_dn;       /* DN of target of request */