X-Git-Url: https://git.sur5r.net/?a=blobdiff_plain;ds=sidebyside;f=servers%2Fslapd%2Fresult.c;h=4c0304e7cb43cbd5f0b1d26e48e4b7d0b683a726;hb=c6e00c7b0fb673d670c3f5e94edd4852f1ff546c;hp=14bd6b7938f7440858d92a62a211b3ac469b3f5b;hpb=ef95ee1755615b44fa6417cd7238dea3fbeb6742;p=openldap

diff --git a/servers/slapd/result.c b/servers/slapd/result.c
index 14bd6b7938..4c0304e7cb 100644
--- a/servers/slapd/result.c
+++ b/servers/slapd/result.c
@@ -2,7 +2,7 @@
 /* $OpenLDAP$ */
 /* This work is part of OpenLDAP Software <http://www.openldap.org/>.
  *
- * Copyright 1998-2014 The OpenLDAP Foundation.
+ * Copyright 1998-2017 The OpenLDAP Foundation.
  * All rights reserved.
  *
  * Redistribution and use in source and binary forms, with or without
@@ -37,6 +37,28 @@
 
 #include "slap.h"
 
+#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; \
+	} \
+	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) \
+	Statslog6(lvl,fmt,pfx,tag,err,timestr,etxt,xtra)
+#else
+#define ETIME_SETUP
+#define ETIME_LOGFMT	""
+#define StatslogEtime	Statslog
+#endif	/* SLAP_STATS_ETIME */
+
 const struct berval slap_dummy_bv = BER_BVNULL;
 
 int slap_null_cb( Operation *op, SlapReply *rs )
@@ -819,8 +841,9 @@ send_ldap_disconnect( Operation	*op, SlapReply *rs )
 	}
 
 	if ( send_ldap_response( op, rs ) == SLAP_CB_CONTINUE ) {
-		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 );
 	}
@@ -884,14 +907,15 @@ abandon:
 	}
 
 	if ( send_ldap_response( op, rs ) == SLAP_CB_CONTINUE ) {
+		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 );
 		}
@@ -917,8 +941,9 @@ 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 ) {
-		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 );
 	}
@@ -941,8 +966,9 @@ 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 ) {
-		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 );
 	}