ITS#8054 operation duration logging

diff --git a/include/ldap_log.h b/include/ldap_log.h
index 1ba5f7230033d410e4d348e8c92b959569ba07f0..58dd4e9a756970edad958b45425e9623b51ad2f0 100644 (file)
--- a/include/ldap_log.h
+++ b/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))

diff --git a/servers/slapd/operation.c b/servers/slapd/operation.c
index a5d218896a6310dfe92269b87cb3cdd22aea57c7..fe025a154e4409965b461153b00d332771b23a74 100644 (file)
--- a/servers/slapd/operation.c
+++ b/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 )

diff --git a/servers/slapd/result.c b/servers/slapd/result.c
index a54e32844b8a6e5d3f6006aac7681b03c7940d1e..3d7e12969b9703bdb6b79a1d69c1a5c906e26a67 100644 (file)
--- a/servers/slapd/result.c
+++ b/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
        }
 }
 

diff --git a/servers/slapd/slap.h b/servers/slapd/slap.h
index f14015aeee41696a6935fec8592aefe937e39b21..0850702947b08a6df8bbb6cdfd2f6ee5375db6a5 100644 (file)
--- a/servers/slapd/slap.h
+++ b/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 */