log: lots of optimizations to terminal output

- implement custom time writer,
- better padding with spaces
- better use of spaces
- log: more efficient handling of slog.Value
- log: utilize scratch-buffer in terminal handler
- log: use scratch-space for value formatting

internal/testlog/testlog.go

@@ -183,8 +183,7 @@ func (h *bufHandler) terminalFormat(r slog.Record) string {
 	}
 
 	for _, attr := range attrs {
-		rawVal := attr.Value.Any()
+		fmt.Fprintf(buf, " %s=%s", attr.Key, string(log.FormatSlogValue(attr.Value, true, nil)))
-		fmt.Fprintf(buf, " %s=%s", attr.Key, log.FormatLogfmtValue(rawVal, true))
 	}
 	buf.WriteByte('\n')
 	return buf.String()

log/format.go

@@ -21,6 +21,9 @@ const (
 	termCtxMaxPadding = 40
 )
 
+// 40 spaces
+var spaces = []byte("                                        ")
+
 type Format interface {
 	Format(r slog.Record) []byte
 }
@@ -44,7 +47,7 @@ type TerminalStringer interface {
 	TerminalString() string
 }
 
-func (h *TerminalHandler) TerminalFormat(r slog.Record, usecolor bool) []byte {
+func (h *TerminalHandler) TerminalFormat(buf []byte, r slog.Record, usecolor bool) []byte {
 	msg := escapeMessage(r.Message)
 	var color = 0
 	if usecolor {
@@ -63,18 +66,25 @@ func (h *TerminalHandler) TerminalFormat(r slog.Record, usecolor bool) []byte {
 			color = 34
 		}
 	}
-
+	if buf == nil {
-	b := &bytes.Buffer{}
+		buf = make([]byte, 0, 30+termMsgJust)
+	}
+	b := bytes.NewBuffer(buf)
 	lvl := LevelAlignedString(r.Level)
 	if color > 0 {
+		// TODO improve this
 		fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s] %s ", color, lvl, r.Time.Format(termTimeFormat), msg)
 	} else {
-		fmt.Fprintf(b, "%s[%s] %s ", lvl, r.Time.Format(termTimeFormat), msg)
+		b.WriteString(lvl)
+		b.WriteString("[")
+		writeTimeTermFormat(b, r.Time)
+		b.WriteString("] ")
+		b.WriteString(msg)
 	}
 	// try to justify the log output for short messages
 	length := utf8.RuneCountInString(msg)
-	if r.NumAttrs() > 0 && length < termMsgJust {
+	if (r.NumAttrs()+len(h.attrs)) > 0 && length < termMsgJust {
-		b.Write(bytes.Repeat([]byte{' '}, termMsgJust-length))
+		b.Write(spaces[:termMsgJust-length])
 	}
 	// print the keys logfmt style
 	h.logfmt(b, r, color)
@@ -83,149 +93,136 @@ func (h *TerminalHandler) TerminalFormat(r slog.Record, usecolor bool) []byte {
 }
 
 func (h *TerminalHandler) logfmt(buf *bytes.Buffer, r slog.Record, color int) {
-	attrs := []slog.Attr{}
+	writeAttr := func(attr slog.Attr, first, last bool) {
-	r.Attrs(func(attr slog.Attr) bool {
+		//if !first {
-		attrs = append(attrs, attr)
-		return true
-	})
-
-	attrs = append(h.attrs, attrs...)
-
-	for i, attr := range attrs {
-		if i != 0 {
 		buf.WriteByte(' ')
-		}
+		//}
-
 		key := escapeString(attr.Key)
-		rawVal := attr.Value.Any()
-		val := FormatLogfmtValue(rawVal, true)
-
-		// XXX: we should probably check that all of your key bytes aren't invalid
-		// TODO (jwasinger) above comment was from log15 code.  what does it mean?  check that key bytes are ascii characters?
-		padding := h.fieldPadding[key]
-
-		length := utf8.RuneCountInString(val)
-		if padding < length && length <= termCtxMaxPadding {
-			padding = length
-			h.fieldPadding[key] = padding
-		}
 		if color > 0 {
+			// TODO improve this
 			fmt.Fprintf(buf, "\x1b[%dm%s\x1b[0m=", color, key)
 		} else {
 			buf.WriteString(key)
 			buf.WriteByte('=')
 		}
-		buf.WriteString(val)
+		tmp := buf.AvailableBuffer()
-		if i < r.NumAttrs()-1 && padding > length {
+		val := FormatSlogValue(attr.Value, true, tmp)
-			buf.Write(bytes.Repeat([]byte{' '}, padding-length))
+
+		// XXX: we should probably check that all of your key bytes aren't invalid
+		// TODO (jwasinger) above comment was from log15 code.  what does it mean?  check that key bytes are ascii characters?
+		padding := h.fieldPadding[attr.Key]
+
+		length := utf8.RuneCount(val)
+		if padding < length && length <= termCtxMaxPadding {
+			padding = length
+			h.fieldPadding[attr.Key] = padding
+		}
+		buf.Write(val)
+		if !last && padding > length {
+			buf.Write(spaces[:padding-length])
 		}
 	}
+	var n = 0
+	var nAttrs = len(h.attrs) + r.NumAttrs()
+	for _, attr := range h.attrs {
+		writeAttr(attr, n == 0, n == nAttrs-1)
+		n++
+	}
+	r.Attrs(func(attr slog.Attr) bool {
+		writeAttr(attr, n == 0, n == nAttrs-1)
+		n++
+		return true
+	})
 	buf.WriteByte('\n')
 }
 
-// formatValue formats a value for serialization
+// FormatSlogValue formats a slog.Value for serialization
-func FormatLogfmtValue(value interface{}, term bool) (result string) {
+func FormatSlogValue(v slog.Value, term bool, tmp []byte) (result []byte) {
-	if value == nil {
+	var value any
-		return "<nil>"
-	}
 	defer func() {
 		if err := recover(); err != nil {
 			if v := reflect.ValueOf(value); v.Kind() == reflect.Ptr && v.IsNil() {
-				result = "<nil>"
+				result = []byte("<nil>")
 			} else {
 				panic(err)
 			}
 		}
 	}()
 
-	switch v := value.(type) {
+	switch v.Kind() {
-	case time.Time:
+	case slog.KindString:
+		return appendEscapeString(tmp, v.String())
+	case slog.KindAny:
+		value = v.Any()
+	case slog.KindInt64: // All int-types (int8 ,int16 etc) wind up here
+		return appendInt64(tmp, v.Int64())
+	case slog.KindUint64: // All uint-types (int8 ,int16 etc) wind up here
+		return appendUint64(tmp, v.Uint64(), false)
+	case slog.KindFloat64:
+		return strconv.AppendFloat(tmp, v.Float64(), floatFormat, 3, 64)
+	case slog.KindBool:
+		return strconv.AppendBool(tmp, v.Bool())
+	case slog.KindDuration:
+		value = v.Duration()
+	case slog.KindTime:
 		// Performance optimization: No need for escaping since the provided
 		// timeFormat doesn't have any escape characters, and escaping is
 		// expensive.
-		return v.Format(timeFormat)
+		return v.Time().AppendFormat(tmp, timeFormat)
-
+	default:
+		value = v.Any()
+	}
+	if value == nil {
+		return []byte("nil")
+	}
+	switch v := value.(type) {
 	case *big.Int:
 		// Big ints get consumed by the Stringer clause, so we need to handle
 		// them earlier on.
 		if v == nil {
-			return "<nil>"
+			return append(tmp, []byte("<nil>")...)
 		}
-		return formatLogfmtBigInt(v)
+		return appendBigInt(tmp, v)
 
 	case *uint256.Int:
 		// Uint256s get consumed by the Stringer clause, so we need to handle
 		// them earlier on.
 		if v == nil {
-			return "<nil>"
+			return append(tmp, []byte("<nil>")...)
 		}
-		return formatLogfmtUint256(v)
+		return appendU256(tmp, v)
-	}
-	if term {
-		if s, ok := value.(TerminalStringer); ok {
-			// Custom terminal stringer provided, use that
-			return escapeString(s.TerminalString())
-		}
-	}
-	switch v := value.(type) {
 	case error:
-		return escapeString(v.Error())
+		return appendEscapeString(tmp, v.Error())
+	case TerminalStringer:
+		if term {
+			return appendEscapeString(tmp, v.TerminalString()) // Custom terminal stringer provided, use that
+		}
 	case fmt.Stringer:
-		return escapeString(v.String())
+		return appendEscapeString(tmp, v.String())
-	case bool:
-		return strconv.FormatBool(v)
-	case float32:
-		return strconv.FormatFloat(float64(v), floatFormat, 3, 64)
-	case float64:
-		return strconv.FormatFloat(v, floatFormat, 3, 64)
-	case int8:
-		return strconv.FormatInt(int64(v), 10)
-	case uint8:
-		return strconv.FormatInt(int64(v), 10)
-	case int16:
-		return strconv.FormatInt(int64(v), 10)
-	case uint16:
-		return strconv.FormatInt(int64(v), 10)
-	// Larger integers get thousands separators.
-	case int:
-		return FormatLogfmtInt64(int64(v))
-	case int32:
-		return FormatLogfmtInt64(int64(v))
-	case int64:
-		return FormatLogfmtInt64(v)
-	case uint:
-		return FormatLogfmtUint64(uint64(v))
-	case uint32:
-		return FormatLogfmtUint64(uint64(v))
-	case uint64:
-		return FormatLogfmtUint64(v)
-	case string:
-		return escapeString(v)
-	default:
-		return escapeString(fmt.Sprintf("%+v", value))
 	}
+
+	// We can use the 'tmp' as a scratch-buffer, to first format the
+	// value, and in a second step do escaping.
+	internal := fmt.Appendf(tmp, "%+v", value)
+	return appendEscapeString(tmp, string(internal))
 }
 
-// FormatLogfmtInt64 formats n with thousand separators.
+// appendInt64 formats n with thousand separators and writes into buffer dst.
-func FormatLogfmtInt64(n int64) string {
+func appendInt64(dst []byte, n int64) []byte {
 	if n < 0 {
-		return formatLogfmtUint64(uint64(-n), true)
+		return appendUint64(dst, uint64(-n), true)
 	}
-	return formatLogfmtUint64(uint64(n), false)
+	return appendUint64(dst, uint64(n), false)
 }
 
-// FormatLogfmtUint64 formats n with thousand separators.
+// appendUint64 formats n with thousand separators and writes into buffer dst.
-func FormatLogfmtUint64(n uint64) string {
+func appendUint64(dst []byte, n uint64, neg bool) []byte {
-	return formatLogfmtUint64(n, false)
-}
-
-func formatLogfmtUint64(n uint64, neg bool) string {
 	// Small numbers are fine as is
 	if n < 100000 {
 		if neg {
-			return strconv.Itoa(-int(n))
+			return strconv.AppendInt(dst, -int64(n), 10)
 		} else {
-			return strconv.Itoa(int(n))
+			return strconv.AppendInt(dst, int64(n), 10)
 		}
 	}
 	// Large numbers should be split
@@ -250,16 +247,21 @@ func formatLogfmtUint64(n uint64, neg bool) string {
 		out[i] = '-'
 		i--
 	}
-	return string(out[i+1:])
+	return append(dst, out[i+1:]...)
 }
 
-// formatLogfmtBigInt formats n with thousand separators.
+// FormatLogfmtUint64 formats n with thousand separators.
-func formatLogfmtBigInt(n *big.Int) string {
+func FormatLogfmtUint64(n uint64) string {
+	return string(appendUint64(nil, n, false))
+}
+
+// appendBigInt formats n with thousand separators and writes to dst.
+func appendBigInt(dst []byte, n *big.Int) []byte {
 	if n.IsUint64() {
-		return FormatLogfmtUint64(n.Uint64())
+		return appendUint64(dst, n.Uint64(), false)
 	}
 	if n.IsInt64() {
-		return FormatLogfmtInt64(n.Int64())
+		return appendInt64(dst, n.Int64())
 	}
 
 	var (
@@ -284,37 +286,33 @@ func formatLogfmtBigInt(n *big.Int) string {
 			comma++
 		}
 	}
-	return string(buf[i+1:])
+	return append(dst, buf[i+1:]...)
 }
 
-// formatLogfmtUint256 formats n with thousand separators.
+// appendU256 formats n with thousand separators.
-func formatLogfmtUint256(n *uint256.Int) string {
+func appendU256(dst []byte, n *uint256.Int) []byte {
 	if n.IsUint64() {
-		return FormatLogfmtUint64(n.Uint64())
+		return appendUint64(dst, n.Uint64(), false)
 	}
-	var (
+	res := []byte(n.PrettyDec(','))
-		text  = n.Dec()
+	return append(dst, res...)
-		buf   = make([]byte, len(text)+len(text)/3)
+}
-		comma = 0
-		i     = len(buf) - 1
-	)
-	for j := len(text) - 1; j >= 0; j, i = j-1, i-1 {
-		c := text[j]
 
-		switch {
+// appendEscapeString writes the string s to the given writer, with
-		case c == '-':
+// escaping/quoting if needed.
-			buf[i] = c
+func appendEscapeString(dst []byte, s string) []byte {
-		case comma == 3:
+	needsQuoting := false
-			buf[i] = ','
+	for _, r := range s {
-			i--
+		// We quote everything below " (0x22) and above~ (0x7E), plus equal-sign
-			comma = 0
+		if r <= '"' || r > '~' || r == '=' {
-			fallthrough
+			needsQuoting = true
-		default:
+			break
-			buf[i] = c
-			comma++
 		}
 	}
-	return string(buf[i+1:])
+	if !needsQuoting {
+		return append(dst, []byte(s)...)
+	}
+	return strconv.AppendQuote(dst, s)
 }
 
 // escapeString checks if the provided string needs escaping/quoting, and
@@ -356,3 +354,45 @@ func escapeMessage(s string) string {
 	}
 	return strconv.Quote(s)
 }
+
+// writeTimeTermFormat
+func writeTimeTermFormat(buf *bytes.Buffer, t time.Time) {
+	_, month, day := t.Date()
+	writePosIntWidth(buf, int(month), 2)
+	buf.WriteByte('-')
+	writePosIntWidth(buf, day, 2)
+	buf.WriteByte('|')
+	hour, min, sec := t.Clock()
+	writePosIntWidth(buf, hour, 2)
+	buf.WriteByte(':')
+	writePosIntWidth(buf, min, 2)
+	buf.WriteByte(':')
+	writePosIntWidth(buf, sec, 2)
+	ns := t.Nanosecond()
+	buf.WriteByte('.')
+	writePosIntWidth(buf, ns/1e6, 3)
+}
+
+// writePosIntWidth writes non-negative integer i to the buffer, padded on the left
+// by zeroes to the given width. Use a width of 0 to omit padding.
+// Adapted from golang.org/x/exp/slog/internal/buffer/buffer.go
+func writePosIntWidth(b *bytes.Buffer, i, width int) {
+	// Cheap integer to fixed-width decimal ASCII.
+	// Copied from log/log.go.
+	if i < 0 {
+		panic("negative int")
+	}
+	// Assemble decimal in reverse order.
+	var bb [20]byte
+	bp := len(bb) - 1
+	for i >= 10 || width > 1 {
+		width--
+		q := i / 10
+		bb[bp] = byte('0' + i - q*10)
+		bp--
+		i = q
+	}
+	// i < 10
+	bb[bp] = byte('0' + i)
+	b.Write(bb[bp:])
+}

log/format_test.go

@@ -5,18 +5,20 @@ import (
 	"testing"
 )
 
-var sink string
+var sink []byte
 
 func BenchmarkPrettyInt64Logfmt(b *testing.B) {
+	buf := make([]byte, 100)
 	b.ReportAllocs()
 	for i := 0; i < b.N; i++ {
-		sink = FormatLogfmtInt64(rand.Int63())
+		sink = appendInt64(buf, rand.Int63())
 	}
 }
 
 func BenchmarkPrettyUint64Logfmt(b *testing.B) {
+	buf := make([]byte, 100)
 	b.ReportAllocs()
 	for i := 0; i < b.N; i++ {
-		sink = FormatLogfmtUint64(rand.Uint64())
+		sink = appendUint64(buf, rand.Uint64(), false)
 	}
 }

log/handler.go

@@ -81,6 +81,8 @@ type TerminalHandler struct {
 	// fieldPadding is a map with maximum field value lengths seen until now
 	// to allow padding log contexts in a bit smarter way.
 	fieldPadding map[string]int
+
+	buf []byte
 }
 
 // NewTerminalHandler returns a handler which formats log records at all levels optimized for human readability on
@@ -110,7 +112,9 @@ func NewTerminalHandlerWithLevel(wr io.Writer, lvl slog.Level, useColor bool) *T
 func (h *TerminalHandler) Handle(_ context.Context, r slog.Record) error {
 	h.mu.Lock()
 	defer h.mu.Unlock()
-	h.wr.Write(h.TerminalFormat(r, h.useColor))
+	buf := h.TerminalFormat(h.buf, r, h.useColor)
+	h.wr.Write(buf)
+	h.buf = buf[:0]
 	return nil
 }