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

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
 

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 );

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 );
 }

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
  */

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 */

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