ITS#8054 add queue time to log

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

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 */

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 *

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	""

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 */