Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

perf(log): use sonic json lib #22233

Merged
merged 5 commits into from
Oct 22, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 4 additions & 0 deletions log/CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
9 changes: 7 additions & 2 deletions log/go.mod
Original file line number Diff line number Diff line change
Expand Up @@ -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
)
38 changes: 34 additions & 4 deletions log/go.sum
Original file line number Diff line number Diff line change
@@ -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=
Expand All @@ -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=
94 changes: 68 additions & 26 deletions log/level_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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")
}
}
10 changes: 6 additions & 4 deletions log/logger.go
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@ import (
"fmt"
"io"

"github.com/bytedance/sonic"
"github.com/pkg/errors"
"github.com/rs/zerolog"
"github.com/rs/zerolog/pkgerrors"
Expand All @@ -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)
}
}
}
Expand Down Expand Up @@ -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))
Expand Down
45 changes: 25 additions & 20 deletions log/logger_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -7,27 +7,10 @@ import (
"testing"

"github.com/rs/zerolog"
"gotest.tools/v3/assert"

"cosmossdk.io/log"
)

func TestLoggerOptionStackTrace(t *testing.T) {
tac0turtle marked this conversation as resolved.
Show resolved Hide resolved
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")
}
Expand All @@ -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())
}
}
5 changes: 3 additions & 2 deletions log/writer.go
Original file line number Diff line number Diff line change
@@ -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.
Expand All @@ -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)
}

Expand Down
14 changes: 9 additions & 5 deletions log/writer_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -5,8 +5,6 @@ import (
"strings"
"testing"

"gotest.tools/v3/assert"

"cosmossdk.io/log"
)

Expand All @@ -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")
}
}
Loading