diff --git a/internal/entryhuman/entry.go b/internal/entryhuman/entry.go index 8af4d82..6708fc3 100644 --- a/internal/entryhuman/entry.go +++ b/internal/entryhuman/entry.go @@ -88,60 +88,165 @@ 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 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 +258,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/new_entry b/internal/entryhuman/new_entry new file mode 100644 index 0000000..562143e --- /dev/null +++ b/internal/entryhuman/new_entry @@ -0,0 +1,66 @@ +goos: darwin +goarch: arm64 +pkg: cdr.dev/slog/internal/entryhuman +cpu: Apple M4 Pro +BenchmarkFmt/Colored-nf=1-12 269846 4442 ns/op 1994 B/op 119 allocs/op +BenchmarkFmt/Colored-nf=1-12 279056 4421 ns/op 1994 B/op 119 allocs/op +BenchmarkFmt/Colored-nf=1-12 266496 4414 ns/op 1994 B/op 119 allocs/op +BenchmarkFmt/Colored-nf=1-12 269301 4373 ns/op 1994 B/op 119 allocs/op +BenchmarkFmt/Colored-nf=1-12 275001 4399 ns/op 1994 B/op 119 allocs/op +BenchmarkFmt/Colored-nf=1-12 274089 4504 ns/op 1994 B/op 119 allocs/op +BenchmarkFmt/Colored-nf=1-12 259311 4450 ns/op 1994 B/op 119 allocs/op +BenchmarkFmt/Colored-nf=1-12 272248 4437 ns/op 1994 B/op 119 allocs/op +BenchmarkFmt/Colored-nf=1-12 272348 4420 ns/op 1994 B/op 119 allocs/op +BenchmarkFmt/Colored-nf=1-12 271333 4406 ns/op 1994 B/op 119 allocs/op +BenchmarkFmt/Colored-nf=4-12 111796 10667 ns/op 4669 B/op 300 allocs/op +BenchmarkFmt/Colored-nf=4-12 113119 10787 ns/op 4669 B/op 300 allocs/op +BenchmarkFmt/Colored-nf=4-12 109360 10920 ns/op 4669 B/op 300 allocs/op +BenchmarkFmt/Colored-nf=4-12 109830 10845 ns/op 4669 B/op 300 allocs/op +BenchmarkFmt/Colored-nf=4-12 110982 10928 ns/op 4669 B/op 300 allocs/op +BenchmarkFmt/Colored-nf=4-12 109868 10828 ns/op 4669 B/op 300 allocs/op +BenchmarkFmt/Colored-nf=4-12 111752 10993 ns/op 4669 B/op 300 allocs/op +BenchmarkFmt/Colored-nf=4-12 110218 10928 ns/op 4669 B/op 300 allocs/op +BenchmarkFmt/Colored-nf=4-12 111771 11054 ns/op 4669 B/op 300 allocs/op +BenchmarkFmt/Colored-nf=4-12 109627 11004 ns/op 4669 B/op 300 allocs/op +BenchmarkFmt/Colored-nf=16-12 32572 36878 ns/op 14345 B/op 1021 allocs/op +BenchmarkFmt/Colored-nf=16-12 32392 37065 ns/op 14345 B/op 1021 allocs/op +BenchmarkFmt/Colored-nf=16-12 31656 36563 ns/op 14345 B/op 1021 allocs/op +BenchmarkFmt/Colored-nf=16-12 32716 36595 ns/op 14345 B/op 1021 allocs/op +BenchmarkFmt/Colored-nf=16-12 32643 36689 ns/op 14344 B/op 1021 allocs/op +BenchmarkFmt/Colored-nf=16-12 33141 36715 ns/op 14345 B/op 1021 allocs/op +BenchmarkFmt/Colored-nf=16-12 32709 36536 ns/op 14345 B/op 1021 allocs/op +BenchmarkFmt/Colored-nf=16-12 32095 37598 ns/op 14344 B/op 1021 allocs/op +BenchmarkFmt/Colored-nf=16-12 32638 36983 ns/op 14345 B/op 1021 allocs/op +BenchmarkFmt/Colored-nf=16-12 32463 36885 ns/op 14345 B/op 1021 allocs/op +BenchmarkFmt/nf=1-12 3690738 323.5 ns/op 184 B/op 9 allocs/op +BenchmarkFmt/nf=1-12 3740504 322.6 ns/op 184 B/op 9 allocs/op +BenchmarkFmt/nf=1-12 3741657 322.0 ns/op 184 B/op 9 allocs/op +BenchmarkFmt/nf=1-12 3716818 321.0 ns/op 184 B/op 9 allocs/op +BenchmarkFmt/nf=1-12 3765878 320.6 ns/op 184 B/op 9 allocs/op +BenchmarkFmt/nf=1-12 3714015 321.4 ns/op 184 B/op 9 allocs/op +BenchmarkFmt/nf=1-12 3722384 321.4 ns/op 184 B/op 9 allocs/op +BenchmarkFmt/nf=1-12 3746545 318.7 ns/op 184 B/op 9 allocs/op +BenchmarkFmt/nf=1-12 3775784 321.2 ns/op 184 B/op 9 allocs/op +BenchmarkFmt/nf=1-12 3700758 322.1 ns/op 184 B/op 9 allocs/op +BenchmarkFmt/nf=4-12 1418212 836.5 ns/op 456 B/op 28 allocs/op +BenchmarkFmt/nf=4-12 1450852 824.9 ns/op 456 B/op 28 allocs/op +BenchmarkFmt/nf=4-12 1456974 831.9 ns/op 456 B/op 28 allocs/op +BenchmarkFmt/nf=4-12 1432821 831.1 ns/op 456 B/op 28 allocs/op +BenchmarkFmt/nf=4-12 1444159 836.3 ns/op 456 B/op 28 allocs/op +BenchmarkFmt/nf=4-12 1368248 850.0 ns/op 456 B/op 28 allocs/op +BenchmarkFmt/nf=4-12 1419829 843.4 ns/op 456 B/op 28 allocs/op +BenchmarkFmt/nf=4-12 1432812 840.5 ns/op 456 B/op 28 allocs/op +BenchmarkFmt/nf=4-12 1440943 833.4 ns/op 456 B/op 28 allocs/op +BenchmarkFmt/nf=4-12 1432062 843.1 ns/op 456 B/op 28 allocs/op +BenchmarkFmt/nf=16-12 426823 2811 ns/op 1288 B/op 101 allocs/op +BenchmarkFmt/nf=16-12 427839 2799 ns/op 1288 B/op 101 allocs/op +BenchmarkFmt/nf=16-12 429816 2799 ns/op 1288 B/op 101 allocs/op +BenchmarkFmt/nf=16-12 439380 2779 ns/op 1288 B/op 101 allocs/op +BenchmarkFmt/nf=16-12 434738 2842 ns/op 1288 B/op 101 allocs/op +BenchmarkFmt/nf=16-12 391664 2908 ns/op 1288 B/op 101 allocs/op +BenchmarkFmt/nf=16-12 423054 2835 ns/op 1288 B/op 101 allocs/op +BenchmarkFmt/nf=16-12 423688 2843 ns/op 1288 B/op 101 allocs/op +BenchmarkFmt/nf=16-12 416474 2863 ns/op 1288 B/op 101 allocs/op +BenchmarkFmt/nf=16-12 421389 2803 ns/op 1288 B/op 101 allocs/op +PASS +ok cdr.dev/slog/internal/entryhuman 90.528s diff --git a/internal/entryhuman/orig_entry b/internal/entryhuman/orig_entry new file mode 100644 index 0000000..b542b67 --- /dev/null +++ b/internal/entryhuman/orig_entry @@ -0,0 +1,66 @@ +goos: darwin +goarch: arm64 +pkg: cdr.dev/slog/internal/entryhuman +cpu: Apple M4 Pro +BenchmarkFmt/Colored-nf=1-12 269304 4448 ns/op 2034 B/op 122 allocs/op +BenchmarkFmt/Colored-nf=1-12 273135 4448 ns/op 2034 B/op 122 allocs/op +BenchmarkFmt/Colored-nf=1-12 267333 4455 ns/op 2034 B/op 122 allocs/op +BenchmarkFmt/Colored-nf=1-12 272311 4458 ns/op 2034 B/op 122 allocs/op +BenchmarkFmt/Colored-nf=1-12 268456 4489 ns/op 2034 B/op 122 allocs/op +BenchmarkFmt/Colored-nf=1-12 266517 4489 ns/op 2034 B/op 122 allocs/op +BenchmarkFmt/Colored-nf=1-12 268579 4481 ns/op 2034 B/op 122 allocs/op +BenchmarkFmt/Colored-nf=1-12 263763 4487 ns/op 2034 B/op 122 allocs/op +BenchmarkFmt/Colored-nf=1-12 265862 4460 ns/op 2034 B/op 122 allocs/op +BenchmarkFmt/Colored-nf=1-12 264967 4464 ns/op 2034 B/op 122 allocs/op +BenchmarkFmt/Colored-nf=4-12 112771 10783 ns/op 4709 B/op 303 allocs/op +BenchmarkFmt/Colored-nf=4-12 111157 10915 ns/op 4709 B/op 303 allocs/op +BenchmarkFmt/Colored-nf=4-12 110229 10892 ns/op 4709 B/op 303 allocs/op +BenchmarkFmt/Colored-nf=4-12 109729 10922 ns/op 4709 B/op 303 allocs/op +BenchmarkFmt/Colored-nf=4-12 108057 10865 ns/op 4709 B/op 303 allocs/op +BenchmarkFmt/Colored-nf=4-12 111726 10717 ns/op 4709 B/op 303 allocs/op +BenchmarkFmt/Colored-nf=4-12 111646 10732 ns/op 4709 B/op 303 allocs/op +BenchmarkFmt/Colored-nf=4-12 107232 10950 ns/op 4709 B/op 303 allocs/op +BenchmarkFmt/Colored-nf=4-12 111188 10845 ns/op 4709 B/op 303 allocs/op +BenchmarkFmt/Colored-nf=4-12 109567 10868 ns/op 4709 B/op 303 allocs/op +BenchmarkFmt/Colored-nf=16-12 33309 36225 ns/op 14385 B/op 1024 allocs/op +BenchmarkFmt/Colored-nf=16-12 33093 37350 ns/op 14384 B/op 1024 allocs/op +BenchmarkFmt/Colored-nf=16-12 32305 37010 ns/op 14385 B/op 1024 allocs/op +BenchmarkFmt/Colored-nf=16-12 32649 37053 ns/op 14385 B/op 1024 allocs/op +BenchmarkFmt/Colored-nf=16-12 33194 36146 ns/op 14385 B/op 1024 allocs/op +BenchmarkFmt/Colored-nf=16-12 33139 36181 ns/op 14385 B/op 1024 allocs/op +BenchmarkFmt/Colored-nf=16-12 33471 39460 ns/op 14385 B/op 1024 allocs/op +BenchmarkFmt/Colored-nf=16-12 32377 36778 ns/op 14385 B/op 1024 allocs/op +BenchmarkFmt/Colored-nf=16-12 32793 36540 ns/op 14385 B/op 1024 allocs/op +BenchmarkFmt/Colored-nf=16-12 33226 36042 ns/op 14385 B/op 1024 allocs/op +BenchmarkFmt/nf=1-12 3228714 366.9 ns/op 224 B/op 12 allocs/op +BenchmarkFmt/nf=1-12 3217460 374.9 ns/op 224 B/op 12 allocs/op +BenchmarkFmt/nf=1-12 3219823 370.4 ns/op 224 B/op 12 allocs/op +BenchmarkFmt/nf=1-12 3256626 367.3 ns/op 224 B/op 12 allocs/op +BenchmarkFmt/nf=1-12 3231498 368.7 ns/op 224 B/op 12 allocs/op +BenchmarkFmt/nf=1-12 3286234 369.1 ns/op 224 B/op 12 allocs/op +BenchmarkFmt/nf=1-12 3221338 370.1 ns/op 224 B/op 12 allocs/op +BenchmarkFmt/nf=1-12 3158478 375.5 ns/op 224 B/op 12 allocs/op +BenchmarkFmt/nf=1-12 3192966 374.9 ns/op 224 B/op 12 allocs/op +BenchmarkFmt/nf=1-12 3212212 372.8 ns/op 224 B/op 12 allocs/op +BenchmarkFmt/nf=4-12 1334484 921.6 ns/op 496 B/op 31 allocs/op +BenchmarkFmt/nf=4-12 1316500 903.2 ns/op 496 B/op 31 allocs/op +BenchmarkFmt/nf=4-12 1330128 897.0 ns/op 496 B/op 31 allocs/op +BenchmarkFmt/nf=4-12 1333930 898.4 ns/op 496 B/op 31 allocs/op +BenchmarkFmt/nf=4-12 1331115 892.0 ns/op 496 B/op 31 allocs/op +BenchmarkFmt/nf=4-12 1345486 900.4 ns/op 496 B/op 31 allocs/op +BenchmarkFmt/nf=4-12 1352221 880.5 ns/op 496 B/op 31 allocs/op +BenchmarkFmt/nf=4-12 1356229 897.1 ns/op 496 B/op 31 allocs/op +BenchmarkFmt/nf=4-12 1341136 885.3 ns/op 496 B/op 31 allocs/op +BenchmarkFmt/nf=4-12 1344148 905.6 ns/op 496 B/op 31 allocs/op +BenchmarkFmt/nf=16-12 415588 2850 ns/op 1328 B/op 104 allocs/op +BenchmarkFmt/nf=16-12 417280 2866 ns/op 1328 B/op 104 allocs/op +BenchmarkFmt/nf=16-12 424370 2876 ns/op 1328 B/op 104 allocs/op +BenchmarkFmt/nf=16-12 421772 2836 ns/op 1328 B/op 104 allocs/op +BenchmarkFmt/nf=16-12 424786 2883 ns/op 1328 B/op 104 allocs/op +BenchmarkFmt/nf=16-12 407095 2856 ns/op 1328 B/op 104 allocs/op +BenchmarkFmt/nf=16-12 429909 2840 ns/op 1328 B/op 104 allocs/op +BenchmarkFmt/nf=16-12 427279 2921 ns/op 1328 B/op 104 allocs/op +BenchmarkFmt/nf=16-12 403155 2945 ns/op 1328 B/op 104 allocs/op +BenchmarkFmt/nf=16-12 419020 2878 ns/op 1328 B/op 104 allocs/op +PASS +ok cdr.dev/slog/internal/entryhuman 91.606s diff --git a/internal/entryhuman/out.txt b/internal/entryhuman/out.txt new file mode 100644 index 0000000..189af87 --- /dev/null +++ b/internal/entryhuman/out.txt @@ -0,0 +1,241 @@ +diff --git a/internal/entryhuman/entry.go b/internal/entryhuman/entry.go +index d11db4f..14bb884 100644 +--- a/internal/entryhuman/entry.go ++++ b/internal/entryhuman/entry.go +@@ -282,57 +282,37 @@ func Fmt( + + // OptimizedFmt 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 neceesary than for an arbitrary io.Writer/io.StringWriter ++// 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 OptimizedFmt( +- buf *bytes.Buffer, +- termW io.Writer, +- ent slog.SinkEntry, +-) error { +- writeString := func(s string) error { +- _, err := buf.WriteString(s) +- return err +- } +- ++func OptimizedFmt(buf *bytes.Buffer, termW io.Writer, ent slog.SinkEntry) { + reset(buf, termW) + + // Timestamp + space +- if err := writeString(render(termW, timeStyle, ent.Time.Format(TimeFormat))); err != nil { +- return err +- } +- if err := writeString(" "); err != nil { +- return err +- } ++ buf.WriteString(render(termW, timeStyle, ent.Time.Format(TimeFormat)+" ")) ++ buf.WriteString("") + + // Level label + two spaces + lvl := bracketedLevel(ent.Level) // e.g. "[debu]", "[info]" +- if err := writeString(render(termW, levelStyle(ent.Level), lvl)); err != nil { +- return err +- } +- if err := writeString(" "); err != nil { +- return err +- } ++ buf.WriteString(render(termW, levelStyle(ent.Level), lvl)) ++ buf.WriteString("") + + // Logger names: name1.name2.name3: (no strings.Join allocation) + if len(ent.LoggerNames) > 0 { + for i, name := range ent.LoggerNames { + if i > 0 { +- if err := writeString("."); err != nil { +- return err +- } +- } +- if err := writeString(quoteKey(name)); err != nil { +- return err ++ buf.WriteString(".") + } ++ buf.WriteString(quoteKey(name)) + } +- if err := writeString(": "); err != nil { +- return err +- } ++ buf.WriteString(": ") + } + + // Message (detect multiline) +@@ -344,40 +324,22 @@ func OptimizedFmt( + multilineVal = msg + msg = quote("...") + } +- if err := writeString(msg); err != nil { +- return err +- } ++ buf.WriteString(msg) + + keyStyle := timeStyle + equalsStyle := timeStyle + + // Write trace/span directly (do not mutate ent.Fields) + if ent.SpanContext.IsValid() { +- if err := writeString(tab); err != nil { +- return err +- } +- if err := writeString(render(termW, keyStyle, quoteKey("trace"))); err != nil { +- return err +- } +- if err := writeString(render(termW, equalsStyle, "=")); err != nil { +- return err +- } +- if err := writeString(ent.SpanContext.TraceID().String()); err != nil { +- return err +- } ++ buf.WriteString(tab) + +- if err := writeString(tab); err != nil { +- return err +- } +- if err := writeString(render(termW, keyStyle, quoteKey("span"))); err != nil { +- return err +- } +- if err := writeString(render(termW, equalsStyle, "=")); err != nil { +- return err +- } +- if err := writeString(ent.SpanContext.SpanID().String()); err != nil { +- return err +- } ++ 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. +@@ -409,84 +371,55 @@ func OptimizedFmt( + continue + } + if i < len(ent.Fields) { +- if err := writeString(tab); err != nil { +- return err +- } +- } +- if err := writeString(render(termW, keyStyle, quoteKey(f.Name))); err != nil { +- return err +- } +- if err := writeString(render(termW, equalsStyle, "=")); err != nil { +- return err ++ buf.WriteString(tab) + } + ++ buf.WriteString(render(termW, keyStyle, quoteKey(f.Name))) ++ buf.WriteString(render(termW, equalsStyle, "=")) ++ + if ok, err := writeValueFast(buf, f.Value); err != nil { +- return err ++ // return err + } else if !ok { +- if err := writeString(formatValue(f.Value)); err != nil { +- return err +- } ++ buf.WriteString(formatValue(f.Value)) + } + } + + // Multiline value block + if multilineVal != "" { + if msg != "..." { +- if err := writeString(" ..."); err != nil { +- return err +- } ++ buf.WriteString(" ...") + } + +- if err := writeString("\n"); err != nil { +- return err +- } +- if err := writeString(render(termW, keyStyle, multilineKey)); err != nil { +- return err +- } +- if err := writeString("= "); err != nil { +- return err +- } ++ buf.WriteString("\n") ++ buf.WriteString(render(termW, keyStyle, multilineKey)) ++ buf.WriteString("= ") + + // First line up to first newline + s := multilineVal + if n := strings.IndexByte(s, '\n'); n >= 0 { +- if err := writeString(s[:n]); err != nil { +- return err +- } ++ buf.WriteString(s[:n]) + s = s[n+1:] + } else { +- if err := writeString(s); err != nil { +- return err +- } ++ buf.WriteString(s) + s = "" + } + + indent := strings.Repeat(" ", len(multilineKey)+2) + for len(s) > 0 { +- if err := writeString("\n"); err != nil { +- return err +- } ++ buf.WriteString("\n") + // Only indent non-empty lines. + if s[0] != '\n' { +- if err := writeString(indent); err != nil { +- return err +- } ++ buf.WriteString(indent) + } + if n := strings.IndexByte(s, '\n'); n >= 0 { +- if err := writeString(s[:n]); err != nil { +- return err +- } ++ buf.WriteString(s[:n]) + s = s[n+1:] + } else { +- if err := writeString(s); err != nil { +- return err +- } ++ buf.WriteString(s) + break + } + } + } +- +- return nil + } + + var ( +diff --git a/internal/entryhuman/entry_test.go b/internal/entryhuman/entry_test.go +index b791b6d..87e3435 100644 +--- a/internal/entryhuman/entry_test.go ++++ b/internal/entryhuman/entry_test.go +@@ -411,10 +411,7 @@ func TestEntry_Optimized(t *testing.T) { + var optBuf bytes.Buffer + + entryhuman.Fmt(&fmtBuf, io.Discard, tc.ent) +- err := entryhuman.OptimizedFmt(&optBuf, io.Discard, tc.ent) +- if err != nil { +- t.Fatal(err) +- } ++ entryhuman.OptimizedFmt(&optBuf, io.Discard, tc.ent) + + assert.Equal(t, "outputs match", fmtBuf.String(), optBuf.String()) + }) 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..b52e6ff --- /dev/null +++ b/sloggers/sloghuman/sloghuman_bench_test.go @@ -0,0 +1,188 @@ +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, + }, + }, + } + 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)