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 b5ba969b7cb39f4f36a6b831d5123eb454099c5e..70db8e7a6352c26e5bb728bbb8f87f3b54943eb2 100644 (file)
--- 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 ad2c84405f2fdb3a72a43f24893fcf9e8f457f3e..d2bd4e940363608caf44023456d71258e5bb6ab8 100644 (file)
--- a/servers/slapd/bind.c
+++ b/servers/slapd/bind.c
@@ -32,6 +32,7 @@
 #include <ac/socket.h>
 
 #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 2488065c405ac77cc8ac0397607c9db0a6e8c8ab..193a102d761c8cabb0f7e989c0270bf7db2848e7 100644 (file)
--- 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 d8c4cabbbd4f602720e87308845b96aef721f28f..1dbb3838ba504f02cc612eaab28dd723b69c7070 100644 (file)
--- 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 c9c7007148b3bd3a9e1d084606f544ea1d325ef8..e806cec29b424908d5bac9f854606993addc50e1 100644 (file)
--- 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 <ldap.h>
@@ -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 47ea1c6d9d721d70986756e4c750831a63f95370..e65e93274a663cbe121fd3285d998c26fe0b7ad3 100644 (file)
--- 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