X-Git-Url: https://git.sur5r.net/?a=blobdiff_plain;f=servers%2Fslapd%2Fresult.c;h=4c0304e7cb43cbd5f0b1d26e48e4b7d0b683a726;hb=a0cc1d9655da112a4d19cddf821460a4dedeed1c;hp=5858496b14d093d41f20e4c6012f7f878bd71526;hpb=01f4aeac4c9ccc42a998c18f8995ce453d819b13;p=openldap

diff --git a/servers/slapd/result.c b/servers/slapd/result.c
index 5858496b14..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-2013 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 )
@@ -132,7 +154,21 @@ slap_req2res( ber_tag_t tag )
 	return tag;
 }
 
-/* SlapReply debugging, prodo-slap.h overrides it in OpenLDAP releases */
+/*
+ * SlapReply debugging enabled by USE_RS_ASSERT.
+ *
+ * Disabled by default, but compiled in (but still unused) when
+ * LDAP_TEST.  #define USE_RS_ASSERT as nonzero to enable some
+ * assertions which check the SlapReply.  USE_RS_ASSERT = 2 or higher
+ * check aggressively, currently some code fail these tests.
+ *
+ * Environment variable $NO_RS_ASSERT controls how USE_RS_ASSERT handles
+ * errors.  > 0: ignore errors, 0: abort (the default), < 0: just warn.
+ *
+ * Wrap LDAP operation calls in macros SLAP_OP() & co from proto-slap.h
+ * to check the SlapReply.  contrib/slapd-tools/wrap_slap_ops converts
+ * source code to use the macros.
+ */
 #if defined(LDAP_TEST) || (defined(USE_RS_ASSERT) && (USE_RS_ASSERT))
 
 int rs_suppress_assert = 0;
@@ -279,6 +315,22 @@ rs_entry2modifiable( Operation *op, SlapReply *rs, slap_overinst *on )
 	return 1;
 }
 
+/* Check for any callbacks that want to be informed about being blocked
+ * on output. These callbacks are expected to leave the callback list
+ * unmodified. Their result is ignored.
+ */
+static void
+slap_writewait_play(
+	Operation *op )
+{
+	slap_callback	*sc = op->o_callback;
+
+	for ( ; sc; sc = sc->sc_next ) {
+		if ( sc->sc_writewait )
+			sc->sc_writewait( op, sc );
+	}
+}
+
 static long send_ldap_ber(
 	Operation *op,
 	BerElement *ber )
@@ -355,6 +407,7 @@ fail:
 		conn->c_writewaiter = 1;
 		ldap_pvt_thread_mutex_unlock( &conn->c_write1_mutex );
 		ldap_pvt_thread_pool_idle( &connection_pool );
+		slap_writewait_play( op );
 		err = slapd_wait_writer( conn->c_sd );
 		conn->c_writewaiter = 0;
 		ldap_pvt_thread_pool_unidle( &connection_pool );
@@ -788,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 );
 	}
@@ -853,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 );
 		}
@@ -886,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 );
 	}
@@ -910,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 );
 	}