From 4d5264fb0be58efc456cf625a3ee63a5edee04b8 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Fri, 15 Sep 2023 13:13:49 +0200 Subject: [PATCH] logging benchmark: support slog MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Replacing zapr with slog as JSON implementation can be benchmarked by replacing "false" with "true" and rerunning. However, slog is slower: Encoding/error-value/JSON-36 171k ± 3% 148k ± 5% -13.64% (p=0.008 n=5+5) Encoding/error/JSON-36 207k ± 9% 149k ± 4% -27.87% (p=0.008 n=5+5) Encoding/kind-worker-kubelet/JSON-36 348k ± 2% 334k ± 1% -4.13% (p=0.008 n=5+5) Encoding/kube-apiserver/JSON-36 210k ± 2% 186k ± 1% -11.53% (p=0.008 n=5+5) Encoding/kube-controller-manager/JSON-36 291k ± 1% 249k ± 2% -14.26% (p=0.008 n=5+5) Encoding/kube-scheduler/JSON-36 262k ± 4% 223k ± 2% -14.91% (p=0.008 n=5+5) Encoding/simple/JSON-36 161k ± 4% 132k ± 2% -17.60% (p=0.008 n=5+5) Encoding/split/JSON-36 159k ± 4% 132k ± 1% -17.23% (p=0.008 n=5+5) Encoding/v3/kind-worker-kubelet/JSON-36 255k ± 1% 256k ± 1% ~ (p=0.222 n=5+5) Encoding/v3/kube-apiserver/JSON-36 131k ± 4% 105k ± 4% -20.07% (p=0.008 n=5+5) Encoding/v3/kube-controller-manager/JSON-36 285k ± 2% 250k ± 2% -12.13% (p=0.008 n=5+5) Encoding/v3/kube-scheduler/JSON-36 216k ± 3% 196k ± 4% -9.63% (p=0.008 n=5+5) --- .../logs/benchmark/benchmark_test.go | 40 +++++++++++++++++++ 1 file changed, 40 insertions(+) diff --git a/test/integration/logs/benchmark/benchmark_test.go b/test/integration/logs/benchmark/benchmark_test.go index abc92e55531..30a906c82ed 100644 --- a/test/integration/logs/benchmark/benchmark_test.go +++ b/test/integration/logs/benchmark/benchmark_test.go @@ -20,6 +20,7 @@ import ( "errors" "io" "io/fs" + "log/slog" "os" "path/filepath" "regexp" @@ -29,6 +30,8 @@ import ( "testing" "time" + "github.com/go-logr/logr" + "go.uber.org/zap/zapcore" "k8s.io/component-base/featuregate" logsapi "k8s.io/component-base/logs/api/v1" _ "k8s.io/component-base/logs/json/register" @@ -93,6 +96,43 @@ func BenchmarkEncoding(b *testing.B) { b.Fatalf("Unexpected error configuring logging: %v", err) } logger := klog.Background() + + // Edit and run with this if branch enabled to use slog instead of zapr for JSON. + if format == "json" && false { + var level slog.LevelVar + level.Set(slog.Level(-3)) // hack + logger = logr.FromSlogHandler(slog.NewJSONHandler(output, &slog.HandlerOptions{ + AddSource: true, + Level: &level, + ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { + switch a.Key { + case slog.TimeKey: + // Could be user-supplied "time". + if a.Value.Kind() == slog.KindTime { + return slog.Float64("ts", float64(a.Value.Time().UnixMicro())/1000) + } + case slog.LevelKey: + level := a.Value.Any().(slog.Level) + if level >= slog.LevelError { + // No verbosity on errors. + return slog.Attr{} + } + if level >= 0 { + return slog.Int("v", 0) + } + return slog.Int("v", int(-level)) + case slog.SourceKey: + caller := zapcore.EntryCaller{ + Defined: true, + File: a.Value.String(), + } + return slog.String("caller", caller.TrimmedPath()) + } + return a + }, + })) + } + b.ResetTimer() start := time.Now() total := int64(0)