ITS#8054 add queue time to log

[openldap] / servers / slapd / result.c

diff --git a/servers/slapd/result.c b/servers/slapd/result.c
index 5858496b14d093d41f20e4c6012f7f878bd71526..4c0304e7cb43cbd5f0b1d26e48e4b7d0b683a726 100644 (file)
--- 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 );
        }