2023-09-07 12:48:49 +00:00
|
|
|
package log
|
|
|
|
|
|
|
|
import (
|
|
|
|
"bytes"
|
slog: faster and less memory-consumption (#28621)
These changes improves the performance of the non-coloured terminal formatting, _quite a lot_.
```
name old time/op new time/op delta
TerminalHandler-8 10.2µs ±15% 5.4µs ± 9% -47.02% (p=0.008 n=5+5)
name old alloc/op new alloc/op delta
TerminalHandler-8 2.17kB ± 0% 0.40kB ± 0% -81.46% (p=0.008 n=5+5)
name old allocs/op new allocs/op delta
TerminalHandler-8 33.0 ± 0% 5.0 ± 0% -84.85% (p=0.008 n=5+5)
```
I tried to _somewhat_ organize the commits, but the it might still be a bit chaotic. Some core insights:
- The function `terminalHandler.Handl` uses a mutex, and writes all output immediately to 'upstream'. Thus, it can reuse a scratch-buffer every time.
- This buffer can be propagated internally, making all the internal formatters either write directly to it,
- OR, make use of the `tmp := buf.AvailableBuffer()` in some cases, where a byte buffer "extra capacity" can be temporarily used.
- The `slog` package uses `Attr` by value. It makes sense to minimize operating on them, since iterating / collecting into a new slice, iterating again etc causes copy-on-heap. Better to operate on them only once.
- If we want to do padding, it's better to copy from a constant `space`-buffer than to invoke `bytes.Repeat` every single time.
2023-12-01 12:28:20 +00:00
|
|
|
"fmt"
|
|
|
|
"io"
|
|
|
|
"math/big"
|
2023-09-07 12:48:49 +00:00
|
|
|
"os"
|
|
|
|
"strings"
|
|
|
|
"testing"
|
slog: faster and less memory-consumption (#28621)
These changes improves the performance of the non-coloured terminal formatting, _quite a lot_.
```
name old time/op new time/op delta
TerminalHandler-8 10.2µs ±15% 5.4µs ± 9% -47.02% (p=0.008 n=5+5)
name old alloc/op new alloc/op delta
TerminalHandler-8 2.17kB ± 0% 0.40kB ± 0% -81.46% (p=0.008 n=5+5)
name old allocs/op new allocs/op delta
TerminalHandler-8 33.0 ± 0% 5.0 ± 0% -84.85% (p=0.008 n=5+5)
```
I tried to _somewhat_ organize the commits, but the it might still be a bit chaotic. Some core insights:
- The function `terminalHandler.Handl` uses a mutex, and writes all output immediately to 'upstream'. Thus, it can reuse a scratch-buffer every time.
- This buffer can be propagated internally, making all the internal formatters either write directly to it,
- OR, make use of the `tmp := buf.AvailableBuffer()` in some cases, where a byte buffer "extra capacity" can be temporarily used.
- The `slog` package uses `Attr` by value. It makes sense to minimize operating on them, since iterating / collecting into a new slice, iterating again etc causes copy-on-heap. Better to operate on them only once.
- If we want to do padding, it's better to copy from a constant `space`-buffer than to invoke `bytes.Repeat` every single time.
2023-12-01 12:28:20 +00:00
|
|
|
"time"
|
2023-11-29 07:33:50 +00:00
|
|
|
|
slog: faster and less memory-consumption (#28621)
These changes improves the performance of the non-coloured terminal formatting, _quite a lot_.
```
name old time/op new time/op delta
TerminalHandler-8 10.2µs ±15% 5.4µs ± 9% -47.02% (p=0.008 n=5+5)
name old alloc/op new alloc/op delta
TerminalHandler-8 2.17kB ± 0% 0.40kB ± 0% -81.46% (p=0.008 n=5+5)
name old allocs/op new allocs/op delta
TerminalHandler-8 33.0 ± 0% 5.0 ± 0% -84.85% (p=0.008 n=5+5)
```
I tried to _somewhat_ organize the commits, but the it might still be a bit chaotic. Some core insights:
- The function `terminalHandler.Handl` uses a mutex, and writes all output immediately to 'upstream'. Thus, it can reuse a scratch-buffer every time.
- This buffer can be propagated internally, making all the internal formatters either write directly to it,
- OR, make use of the `tmp := buf.AvailableBuffer()` in some cases, where a byte buffer "extra capacity" can be temporarily used.
- The `slog` package uses `Attr` by value. It makes sense to minimize operating on them, since iterating / collecting into a new slice, iterating again etc causes copy-on-heap. Better to operate on them only once.
- If we want to do padding, it's better to copy from a constant `space`-buffer than to invoke `bytes.Repeat` every single time.
2023-12-01 12:28:20 +00:00
|
|
|
"github.com/holiman/uint256"
|
2023-11-29 07:33:50 +00:00
|
|
|
"golang.org/x/exp/slog"
|
2023-09-07 12:48:49 +00:00
|
|
|
)
|
|
|
|
|
2023-11-29 07:33:50 +00:00
|
|
|
// TestLoggingWithVmodule checks that vmodule works.
|
|
|
|
func TestLoggingWithVmodule(t *testing.T) {
|
2023-09-07 12:48:49 +00:00
|
|
|
out := new(bytes.Buffer)
|
2023-11-29 07:33:50 +00:00
|
|
|
glog := NewGlogHandler(NewTerminalHandlerWithLevel(out, LevelTrace, false))
|
|
|
|
glog.Verbosity(LevelCrit)
|
|
|
|
logger := NewLogger(glog)
|
|
|
|
logger.Warn("This should not be seen", "ignored", "true")
|
|
|
|
glog.Vmodule("logger_test.go=5")
|
|
|
|
logger.Trace("a message", "foo", "bar")
|
2023-09-07 12:48:49 +00:00
|
|
|
have := out.String()
|
|
|
|
// The timestamp is locale-dependent, so we want to trim that off
|
|
|
|
// "INFO [01-01|00:00:00.000] a messag ..." -> "a messag..."
|
|
|
|
have = strings.Split(have, "]")[1]
|
2023-11-29 07:33:50 +00:00
|
|
|
want := " a message foo=bar\n"
|
|
|
|
if have != want {
|
|
|
|
t.Errorf("\nhave: %q\nwant: %q\n", have, want)
|
2023-09-07 12:48:49 +00:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2023-11-29 07:33:50 +00:00
|
|
|
func TestTerminalHandlerWithAttrs(t *testing.T) {
|
2023-09-07 12:48:49 +00:00
|
|
|
out := new(bytes.Buffer)
|
2023-11-29 07:33:50 +00:00
|
|
|
glog := NewGlogHandler(NewTerminalHandlerWithLevel(out, LevelTrace, false).WithAttrs([]slog.Attr{slog.String("baz", "bat")}))
|
|
|
|
glog.Verbosity(LevelTrace)
|
|
|
|
logger := NewLogger(glog)
|
2023-09-07 12:48:49 +00:00
|
|
|
logger.Trace("a message", "foo", "bar")
|
|
|
|
have := out.String()
|
|
|
|
// The timestamp is locale-dependent, so we want to trim that off
|
|
|
|
// "INFO [01-01|00:00:00.000] a messag ..." -> "a messag..."
|
|
|
|
have = strings.Split(have, "]")[1]
|
2023-11-29 07:33:50 +00:00
|
|
|
want := " a message baz=bat foo=bar\n"
|
2023-09-07 12:48:49 +00:00
|
|
|
if have != want {
|
|
|
|
t.Errorf("\nhave: %q\nwant: %q\n", have, want)
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
func BenchmarkTraceLogging(b *testing.B) {
|
2023-11-29 07:33:50 +00:00
|
|
|
SetDefault(NewLogger(NewTerminalHandler(os.Stderr, true)))
|
2023-09-07 12:48:49 +00:00
|
|
|
b.ResetTimer()
|
|
|
|
for i := 0; i < b.N; i++ {
|
|
|
|
Trace("a message", "v", i)
|
|
|
|
}
|
|
|
|
}
|
slog: faster and less memory-consumption (#28621)
These changes improves the performance of the non-coloured terminal formatting, _quite a lot_.
```
name old time/op new time/op delta
TerminalHandler-8 10.2µs ±15% 5.4µs ± 9% -47.02% (p=0.008 n=5+5)
name old alloc/op new alloc/op delta
TerminalHandler-8 2.17kB ± 0% 0.40kB ± 0% -81.46% (p=0.008 n=5+5)
name old allocs/op new allocs/op delta
TerminalHandler-8 33.0 ± 0% 5.0 ± 0% -84.85% (p=0.008 n=5+5)
```
I tried to _somewhat_ organize the commits, but the it might still be a bit chaotic. Some core insights:
- The function `terminalHandler.Handl` uses a mutex, and writes all output immediately to 'upstream'. Thus, it can reuse a scratch-buffer every time.
- This buffer can be propagated internally, making all the internal formatters either write directly to it,
- OR, make use of the `tmp := buf.AvailableBuffer()` in some cases, where a byte buffer "extra capacity" can be temporarily used.
- The `slog` package uses `Attr` by value. It makes sense to minimize operating on them, since iterating / collecting into a new slice, iterating again etc causes copy-on-heap. Better to operate on them only once.
- If we want to do padding, it's better to copy from a constant `space`-buffer than to invoke `bytes.Repeat` every single time.
2023-12-01 12:28:20 +00:00
|
|
|
|
|
|
|
func BenchmarkTerminalHandler(b *testing.B) {
|
|
|
|
l := NewLogger(NewTerminalHandler(io.Discard, false))
|
|
|
|
benchmarkLogger(b, l)
|
|
|
|
}
|
|
|
|
func BenchmarkLogfmtHandler(b *testing.B) {
|
|
|
|
l := NewLogger(LogfmtHandler(io.Discard))
|
|
|
|
benchmarkLogger(b, l)
|
|
|
|
}
|
|
|
|
|
|
|
|
func BenchmarkJSONHandler(b *testing.B) {
|
|
|
|
l := NewLogger(JSONHandler(io.Discard))
|
|
|
|
benchmarkLogger(b, l)
|
|
|
|
}
|
|
|
|
|
|
|
|
func benchmarkLogger(b *testing.B, l Logger) {
|
|
|
|
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=<nil> 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)
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
const termTimeFormat = "01-02|15:04:05.000"
|
|
|
|
|
|
|
|
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 TestTermTimeFormat(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)
|
|
|
|
}
|
|
|
|
}
|