perf(log): use sonic json lib (#22233)

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.

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
 )

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=

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")
+	}
 }

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))

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())
+	}
 }

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)
 	}
 

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")
+	}
 }