From 5324d283d9ff1ba0f608d1130be683eb698f831e Mon Sep 17 00:00:00 2001 From: Emily Backes Date: Thu, 5 Feb 2015 18:52:19 -0800 Subject: [PATCH] ITS#8054 operation duration logging --- include/ldap_log.h | 6 +++ servers/slapd/operation.c | 3 ++ servers/slapd/result.c | 98 +++++++++++++++++++++++++++++++++++++++ servers/slapd/slap.h | 19 ++++++++ 4 files changed, 126 insertions(+) diff --git a/include/ldap_log.h b/include/ldap_log.h index 1ba5f72300..58dd4e9a75 100644 --- 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 a5d218896a..fe025a154e 100644 --- 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 a54e32844b..3d7e12969b 100644 --- a/servers/slapd/result.c +++ b/servers/slapd/result.c @@ -36,6 +36,19 @@ #include #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 f14015aeee..0850702947 100644 --- 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 */ -- 2.39.5