ITS#8054 operation duration logging

include/ldap_log.h

@@ -192,6 +192,12 @@ extern void eb_syslog(int pri, const char *fmt, ...);
 #define Log5(level, severity, fmt, a1, a2, a3, a4, a5) \
 	LogExpand((level), (severity), (fmt) LogArg(a1) LogArg(a2) LogArg(a3) \
 		LogArg(a4) LogArg(a5))
+#define Log6(level, severity, fmt, a1, a2, a3, a4, a5, a6) \
+	LogExpand((level), (severity), (fmt) LogArg(a1) LogArg(a2) LogArg(a3) \
+		LogArg(a4) LogArg(a5) LogArg(a6))
+#define Log7(level, severity, fmt, a1, a2, a3, a4, a5, a6, a7) \
+	LogExpand((level), (severity), (fmt) LogArg(a1) LogArg(a2) LogArg(a3) \
+		LogArg(a4) LogArg(a5) LogArg(a6) LogArg(a7))
 #define Debug(level, fmt, a1, a2, a3) \
 	LogExpand((level), ldap_syslog_level, (fmt) \
 		LogArg(a1) LogArg(a2) LogArg(a3))

servers/slapd/operation.c

@@ -204,6 +204,9 @@ 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 )

servers/slapd/result.c

@@ -36,6 +36,19 @@
 #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
 
 const struct berval slap_dummy_bv = BER_BVNULL;
 
@@ -819,10 +832,27 @@ 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",
 			op->o_log_prefix, rs->sr_tag, rs->sr_err,
 			rs->sr_text ? rs->sr_text : "", 0 );
+#endif
 	}
 }
 
@@ -884,6 +914,37 @@ 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
 		if ( op->o_tag == LDAP_REQ_SEARCH ) {
 			Statslog( LDAP_DEBUG_STATS,
 				"%s SEARCH RESULT tag=%lu err=%d nentries=%d text=%s\n",
@@ -895,6 +956,7 @@ abandon:
 				op->o_log_prefix, rs->sr_tag, rs->sr_err,
 				rs->sr_text ? rs->sr_text : "", 0 );
 		}
+#endif
 	}
 
 	if( tmp != NULL ) ch_free(tmp);
@@ -917,10 +979,27 @@ 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",
 			op->o_log_prefix, rs->sr_tag, rs->sr_err,
 			rs->sr_text ? rs->sr_text : "", 0 );
+#endif
 	}
 }
 
@@ -941,10 +1020,29 @@ 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",
 			op->o_log_prefix, rs->sr_rspoid ? rs->sr_rspoid : "",
 			rs->sr_err, rs->sr_text ? rs->sr_text : "", 0 );
+#endif
 	}
 }
 

servers/slapd/slap.h

@@ -2618,6 +2618,9 @@ 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 */
 
@@ -2990,6 +2993,10 @@ struct Connection {
 
 #define Statslog( level, fmt, connid, opid, arg1, arg2, arg3 )	\
 	Log5( (level), ldap_syslog_level, (fmt), (connid), (opid), (arg1), (arg2), (arg3) )
+#define Statslog6( level, fmt, a1, a2, a3, a4, a5, a6 )				\
+	Log6( (level), ldap_syslog_level, (fmt), (a1), (a2), (a3), (a4), (a5), (a6) )
+#define Statslog7( level, fmt, a1, a2, a3, a4, a5, a6, a7 )				\
+	Log7( (level), ldap_syslog_level, (fmt), (a1), (a2), (a3), (a4), (a5), (a6), (a7) )
 #define StatslogTest( level ) ((ldap_debug | ldap_syslog) & (level))
 #else /* !LDAP_SYSLOG */
 #define Statslog( level, fmt, connid, opid, arg1, arg2, arg3 )	\
@@ -2997,10 +3004,22 @@ struct Connection {
 		if ( ldap_debug & (level) ) \
 			lutil_debug( ldap_debug, (level), (fmt), (connid), (opid), (arg1), (arg2), (arg3) );\
 	} while (0)
+#define Statslog6( level, fmt, a1, a2, a3, a4, a5, a6 )				\
+	do { \
+		if ( ldap_debug & (level) ) \
+			lutil_debug( ldap_debug, (level), (fmt), (a1), (a2), (a3), (a4), (a5), (a6) ); \
+	} while (0)
+#define Statslog7( level, fmt, a1, a2, a3, a4, a5, a6, a7 )				\
+	do { \
+		if ( ldap_debug & (level) ) \
+			lutil_debug( ldap_debug, (level), (fmt), (a1), (a2), (a3), (a4), (a5), (a6), (a7) ); \
+	} while (0)
 #define StatslogTest( level ) (ldap_debug & (level))
 #endif /* !LDAP_SYSLOG */
 #else /* !LDAP_DEBUG */
 #define Statslog( level, fmt, connid, opid, arg1, arg2, arg3 ) ((void) 0)
+#define Statslog6( level, fmt, a1, a2, a3, a4, a5, a6 ) ((void) 0)
+#define Statslog7( level, fmt, a1, a2, a3, a4, a5, a6, a7 ) ((void) 0)
 #define StatslogTest( level ) (0)
 #endif /* !LDAP_DEBUG */