refactor(log): elide keyval translation to map (#15158)

log/CHANGELOG.md

@@ -30,3 +30,7 @@ Ref: https://keepachangelog.com/en/1.0.0/
 # Changelog
 
 ## [Unreleased]
+
+### Improvements
+
+* [#15158](https://github.com/cosmos/cosmos-sdk/pull/15158) Ensure zero allocations during logging calls to Debug(), Info(), Error()

log/bench_test.go

@@ -0,0 +1,124 @@
+package log_test
+
+import (
+	"bytes"
+	"io"
+	"testing"
+	"time"
+
+	"cosmossdk.io/log"
+	"github.com/rs/zerolog"
+)
+
+func BenchmarkLoggers(b *testing.B) {
+	b.ReportAllocs()
+
+	type benchCase struct {
+		name    string
+		keyVals []any
+	}
+
+	// Just test two simple cases for the nop logger benchmarks.
+	nopCases := []benchCase{
+		{name: "empty key vals"},
+		{name: "single string", keyVals: []any{"foo", "bar"}},
+	}
+
+	benchCases := append(nopCases, []benchCase{
+		{
+			name:    "single small int",
+			keyVals: []any{"foo", 1},
+		},
+		{
+			// Small numbers may be optimized, so check if an unusual/larger number performs different.
+			name:    "single largeish int",
+			keyVals: []any{"foo", 123456789},
+		},
+		{
+			name:    "single float",
+			keyVals: []any{"foo", 2.71828182},
+		},
+		{
+			name:    "single byte slice",
+			keyVals: []any{"foo", []byte{0xde, 0xad, 0xbe, 0xef}},
+		},
+		{
+			name:    "single duration",
+			keyVals: []any{"foo", 10 * time.Second},
+		},
+
+		{
+			name:    "two values",
+			keyVals: []any{"foo", "foo", "bar", "bar"},
+		},
+		{
+			name:    "four values",
+			keyVals: []any{"foo", "foo", "bar", "bar", "baz", "baz", "quux", "quux"},
+		},
+		{
+			name:    "eight values",
+			keyVals: []any{"one", 1, "two", 2, "three", 3, "four", 4, "five", 5, "six", 6, "seven", 7, "eight", 8},
+		},
+	}...)
+
+	const message = "test message"
+
+	// If running with "go test -v", print out the log messages as a sanity check.
+	if testing.Verbose() {
+		checkBuf := new(bytes.Buffer)
+		for _, bc := range benchCases {
+			checkBuf.Reset()
+			logger := log.ZeroLogWrapper{Logger: zerolog.New(checkBuf)}
+			logger.Info(message, bc.keyVals...)
+
+			b.Logf("zero logger output for %s: %s", bc.name, checkBuf.String())
+		}
+	}
+
+	// The real logger exposed by this package,
+	// writing to an io.Discard writer,
+	// so that real write time is negligible.
+	b.Run("zerolog", func(b *testing.B) {
+		for _, bc := range benchCases {
+			bc := bc
+			b.Run(bc.name, func(b *testing.B) {
+				logger := log.ZeroLogWrapper{Logger: zerolog.New(io.Discard)}
+
+				for i := 0; i < b.N; i++ {
+					logger.Info(message, bc.keyVals...)
+				}
+			})
+		}
+	})
+
+	// zerolog offers a no-op writer.
+	// It appears to be slower than our custom NopLogger,
+	// so include it in the nop benchmarks as a point of reference.
+	b.Run("zerolog nop", func(b *testing.B) {
+		for _, bc := range nopCases {
+			bc := bc
+			b.Run(bc.name, func(b *testing.B) {
+				logger := log.ZeroLogWrapper{Logger: zerolog.Nop()}
+
+				for i := 0; i < b.N; i++ {
+					logger.Info(message, bc.keyVals...)
+				}
+			})
+		}
+	})
+
+	// The nop logger we use in tests,
+	// also useful as a reference for how expensive zerolog is.
+	b.Run("nop logger", func(b *testing.B) {
+		for _, bc := range nopCases {
+			bc := bc
+			b.Run(bc.name, func(b *testing.B) {
+				logger := log.NewNopLogger()
+
+				for i := 0; i < b.N; i++ {
+					logger.Info(message, bc.keyVals...)
+				}
+			})
+		}
+	})
+}

log/zerolog.go

@@ -35,39 +35,26 @@ type ZeroLogWrapper struct {
 // of key/value tuples may be provided to add context to the log. The number of
 // tuples must be even and the key of the tuple must be a string.
 func (z ZeroLogWrapper) Info(msg string, keyVals ...interface{}) {
-	z.Logger.Info().Fields(getLogFields(keyVals...)).Msg(msg)
+	z.Logger.Info().Fields(keyVals).Msg(msg)
 }
 
 // Error implements Tendermint's Logger interface and logs with level ERR. A set
 // of key/value tuples may be provided to add context to the log. The number of
 // tuples must be even and the key of the tuple must be a string.
 func (z ZeroLogWrapper) Error(msg string, keyVals ...interface{}) {
-	z.Logger.Error().Fields(getLogFields(keyVals...)).Msg(msg)
+	z.Logger.Error().Fields(keyVals).Msg(msg)
 }
 
 // Debug implements Tendermint's Logger interface and logs with level DEBUG. A set
 // of key/value tuples may be provided to add context to the log. The number of
 // tuples must be even and the key of the tuple must be a string.
 func (z ZeroLogWrapper) Debug(msg string, keyVals ...interface{}) {
-	z.Logger.Debug().Fields(getLogFields(keyVals...)).Msg(msg)
+	z.Logger.Debug().Fields(keyVals).Msg(msg)
 }
 
 // With returns a new wrapped logger with additional context provided by a set
 // of key/value tuples. The number of tuples must be even and the key of the
 // tuple must be a string.
 func (z ZeroLogWrapper) With(keyVals ...interface{}) cmtlog.Logger {
-	return ZeroLogWrapper{z.Logger.With().Fields(getLogFields(keyVals...)).Logger()}
-}
-
-func getLogFields(keyVals ...interface{}) map[string]interface{} {
-	if len(keyVals)%2 != 0 {
-		return nil
-	}
-
-	fields := make(map[string]interface{})
-	for i := 0; i < len(keyVals); i += 2 {
-		fields[keyVals[i].(string)] = keyVals[i+1]
-	}
-
-	return fields
+	return ZeroLogWrapper{z.Logger.With().Fields(keyVals).Logger()}
 }