diff --git a/level.go b/level.go index 1591972..72c3e45 100644 --- a/level.go +++ b/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"...) + } +} diff --git a/log.go b/log.go index 27f5f2a..3ec812c 100644 --- a/log.go +++ b/log.go @@ -9,14 +9,11 @@ package log // import "go.followtheprocess.codes/log" import ( - "bytes" "io" "log/slog" "slices" "strconv" - "strings" "sync" - "sync/atomic" "time" "unicode" "unicode/utf8" @@ -24,6 +21,22 @@ import ( "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,10 +245,9 @@ 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 } @@ -193,21 +255,22 @@ func (l *Logger) clone() *Logger { // 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 diff --git a/log_test.go b/log_test.go index fedf34f..ed2b3c2 100644 --- a/log_test.go +++ b/log_test.go @@ -90,6 +90,42 @@ func TestDebug(t *testing.T) { }, want: "[TIME] DEBUG: Hello debug! number=12 duration=30s enabled=true\n", }, + { + name: "with scalar attrs", + options: []log.Option{ + log.WithLevel(log.LevelDebug), + }, + msg: "Hello debug!", + attrs: []slog.Attr{ + slog.Int("negative", -5), + slog.Uint64("count", 42), + slog.Float64("ratio", 3.14), + slog.Bool("disabled", false), + }, + want: "[TIME] DEBUG: Hello debug! negative=-5 count=42 ratio=3.14 disabled=false\n", + }, + { + name: "quotes keys with whitespace", + options: []log.Option{ + log.WithLevel(log.LevelDebug), + }, + msg: "Hello debug!", + attrs: []slog.Attr{ + slog.Int("a key", 1), + }, + want: `[TIME] DEBUG: Hello debug! "a key"=1` + "\n", + }, + { + name: "resolves logvaluer attrs", + options: []log.Option{ + log.WithLevel(log.LevelDebug), + }, + msg: "Hello debug!", + attrs: []slog.Attr{ + slog.Any("token", secret("hunter2")), + }, + want: "[TIME] DEBUG: Hello debug! token=REDACTED\n", + }, { name: "with attrs quoted", options: []log.Option{ @@ -282,6 +318,8 @@ func BenchmarkLogger(b *testing.B) { debugLogger := log.New(buf, log.WithLevel(log.LevelDebug)) infoLogger := log.New(buf, log.WithLevel(log.LevelInfo)) discardLogger := log.New(io.Discard, log.WithLevel(log.LevelDebug)) + prefixedLogger := debugLogger.Prefixed("bench") + attrLogger := debugLogger.With(slog.String("service", "oven")) b.Run("enabled", func(b *testing.B) { for b.Loop() { @@ -291,6 +329,35 @@ func BenchmarkLogger(b *testing.B) { buf.Reset() }) + b.Run("prefixed", func(b *testing.B) { + for b.Loop() { + prefixedLogger.Debug("A message!") + } + + buf.Reset() + }) + + b.Run("attrs", func(b *testing.B) { + for b.Loop() { + debugLogger.Debug( + "A message!", + slog.Int("status", http.StatusOK), + slog.Duration("duration", 57*time.Millisecond), + slog.String("sentence", "has spaces"), + ) + } + + buf.Reset() + }) + + b.Run("persistent_attrs", func(b *testing.B) { + for b.Loop() { + attrLogger.Debug("A message!", slog.Int("status", http.StatusOK)) + } + + buf.Reset() + }) + b.Run("disabled", func(b *testing.B) { for b.Loop() { infoLogger.Debug("A message!") @@ -309,3 +376,10 @@ func BenchmarkLogger(b *testing.B) { buf.Reset() }) } + +// secret is a [slog.LogValuer] that redacts its value when logged. +type secret string + +func (s secret) LogValue() slog.Value { + return slog.StringValue("REDACTED") +} diff --git a/option.go b/option.go index ab1d274..fd038cd 100644 --- a/option.go +++ b/option.go @@ -39,6 +39,6 @@ func TimeFunc(fn func() time.Time) Option { // to the message and any key value pairs. func Prefix(prefix string) Option { return func(l *Logger) { - l.prefix = prefix + l.prefix = []byte(prefix) } }