From 3ddd22697b21ea3b5caac97de070387e2a946f80 Mon Sep 17 00:00:00 2001 From: spacewander Date: Fri, 1 Dec 2023 10:59:04 +0800 Subject: [PATCH 1/2] funcr: Add LogInfoLevel Option to skip logging level in the info log Benchmark before: ``` goos: darwin goarch: arm64 pkg: github.com/go-logr/logr/benchmark BenchmarkDiscardLogInfoOneArg-10 58466427 21.36 ns/op 32 B/op 1 allocs/op BenchmarkDiscardLogInfoSeveralArgs-10 24470527 49.62 ns/op 176 B/op 2 allocs/op BenchmarkDiscardLogInfoWithValues-10 21938677 47.06 ns/op 176 B/op 2 allocs/op BenchmarkDiscardLogV0Info-10 24796845 47.45 ns/op 176 B/op 2 allocs/op BenchmarkDiscardLogV9Info-10 26069977 49.02 ns/op 176 B/op 2 allocs/op BenchmarkDiscardLogError-10 23731986 47.94 ns/op 176 B/op 2 allocs/op BenchmarkDiscardWithValues-10 50995291 22.28 ns/op 64 B/op 1 allocs/op BenchmarkDiscardWithName-10 1000000000 0.4716 ns/op 0 B/op 0 allocs/op BenchmarkFuncrLogInfoOneArg-10 2684097 433.9 ns/op 1152 B/op 7 allocs/op BenchmarkFuncrJSONLogInfoOneArg-10 2413437 480.4 ns/op 1168 B/op 8 allocs/op BenchmarkFuncrLogInfoSeveralArgs-10 1261210 953.2 ns/op 1448 B/op 17 allocs/op BenchmarkFuncrJSONLogInfoSeveralArgs-10 1000000 1003 ns/op 1448 B/op 18 allocs/op BenchmarkFuncrLogInfoWithValues-10 1247379 1027 ns/op 1480 B/op 17 allocs/op BenchmarkFuncrJSONLogInfoWithValues-10 1000000 1109 ns/op 1496 B/op 18 allocs/op BenchmarkFuncrLogV0Info-10 1000000 1043 ns/op 1448 B/op 17 allocs/op BenchmarkFuncrJSONLogV0Info-10 1000000 1100 ns/op 1448 B/op 18 allocs/op BenchmarkFuncrLogV9Info-10 24429925 48.76 ns/op 176 B/op 2 allocs/op BenchmarkFuncrJSONLogV9Info-10 24799878 53.82 ns/op 176 B/op 2 allocs/op BenchmarkFuncrLogError-10 1000000 1010 ns/op 1480 B/op 19 allocs/op BenchmarkFuncrJSONLogError-10 1000000 1124 ns/op 1496 B/op 20 allocs/op BenchmarkFuncrWithValues-10 4088592 296.0 ns/op 264 B/op 8 allocs/op BenchmarkFuncrWithName-10 34046577 32.95 ns/op 96 B/op 1 allocs/op BenchmarkFuncrWithCallDepth-10 34601535 32.77 ns/op 96 B/op 1 allocs/op BenchmarkFuncrJSONLogInfoStringerValue-10 2062101 562.0 ns/op 1200 B/op 10 allocs/op BenchmarkFuncrJSONLogInfoErrorValue-10 2278339 529.9 ns/op 1200 B/op 10 allocs/op BenchmarkFuncrJSONLogInfoMarshalerValue-10 2108040 533.6 ns/op 1200 B/op 10 allocs/op ``` Benchmark after: ``` goos: darwin goarch: arm64 pkg: github.com/go-logr/logr/benchmark BenchmarkDiscardLogInfoOneArg-10 59617632 20.01 ns/op 32 B/op 1 allocs/op BenchmarkDiscardLogInfoSeveralArgs-10 26171325 47.09 ns/op 176 B/op 2 allocs/op BenchmarkDiscardLogInfoWithValues-10 25975759 45.76 ns/op 176 B/op 2 allocs/op BenchmarkDiscardLogV0Info-10 25654935 46.02 ns/op 176 B/op 2 allocs/op BenchmarkDiscardLogV9Info-10 25722668 46.00 ns/op 176 B/op 2 allocs/op BenchmarkDiscardLogError-10 25181846 45.97 ns/op 176 B/op 2 allocs/op BenchmarkDiscardWithValues-10 53340940 21.92 ns/op 64 B/op 1 allocs/op BenchmarkDiscardWithName-10 1000000000 0.4757 ns/op 0 B/op 0 allocs/op BenchmarkFuncrLogInfoOneArg-10 2887884 416.5 ns/op 1152 B/op 7 allocs/op BenchmarkFuncrJSONLogInfoOneArg-10 2556847 474.0 ns/op 1168 B/op 8 allocs/op BenchmarkFuncrLogInfoSeveralArgs-10 1280838 957.4 ns/op 1448 B/op 17 allocs/op BenchmarkFuncrJSONLogInfoSeveralArgs-10 1000000 1003 ns/op 1448 B/op 18 allocs/op BenchmarkFuncrLogInfoWithValues-10 1241484 967.6 ns/op 1480 B/op 17 allocs/op BenchmarkFuncrJSONLogInfoWithValues-10 1000000 1021 ns/op 1496 B/op 18 allocs/op BenchmarkFuncrLogV0Info-10 1202900 925.3 ns/op 1448 B/op 17 allocs/op BenchmarkFuncrJSONLogV0Info-10 1000000 1021 ns/op 1448 B/op 18 allocs/op BenchmarkFuncrLogV9Info-10 24424683 48.45 ns/op 176 B/op 2 allocs/op BenchmarkFuncrJSONLogV9Info-10 24633237 48.23 ns/op 176 B/op 2 allocs/op BenchmarkFuncrLogError-10 1000000 1066 ns/op 1480 B/op 19 allocs/op BenchmarkFuncrJSONLogError-10 1072557 1093 ns/op 1496 B/op 20 allocs/op BenchmarkFuncrWithValues-10 4094355 292.9 ns/op 264 B/op 8 allocs/op BenchmarkFuncrWithName-10 36661557 33.96 ns/op 96 B/op 1 allocs/op BenchmarkFuncrWithCallDepth-10 32008606 32.65 ns/op 96 B/op 1 allocs/op BenchmarkFuncrJSONLogInfoStringerValue-10 2329975 517.9 ns/op 1200 B/op 10 allocs/op BenchmarkFuncrJSONLogInfoErrorValue-10 2200308 522.0 ns/op 1200 B/op 10 allocs/op BenchmarkFuncrJSONLogInfoMarshalerValue-10 2242267 536.0 ns/op 1200 B/op 10 allocs/op ``` The performance is similar. Only a nil pointer check is added in the main path. Signed-off-by: spacewander --- funcr/funcr.go | 15 ++++++++++++++- funcr/funcr_test.go | 32 ++++++++++++++++++++++++++++++++ 2 files changed, 46 insertions(+), 1 deletion(-) diff --git a/funcr/funcr.go b/funcr/funcr.go index 12e5807..19c14da 100644 --- a/funcr/funcr.go +++ b/funcr/funcr.go @@ -100,6 +100,10 @@ type Options struct { // details, see docs for Go's time.Layout. TimestampFormat string + // LogInfoLevel tells func what key to use to log the integer level. By default, + // a "level" key will be used. If set it to "", the integer level will not be logged. + LogInfoLevel *string + // Verbosity tells funcr which V logs to produce. Higher values enable // more logs. Info logs at or below this level will be written, while logs // above this level will be discarded. @@ -740,7 +744,16 @@ func (f Formatter) FormatInfo(level int, msg string, kvList []any) (prefix, args if policy := f.opts.LogCaller; policy == All || policy == Info { args = append(args, "caller", f.caller()) } - args = append(args, "level", level, "msg", msg) + if f.opts.LogInfoLevel == nil { + args = append(args, "level", level, "msg", msg) + } else { + lvKey := *f.opts.LogInfoLevel + if lvKey != "" { + args = append(args, lvKey, level, "msg", msg) + } else { + args = append(args, "msg", msg) + } + } return prefix, f.render(args, kvList) } diff --git a/funcr/funcr_test.go b/funcr/funcr_test.go index b3a6f70..f2dc835 100644 --- a/funcr/funcr_test.go +++ b/funcr/funcr_test.go @@ -1361,3 +1361,35 @@ func TestOptionsTimestampFormat(t *testing.T) { t.Errorf("\nexpected %q\n got %q", expect, capt.log) } } + +func TestOptionsLogInfoLevel(t *testing.T) { + testCases := []struct { + name string + level string + expect string + }{ + { + name: "custom key", + level: "info_level", + expect: `"info_level"=0 "msg"="msg"`, + }, + { + name: "no level", + level: "", + expect: `"msg"="msg"`, + }, + } + + for _, tc := range testCases { + t.Run("Run: "+tc.name, func(t *testing.T) { + capt := &capture{} + sink := newSink(capt.Func, NewFormatter(Options{LogInfoLevel: &tc.level})) + dSink, _ := sink.(logr.CallDepthLogSink) + sink = dSink.WithCallDepth(1) + sink.Info(0, "msg") + if capt.log != tc.expect { + t.Errorf("\nexpected %q\n got %q", tc.expect, capt.log) + } + }) + } +} From b4525f628027ff7e7a78baf809bc5f8755032cae Mon Sep 17 00:00:00 2001 From: spacewander Date: Tue, 19 Dec 2023 12:55:39 +0800 Subject: [PATCH 2/2] apply @thockin's suggestion Signed-off-by: spacewander --- funcr/funcr.go | 21 ++++++++++----------- funcr/funcr_test.go | 13 +++++++++---- 2 files changed, 19 insertions(+), 15 deletions(-) diff --git a/funcr/funcr.go b/funcr/funcr.go index 19c14da..db64bbd 100644 --- a/funcr/funcr.go +++ b/funcr/funcr.go @@ -100,8 +100,9 @@ type Options struct { // details, see docs for Go's time.Layout. TimestampFormat string - // LogInfoLevel tells func what key to use to log the integer level. By default, - // a "level" key will be used. If set it to "", the integer level will not be logged. + // LogInfoLevel tells funcr what key to use to log the info level. + // If not specified, the info level will be logged as "level". + // If this is set to "", the info level will not be logged at all. LogInfoLevel *string // Verbosity tells funcr which V logs to produce. Higher values enable @@ -217,6 +218,10 @@ func newFormatter(opts Options, outfmt outputFormat) Formatter { if opts.MaxLogDepth == 0 { opts.MaxLogDepth = defaultMaxLogDepth } + if opts.LogInfoLevel == nil { + opts.LogInfoLevel = new(string) + *opts.LogInfoLevel = "level" + } f := Formatter{ outputFormat: outfmt, prefix: "", @@ -744,16 +749,10 @@ func (f Formatter) FormatInfo(level int, msg string, kvList []any) (prefix, args if policy := f.opts.LogCaller; policy == All || policy == Info { args = append(args, "caller", f.caller()) } - if f.opts.LogInfoLevel == nil { - args = append(args, "level", level, "msg", msg) - } else { - lvKey := *f.opts.LogInfoLevel - if lvKey != "" { - args = append(args, lvKey, level, "msg", msg) - } else { - args = append(args, "msg", msg) - } + if key := *f.opts.LogInfoLevel; key != "" { + args = append(args, key, level) } + args = append(args, "msg", msg) return prefix, f.render(args, kvList) } diff --git a/funcr/funcr_test.go b/funcr/funcr_test.go index f2dc835..b0943ff 100644 --- a/funcr/funcr_test.go +++ b/funcr/funcr_test.go @@ -1365,25 +1365,30 @@ func TestOptionsTimestampFormat(t *testing.T) { func TestOptionsLogInfoLevel(t *testing.T) { testCases := []struct { name string - level string + level *string expect string }{ { name: "custom key", - level: "info_level", + level: ptrstr("info_level"), expect: `"info_level"=0 "msg"="msg"`, }, { name: "no level", - level: "", + level: ptrstr(""), expect: `"msg"="msg"`, }, + { + name: "default", + level: nil, + expect: `"level"=0 "msg"="msg"`, + }, } for _, tc := range testCases { t.Run("Run: "+tc.name, func(t *testing.T) { capt := &capture{} - sink := newSink(capt.Func, NewFormatter(Options{LogInfoLevel: &tc.level})) + sink := newSink(capt.Func, NewFormatter(Options{LogInfoLevel: tc.level})) dSink, _ := sink.(logr.CallDepthLogSink) sink = dSink.WithCallDepth(1) sink.Info(0, "msg")