improve textlogger

.github/workflows/test.yml

@@ -30,7 +30,7 @@ jobs:
       - name: Lint
         run: |
           docker run --rm -v `pwd`:/go/src/k8s.io/klog -w /go/src/k8s.io/klog \
-            golangci/golangci-lint:v1.23.8 golangci-lint run --disable-all -v \
+            golangci/golangci-lint:v1.50.1 golangci-lint run --disable-all -v \
             -E govet -E misspell -E gofmt -E ineffassign -E golint
   apidiff:
     runs-on: ubuntu-latest

examples/output_test/output_test.go

@@ -34,40 +34,13 @@ import (
 	"k8s.io/klog/v2/textlogger"
 )
 
-func init() {
-	test.InitKlog()
-}
-
-// TestKlogOutput tests klog output without a logger.
-func TestKlogOutput(t *testing.T) {
-	test.Output(t, test.OutputConfig{})
-}
-
-// TestTextloggerOutput tests the textlogger, directly and as backend.
-func TestTextloggerOutput(t *testing.T) {
-	newLogger := func(out io.Writer, v int, vmodule string) logr.Logger {
-		config := textlogger.NewConfig(
-			textlogger.Verbosity(v),
-			textlogger.Output(out),
-		)
-		if err := config.VModule().Set(vmodule); err != nil {
-			panic(err)
-		}
-		return textlogger.NewLogger(config)
-	}
-	t.Run("direct", func(t *testing.T) {
-		test.Output(t, test.OutputConfig{NewLogger: newLogger, SupportsVModule: true})
-	})
-	t.Run("klog-backend", func(t *testing.T) {
-		test.Output(t, test.OutputConfig{NewLogger: newLogger, AsBackend: true})
-	})
+func newLogger(out io.Writer, v int, vmodule string) logr.Logger {
+	return newZaprLogger(out, v)
 }
 
 // TestZaprOutput tests the zapr, directly and as backend.
 func TestZaprOutput(t *testing.T) {
-	newLogger := func(out io.Writer, v int, vmodule string) logr.Logger {
-		return newZaprLogger(out, v)
-	}
+	test.InitKlog(t)
 	t.Run("direct", func(t *testing.T) {
 		test.Output(t, test.OutputConfig{NewLogger: newLogger, ExpectedOutputMapping: test.ZaprOutputMappingDirect()})
 	})
@@ -76,17 +49,15 @@ func TestZaprOutput(t *testing.T) {
 	})
 }
 
