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 a54e32844b8a6e5d3f6006aac7681b03c7940d1e..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-2015 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 );
        }