Some performance improvements (#39)

Author: FollowTheProcess

level.go

@@ -29,6 +29,15 @@ const (
 	errorString = "ERROR"
 )
 
+// Pre-converted label bytes so the hot path can append them with
+// [hue.Style.AppendText] without allocating a fresh []byte each log call.
+var (
+	debugBytes = []byte(debugString)
+	infoBytes  = []byte(infoString)
+	warnBytes  = []byte(warnString)
+	errorBytes = []byte(errorString)
+)
+
 // String returns the stylised representation of the log level.
 func (l Level) String() string {
 	switch l {
@@ -44,3 +53,21 @@ func (l Level) String() string {
 		return "unknown"
 	}
 }
+
+// appendTo appends the stylised level label to dst and returns the extended
+// slice. It is the allocation-light equivalent of [Level.String] used on the
+// logging hot path.
+func (l Level) appendTo(dst []byte) []byte {
+	switch l {
+	case LevelDebug:
+		return debugStyle.AppendText(dst, debugBytes)
+	case LevelInfo:
+		return infoStyle.AppendText(dst, infoBytes)
+	case LevelWarn:
+		return warnStyle.AppendText(dst, warnBytes)
+	case LevelError:
+		return errorStyle.AppendText(dst, errorBytes)
+	default:
+		return append(dst, "unknown"...)
+	}
+}

log.go

@@ -9,21 +9,34 @@
 package log // import "go.followtheprocess.codes/log"
 
 import (
-	"bytes"
 	"io"
 	"log/slog"
 	"slices"
 	"strconv"
-	"strings"
 	"sync"
-	"sync/atomic"
 	"time"
 	"unicode"
 	"unicode/utf8"
 
 	"go.followtheprocess.codes/hue"
 )
 
+const (
+	// scratchSize is the size of the stack buffer used to format a timestamp
+	// before styling it; comfortably larger than any standard time layout.
+	scratchSize = 64
+
+	// bufferSize is the initial capacity of a pooled log line buffer, chosen to
+	// hold a typical line without reallocating.
+	bufferSize = 256
+
+	// base10 is the radix used to format integer attribute values.
+	base10 = 10
+
+	// float64Bits is the bit size used to format floating point attribute values.
+	float64Bits = 64
+)
+
 // Styles.
 const (
 	timestampStyle = hue.Dim
@@ -37,15 +50,17 @@ const (
 
 // Logger is a command line logger. It is safe to use across concurrently
 // executing goroutines.
+//
+// The zero value is not usable; construct a Logger with [New].
 type Logger struct {
 	w          io.Writer        // Where to write logs to
 	timeFunc   func() time.Time // A function to get the current time, defaults to [time.Now] (with UTC)
 	mu         *sync.Mutex      // Protects w, pointer so that child loggers share the same mutex
 	timeFormat string           // The time format layout string, defaults to [time.RFC3339]
-	prefix     string           // Optional prefix to prepend to all log messages
+	prefix     []byte           // Optional prefix to prepend to all log messages, stored as bytes for the hot path
 	attrs      []slog.Attr      // Persistent key value pairs
 	level      Level            // The configured level of this logger, logs below this level are not shown
-	isDiscard  atomic.Bool      // w == [io.Discard], cached
+	isDiscard  bool             // w == [io.Discard], cached. Only written during construction, before the logger is shared
 }
 
 // New returns a new [Logger] configured to write to w.
@@ -59,10 +74,9 @@ func New(w io.Writer, options ...Option) *Logger {
 		timeFormat: time.RFC3339,
 		timeFunc:   func() time.Time { return time.Now().UTC() },
 		mu:         &sync.Mutex{},
+		isDiscard:  w == io.Discard,
 	}
 
-	logger.isDiscard.Store(w == io.Discard)
-
 	for _, option := range options {
 		option(logger)
 	}
@@ -87,7 +101,7 @@ func (l *Logger) With(attrs ...slog.Attr) *Logger {
 func (l *Logger) Prefixed(prefix string) *Logger {
 	sub := l.clone()
 
-	sub.prefix = prefix
+	sub.prefix = []byte(prefix)
 
 	return sub
 }
@@ -114,62 +128,111 @@ func (l *Logger) Error(msg string, attrs ...slog.Attr) {
 
 // log logs the given levelled message.
 func (l *Logger) log(level Level, msg string, attrs ...slog.Attr) {
-	if l.isDiscard.Load() || l.level > level {
+	if l.isDiscard || l.level > level {
 		// Do as little work as possible
 		return
 	}
 
-	// Buffer the output as e.g. stderr is not buffered by default. Do this
-	// by fetching and putting buffers from a [sync.Pool] so we don't have to
-	// constantly allocate new buffers
-	buf := getBuffer()
-	defer putBuffer(buf)
+	// Build the line in a byte buffer fetched from a [sync.Pool] so we don't
+	// constantly allocate. Styled, known-ahead text (timestamp, level, prefix)
+	// is appended with hue's allocation-free AppendText.
+	bufp := getBuffer()
+	defer putBuffer(bufp)
 
-	buf.WriteString(timestampStyle.Text(l.timeFunc().Format(l.timeFormat)))
-	buf.WriteByte(' ')
-	buf.WriteString(level.String())
+	// Dereference the working copy so we don't have to dereference every call
+	buf := *bufp
 
-	if l.prefix != "" {
-		buf.WriteString(" ")
-		buf.WriteString(prefixStyle.Text(l.prefix))
-	}
+	// Format the timestamp into a stack scratch buffer so we avoid allocating
+	// an intermediate string before styling it.
+	var scratch [scratchSize]byte
 
-	buf.WriteByte(':')
+	timestamp := l.timeFunc().AppendFormat(scratch[:0], l.timeFormat)
+	buf = timestampStyle.AppendText(buf, timestamp)
 
-	padding := 2
-	if level == LevelDebug || level == LevelError {
-		padding = 1
-	}
+	buf = append(buf, ' ')
+	buf = level.appendTo(buf)
 
-	buf.WriteString(strings.Repeat(" ", padding))
-	buf.WriteString(msg)
+	if len(l.prefix) != 0 {
+		buf = append(buf, ' ')
+		buf = prefixStyle.AppendText(buf, l.prefix)
+	}
 
-	if totalAttrs := len(l.attrs) + len(attrs); totalAttrs != 0 {
-		all := slices.Concat(l.attrs, attrs)
+	buf = append(buf, ':')
 
-		for _, attr := range all {
-			buf.WriteByte(' ')
+	// DEBUG and ERROR are 5 characters, INFO and WARN are 4. Pad the shorter
+	// labels with an extra space so the message always starts in the same column.
+	buf = append(buf, ' ')
+	if level == LevelInfo || level == LevelWarn {
+		buf = append(buf, ' ')
+	}
 
-			key := keyStyle.Text(attr.Key)
-			val := attr.Value.String()
+	buf = append(buf, msg...)
 
-			if needsQuotes(val) || val == "" {
-				val = strconv.Quote(val)
-			}
+	for _, attr := range l.attrs {
+		buf = appendAttr(buf, attr)
+	}
 
-			buf.WriteString(key)
-			buf.WriteByte('=')
-			buf.WriteString(val)
-		}
+	for _, attr := range attrs {
+		buf = appendAttr(buf, attr)
 	}
 
-	buf.WriteByte('\n')
+	buf = append(buf, '\n')
+
+	// Put it back
+	*bufp = buf
 
-	// WriteTo drains the buffer
 	l.mu.Lock()
 	defer l.mu.Unlock()
 
-	buf.WriteTo(l.w) //nolint: errcheck // Just like printing
+	l.w.Write(buf) //nolint: errcheck // Just like printing
+}
+
+// appendAttr appends a single " key=value" pair to dst and returns the
+// extended slice. The key is quoted if it contains whitespace or is empty.
+func appendAttr(dst []byte, attr slog.Attr) []byte {
+	dst = append(dst, ' ')
+
+	key := attr.Key
+	if key == "" || needsQuotes(key) {
+		key = strconv.Quote(key)
+	}
+
+	dst = append(dst, keyStyle.Text(key)...)
+	dst = append(dst, '=')
+
+	return appendValue(dst, attr.Value)
+}
+
+// appendValue appends the textual form of v to dst and returns the extended slice.
+//
+// Scalar kinds are written straight into the buffer, skipping the "needs quotes" check
+// as their text can never contain whitespace and so are never quoted.
+//
+// Other kinds fall back to [slog.Value.String], quoted if they contain whitespace or are empty.
+func appendValue(dst []byte, v slog.Value) []byte {
+	// Resolve any [slog.LogValuer]
+	// See https://github.com/golang/example/blob/master/slog-handler-guide/README.md
+	if v.Kind() == slog.KindLogValuer {
+		v = v.Resolve()
+	}
+
+	switch v.Kind() {
+	case slog.KindInt64:
+		return strconv.AppendInt(dst, v.Int64(), base10)
+	case slog.KindUint64:
+		return strconv.AppendUint(dst, v.Uint64(), base10)
+	case slog.KindFloat64:
+		return strconv.AppendFloat(dst, v.Float64(), 'g', -1, float64Bits)
+	case slog.KindBool:
+		return strconv.AppendBool(dst, v.Bool())
+	default:
+		s := v.String()
+		if s == "" || needsQuotes(s) {
+			return strconv.AppendQuote(dst, s)
+		}
+
+		return append(dst, s...)
+	}
 }
 
 // clone returns an exact clone of the calling logger.
@@ -182,32 +245,32 @@ func (l *Logger) clone() *Logger {
 		attrs:      l.attrs,
 		level:      l.level,
 		mu:         l.mu,
+		isDiscard:  l.isDiscard,
 	}
 
-	clone.isDiscard.Store(l.isDiscard.Load())
-
 	return clone
 }
 
 // Each log method (Debug, Info, Warn) etc. gets a buffer from this pool
 // so as not to keep re-allocating and destroying them.
 var bufPool = sync.Pool{
 	New: func() any {
-		return new(bytes.Buffer)
+		buf := make([]byte, 0, bufferSize)
+		return &buf
 	},
 }
 
 // getBuffer fetches a buffer from the pool, the returned buffer
 // is empty and ready to use.
-func getBuffer() *bytes.Buffer {
-	buf := bufPool.Get().(*bytes.Buffer) //nolint:revive,errcheck,forcetypeassert // We are in total control of this
-	buf.Reset()
+func getBuffer() *[]byte {
+	bufp := bufPool.Get().(*[]byte) //nolint:revive,errcheck,forcetypeassert // We are in total control of this
+	*bufp = (*bufp)[:0]             // Reset
 
-	return buf
+	return bufp
 }
 
 // putBuffer puts the buffer back into the pool.
-func putBuffer(buf *bytes.Buffer) {
+func putBuffer(bufp *[]byte) {
 	// Proper usage of a sync.Pool requires each entry to have approximately
 	// the same memory cost. To obtain this property when the stored type
 	// contains a variably-sized buffer, we add a hard limit on the maximum buffer
@@ -217,19 +280,34 @@ func putBuffer(buf *bytes.Buffer) {
 
 	// Approx 65kb
 	const maxSize = 64 << 10
-	if buf.Cap() > maxSize {
+	if cap(*bufp) > maxSize {
 		return
 	}
 
-	bufPool.Put(buf)
+	bufPool.Put(bufp)
 }
 
 // needsQuotes returns whether s should be displayed as "s".
 func needsQuotes(s string) bool {
-	for _, char := range s {
+	for i := 0; i < len(s); {
+		// ASCII fast path: most keys and values are printable ASCII
+		// Anything <= space (control characters and space itself) or DEL needs quoting.
+		if b := s[i]; b < utf8.RuneSelf {
+			if b <= ' ' || b == 0x7f {
+				return true
+			}
+
+			i++
+
+			continue
+		}
+
+		char, size := utf8.DecodeRuneInString(s[i:])
 		if char == utf8.RuneError || unicode.IsSpace(char) || !unicode.IsPrint(char) {
 			return true
 		}
+
+		i += size
 	}
 
 	return false