-// TestKlogrOutput tests klogr output via klog.
-func TestKlogrOutput(t *testing.T) {
-	test.Output(t, test.OutputConfig{
-		NewLogger: func(out io.Writer, v int, vmodule string) logr.Logger {
-			return klogr.NewWithOptions(klogr.WithFormat(klogr.FormatKlog))
-		},
-	})
+// Benchmark direct zapr output.
+func BenchmarkZaprOutput(b *testing.B) {
+	test.InitKlog(b)
+	test.Benchmark(b, test.OutputConfig{NewLogger: newLogger, ExpectedOutputMapping: test.ZaprOutputMappingDirect()})
 }
 
 // TestKlogrStackText tests klogr.klogr -> klog -> text logger.
 func TestKlogrStackText(t *testing.T) {
+	test.InitKlog(t)
 	newLogger := func(out io.Writer, v int, vmodule string) logr.Logger {
 		// Backend: text output.
 		config := textlogger.NewConfig(
@@ -110,6 +81,7 @@ func TestKlogrStackText(t *testing.T) {
 // (https://github.com/kubernetes/klog/issues/294) because klogr logging
 // records that.
 func TestKlogrStackZapr(t *testing.T) {
+	test.InitKlog(t)
 	mapping := test.ZaprOutputMappingIndirect()
 
 	// klogr doesn't warn about invalid KVs and just inserts
@@ -150,6 +122,7 @@ func TestKlogrStackZapr(t *testing.T) {
 
 // TestKlogrInternalStackText tests klog.klogr (the simplified version used for contextual logging) -> klog -> text logger.
 func TestKlogrInternalStackText(t *testing.T) {
+	test.InitKlog(t)
 	newLogger := func(out io.Writer, v int, vmodule string) logr.Logger {
 		// Backend: text output.
 		config := textlogger.NewConfig(
@@ -173,6 +146,7 @@ func TestKlogrInternalStackText(t *testing.T) {
 // (https://github.com/kubernetes/klog/issues/294) because klogr logging
 // records that.
 func TestKlogrInternalStackZapr(t *testing.T) {
+	test.InitKlog(t)
 	mapping := test.ZaprOutputMappingIndirect()
 
 	// klogr doesn't warn about invalid KVs and just inserts

internal/buffer/buffer.go

@@ -40,44 +40,22 @@ type Buffer struct {
 	next *Buffer
 }
 
-// Buffers manages the reuse of individual buffer instances. It is thread-safe.
-type Buffers struct {
-	// mu protects the free list. It is separate from the main mutex
-	// so buffers can be grabbed and printed to without holding the main lock,
-	// for better parallelization.
-	mu sync.Mutex
-
-	// freeList is a list of byte buffers, maintained under mu.
-	freeList *Buffer
+var buffers = sync.Pool{
+	New: func() interface{} {
+		return new(Buffer)
+	},
 }
 
 // GetBuffer returns a new, ready-to-use buffer.
-func (bl *Buffers) GetBuffer() *Buffer {
-	bl.mu.Lock()
-	b := bl.freeList
-	if b != nil {
-		bl.freeList = b.next
-	}
-	bl.mu.Unlock()
-	if b == nil {
-		b = new(Buffer)
-	} else {
-		b.next = nil
-		b.Reset()
-	}
+func GetBuffer() *Buffer {
+	b := buffers.Get().(*Buffer)
+	b.Reset()
 	return b
 }
 
 // PutBuffer returns a buffer to the free list.
-func (bl *Buffers) PutBuffer(b *Buffer) {
-	if b.Len() >= 256 {
-		// Let big buffers die a natural death.
-		return
-	}
-	bl.mu.Lock()
-	b.next = bl.freeList
-	bl.freeList = b
-	bl.mu.Unlock()
+func PutBuffer(b *Buffer) {
+	buffers.Put(b)
 }
 
 // Some custom tiny helper functions to print the log header efficiently.

internal/serialize/keyvalues.go

@@ -24,6 +24,10 @@ import (
 	"github.com/go-logr/logr"
 )
 
+type textWriter interface {
+	WriteText(*bytes.Buffer)
+}
+
 // WithValues implements LogSink.WithValues. The old key/value pairs are
 // assumed to be well-formed, the new ones are checked and padded if
 // necessary. It returns a new slice.
@@ -91,6 +95,51 @@ func MergeKVs(first, second []interface{}) []interface{} {
 	return merged
 }
 
+// MergeKVsInto is a variant of MergeKVs which directly formats the key/value
+// pairs into a buffer.
+func MergeAndFormatKVs(b *bytes.Buffer, first, second []interface{}) {
+	if len(first) == 0 && len(second) == 0 {
+		// Nothing to do at all.
+		return
+	}
+
+	if len(first) == 0 && len(second)%2 == 0 {
+		// Nothing to be overridden, second slice is well-formed
+		// and can be used directly.
+		for i := 0; i < len(second); i += 2 {
+			KVFormat(b, second[i], second[i+1])
+		}
+		return
+	}
+
+	// Determine which keys are in the second slice so that we can skip
+	// them when iterating over the first one. The code intentionally
+	// favors performance over completeness: we assume that keys are string
+	// constants and thus compare equal when the string values are equal. A
+	// string constant being overridden by, for example, a fmt.Stringer is
+	// not handled.
+	overrides := map[interface{}]bool{}
+	for i := 0; i < len(second); i += 2 {
+		overrides[second[i]] = true
+	}
+	for i := 0; i < len(first); i += 2 {
+		key := first[i]
+		if overrides[key] {
+			continue
+		}
+		KVFormat(b, key, first[i+1])
+	}
+	// Round down.
+	l := len(second)
+	l = l / 2 * 2
+	for i := 1; i < l; i += 2 {
+		KVFormat(b, second[i-1], second[i])
+	}
+	if len(second)%2 == 1 {
+		KVFormat(b, second[len(second)-1], missingValue)
+	}
+}
+
 const missingValue = "(MISSING)"
 
 // KVListFormat serializes all key/value pairs into the provided buffer.
@@ -104,66 +153,74 @@ func KVListFormat(b *bytes.Buffer, keysAndValues ...interface{}) {
 		} else {
 			v = missingValue
 		}
-		b.WriteByte(' ')
-		// Keys are assumed to be well-formed according to
-		// https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/migration-to-structured-logging.md#name-arguments
-		// for the sake of performance. Keys with spaces,
-		// special characters, etc. will break parsing.
-		if sK, ok := k.(string); ok {
-			// Avoid one allocation when the key is a string, which
-			// normally it should be.
-			b.WriteString(sK)
-		} else {
-			b.WriteString(fmt.Sprintf("%s", k))
-		}
+		KVFormat(b, k, v)
+	}
+}
+
+// KVFormat serializes one key/value pair into the provided buffer.
+// A space gets inserted before the pair.
+func KVFormat(b *bytes.Buffer, k, v interface{}) {
+	b.WriteByte(' ')
+	// Keys are assumed to be well-formed according to
+	// https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/migration-to-structured-logging.md#name-arguments
+	// for the sake of performance. Keys with spaces,
+	// special characters, etc. will break parsing.
+	if sK, ok := k.(string); ok {
+		// Avoid one allocation when the key is a string, which
+		// normally it should be.
+		b.WriteString(sK)
+	} else {
+		b.WriteString(fmt.Sprintf("%s", k))
+	}
 
-		// The type checks are sorted so that more frequently used ones
-		// come first because that is then faster in the common
-		// cases. In Kubernetes, ObjectRef (a Stringer) is more common
-		// than plain strings
-		// (https://github.com/kubernetes/kubernetes/pull/106594#issuecomment-975526235).
-		switch v := v.(type) {
-		case fmt.Stringer:
-			writeStringValue(b, true, StringerToString(v))
+	// The type checks are sorted so that more frequently used ones
+	// come first because that is then faster in the common
+	// cases. In Kubernetes, ObjectRef (a Stringer) is more common
+	// than plain strings
+	// (https://github.com/kubernetes/kubernetes/pull/106594#issuecomment-975526235).
+	switch v := v.(type) {
+	case textWriter:
+		writeTextWriterValue(b, v)
+	case fmt.Stringer:
+		writeStringValue(b, true, StringerToString(v))
+	case string:
+		writeStringValue(b, true, v)
+	case error:
+		writeStringValue(b, true, ErrorToString(v))
+	case logr.Marshaler:
+		value := MarshalerToValue(v)
+		// A marshaler that returns a string is useful for
+		// delayed formatting of complex values. We treat this
+		// case like a normal string. This is useful for
+		// multi-line support.
+		//
+		// We could do this by recursively formatting a value,
+		// but that comes with the risk of infinite recursion
+		// if a marshaler returns itself. Instead we call it
+		// only once and rely on it returning the intended
+		// value directly.
+		switch value := value.(type) {
 		case string:
-			writeStringValue(b, true, v)
-		case error:
-			writeStringValue(b, true, ErrorToString(v))
-		case logr.Marshaler:
-			value := MarshalerToValue(v)
-			// A marshaler that returns a string is useful for
-			// delayed formatting of complex values. We treat this
-			// case like a normal string. This is useful for
-			// multi-line support.
-			//
-			// We could do this by recursively formatting a value,
-			// but that comes with the risk of infinite recursion
-			// if a marshaler returns itself. Instead we call it
-			// only once and rely on it returning the intended
-			// value directly.
-			switch value := value.(type) {
-			case string:
-				writeStringValue(b, true, value)
-			default:
-				writeStringValue(b, false, fmt.Sprintf("%+v", value))
-			}
-		case []byte:
-			// In https://github.com/kubernetes/klog/pull/237 it was decided
-			// to format byte slices with "%+q". The advantages of that are:
-			// - readable output if the bytes happen to be printable
-			// - non-printable bytes get represented as unicode escape
-			//   sequences (\uxxxx)
-			//
-			// The downsides are that we cannot use the faster
-			// strconv.Quote here and that multi-line output is not
-			// supported. If developers know that a byte array is
-			// printable and they want multi-line output, they can
-			// convert the value to string before logging it.
-			b.WriteByte('=')
-			b.WriteString(fmt.Sprintf("%+q", v))
+			writeStringValue(b, true, value)
 		default:
-			writeStringValue(b, false, fmt.Sprintf("%+v", v))
+			writeStringValue(b, false, fmt.Sprintf("%+v", value))
 		}
+	case []byte:
+		// In https://github.com/kubernetes/klog/pull/237 it was decided
+		// to format byte slices with "%+q". The advantages of that are:
+		// - readable output if the bytes happen to be printable
+		// - non-printable bytes get represented as unicode escape
+		//   sequences (\uxxxx)
+		//
+		// The downsides are that we cannot use the faster
+		// strconv.Quote here and that multi-line output is not
+		// supported. If developers know that a byte array is
+		// printable and they want multi-line output, they can
+		// convert the value to string before logging it.
+		b.WriteByte('=')
+		b.WriteString(fmt.Sprintf("%+q", v))
+	default:
+		writeStringValue(b, false, fmt.Sprintf("%+v", v))
 	}
 }
 
@@ -203,6 +260,16 @@ func ErrorToString(err error) (ret string) {
 	return
 }
 
+func writeTextWriterValue(b *bytes.Buffer, v textWriter) {
+	b.WriteRune('=')
+	defer func() {
+		if err := recover(); err != nil {
+			fmt.Fprintf(b, `"<panic: %s>"`, err)
+		}
+	}()
+	v.WriteText(b)
+}
+
 func writeStringValue(b *bytes.Buffer, quote bool, v string) {
 	data := []byte(v)
 	index := bytes.IndexByte(data, '\n')