From 747c29e8fa31e7bb171a87872e7b7c3b590b8c6c Mon Sep 17 00:00:00 2001 From: Mark Rushakoff Date: Fri, 24 Feb 2023 13:54:34 -0500 Subject: [PATCH] refactor(log): elide keyval translation to map (#15158) --- log/CHANGELOG.md | 4 ++ log/bench_test.go | 124 ++++++++++++++++++++++++++++++++++++++++++++++ log/zerolog.go | 21 ++------ 3 files changed, 132 insertions(+), 17 deletions(-) create mode 100644 log/bench_test.go diff --git a/log/CHANGELOG.md b/log/CHANGELOG.md index 16de809f27..a8878a1aa3 100644 --- a/log/CHANGELOG.md +++ b/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() diff --git a/log/bench_test.go b/log/bench_test.go new file mode 100644 index 0000000000..ed3fa9303f --- /dev/null +++ b/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...) + } + }) + } + }) +} diff --git a/log/zerolog.go b/log/zerolog.go index dc3ce5d63e..d3d60105d5 100644 --- a/log/zerolog.go +++ b/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()} }