From cd3ce0c7a415db4f4e1b04815600a224aba795e2 Mon Sep 17 00:00:00 2001 From: Marko Date: Tue, 22 Oct 2024 19:43:32 +0200 Subject: [PATCH] perf(log): use sonic json lib (#22233) --- log/CHANGELOG.md | 4 ++ log/go.mod | 9 ++++- log/go.sum | 38 +++++++++++++++++-- log/level_test.go | 94 +++++++++++++++++++++++++++++++++------------- log/logger.go | 10 +++-- log/logger_test.go | 45 ++++++++++++---------- log/writer.go | 5 ++- log/writer_test.go | 14 ++++--- 8 files changed, 156 insertions(+), 63 deletions(-) diff --git a/log/CHANGELOG.md b/log/CHANGELOG.md index c9f2475683e9..72b4e6d1adf7 100644 --- a/log/CHANGELOG.md +++ b/log/CHANGELOG.md @@ -22,6 +22,10 @@ Each entry must include the Github issue reference in the following format: ## [Unreleased] +### Improvements + +* [#22233](https://github.com/cosmos/cosmos-sdk/pull/22233) Use sonic json library for faster json handling + ## [v1.4.1](https://github.com/cosmos/cosmos-sdk/releases/tag/log/v1.4.1) - 2024-08-16 * [#21326](https://github.com/cosmos/cosmos-sdk/pull/21326) Avoid context key collision. diff --git a/log/go.mod b/log/go.mod index 8ad68695218b..292e5d973e6f 100644 --- a/log/go.mod +++ b/log/go.mod @@ -3,14 +3,19 @@ module cosmossdk.io/log go 1.20 require ( + github.com/bytedance/sonic v1.12.3 github.com/pkg/errors v0.9.1 github.com/rs/zerolog v1.33.0 - gotest.tools/v3 v3.5.1 ) require ( - github.com/google/go-cmp v0.6.0 // indirect + github.com/bytedance/sonic/loader v0.2.0 // indirect + github.com/cloudwego/base64x v0.1.4 // indirect + github.com/cloudwego/iasm v0.2.0 // indirect + github.com/klauspost/cpuid/v2 v2.0.9 // indirect github.com/mattn/go-colorable v0.1.13 // indirect github.com/mattn/go-isatty v0.0.20 // indirect + github.com/twitchyliquid64/golang-asm v0.15.1 // indirect + golang.org/x/arch v0.0.0-20210923205945-b76863e36670 // indirect golang.org/x/sys v0.22.0 // indirect ) diff --git a/log/go.sum b/log/go.sum index 12553f8dc11e..b6a141763c97 100644 --- a/log/go.sum +++ b/log/go.sum @@ -1,7 +1,20 @@ +github.com/bytedance/sonic v1.12.3 h1:W2MGa7RCU1QTeYRTPE3+88mVC0yXmsRQRChiyVocVjU= +github.com/bytedance/sonic v1.12.3/go.mod h1:B8Gt/XvtZ3Fqj+iSKMypzymZxw/FVwgIGKzMzT9r/rk= +github.com/bytedance/sonic/loader v0.1.1/go.mod h1:ncP89zfokxS5LZrJxl5z0UJcsk4M4yY2JpfqGeCtNLU= +github.com/bytedance/sonic/loader v0.2.0 h1:zNprn+lsIP06C/IqCHs3gPQIvnvpKbbxyXQP1iU4kWM= +github.com/bytedance/sonic/loader v0.2.0/go.mod h1:ncP89zfokxS5LZrJxl5z0UJcsk4M4yY2JpfqGeCtNLU= +github.com/cloudwego/base64x v0.1.4 h1:jwCgWpFanWmN8xoIUHa2rtzmkd5J2plF/dnLS6Xd/0Y= +github.com/cloudwego/base64x v0.1.4/go.mod h1:0zlkT4Wn5C6NdauXdJRhSKRlJvmclQ1hhJgA0rcu/8w= +github.com/cloudwego/iasm v0.2.0 h1:1KNIy1I1H9hNNFEEH3DVnI4UujN+1zjpuk6gwHLTssg= +github.com/cloudwego/iasm v0.2.0/go.mod h1:8rXZaNYT2n95jn+zTI1sDr+IgcD2GVs0nlbbQPiEFhY= github.com/coreos/go-systemd/v22 v22.5.0/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc= +github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= +github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= +github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA= -github.com/google/go-cmp v0.6.0 h1:ofyhxvXcZhMsU5ulbFiLKl/XBFqE1GSq7atu8tAmTRI= -github.com/google/go-cmp v0.6.0/go.mod h1:17dUlkBOakJ0+DkrSSNjCkIjxS6bF9zb3elmeNGIjoY= +github.com/klauspost/cpuid/v2 v2.0.9 h1:lgaqFMSdTdQYdZ04uHyN2d/eKdOMyi2YLSvlQIBFYa4= +github.com/klauspost/cpuid/v2 v2.0.9/go.mod h1:FInQzS24/EEf25PyTYn52gqo7WaD8xa0213Md/qVLRg= +github.com/knz/go-libedit v1.10.1/go.mod h1:MZTVkCWyz0oBc7JOWP3wNAzd002ZbM/5hgShxwh4x8M= github.com/mattn/go-colorable v0.1.13 h1:fFA4WZxdEF4tXPZVKMLwD8oUnCTTo08duU7wxecdEvA= github.com/mattn/go-colorable v0.1.13/go.mod h1:7S9/ev0klgBDR4GtXTXX8a3vIGJpMovkB8vQcUbaXHg= github.com/mattn/go-isatty v0.0.16/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM= @@ -10,13 +23,30 @@ github.com/mattn/go-isatty v0.0.20 h1:xfD0iDuEKnDkl03q4limB+vH+GxLEtL/jb4xVJSWWE github.com/mattn/go-isatty v0.0.20/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y= github.com/pkg/errors v0.9.1 h1:FEBLx1zS214owpjy7qsBeixbURkuhQAwrK5UwLGTwt4= github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0= +github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= +github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= github.com/rs/xid v1.5.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg= github.com/rs/zerolog v1.33.0 h1:1cU2KZkvPxNyfgEmhHAz/1A9Bz+llsdYzklWFzgp0r8= github.com/rs/zerolog v1.33.0/go.mod h1:/7mN4D5sKwJLZQ2b/znpjC3/GQWY/xaDXUM0kKWRHss= +github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= +github.com/stretchr/objx v0.4.0/go.mod h1:YvHI0jy2hoMjB+UWwv71VJQ9isScKT/TqJzVSSt89Yw= +github.com/stretchr/objx v0.5.0/go.mod h1:Yh+to48EsGEfYuaHDzXPcE3xhTkx73EhmCGUpEOglKo= +github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg= +github.com/stretchr/testify v1.7.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg= +github.com/stretchr/testify v1.8.0/go.mod h1:yNjHg4UonilssWZ8iaSj1OCr/vHnekPRkoO+kdMU+MU= +github.com/stretchr/testify v1.8.1 h1:w7B6lhMri9wdJUVmEZPGGhZzrYTPvgJArz7wNPgYKsk= +github.com/stretchr/testify v1.8.1/go.mod h1:w2LPCIKwWwSfY2zedu0+kehJoqGctiVI29o6fzry7u4= +github.com/twitchyliquid64/golang-asm v0.15.1 h1:SU5vSMR7hnwNxj24w34ZyCi/FmDZTkS4MhqMhdFk5YI= +github.com/twitchyliquid64/golang-asm v0.15.1/go.mod h1:a1lVb/DtPvCB8fslRZhAngC2+aY1QWCk3Cedj/Gdt08= +golang.org/x/arch v0.0.0-20210923205945-b76863e36670 h1:18EFjUmQOcUvxNYSkA6jO9VAiXCnxFY6NyDX0bHDmkU= +golang.org/x/arch v0.0.0-20210923205945-b76863e36670/go.mod h1:5om86z9Hs0C8fWVUuoMHwpExlXzs5Tkyp9hOrfG7pp8= golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.12.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.22.0 h1:RI27ohtqKCnwULzJLqkv897zojh5/DwS/ENaMzUOaWI= golang.org/x/sys v0.22.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA= -gotest.tools/v3 v3.5.1 h1:EENdUnS3pdur5nybKYIh2Vfgc8IUNBjxDPSjtiJcOzU= -gotest.tools/v3 v3.5.1/go.mod h1:isy3WKz7GK6uNw/sbHzfKBLvlvXwUyV06n6brMxxopU= +gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= +gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= +gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA= +gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= +nullprogram.com/x/optparse v1.0.0/go.mod h1:KdyPE+Igbe0jQUrVfMqDMeJQIJZEuyV7pjYmp6pbG50= diff --git a/log/level_test.go b/log/level_test.go index e893ca424274..9b7e2a5ac103 100644 --- a/log/level_test.go +++ b/log/level_test.go @@ -3,46 +3,88 @@ package log_test import ( "testing" - "gotest.tools/v3/assert" - "cosmossdk.io/log" ) func TestParseLogLevel(t *testing.T) { _, err := log.ParseLogLevel("") - assert.Error(t, err, "empty log level") + if err == nil { + t.Errorf("expected error for empty log level, got nil") + } level := "consensus:foo,mempool:debug,*:error" _, err = log.ParseLogLevel(level) - assert.Error(t, err, "invalid log level foo in log level list [consensus:foo mempool:debug *:error]") + if err == nil { + t.Errorf("expected error for invalid log level foo in log level list [consensus:foo mempool:debug *:error], got nil") + } level = "consensus:debug,mempool:debug,*:error" filter, err := log.ParseLogLevel(level) - assert.NilError(t, err) - assert.Assert(t, filter != nil) - - assert.Assert(t, !filter("consensus", "debug")) - assert.Assert(t, !filter("consensus", "info")) - assert.Assert(t, !filter("consensus", "error")) - assert.Assert(t, !filter("mempool", "debug")) - assert.Assert(t, !filter("mempool", "info")) - assert.Assert(t, !filter("mempool", "error")) - assert.Assert(t, !filter("state", "error")) - assert.Assert(t, !filter("server", "panic")) - - assert.Assert(t, filter("server", "debug")) - assert.Assert(t, filter("state", "debug")) - assert.Assert(t, filter("state", "info")) + if err != nil { + t.Errorf("unexpected error: %v", err) + } + if filter == nil { + t.Fatalf("expected non-nil filter, got nil") + } + + if filter("consensus", "debug") { + t.Errorf("expected filter to return false for consensus:debug") + } + if filter("consensus", "info") { + t.Errorf("expected filter to return false for consensus:info") + } + if filter("consensus", "error") { + t.Errorf("expected filter to return false for consensus:error") + } + if filter("mempool", "debug") { + t.Errorf("expected filter to return false for mempool:debug") + } + if filter("mempool", "info") { + t.Errorf("expected filter to return false for mempool:info") + } + if filter("mempool", "error") { + t.Errorf("expected filter to return false for mempool:error") + } + if filter("state", "error") { + t.Errorf("expected filter to return false for state:error") + } + if filter("server", "panic") { + t.Errorf("expected filter to return false for server:panic") + } + + if !filter("server", "debug") { + t.Errorf("expected filter to return true for server:debug") + } + if !filter("state", "debug") { + t.Errorf("expected filter to return true for state:debug") + } + if !filter("state", "info") { + t.Errorf("expected filter to return true for state:info") + } level = "error" filter, err = log.ParseLogLevel(level) - assert.NilError(t, err) - assert.Assert(t, filter != nil) + if err != nil { + t.Errorf("unexpected error: %v", err) + } + if filter == nil { + t.Fatalf("expected non-nil filter, got nil") + } - assert.Assert(t, !filter("state", "error")) - assert.Assert(t, !filter("consensus", "error")) + if filter("state", "error") { + t.Errorf("expected filter to return false for state:error") + } + if filter("consensus", "error") { + t.Errorf("expected filter to return false for consensus:error") + } - assert.Assert(t, filter("consensus", "debug")) - assert.Assert(t, filter("consensus", "info")) - assert.Assert(t, filter("state", "debug")) + if !filter("consensus", "debug") { + t.Errorf("expected filter to return true for consensus:debug") + } + if !filter("consensus", "info") { + t.Errorf("expected filter to return true for consensus:info") + } + if !filter("state", "debug") { + t.Errorf("expected filter to return true for state:debug") + } } diff --git a/log/logger.go b/log/logger.go index 8a27538e80ff..ef9928029edb 100644 --- a/log/logger.go +++ b/log/logger.go @@ -6,6 +6,7 @@ import ( "fmt" "io" + "github.com/bytedance/sonic" "github.com/pkg/errors" "github.com/rs/zerolog" "github.com/rs/zerolog/pkgerrors" @@ -15,13 +16,13 @@ func init() { zerolog.InterfaceMarshalFunc = func(i any) ([]byte, error) { switch v := i.(type) { case json.Marshaler: - return json.Marshal(i) + return sonic.Marshal(i) case encoding.TextMarshaler: - return json.Marshal(i) + return sonic.Marshal(i) case fmt.Stringer: - return json.Marshal(v.String()) + return sonic.Marshal(v.String()) default: - return json.Marshal(i) + return sonic.Marshal(i) } } } @@ -112,6 +113,7 @@ func NewLogger(dst io.Writer, options ...Option) Logger { } logger := zerolog.New(output) + if logCfg.StackTrace { zerolog.ErrorStackMarshaler = func(err error) interface{} { return pkgerrors.MarshalStack(errors.WithStack(err)) diff --git a/log/logger_test.go b/log/logger_test.go index 534183e524e9..752026a25bd8 100644 --- a/log/logger_test.go +++ b/log/logger_test.go @@ -7,27 +7,10 @@ import ( "testing" "github.com/rs/zerolog" - "gotest.tools/v3/assert" "cosmossdk.io/log" ) -func TestLoggerOptionStackTrace(t *testing.T) { - buf := new(bytes.Buffer) - logger := log.NewLogger(buf, log.TraceOption(true), log.ColorOption(false)) - logger.Error("this log should be displayed", "error", inner()) - if strings.Count(buf.String(), "logger_test.go") != 1 { - t.Fatalf("stack trace not found, got: %s", buf.String()) - } - buf.Reset() - - logger = log.NewLogger(buf, log.TraceOption(false), log.ColorOption(false)) - logger.Error("this log should be displayed", "error", inner()) - if strings.Count(buf.String(), "logger_test.go") > 0 { - t.Fatalf("stack trace found, got: %s", buf.String()) - } -} - func inner() error { return errors.New("seems we have an error here") } @@ -46,11 +29,33 @@ func TestLoggerOptionHooks(t *testing.T) { ) logger := log.NewLogger(buf, log.HooksOption(mockHook1, mockHook2), log.ColorOption(false)) logger.Info("hello world") - assert.Assert(t, strings.Contains(buf.String(), "mock_message1=true")) - assert.Assert(t, strings.Contains(buf.String(), "mock_message2=true")) + if !strings.Contains(buf.String(), "mock_message1=true") { + t.Fatalf("expected mock_message1=true, got: %s", buf.String()) + } + if !strings.Contains(buf.String(), "mock_message2=true") { + t.Fatalf("expected mock_message2=true, got: %s", buf.String()) + } buf.Reset() logger = log.NewLogger(buf, log.HooksOption(), log.ColorOption(false)) logger.Info("hello world") - assert.Assert(t, strings.Contains(buf.String(), "hello world")) + if !strings.Contains(buf.String(), "hello world") { + t.Fatalf("expected hello world, got: %s", buf.String()) + } +} + +func TestLoggerOptionStackTrace(t *testing.T) { + buf := new(bytes.Buffer) + logger := log.NewLogger(buf, log.TraceOption(true), log.ColorOption(false)) + logger.Error("this log should be displayed", "error", inner()) + if strings.Count(buf.String(), "logger_test.go") != 1 { + t.Fatalf("stack trace not found, got: %s", buf.String()) + } + buf.Reset() + + logger = log.NewLogger(buf, log.TraceOption(false), log.ColorOption(false)) + logger.Error("this log should be displayed", "error", inner()) + if strings.Count(buf.String(), "logger_test.go") > 0 { + t.Fatalf("stack trace found, got: %s", buf.String()) + } } diff --git a/log/writer.go b/log/writer.go index 9c6befef71fe..d6f0dc2381cb 100644 --- a/log/writer.go +++ b/log/writer.go @@ -1,9 +1,10 @@ package log import ( - "encoding/json" "fmt" "io" + + "github.com/bytedance/sonic" ) // NewFilterWriter returns a writer that filters out all key/value pairs that do not match the filter. @@ -28,7 +29,7 @@ func (fw *filterWriter) Write(p []byte) (n int, err error) { Module string `json:"module"` } - if err := json.Unmarshal(p, &event); err != nil { + if err := sonic.Unmarshal(p, &event); err != nil { return 0, fmt.Errorf("failed to unmarshal event: %w", err) } diff --git a/log/writer_test.go b/log/writer_test.go index 1c43030f8d7e..d69d6ccdd60c 100644 --- a/log/writer_test.go +++ b/log/writer_test.go @@ -5,8 +5,6 @@ import ( "strings" "testing" - "gotest.tools/v3/assert" - "cosmossdk.io/log" ) @@ -15,13 +13,19 @@ func TestFilteredWriter(t *testing.T) { level := "consensus:debug,mempool:debug,*:error" filter, err := log.ParseLogLevel(level) - assert.NilError(t, err) + if err != nil { + t.Fatalf("failed to parse log level: %v", err) + } logger := log.NewLogger(buf, log.FilterOption(filter)) logger.Debug("this log line should be displayed", log.ModuleKey, "consensus") - assert.Check(t, strings.Contains(buf.String(), "this log line should be displayed")) + if !strings.Contains(buf.String(), "this log line should be displayed") { + t.Errorf("expected log line to be displayed, but it was not") + } buf.Reset() logger.Debug("this log line should be filtered", log.ModuleKey, "server") - assert.Check(t, buf.Len() == 0) + if buf.Len() != 0 { + t.Errorf("expected log line to be filtered, but it was not") + } }