mirror of
https://git.openldap.org/openldap/openldap.git
synced 2025-01-18 11:05:48 +08:00
ITS#8054 Cleanup duration patch
Don't need op->o_hr_time, just use o_tincr, that's what it was intended for anyway. Use "etime=" like other products do. Simplify ifdefs. Use gettimeofday, it's always available now.
This commit is contained in:
Howard Chu
parent
5324d283d9
commit
2d5996ac60
@ -38,8 +38,7 @@
|
||||
#endif
|
||||
|
||||
static ldap_pvt_thread_mutex_t slap_op_mutex;
|
||||
static time_t last_time;
|
||||
static int last_incr;
|
||||
static struct timeval last_time;
|
||||
|
||||
void slap_op_init(void)
|
||||
{
|
||||
@ -159,16 +158,31 @@ slap_op_free( Operation *op, void *ctx )
|
||||
void
|
||||
slap_op_time(time_t *t, int *nop)
|
||||
{
|
||||
*t = slap_get_time();
|
||||
struct timeval tv;
|
||||
#if SLAP_STATS_ETIME
|
||||
gettimeofday( &tv, NULL );
|
||||
#else
|
||||
tv.tv_sec = slap_get_time();
|
||||
tv.tv_usec = 0;
|
||||
#endif
|
||||
ldap_pvt_thread_mutex_lock( &slap_op_mutex );
|
||||
if ( *t == last_time ) {
|
||||
*nop = ++last_incr;
|
||||
} else {
|
||||
last_time = *t;
|
||||
last_incr = 0;
|
||||
*nop = 0;
|
||||
/* Usually tv.tv_sec cannot be < last_time.tv_sec
|
||||
* but it might happen if we wrapped around tv_usec.
|
||||
*/
|
||||
if ( tv.tv_sec <= last_time.tv_sec &&
|
||||
tv.tv_usec <= last_time.tv_usec ) {
|
||||
tv.tv_sec = last_time.tv_sec;
|
||||
tv.tv_usec = last_time.tv_usec + 1;
|
||||
if (tv.tv_usec >= 1000000) {
|
||||
tv.tv_usec -= 1000000;
|
||||
tv.tv_sec++;
|
||||
last_time.tv_sec = tv.tv_sec;
|
||||
}
|
||||
}
|
||||
last_time.tv_usec = tv.tv_usec;
|
||||
ldap_pvt_thread_mutex_unlock( &slap_op_mutex );
|
||||
*t = tv.tv_sec;
|
||||
*nop = tv.tv_usec;
|
||||
}
|
||||
|
||||
Operation *
|
||||
@ -204,9 +218,6 @@ 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 )
|
||||
|
||||
@ -36,19 +36,24 @@
|
||||
#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
|
||||
#if SLAP_STATS_ETIME
|
||||
#define ETIME_SETUP \
|
||||
struct timeval now; \
|
||||
(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; \
|
||||
}
|
||||
#define ETIME_LOGFMT "etime=%d.%06d "
|
||||
#define StatslogEtime(lvl,fmt,pfx,tag,err,etxt,xtra) \
|
||||
Statslog7(lvl,fmt,pfx,tag,err,(int)now.tv_sec,(int)now.tv_usec,etxt,xtra)
|
||||
#else
|
||||
#define ETIME_SETUP
|
||||
#define ETIME_LOGFMT ""
|
||||
#define StatslogEtime Statslog
|
||||
#endif /* SLAP_STATS_ETIME */
|
||||
|
||||
const struct berval slap_dummy_bv = BER_BVNULL;
|
||||
|
||||
@ -832,27 +837,11 @@ 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",
|
||||
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 );
|
||||
#endif
|
||||
}
|
||||
}
|
||||
|
||||
@ -914,49 +903,18 @@ 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;
|
||||
|
||||
ETIME_SETUP;
|
||||
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",
|
||||
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 );
|
||||
}
|
||||
#endif
|
||||
}
|
||||
|
||||
if( tmp != NULL ) ch_free(tmp);
|
||||
@ -979,27 +937,11 @@ 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",
|
||||
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 );
|
||||
#endif
|
||||
}
|
||||
}
|
||||
|
||||
@ -1020,29 +962,11 @@ 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",
|
||||
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 );
|
||||
#endif
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@ -74,6 +74,10 @@ LDAP_BEGIN_DECL
|
||||
#define SLAP_CONTROL_X_SESSION_TRACKING
|
||||
#define SLAP_DISTPROC
|
||||
|
||||
#ifndef SLAP_STATS_ETIME
|
||||
#define SLAP_STATS_ETIME 1 /* microsecond op timing */
|
||||
#endif
|
||||
|
||||
#ifdef ENABLE_REWRITE
|
||||
#define SLAP_AUTH_REWRITE 1 /* use librewrite for sasl-regexp */
|
||||
#endif
|
||||
@ -2618,9 +2622,6 @@ 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 */
|
||||
|
||||
|
||||
Loading…
Reference in New Issue
Block a user