openldap-bugs

openldap-bugs@openldap.org

1 participants
20967 discussions

Re: (ITS#8054) Operation duration logging
by michael＠stroeder.com 11 Feb '15

11 Feb '15

h.b.furuseth(a)usit.uio.no wrote: > Cool feture, but please use fewer characteres in the already > bloated log. How about "time=<integer>us" or even omit the "us"? +1 But 'time' sounds a bit general. How about 'tdu' or even 'td' as abbreviation for "time duration"? Ciao, Michael.

1 0

Re: (ITS#8054) Operation duration logging
by h.b.furuseth＠usit.uio.no 11 Feb '15

11 Feb '15

Cool feture, but please use fewer characteres in the already bloated log. How about "time=<integer>us" or even omit the "us"? When duration is of interest, what's usually interesting is probably which operations stand out as slower, not the actual speed. When duration is not of interest, then it's noise to keep small and boring. And we should document at least the default log format (Statslog). == About the code, ignoring the above suggestion for now: Once upon a time, floating-point was slow. Today, that extra code to avoid it is a pessimization at least on my Linux/x86. Try this: #define TIMEDIFF_MS(a,b) \ (((a)->tv_sec-(b)->tv_sec)*1000 + ((a)->tv_usec-(b)->tv_usec)/1000.0) OTOH floating-point printf is compex, you save a bit by doing msec = (int)t; printf("%d.%03d", msec, (int)((t-msec)*1000)); instead of printf("%4.3f", t); %d format requires 'int msec;' and (int)(duration.tv_usec % 1000). Since timersub() is use the same way each time, a macro could instead compute duration and msec, and maybe declare them too: DURATION_DECLARE(duration, msec, op->o_hr_time); For that matter, maybe we should get rid of the #ifdef-duplicated Statslog() statements and put the ugliness in macros instead. Like this, I think - an untested draft: DURATION_DECLARE(duration, msec, op->o_hr_time); StatslogDuration( LDAP_DEBUG_STATS, "%s DISCONNECT tag=%lu err=%d "DURATION_LOG_FMT" text=%s\n", op->o_log_prefix, rs->sr_tag, rs->sr_err, DURATION_LOG_ARG(duration, msec) /* no comma after this */ rs->sr_text ? rs->sr_text : "", 0 ); #ifdef HAVE_GETTIMEOFDAY #define DURATION_DECLARE(..blah..) <the duration code before Statslog> #define DURATION_LOG_FMT "duration=%d.%03dms " /* This is passed to StatslogDuration() without a comma before next arg. * So it is not an extra arg to StatslogDuration(), but it gives two * extra 'int' args to whatever StatslogDuration() passes it args on to. */ #define DURATION_LOG_ARG(duration,msec) (msec), (int)((duration).tv_usec%1000), #define StatslogDuration <like Statslog, but using Log7 instead of Log5> #else #define DURATION_DECLARE(..blah..) #define DURATION_LOG_FMT "" #define DURATION_LOG_ARG(duration, msec) #define StatslogDuration Statslog #endif

1 0

(ITS#8056) [PATCH] libdb version is not detected correctly when using gcc5
by jsynacek＠redhat.com 11 Feb '15

11 Feb '15

Full_Name: Jan Synacek Version: 2.4.40 OS: GNU/Linux URL: https://jsynacek.fedorapeople.org/openldap/jsynacek-20150211-fix-libdb-dete… Submission from: (NULL) (94.112.188.81) The old cpp version generated: __db_version 5 Configure then correctly picked up the version, since it greps for "__db_version". The new output: __db_version 5 Grepping no longer works and configure fails. Running cpp with -P (inhibit linemarkers generation) fixes this when using gcc 5. Behavior with older versions of gcc is not changed.

1 0

(ITS#8055) High CPU usage with syncreply and wrong port
by adam＠cassar.id.au 09 Feb '15

09 Feb '15

Full_Name: Adam Version: 2.4.40 OS: Linux URL: ftp://ftp.openldap.org/incoming/ Submission from: (NULL) (115.70.231.55) Specifying a syncrepl provider with an unreachable port results in high CPU usage with slapd with slapd never terminating. Example configuration: syncrepl rid=1 provider=ldap://10.1.1.10:9292 type=refreshAndPersist interval=00:00:01:00 retry="60 +" searchbase="dc=howard,dc=chew" scope=sub schemachecking=on bindmethod=simple binddn="cn=admin,dc=howard,dc=chew" credentials=iwritecode

1 0

Re: (ITS#8054) Operation duration logging
by michael＠stroeder.com 09 Feb '15

09 Feb '15

hyc(a)symas.com wrote: > michael(a)stroeder.com wrote: >> ebackes(a)symas.com wrote: >>> Here is a patch to add duration logging for operations that appears in the >>> standard result messages of statslog. It's a reasonably small change with >>> negligible performance implications except under pathological benchmarking >>> conditions. It does change the quasi-machine-parsable statslog format, however, >>> so it might not be appropriate for general 2.4 release. Example line: >>> >>> 54d8298c conn=1000 op=1 SEARCH RESULT tag=101 err=0 duration=0.170ms nentries=1 >>> text= >> >> This is a very important feature. Highly appreciated! >> >> I'd love to see this in RE24. Yes, I know. No more features. :-( >> >> Would it be possible and make sense to have this configurable per database? > > No it would not make sense. There are ops like Abandon and Unbind which > have no associated database. Aren't Abandon and Unbind associated by authz-DN? Or how is this solved in slapo-accesslog? Ciao, Michael.

1 0

Re: (ITS#8054) Operation duration logging
by hyc＠symas.com 09 Feb '15

09 Feb '15

michael(a)stroeder.com wrote: > ebackes(a)symas.com wrote: >> Here is a patch to add duration logging for operations that appears in the >> standard result messages of statslog. It's a reasonably small change with >> negligible performance implications except under pathological benchmarking >> conditions. It does change the quasi-machine-parsable statslog format, however, >> so it might not be appropriate for general 2.4 release. Example line: >> >> 54d8298c conn=1000 op=1 SEARCH RESULT tag=101 err=0 duration=0.170ms nentries=1 >> text= > > This is a very important feature. Highly appreciated! > > I'd love to see this in RE24. Yes, I know. No more features. :-( > > Would it be possible and make sense to have this configurable per database? No it would not make sense. There are ops like Abandon and Unbind which have no associated database. Adding variation here is creating gratuitous complexity for no benefit. -- -- Howard Chu CTO, Symas Corp. http://www.symas.com Director, Highland Sun http://highlandsun.com/hyc/ Chief Architect, OpenLDAP http://www.openldap.org/project/

1 0

Re: (ITS#8054) Operation duration logging
by michael＠stroeder.com 09 Feb '15

09 Feb '15

ebackes(a)symas.com wrote: > Here is a patch to add duration logging for operations that appears in the > standard result messages of statslog. It's a reasonably small change with > negligible performance implications except under pathological benchmarking > conditions. It does change the quasi-machine-parsable statslog format, however, > so it might not be appropriate for general 2.4 release. Example line: > > 54d8298c conn=1000 op=1 SEARCH RESULT tag=101 err=0 duration=0.170ms nentries=1 > text= This is a very important feature. Highly appreciated! I'd love to see this in RE24. Yes, I know. No more features. :-( Would it be possible and make sense to have this configurable per database? Ciao, Michael.

1 0

Re: (ITS#8054) Operation duration logging
by ebackes＠symas.com 08 Feb '15

08 Feb '15

This is a multi-part message in MIME format. --Multipart=_Sun__8_Feb_2015_19_56_17_-0800_yxgp4/9WqjBC20PY Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit Here are the patches. -- Emily Backes Symas Corporation ebackes(a)symas.com --Multipart=_Sun__8_Feb_2015_19_56_17_-0800_yxgp4/9WqjBC20PY Content-Type: text/x-diff; name="master-operation-duration-logging.patch" Content-Disposition: attachment; filename="master-operation-duration-logging.patch" Content-Transfer-Encoding: 7bit >From 7582a21a4bc06271519e37cef11dcfb4348a34a2 Mon Sep 17 00:00:00 2001 From: Emily Backes <ebackes(a)symas.com> Date: Thu, 5 Feb 2015 18:52:19 -0800 Subject: [PATCH] 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 9036060..289db00 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 d16413f..1450718 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 /* HAVE_GETTIMEOFDAY */ op->o_opid = id; #if defined( LDAP_SLAPI ) diff --git a/servers/slapd/result.c b/servers/slapd/result.c index 14bd6b7..20fc745 100644 --- 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 /* ! HAVE_GETTIMEOFDAY */ 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 /* ! HAVE_GETTIMEOFDAY */ } } @@ -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 /* ! HAVE_GETTIMEOFDAY */ 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 /* ! HAVE_GETTIMEOFDAY */ } 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 /* ! HAVE_GETTIMEOFDAY */ 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 /* ! HAVE_GETTIMEOFDAY */ } } @@ -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 /* ! HAVE_GETTIMEOFDAY */ 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 /* ! HAVE_GETTIMEOFDAY */ } } diff --git a/servers/slapd/slap.h b/servers/slapd/slap.h index f89da27..17d09d9 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 /* HAVE_GETTIMEOFDAY */ 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.1.4 --Multipart=_Sun__8_Feb_2015_19_56_17_-0800_yxgp4/9WqjBC20PY Content-Type: text/x-diff; name="RE24-operation-duration-logging.patch" Content-Disposition: attachment; filename="RE24-operation-duration-logging.patch" Content-Transfer-Encoding: 7bit >From bfabab23da6d0914f222a22f1cd0e28c48b4db90 Mon Sep 17 00:00:00 2001 From: Emily Backes <ebackes(a)symas.com> Date: Thu, 5 Feb 2015 18:52:19 -0800 Subject: [PATCH] operation duration logging --- include/ldap_log.h | 14 +++++++ servers/slapd/operation.c | 3 ++ servers/slapd/result.c | 98 +++++++++++++++++++++++++++++++++++++++++++++++ servers/slapd/slap.h | 19 +++++++++ 4 files changed, 134 insertions(+) diff --git a/include/ldap_log.h b/include/ldap_log.h index 94a73bd..50c7f4b 100644 --- a/include/ldap_log.h +++ b/include/ldap_log.h @@ -190,6 +190,20 @@ extern void eb_syslog(int pri, const char *fmt, ...); if ( ldap_syslog & (level) ) \ syslog( LDAP_LEVEL_MASK((severity)), (fmt), (arg1), (arg2), (arg3), (arg4), (arg5) ); \ } while ( 0 ) +#define Log6( level, severity, fmt, arg1, arg2, arg3, arg4, arg5, arg6 ) \ + do { \ + if ( ldap_debug & (level) ) \ + lutil_debug( ldap_debug, (level), (fmt), (arg1), (arg2), (arg3), (arg4), (arg5), (arg6) ); \ + if ( ldap_syslog & (level) ) \ + syslog( LDAP_LEVEL_MASK((severity)), (fmt), (arg1), (arg2), (arg3), (arg4), (arg5), (arg6) ); \ + } while ( 0 ) +#define Log7( level, severity, fmt, arg1, arg2, arg3, arg4, arg5, arg6, arg7 ) \ + do { \ + if ( ldap_debug & (level) ) \ + lutil_debug( ldap_debug, (level), (fmt), (arg1), (arg2), (arg3), (arg4), (arg5), (arg6), (arg7) ); \ + if ( ldap_syslog & (level) ) \ + syslog( LDAP_LEVEL_MASK((severity)), (fmt), (arg1), (arg2), (arg3), (arg4), (arg5), (arg6), (arg7) ); \ + } while ( 0 ) #define Debug( level, fmt, arg1, arg2, arg3 ) \ Log3( (level), ldap_syslog_level, (fmt), (arg1), (arg2), (arg3) ) #define LogTest(level) ( ( ldap_debug | ldap_syslog ) & (level) ) diff --git a/servers/slapd/operation.c b/servers/slapd/operation.c index cc09a22..1c712e0 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 /* HAVE_GETTIMEOFDAY */ op->o_opid = id; #if defined( LDAP_SLAPI ) diff --git a/servers/slapd/result.c b/servers/slapd/result.c index 35cddc7..2bd910e 100644 --- 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; @@ -794,10 +807,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 /* ! HAVE_GETTIMEOFDAY */ 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 /* ! HAVE_GETTIMEOFDAY */ } } @@ -859,6 +889,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 /* ! HAVE_GETTIMEOFDAY */ if ( op->o_tag == LDAP_REQ_SEARCH ) { Statslog( LDAP_DEBUG_STATS, "%s SEARCH RESULT tag=%lu err=%d nentries=%d text=%s\n", @@ -870,6 +931,7 @@ abandon: op->o_log_prefix, rs->sr_tag, rs->sr_err, rs->sr_text ? rs->sr_text : "", 0 ); } +#endif /* ! HAVE_GETTIMEOFDAY */ } if( tmp != NULL ) ch_free(tmp); @@ -892,10 +954,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 /* ! HAVE_GETTIMEOFDAY */ 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 /* ! HAVE_GETTIMEOFDAY */ } } @@ -916,10 +995,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 /* ! HAVE_GETTIMEOFDAY */ 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 /* ! HAVE_GETTIMEOFDAY */ } } diff --git a/servers/slapd/slap.h b/servers/slapd/slap.h index 60db371..d22f1bf 100644 --- a/servers/slapd/slap.h +++ b/servers/slapd/slap.h @@ -2598,6 +2598,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 /* HAVE_GETTIMEOFDAY */ time_t o_time; /* time op was initiated */ int o_tincr; /* counter for multiple ops with same o_time */ @@ -2969,6 +2972,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 ) \ @@ -2976,10 +2983,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.1.4 --Multipart=_Sun__8_Feb_2015_19_56_17_-0800_yxgp4/9WqjBC20PY--

1 0

(ITS#8054) Operation duration logging
by ebackes＠symas.com 08 Feb '15

08 Feb '15

Full_Name: Emily Backes Version: master, 2.4 OS: URL: Submission from: (NULL) (50.113.67.84) Here is a patch to add duration logging for operations that appears in the standard result messages of statslog. It's a reasonably small change with negligible performance implications except under pathological benchmarking conditions. It does change the quasi-machine-parsable statslog format, however, so it might not be appropriate for general 2.4 release. Example line: 54d8298c conn=1000 op=1 SEARCH RESULT tag=101 err=0 duration=0.170ms nentries=1 text= As written, it uses a separate field in struct Operation and is entirely independent of the o_tincr functionality. Merging those has further portability problems, and is out of the scope of this feature. As a result, the overhead is two additional gettimeofday() calls per operation. The change is wrapped in #ifdef HAVE_GETTIMEOFDAY, so architectures lacking that will see no change. I have patches versus both the master branch (which likely covers 2.5), and OPENLDAP_REL_ENG_2_4. They'll be attached momentarily, outside jitterbug's web interface. %ThThese modifications are the sole work of myself (Emily Backes) on behalf of Symas Corporation based on existing log features of OpenLDAP. Therefore, these modifications are: Copyright 2014-2015 Symas Corporation Redistribution and use in source and binary forms, with or without modification, are permitted only as authorized by the OpenLDAP Public License.

1 0

Re: (ITS#8046) query caused slapd to stop
by ryan＠nardis.ca 06 Feb '15

06 Feb '15

This follow-up is just to add some missing details to the log, since this is getting some traffic now. A query that reproduces the crash is: ldapsearch -E 'mv=(cn={*)(sn=*)' It was introduced by "ITS#7942 plug leak in controls": commit 9d991339 on master, ffd0f03b on RE24. vrFilter_free was broken for a long time, but was never called until the leak was fixed in that ITS. hope that helps, Ryan

1 0

Jump to page:

2025

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

2010

2009

2008

2007

2006

openldap-bugs