From: Howard Chu Date: Sun, 1 Nov 2015 08:13:09 +0000 (+0000) Subject: Checkpoint X-Git-Url: http://git.ipfire.org/gitweb/gitweb.cgi?a=commitdiff_plain;h=5f68fa17cb33715af1ef36717ba3693bcfe7d517;p=thirdparty%2Fopenldap.git Checkpoint Precompute log header - reduce msg formatting overhead More direct use of log buffers - minimize copying Multiple lines per send supported by default in syslog-ng not default in rsyslog --- diff --git a/servers/slapd/Makefile.in b/servers/slapd/Makefile.in index b5ba969b7c..70db8e7a63 100644 --- a/servers/slapd/Makefile.in +++ b/servers/slapd/Makefile.in @@ -20,6 +20,8 @@ XSRCS=version.c SUBDIRS=back-* shell-backends slapi overlays +UNIX_SRCS = syslog.c +UNIX_OBJS = syslog.o NT_SRCS = nt_svc.c NT_OBJS = nt_svc.o ../../libraries/liblutil/slapdmsg.res diff --git a/servers/slapd/bind.c b/servers/slapd/bind.c index ad2c84405f..d2bd4e9403 100644 --- a/servers/slapd/bind.c +++ b/servers/slapd/bind.c @@ -32,6 +32,7 @@ #include #include "slap.h" +#include "lutil.h" int do_bind( @@ -45,6 +46,7 @@ do_bind( struct berval dn = BER_BVNULL; ber_tag_t tag; Backend *be = NULL; + char *sl = op->o_logptr; Debug( LDAP_DEBUG_TRACE, "%s do_bind\n", op->o_log_prefix, 0, 0 ); @@ -56,11 +58,9 @@ do_bind( if ( op->o_conn->c_sasl_bind_in_progress ) { be = op->o_conn->c_authz_backend; } - if ( !BER_BVISEMPTY( &op->o_conn->c_dn ) ) { + if ( !BER_BVISEMPTY( &op->o_conn->c_dn ) && StatslogTest( LDAP_DEBUG_STATS )) { /* log authorization identity demotion */ - Statslog( LDAP_DEBUG_STATS, - "%s BIND anonymous mech=implicit ssf=0\n", - op->o_log_prefix, 0, 0, 0, 0 ); + sl = lutil_strcopy( sl, " BIND anonymous mech=implicit ssf=0\n" ); } connection2anonymous( op->o_conn ); if ( op->o_conn->c_sasl_bind_in_progress ) { @@ -162,9 +162,16 @@ do_bind( goto cleanup; } - Statslog( LDAP_DEBUG_STATS, "%s BIND dn=\"%s\" method=%ld\n", - op->o_log_prefix, op->o_req_dn.bv_val, - (unsigned long) op->orb_method, 0, 0 ); + if ( StatslogTest( LDAP_DEBUG_STATS )) { + sl += sprintf( sl, " BIND dn=\"%s\" method=%ld\n", + op->o_req_dn.bv_val, (unsigned long) op->orb_method ); + if ( ldap_debug & LDAP_DEBUG_STATS ) + lutil_debug( ldap_debug, LDAP_DEBUG_STATS, "%s", op->o_log_prefix ); + if ( ldap_syslog & LDAP_DEBUG_STATS ) + sendlog( op->o_logbuf, sl - op->o_logbuf ); + sl = op->o_logptr; + *sl = '\0'; + } if( op->orb_method == LDAP_AUTH_SASL ) { Debug( LDAP_DEBUG_TRACE, "do_bind: dn (%s) SASL mech %s\n", @@ -205,6 +212,13 @@ do_bind( rs->sr_err = frontendDB->be_bind( op, rs ); cleanup: + if ( sl != op->o_logptr ) { + if ( ldap_debug & LDAP_DEBUG_STATS ) + lutil_debug( ldap_debug, LDAP_DEBUG_STATS, "%s", op->o_log_prefix ); + if ( ldap_syslog & LDAP_DEBUG_STATS ) + sendlog( op->o_logbuf, sl - op->o_logbuf ); + *op->o_logptr = '\0'; + } if ( rs->sr_err == LDAP_SUCCESS ) { if ( op->orb_method != LDAP_AUTH_SASL ) { ber_dupbv( &op->o_conn->c_authmech, &mech ); diff --git a/servers/slapd/connection.c b/servers/slapd/connection.c index 2488065c40..193a102d76 100644 --- a/servers/slapd/connection.c +++ b/servers/slapd/connection.c @@ -1040,6 +1040,9 @@ conn_counter_init( Operation *op, void *ctx ) op->o_counters = vsc; } +static void +connection_init_log_prefix( Operation *op ); + static void * connection_operation( void *ctx, void *arg_v ) { @@ -1130,6 +1133,7 @@ connection_operation( void *ctx, void *arg_v ) ber_set_option( op->o_ber, LBER_OPT_BER_MEMCTX, &memctx ); } } + connection_init_log_prefix( op ); opidx = slap_req2op( tag ); assert( opidx != SLAP_OP_LAST ); @@ -1787,14 +1791,19 @@ connection_resched( Connection *conn ) static void connection_init_log_prefix( Operation *op ) { + int len; + op->o_logbuf = op->o_tmpalloc( LOGBUFSIZ, op->o_tmpmemctx ); + op->o_log_prefix = preplog( op->o_logbuf ); + len = op->o_log_prefix - op->o_logbuf; if ( op->o_connid == (unsigned long)(-1) ) { - snprintf( op->o_log_prefix, sizeof( op->o_log_prefix ), + len = snprintf( op->o_log_prefix, LOGBUFSIZ-len, "conn=-1 op=%lu", op->o_opid ); } else { - snprintf( op->o_log_prefix, sizeof( op->o_log_prefix ), + len = snprintf( op->o_log_prefix, LOGBUFSIZ-len, "conn=%lu op=%lu", op->o_connid, op->o_opid ); } + op->o_logptr = op->o_log_prefix + len; } static int connection_bind_cleanup_cb( Operation *op, SlapReply *rs ) @@ -1906,7 +1915,6 @@ static void connection_op_queue( Operation *op ) } op->o_connid = op->o_conn->c_connid; - connection_init_log_prefix( op ); LDAP_STAILQ_INSERT_TAIL( &op->o_conn->c_ops, op, o_next ); } diff --git a/servers/slapd/proto-slap.h b/servers/slapd/proto-slap.h index d8c4cabbbd..1dbb3838ba 100644 --- a/servers/slapd/proto-slap.h +++ b/servers/slapd/proto-slap.h @@ -1916,6 +1916,10 @@ LDAP_SLAPD_F (void) syn_delete LDAP_P(( Syntax *at )); LDAP_SLAPD_F (void) syn_unparse LDAP_P(( BerVarray *bva, Syntax *start, Syntax *end, int system )); +/* syslog.c */ +LDAP_SLAPD_F (char *) preplog LDAP_P(( char *buf )); +LDAP_SLAPD_F (void) sendlog LDAP_P(( char *buf, int len )); + /* * user.c */ diff --git a/servers/slapd/slap.h b/servers/slapd/slap.h index c9c7007148..e806cec29b 100644 --- a/servers/slapd/slap.h +++ b/servers/slapd/slap.h @@ -46,6 +46,7 @@ #define ldap_debug slap_debug #endif +#define syslog slap_syslog #include "ldap_log.h" #include @@ -2547,6 +2548,8 @@ typedef struct slap_counters_t { #endif /* SLAPD_MONITOR */ } slap_counters_t; +#define LOGBUFSIZ 2048 /* max msg size for syslogd */ + /* * represents an operation pending from an ldap client */ @@ -2565,8 +2568,10 @@ typedef struct Opheader { BerMemoryFunctions *oh_tmpmfuncs; slap_counters_t *oh_counters; + char *oh_logbuf; /* for Statslog, mainly */ + char *oh_logptr; - char oh_log_prefix[ /* sizeof("conn= op=") + 2*LDAP_PVT_INTTYPE_CHARS(unsigned long) */ SLAP_TEXT_BUFLEN ]; + char *oh_log_prefix; #ifdef LDAP_SLAPI void *oh_extensions; /* NS-SLAPI plugin */ @@ -2620,6 +2625,9 @@ struct Operation { #define o_tmpfree o_tmpmfuncs->bmf_free #define o_log_prefix o_hdr->oh_log_prefix +#define o_logbuf o_hdr->oh_logbuf +#define o_logptr o_hdr->oh_logptr + ber_tag_t o_tag; /* tag of the request */ time_t o_time; /* time op was initiated */ diff --git a/servers/slapd/syslog.c b/servers/slapd/syslog.c index 47ea1c6d9d..e65e93274a 100644 --- a/servers/slapd/syslog.c +++ b/servers/slapd/syslog.c @@ -61,6 +61,8 @@ static void connectlog(void); static void my_localtime(const time_t *t, struct tm *tm); +static struct berval LogPfx; + /* * syslog * print message on log file; output is intended for syslogd(8). @@ -74,11 +76,11 @@ syslog(int pri, const char *fmt, ...) #define FMT_LEN 1024 char tbuf[TBUF_LEN]; int cnt; - int error; int tbuf_left, prlen; va_start(ap, fmt); +#if 0 /* Check for invalid bits. */ if (pri & ~(LOG_PRIMASK|LOG_FACMASK)) { if (LogTest(LOG_ERR)) @@ -116,6 +118,9 @@ syslog(int pri, const char *fmt, ...) *p++ = ':'; *p++ = ' '; } +#endif + pend = tbuf + sizeof(tbuf); + p = preplog(tbuf); tbuf_left = pend - p; prlen = vsnprintf(p, tbuf_left, fmt, ap); @@ -127,6 +132,25 @@ syslog(int pri, const char *fmt, ...) p += prlen; cnt = p - tbuf; + sendlog(tbuf, cnt); +} + +/* Copy the syslog header into tbuf and return a pointer + * to end of header, where caller can begin writing the + * actual message. + */ +char * +preplog(char *tbuf) +{ + memcpy(tbuf, LogPfx.bv_val, LogPfx.bv_len); + return tbuf + LogPfx.bv_len; +} + +void +sendlog(char *tbuf, int cnt) +{ + int error; + /* Get connected, output the message to the local logger. */ if (LogFile == -1) openlog(LogTag, LogStat, 0); @@ -198,12 +222,36 @@ connectlog(void) void openlog(const char *ident, int logstat, int logfac) { + char buf[512], *p = buf; + + if (ident != NULL) LogTag = ident; LogStat = logstat; if (logfac != 0 && (logfac &~ LOG_FACMASK) == 0) LogFacility = logfac; + logfac |= LOG_DEBUG; /* we currently hardcode severity */ + + /* Our facility, pid, and ident never change so + * just build the message header now. Avoiding + * sprintf() and multiple calls to getpid() + * saves a lot of time. + */ + *p++ = '<'; + p += sprintf(p, "%d", logfac); + *p++ = '>'; + /* timestamp goes here but rsyslog ignores it, so skip it */ + p = lutil_strcopy(p, ident); + *p++ = '['; + p += sprintf(p, "%ld", (long)getpid()); + *p++ = ']'; + *p++ = ':'; + *p++ = ' '; + LogPfx.bv_len = p - buf; + LogPfx.bv_val = ch_malloc(LogPfx.bv_len); + memcpy(LogPfx.bv_val, buf, LogPfx.bv_len); + if (LogStat & LOG_NDELAY) /* open immediately */ connectlog(); } @@ -215,6 +263,7 @@ closelog() LogFile = -1; connected = 0; LogTag = NULL; + ch_free(LogPfx.bv_val); } #if 0