diff --git a/internal/entryhuman/entry.go b/internal/entryhuman/entry.go index 8af4d82..d1a33ac 100644 --- a/internal/entryhuman/entry.go +++ b/internal/entryhuman/entry.go @@ -88,60 +88,168 @@ func formatValue(v interface{}) string { const tab = " " -// Fmt returns a human readable format for ent. +// bracketedLevel is an optimization to avoid extra allocations and calls to strings.ToLower +// when we want to translate/print the lowercase version of a log level. +func bracketedLevel(l slog.Level) string { + switch l { + case slog.LevelDebug: + return "[debu]" + case slog.LevelInfo: + return "[info]" + case slog.LevelWarn: + return "[warn]" + case slog.LevelError: + return "[erro]" + case slog.LevelCritical: + return "[crit]" + case slog.LevelFatal: + return "[fata]" + default: + return "[unkn]" + } +} + +// Optimization to avoid allocation of heap allocations/temporary strings via formatValue when dealing with primitive types. +// It returns (handled, error). When handled is false, the caller should fall back to formatValue. +func writeValueFast(w io.Writer, v interface{}) (bool, error) { + switch x := v.(type) { + case string: + _, err := w.Write([]byte(quote(x))) + return true, err + case bool: + if x { + _, err := w.Write([]byte("true")) + return true, err + } + _, err := w.Write([]byte("false")) + return true, err + + // signed ints + case int: + var a [20]byte + _, err := w.Write(strconv.AppendInt(a[:0], int64(x), 10)) + return true, err + case int8: + var a [20]byte + _, err := w.Write(strconv.AppendInt(a[:0], int64(x), 10)) + return true, err + case int16: + var a [20]byte + _, err := w.Write(strconv.AppendInt(a[:0], int64(x), 10)) + return true, err + case int32: + var a [20]byte + _, err := w.Write(strconv.AppendInt(a[:0], int64(x), 10)) + return true, err + case int64: + var a [20]byte + _, err := w.Write(strconv.AppendInt(a[:0], x, 10)) + return true, err + + // unsigned ints + case uint: + var a [20]byte + _, err := w.Write(strconv.AppendUint(a[:0], uint64(x), 10)) + return true, err + case uint8: + var a [20]byte + _, err := w.Write(strconv.AppendUint(a[:0], uint64(x), 10)) + return true, err + case uint16: + var a [20]byte + _, err := w.Write(strconv.AppendUint(a[:0], uint64(x), 10)) + return true, err + case uint32: + var a [20]byte + _, err := w.Write(strconv.AppendUint(a[:0], uint64(x), 10)) + return true, err + case uint64: + var a [20]byte + _, err := w.Write(strconv.AppendUint(a[:0], x, 10)) + return true, err + + // floats: prefer 'g' to keep output bounded (matches fmt default) + case float32: + var a [32]byte + _, err := w.Write(strconv.AppendFloat(a[:0], float64(x), 'g', -1, 32)) + return true, err + case float64: + var a [32]byte + _, err := w.Write(strconv.AppendFloat(a[:0], x, 'g', -1, 64)) + return true, err + default: + return false, nil + } +} + +// Fmt returns a human readable format for ent. Assumes we have a bytes.Buffer +// which we will more easily be able to assume underlying reallocation of it's size is possible +// if necessary than for an arbitrary io.Writer/io.StringWriter +// Note that while bytes.Buffer can in theory return an error for writes, it only does so if the buffer size will +// exceed our architectures max integer size. If the system is actually OOM and more memory cannot be allocated +// it will panic instead. // // We never return with a trailing newline because Go's testing framework adds one // automatically and if we include one, then we'll get two newlines. // We also do not indent the fields as go's test does that automatically // for extra lines in a log so if we did it here, the fields would be indented // twice in test logs. So the Stderr logger indents all the fields itself. -func Fmt( - buf interface { - io.StringWriter - io.Writer - }, termW io.Writer, ent slog.SinkEntry, -) { +func Fmt(buf *bytes.Buffer, termW io.Writer, ent slog.SinkEntry) { reset(buf, termW) - ts := ent.Time.Format(TimeFormat) - buf.WriteString(render(termW, timeStyle, ts+" ")) - level := ent.Level.String() - level = strings.ToLower(level) - if len(level) > 4 { - level = level[:4] - } - level = "[" + level + "]" - buf.WriteString(render(termW, levelStyle(ent.Level), level)) + // Timestamp + space + buf.WriteString(render(termW, timeStyle, ent.Time.Format(TimeFormat))) + buf.WriteString(" ") + + // Level label + two spaces + lvl := bracketedLevel(ent.Level) // e.g. "[debu]", "[info]" + buf.WriteString(render(termW, levelStyle(ent.Level), lvl)) buf.WriteString(" ") + // Logger names: name1.name2.name3: (no strings.Join allocation) if len(ent.LoggerNames) > 0 { - loggerName := quoteKey(strings.Join(ent.LoggerNames, ".")) + ": " - buf.WriteString(loggerName) + for i, name := range ent.LoggerNames { + if i > 0 { + buf.WriteString(".") + } + buf.WriteString(quoteKey(name)) + } + buf.WriteString(": ") } + // Message (detect multiline) var multilineKey string var multilineVal string msg := strings.TrimSpace(ent.Message) if strings.Contains(msg, "\n") { multilineKey = "msg" multilineVal = msg - msg = "..." - msg = quote(msg) + msg = quote("...") } buf.WriteString(msg) + keyStyle := timeStyle + equalsStyle := timeStyle + + // Write trace/span directly (do not mutate ent.Fields) if ent.SpanContext.IsValid() { - ent.Fields = append(slog.M( - slog.F("trace", ent.SpanContext.TraceID), - slog.F("span", ent.SpanContext.SpanID), - ), ent.Fields...) + buf.WriteString(tab) + + buf.WriteString(render(termW, keyStyle, quoteKey("trace"))) + buf.WriteString(render(termW, equalsStyle, "=")) + buf.WriteString(ent.SpanContext.TraceID().String()) + buf.WriteString(tab) + buf.WriteString(render(termW, keyStyle, quoteKey("span"))) + buf.WriteString(render(termW, equalsStyle, "=")) + buf.WriteString(ent.SpanContext.SpanID().String()) } + // Find a multiline field without mutating ent.Fields. + multiIdx := -1 for i, f := range ent.Fields { if multilineVal != "" { break } - var s string switch v := f.Value.(type) { case string: @@ -153,46 +261,66 @@ func Fmt( if !strings.Contains(s, "\n") { continue } - - // Remove this field. - ent.Fields = append(ent.Fields[:i], ent.Fields[i+1:]...) + multiIdx = i multilineKey = f.Name multilineVal = s + break } - keyStyle := timeStyle - // Help users distinguish logs by keeping some color in the equal signs. - equalsStyle := timeStyle - + // Print fields (skip multiline field index). for i, f := range ent.Fields { + if i == multiIdx { + continue + } if i < len(ent.Fields) { buf.WriteString(tab) } + buf.WriteString(render(termW, keyStyle, quoteKey(f.Name))) buf.WriteString(render(termW, equalsStyle, "=")) - valueStr := formatValue(f.Value) - buf.WriteString(valueStr) + + if ok, err := writeValueFast(buf, f.Value); err != nil { + // return err + } else if !ok { + buf.WriteString(formatValue(f.Value)) + } } + // Multiline value block if multilineVal != "" { if msg != "..." { buf.WriteString(" ...") } - // Proper indentation. - lines := strings.Split(multilineVal, "\n") - for i, line := range lines[1:] { - if line != "" { - lines[i+1] = strings.Repeat(" ", len(multilineKey)+2) + line - } - } - multilineVal = strings.Join(lines, "\n") - - multilineKey = render(termW, keyStyle, multilineKey) buf.WriteString("\n") - buf.WriteString(multilineKey) + buf.WriteString(render(termW, keyStyle, multilineKey)) buf.WriteString("= ") - buf.WriteString(multilineVal) + + // First line up to first newline + s := multilineVal + if n := strings.IndexByte(s, '\n'); n >= 0 { + buf.WriteString(s[:n]) + s = s[n+1:] + } else { + buf.WriteString(s) + s = "" + } + + indent := strings.Repeat(" ", len(multilineKey)+2) + for len(s) > 0 { + buf.WriteString("\n") + // Only indent non-empty lines. + if s[0] != '\n' { + buf.WriteString(indent) + } + if n := strings.IndexByte(s, '\n'); n >= 0 { + buf.WriteString(s[:n]) + s = s[n+1:] + } else { + buf.WriteString(s) + break + } + } } } diff --git a/internal/entryhuman/entry_test.go b/internal/entryhuman/entry_test.go index 45a885a..221ad7f 100644 --- a/internal/entryhuman/entry_test.go +++ b/internal/entryhuman/entry_test.go @@ -142,6 +142,79 @@ func TestEntry(t *testing.T) { ), }, }, + { + "primitiveTypes", + slog.SinkEntry{ + Level: slog.LevelInfo, + Message: "primitives", + Time: kt, + Fields: slog.M( + slog.F("bool_true", true), + slog.F("bool_false", false), + slog.F("int", 42), + slog.F("int8", int8(-8)), + slog.F("int16", int16(-16)), + slog.F("int32", int32(-32)), + slog.F("int64", int64(-64)), + slog.F("uint", uint(42)), + slog.F("uint8", uint8(8)), + slog.F("uint16", uint16(16)), + slog.F("uint32", uint32(32)), + slog.F("uint64", uint64(64)), + slog.F("float32", float32(3.14)), + slog.F("float64", 2.71828), + ), + }, + }, + { + "primitiveEdgeCases", + slog.SinkEntry{ + Level: slog.LevelWarn, + Message: "edge cases", + Time: kt, + Fields: slog.M( + slog.F("zero_int", 0), + slog.F("neg_int", -999), + slog.F("max_int64", int64(9223372036854775807)), + slog.F("min_int64", int64(-9223372036854775808)), + slog.F("max_uint64", uint64(18446744073709551615)), + slog.F("zero_float", 0.0), + slog.F("neg_float", -123.456), + ), + }, + }, + { + "mixedPrimitiveAndComplex", + slog.SinkEntry{ + Level: slog.LevelDebug, + Message: "mixed types", + Time: kt, + Fields: slog.M( + slog.F("count", 100), + slog.F("name", "test"), + slog.F("enabled", true), + slog.F("ratio", 0.95), + slog.F("data", []byte("bytes")), + slog.F("nil_val", nil), + ), + }, + }, + { + "allLogLevels", + slog.SinkEntry{ + Level: slog.LevelCritical, // Test Critical + Message: "critical", + Time: kt, + }, + }, + { + "fatalLevel", + slog.SinkEntry{ + Level: slog.LevelFatal, // Test Fatal + Message: "fatal", + Time: kt, + }, + }, } if *updateGoldenFiles { ents, err := os.ReadDir("testdata") diff --git a/internal/entryhuman/testdata/allLogLevels.golden b/internal/entryhuman/testdata/allLogLevels.golden new file mode 100644 index 0000000..2745e93 --- /dev/null +++ b/internal/entryhuman/testdata/allLogLevels.golden @@ -0,0 +1 @@ +2000-02-05 04:04:04.000 [crit] critical \ No newline at end of file diff --git a/internal/entryhuman/testdata/fatalLevel.golden b/internal/entryhuman/testdata/fatalLevel.golden new file mode 100644 index 0000000..20ab42d --- /dev/null +++ b/internal/entryhuman/testdata/fatalLevel.golden @@ -0,0 +1 @@ +2000-02-05 04:04:04.000 [fata] fatal \ No newline at end of file diff --git a/internal/entryhuman/testdata/mixedPrimitiveAndComplex.golden b/internal/entryhuman/testdata/mixedPrimitiveAndComplex.golden new file mode 100644 index 0000000..bc456ce --- /dev/null +++ b/internal/entryhuman/testdata/mixedPrimitiveAndComplex.golden @@ -0,0 +1 @@ +2000-02-05 04:04:04.000 [debu] mixed types count=100 name=test enabled=true ratio=0.95 data="bytes" nil_val= \ No newline at end of file diff --git a/internal/entryhuman/testdata/primitiveEdgeCases.golden b/internal/entryhuman/testdata/primitiveEdgeCases.golden new file mode 100644 index 0000000..6a07d08 --- /dev/null +++ b/internal/entryhuman/testdata/primitiveEdgeCases.golden @@ -0,0 +1 @@ +2000-02-05 04:04:04.000 [warn] edge cases zero_int=0 neg_int=-999 max_int64=9223372036854775807 min_int64=-9223372036854775808 max_uint64=18446744073709551615 zero_float=0 neg_float=-123.456 \ No newline at end of file diff --git a/internal/entryhuman/testdata/primitiveTypes.golden b/internal/entryhuman/testdata/primitiveTypes.golden new file mode 100644 index 0000000..cb68693 --- /dev/null +++ b/internal/entryhuman/testdata/primitiveTypes.golden @@ -0,0 +1 @@ +2000-02-05 04:04:04.000 [info] primitives bool_true=true bool_false=false int=42 int8=-8 int16=-16 int32=-32 int64=-64 uint=42 uint8=8 uint16=16 uint32=32 uint64=64 float32=3.14 float64=2.71828 \ No newline at end of file diff --git a/sloggers/sloghuman/sloghuman.go b/sloggers/sloghuman/sloghuman.go index 5247d17..f6754c5 100644 --- a/sloggers/sloghuman/sloghuman.go +++ b/sloggers/sloghuman/sloghuman.go @@ -3,7 +3,6 @@ package sloghuman // import "cdr.dev/slog/sloggers/sloghuman" import ( - "bufio" "bytes" "context" "io" @@ -42,26 +41,45 @@ func (s humanSink) LogEntry(ctx context.Context, ent slog.SinkEntry) { buf1.Reset() defer bufPool.Put(buf1) + entryhuman.Fmt(buf1, s.w2, ent) + by := buf1.Bytes() + + // Prepare output buffer and indent lines after the first. buf2 := bufPool.Get().(*bytes.Buffer) buf2.Reset() defer bufPool.Put(buf2) - entryhuman.Fmt(buf1, s.w2, ent) + // Pre-grow: worst-case add 4 spaces per non-empty line after the first. + newlines := bytes.Count(by, []byte{'\n'}) + buf2.Grow(len(by) + newlines*4) - var ( - i int - sc = bufio.NewScanner(buf1) - ) + start := 0 + lineIdx := 0 + for { + idx := bytes.IndexByte(by[start:], '\n') + var line []byte + if idx >= 0 { + line = by[start : start+idx] + } else { + line = by[start:] + } - // We need to add 4 spaces before every field line for readability. - // humanfmt doesn't do it for us because the testSink doesn't want - // it as *testing.T automatically does it. - for ; sc.Scan(); i++ { - if i > 0 && len(sc.Bytes()) > 0 { - buf2.Write([]byte(" ")) + if lineIdx > 0 && len(line) > 0 { + buf2.WriteString(" ") } - buf2.Write(sc.Bytes()) + buf2.Write(line) buf2.WriteByte('\n') + + if idx < 0 { + break + } + start += idx + 1 + lineIdx++ + if start >= len(by) { + // The original logic always wrote a trailing newline + // even for an empty last line; we already wrote it. + break + } } s.w.Write("sloghuman", buf2.Bytes()) diff --git a/sloggers/sloghuman/sloghuman_bench_test.go b/sloggers/sloghuman/sloghuman_bench_test.go new file mode 100644 index 0000000..15734cc --- /dev/null +++ b/sloggers/sloghuman/sloghuman_bench_test.go @@ -0,0 +1,206 @@ +package sloghuman_test + +import ( + "bytes" + "context" + "io" + "strconv" + "strings" + "testing" + "time" + + "cdr.dev/slog" + "cdr.dev/slog/internal/entryhuman" + "cdr.dev/slog/sloggers/sloghuman" +) + +func multiline(n int) string { + var b strings.Builder + b.Grow(n * 8) + for i := 0; i < n; i++ { + b.WriteString("line-") + b.WriteString(strconv.Itoa(i)) + b.WriteByte('\n') + } + return b.String() +} + +// Benchmarks target the human sink path: humanSink.LogEntry -> entryhuman.Fmt -> bufio.Scanner indent. +func BenchmarkHumanSinkLogEntry(b *testing.B) { + s := sloghuman.Sink(io.Discard) + testcases := []struct { + name string + entry slog.SinkEntry + }{ + { + "SingleLine", + slog.SinkEntry{ + Time: time.Unix(0, 0), + Level: slog.LevelInfo, + Message: "hello world", + Fields: slog.M( + slog.F("k1", "v1"), + slog.F("k2", 123), + ), + }, + }, + { + "MultiLineFieldSmall", + slog.SinkEntry{ + Time: time.Unix(0, 0), + Level: slog.LevelInfo, + Fields: slog.M( + slog.F("msg", "..."), + slog.F("stack", multiline(10)), // forces multiline field handling in Fmt + ), + }, + }, + { + "MultilineMultifieldLarge", + slog.SinkEntry{ + Time: time.Unix(0, 0), + Level: slog.LevelInfo, + Fields: slog.M( + slog.F("msg", "..."), + slog.F("stack", multiline(1000)), + ), + }, + }, + { + "MultilineMessage", + slog.SinkEntry{ + Time: time.Unix(0, 0), + Level: slog.LevelInfo, + Message: "line1\nline2\nline3\nline4\nline5", + Fields: nil, + }, + }, + { + "StringHeavy", + slog.SinkEntry{ + Time: time.Unix(0, 0), + Level: slog.LevelInfo, + Message: "user action", + Fields: slog.M( + slog.F("user_id", "abc-123-def-456-ghi-789"), + slog.F("action", "login"), + slog.F("ip_address", "192.168.1.100"), + slog.F("user_agent", "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36"), + slog.F("session_id", "sess_9d8f7a6b5c4e3d2a1b0c"), + slog.F("request_id", "req_1a2b3c4d5e6f7g8h9i0j"), + slog.F("endpoint", "/api/v1/users/login"), + slog.F("method", "POST"), + ), + }, + }, + } + for _, tc := range testcases { + b.Run(tc.name, func(b *testing.B) { + ctx := context.Background() + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + s.LogEntry(ctx, tc.entry) + } + }) + } +} + +func genMultiline(n int) string { + var b strings.Builder + b.Grow(n * 8) + for i := 0; i < n; i++ { + b.WriteString("line-") + b.WriteString(strconv.Itoa(i)) + b.WriteByte('\n') + } + return b.String() +} + +func BenchmarkFmt(b *testing.B) { + testcases := []struct { + name string + entry slog.SinkEntry + }{ + { + "WithSpan", + slog.SinkEntry{ + Time: time.Unix(0, 0), + Level: slog.LevelInfo, + Message: "msg", + Fields: slog.M(slog.F("k", "v")), + }, + }, + { + "WithValidSpan", + slog.SinkEntry{ + Time: time.Unix(0, 0), + Level: slog.LevelInfo, + Message: "msg", + Fields: slog.M(slog.F("k", "v")), + }, + }, + { + "WithNames", + slog.SinkEntry{ + Time: time.Unix(0, 0), + Level: slog.LevelInfo, + Message: "msg", + LoggerNames: []string{"svc", "sub", "component"}, + Fields: slog.M(slog.F("k", "v")), + }, + }, + { + "SingleLine", + slog.SinkEntry{ + Time: time.Unix(0, 0), + Level: slog.LevelInfo, + Message: "hello world", + Fields: slog.M( + slog.F("k1", "v1"), + slog.F("k2", 123), + ), + }, + }, + { + "MultilineMsg", + slog.SinkEntry{ + Time: time.Unix(0, 0), + Level: slog.LevelInfo, + Message: "line1\nline2\nline3\nline4\nline5", + }, + }, + { + "MultilineMultifieldSmall", + slog.SinkEntry{ + Time: time.Unix(0, 0), + Level: slog.LevelInfo, + Fields: slog.M( + slog.F("msg", "..."), + slog.F("stack", genMultiline(10)), + ), + }, + }, + { + "MultilineMultifieldLarge", + slog.SinkEntry{ + Time: time.Unix(0, 0), + Level: slog.LevelInfo, + Fields: slog.M( + slog.F("msg", "..."), + slog.F("stack", genMultiline(1000)), + ), + }, + }, + } + for _, tc := range testcases { + b.Run(tc.name, func(b *testing.B) { + w := io.Discard + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + entryhuman.Fmt(bytes.NewBuffer(nil), w, tc.entry) + } + }) + } +} diff --git a/sloggers/slogtest/t.go b/sloggers/slogtest/t.go index b1fbc86..8c0f328 100644 --- a/sloggers/slogtest/t.go +++ b/sloggers/slogtest/t.go @@ -6,11 +6,11 @@ package slogtest // import "cdr.dev/slog/sloggers/slogtest" import ( + "bytes" "context" "fmt" "log" "os" - "strings" "sync" "testing" @@ -97,7 +97,7 @@ func (ts *testSink) LogEntry(_ context.Context, ent slog.SinkEntry) { return } - var sb strings.Builder + var sb bytes.Buffer // The testing package logs to stdout and not stderr. entryhuman.Fmt(&sb, os.Stdout, ent)