From 0c8b6ca8c79239d3dc7b6351af0fc080c2ddc7c8 Mon Sep 17 00:00:00 2001 From: Martin Holst Swende Date: Tue, 7 Nov 2023 19:20:58 +0100 Subject: [PATCH] log: better benchmark --- log/logger_test.go | 117 +++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 117 insertions(+) diff --git a/log/logger_test.go b/log/logger_test.go index fca1f1680f..5caac705e7 100644 --- a/log/logger_test.go +++ b/log/logger_test.go @@ -2,10 +2,15 @@ package log import ( "bytes" + "fmt" + "io" + "math/big" "os" "strings" "testing" + "time" + "github.com/holiman/uint256" "golang.org/x/exp/slog" ) @@ -51,3 +56,115 @@ func BenchmarkTraceLogging(b *testing.B) { Trace("a message", "v", i) } } + +func BenchmarkGloggerTerminal(b *testing.B) { + glogHandler := NewGlogHandler(NewTerminalHandler(io.Discard, false)) + glogHandler.Verbosity(LevelInfo) + l := NewLogger(glogHandler) + + type custom struct { + A string + B int8 + } + var ( + bb = make([]byte, 10) + tt = time.Now() + bigint = big.NewInt(100) + nilbig *big.Int + err = fmt.Errorf("Oh nooes it's crap") + ) + + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + l.Info("This is a message", + "foo", int16(i), + "bytes", bb, + "bonk", "a string with text", + "time", tt, + "bigint", bigint, + "nilbig", nilbig, + "err", err) + } + b.StopTimer() +} + +func TestLoggerOutput(t *testing.T) { + type custom struct { + A string + B int8 + } + var ( + customA = custom{"Foo", 12} + customB = custom{"Foo\nLinebreak", 122} + bb = make([]byte, 10) + tt = time.Time{} + bigint = big.NewInt(100) + nilbig *big.Int + err = fmt.Errorf("Oh nooes it's crap") + lazy = Lazy{Fn: func() interface{} { return "lazy value" }} + smallUint = uint256.NewInt(500_000) + bigUint = &uint256.Int{0xff, 0xff, 0xff, 0xff} + ) + + out := new(bytes.Buffer) + glogHandler := NewGlogHandler(NewTerminalHandler(out, false)) + glogHandler.Verbosity(LevelInfo) + NewLogger(glogHandler).Info("This is a message", + "foo", int16(123), + "bytes", bb, + "bonk", "a string with text", + "time", tt, + "bigint", bigint, + "nilbig", nilbig, + "err", err, + "struct", customA, + "struct", customB, + "ptrstruct", &customA, + "lazy", lazy, + "smalluint", smallUint, + "bigUint", bigUint) + + have := out.String() + t.Logf("output %v", out.String()) + want := `INFO [11-07|19:14:33.821] This is a message foo=123 bytes="[0 0 0 0 0 0 0 0 0 0]" bonk="a string with text" time=0001-01-01T00:00:00+0000 bigint=100 nilbig= err="Oh nooes it's crap" struct="{A:Foo B:12}" struct="{A:Foo\nLinebreak B:122}" ptrstruct="&{A:Foo B:12}" lazy="lazy value" smalluint=500,000 bigUint=1,600,660,942,523,603,594,864,898,306,482,794,244,293,965,082,972,225,630,372,095 +` + if !bytes.Equal([]byte(have)[25:], []byte(want)[25:]) { + t.Errorf("Error\nhave: %q\nwant: %q", have, want) + } + +} + +func BenchmarkAppendFormat(b *testing.B) { + var now = time.Now() + + b.Run("fmt time.Format", func(b *testing.B) { + for i := 0; i < b.N; i++ { + fmt.Fprintf(io.Discard, "%s", now.Format(termTimeFormat)) + + } + }) + b.Run("time.AppendFormat", func(b *testing.B) { + for i := 0; i < b.N; i++ { + now.AppendFormat(nil, termTimeFormat) + } + }) + //var buf = new(bytes.Buffer) + //b.Run("time.Custom", func(b *testing.B) { + // for i := 0; i < b.N; i++ { + // writeTimeTermFormat(buf, now) + // buf.Reset() + // } + //}) +} + +//func TestTimeFormat(t *testing.T) { +// var now = time.Now() +// want := now.AppendFormat(nil, termTimeFormat) +// var b = new(bytes.Buffer) +// writeTimeTermFormat(b, now) +// have := b.Bytes() +// if !bytes.Equal(have, want) { +// t.Errorf("have != want\nhave: %q\nwant: %q\n", have, want) +// } +//}