From 23a96fd4749a11c7eb35edd41266bbb1a5030c5e Mon Sep 17 00:00:00 2001 From: "Steven E. Harris" Date: Sun, 2 Oct 2016 17:49:38 -0400 Subject: [PATCH 1/3] log/alt_experimental_level: concept demonstration MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Demonstrate an alternate approach to the "level" package offered via the "github.com/go-kit/kit/log/experimental_level" import path, allowing use of either a global log event level filtering threshold or local filtering via instances of the level.Leveler interface. Features not accommodated here for now: - Returning an error from log.Log when squelching an event - Returning an error from log.Log for events that lack a level - Squelching events that lack a level - Concurrent-safe adjustment of the global level threshold (Note the "alternately" comments in file global.go.) - Documentation Benchmarks demonstrate both run time and allocation reduction for the disallowed/squelching cases compared to the "experimental_level" alternate: name old time/op new time/op delta NopBaseline-4 737ns ± 0% 197ns ± 0% -73.27% NopDisallowedLevel-4 805ns ± 0% 189ns ± 0% -76.52% NopAllowedLevel-4 800ns ± 0% 754ns ± 0% -5.75% JSONBaseline-4 4.00µs ± 0% 4.08µs ± 0% +1.95% JSONDisallowedLevel-4 778ns ± 0% 193ns ± 0% -75.19% JSONAllowedLevel-4 4.24µs ± 0% 4.00µs ± 0% -5.57% LogfmtBaseline-4 1.50µs ± 0% 1.59µs ± 0% +6.28% LogfmtDisallowedLevel-4 795ns ± 0% 186ns ± 0% -76.60% LogfmtAllowedLevel-4 1.63µs ± 0% 1.59µs ± 0% -2.27% name old alloc/op new alloc/op delta NopBaseline-4 288B ± 0% 64B ± 0% -77.78% NopDisallowedLevel-4 288B ± 0% 64B ± 0% -77.78% NopAllowedLevel-4 288B ± 0% 288B ± 0% +0.00% JSONBaseline-4 968B ± 0% 968B ± 0% +0.00% JSONDisallowedLevel-4 288B ± 0% 64B ± 0% -77.78% JSONAllowedLevel-4 968B ± 0% 968B ± 0% +0.00% LogfmtBaseline-4 288B ± 0% 288B ± 0% +0.00% LogfmtDisallowedLevel-4 288B ± 0% 64B ± 0% -77.78% LogfmtAllowedLevel-4 288B ± 0% 288B ± 0% +0.00% name old allocs/op new allocs/op delta NopBaseline-4 9.00 ± 0% 3.00 ± 0% -66.67% NopDisallowedLevel-4 9.00 ± 0% 3.00 ± 0% -66.67% NopAllowedLevel-4 9.00 ± 0% 9.00 ± 0% +0.00% JSONBaseline-4 22.0 ± 0% 22.0 ± 0% +0.00% JSONDisallowedLevel-4 9.00 ± 0% 3.00 ± 0% -66.67% JSONAllowedLevel-4 22.0 ± 0% 22.0 ± 0% +0.00% LogfmtBaseline-4 9.00 ± 0% 9.00 ± 0% +0.00% LogfmtDisallowedLevel-4 9.00 ± 0% 3.00 ± 0% -66.67% LogfmtAllowedLevel-4 9.00 ± 0% 9.00 ± 0% +0.00% --- log/alt_experimental_level/benchmark_test.go | 59 ++++++ log/alt_experimental_level/global.go | 73 ++++++++ log/alt_experimental_level/level.go | 99 ++++++++++ log/alt_experimental_level/level_test.go | 186 +++++++++++++++++++ 4 files changed, 417 insertions(+) create mode 100644 log/alt_experimental_level/benchmark_test.go create mode 100644 log/alt_experimental_level/global.go create mode 100644 log/alt_experimental_level/level.go create mode 100644 log/alt_experimental_level/level_test.go diff --git a/log/alt_experimental_level/benchmark_test.go b/log/alt_experimental_level/benchmark_test.go new file mode 100644 index 000000000..314cd50bb --- /dev/null +++ b/log/alt_experimental_level/benchmark_test.go @@ -0,0 +1,59 @@ +package level_test + +import ( + "io/ioutil" + "testing" + + "github.com/go-kit/kit/log" + "github.com/go-kit/kit/log/alt_experimental_level" +) + +func BenchmarkNopBaseline(b *testing.B) { + benchmarkRunner(b, log.NewNopLogger()) +} + +func BenchmarkNopDisallowedLevel(b *testing.B) { + level.AllowInfoAndAbove() + benchmarkRunner(b, log.NewNopLogger()) +} + +func BenchmarkNopAllowedLevel(b *testing.B) { + level.AllowAll() + benchmarkRunner(b, log.NewNopLogger()) +} + +func BenchmarkJSONBaseline(b *testing.B) { + benchmarkRunner(b, log.NewJSONLogger(ioutil.Discard)) +} + +func BenchmarkJSONDisallowedLevel(b *testing.B) { + level.AllowInfoAndAbove() + benchmarkRunner(b, log.NewJSONLogger(ioutil.Discard)) +} + +func BenchmarkJSONAllowedLevel(b *testing.B) { + level.AllowAll() + benchmarkRunner(b, log.NewJSONLogger(ioutil.Discard)) +} + +func BenchmarkLogfmtBaseline(b *testing.B) { + benchmarkRunner(b, log.NewLogfmtLogger(ioutil.Discard)) +} + +func BenchmarkLogfmtDisallowedLevel(b *testing.B) { + level.AllowInfoAndAbove() + benchmarkRunner(b, log.NewLogfmtLogger(ioutil.Discard)) +} + +func BenchmarkLogfmtAllowedLevel(b *testing.B) { + level.AllowAll() + benchmarkRunner(b, log.NewLogfmtLogger(ioutil.Discard)) +} + +func benchmarkRunner(b *testing.B, logger log.Logger) { + b.ResetTimer() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + level.Debug(logger).Log("foo", "bar") + } +} diff --git a/log/alt_experimental_level/global.go b/log/alt_experimental_level/global.go new file mode 100644 index 000000000..e0aabb4df --- /dev/null +++ b/log/alt_experimental_level/global.go @@ -0,0 +1,73 @@ +package level + +import ( + "github.com/go-kit/kit/log" +) + +var ( + global Leveler = errorOnly{} + /* + Alternately: + global atomic.Value + */ +) + +/* Alternately: +func init() { + global.Store(errorOnly{}) +} +*/ + +func resetGlobal(proposed Leveler) { + global = proposed + /* Alternately: + global.Store(proposed) + */ +} + +func AllowAll() { + AllowDebugAndAbove() +} + +func AllowDebugAndAbove() { + resetGlobal(debugAndAbove{}) +} + +func AllowInfoAndAbove() { + resetGlobal(infoAndAbove{}) +} + +func AllowWarnAndAbove() { + resetGlobal(warnAndAbove{}) +} + +func AllowErrorOnly() { + resetGlobal(errorOnly{}) +} + +func AllowNone() { + resetGlobal(none{}) +} + +func getGlobal() Leveler { + return global + /* Alternately: + return global.Load().(Leveler) + */ +} + +func Debug(logger log.Logger) log.Logger { + return getGlobal().Debug(logger) +} + +func Info(logger log.Logger) log.Logger { + return getGlobal().Info(logger) +} + +func Warn(logger log.Logger) log.Logger { + return getGlobal().Warn(logger) +} + +func Error(logger log.Logger) log.Logger { + return getGlobal().Error(logger) +} diff --git a/log/alt_experimental_level/level.go b/log/alt_experimental_level/level.go new file mode 100644 index 000000000..caffefa99 --- /dev/null +++ b/log/alt_experimental_level/level.go @@ -0,0 +1,99 @@ +package level + +import ( + "github.com/go-kit/kit/log" +) + +var ( + levelKey = "level" + + debugLevelValue = "debug" + infoLevelValue = "info" + warnLevelValue = "warn" + errorLevelValue = "error" + + // Alternately, we could use a similarly inert logger that does nothing but + // return a given error value. + nop = log.NewNopLogger() +) + +type Leveler interface { + Debug(logger log.Logger) log.Logger + Info(logger log.Logger) log.Logger + Warn(logger log.Logger) log.Logger + Error(logger log.Logger) log.Logger +} + +type debugAndAbove struct{} + +func (debugAndAbove) Debug(logger log.Logger) log.Logger { + return log.NewContext(logger).With(levelKey, debugLevelValue) +} + +func (debugAndAbove) Info(logger log.Logger) log.Logger { + return log.NewContext(logger).With(levelKey, infoLevelValue) +} + +func (debugAndAbove) Warn(logger log.Logger) log.Logger { + return log.NewContext(logger).With(levelKey, warnLevelValue) +} + +func (debugAndAbove) Error(logger log.Logger) log.Logger { + return log.NewContext(logger).With(levelKey, errorLevelValue) +} + +type infoAndAbove struct { + debugAndAbove +} + +func (infoAndAbove) Debug(logger log.Logger) log.Logger { + return nop +} + +type warnAndAbove struct { + infoAndAbove +} + +func (warnAndAbove) Info(logger log.Logger) log.Logger { + return nop +} + +type errorOnly struct { + warnAndAbove +} + +func (errorOnly) Warn(logger log.Logger) log.Logger { + return nop +} + +type none struct { + errorOnly +} + +func (none) Error(logger log.Logger) log.Logger { + return nop +} + +func AllowingAll() Leveler { + return AllowingDebugAndAbove() +} + +func AllowingDebugAndAbove() Leveler { + return debugAndAbove{} +} + +func AllowingInfoAndAbove() Leveler { + return infoAndAbove{} +} + +func AllowingWarnAndAbove() Leveler { + return warnAndAbove{} +} + +func AllowingErrorOnly() Leveler { + return errorOnly{} +} + +func AllowingNone() Leveler { + return none{} +} diff --git a/log/alt_experimental_level/level_test.go b/log/alt_experimental_level/level_test.go new file mode 100644 index 000000000..ded26b323 --- /dev/null +++ b/log/alt_experimental_level/level_test.go @@ -0,0 +1,186 @@ +package level_test + +import ( + "bytes" + "strings" + "testing" + + "github.com/go-kit/kit/log" + "github.com/go-kit/kit/log/alt_experimental_level" +) + +func TestGlobalLevels(t *testing.T) { + for _, testcase := range []struct { + allowed string + allow func() + want string + }{ + { + "all", + level.AllowAll, + strings.Join([]string{ + `{"level":"debug","this is":"debug log"}`, + `{"level":"info","this is":"info log"}`, + `{"level":"warn","this is":"warn log"}`, + `{"level":"error","this is":"error log"}`, + }, "\n"), + }, + { + "debug+", + level.AllowDebugAndAbove, + strings.Join([]string{ + `{"level":"debug","this is":"debug log"}`, + `{"level":"info","this is":"info log"}`, + `{"level":"warn","this is":"warn log"}`, + `{"level":"error","this is":"error log"}`, + }, "\n"), + }, + { + "info+", + level.AllowInfoAndAbove, + strings.Join([]string{ + `{"level":"info","this is":"info log"}`, + `{"level":"warn","this is":"warn log"}`, + `{"level":"error","this is":"error log"}`, + }, "\n"), + }, + { + "warn+", + level.AllowWarnAndAbove, + strings.Join([]string{ + `{"level":"warn","this is":"warn log"}`, + `{"level":"error","this is":"error log"}`, + }, "\n"), + }, + { + "error", + level.AllowErrorOnly, + strings.Join([]string{ + `{"level":"error","this is":"error log"}`, + }, "\n"), + }, + { + "none", + level.AllowNone, + ``, + }, + } { + var buf bytes.Buffer + logger := log.NewJSONLogger(&buf) + + testcase.allow() + + level.Debug(logger).Log("this is", "debug log") + level.Info(logger).Log("this is", "info log") + level.Warn(logger).Log("this is", "warn log") + level.Error(logger).Log("this is", "error log") + + if want, have := testcase.want, strings.TrimSpace(buf.String()); want != have { + t.Errorf("given Allowed=%s: want\n%s\nhave\n%s", testcase.allowed, want, have) + } + } +} + +func TestInstanceLevels(t *testing.T) { + for _, testcase := range []struct { + allowed string + leveler level.Leveler + want string + }{ + { + "all", + level.AllowingAll(), + strings.Join([]string{ + `{"level":"debug","this is":"debug log"}`, + `{"level":"info","this is":"info log"}`, + `{"level":"warn","this is":"warn log"}`, + `{"level":"error","this is":"error log"}`, + }, "\n"), + }, + { + "debug+", + level.AllowingDebugAndAbove(), + strings.Join([]string{ + `{"level":"debug","this is":"debug log"}`, + `{"level":"info","this is":"info log"}`, + `{"level":"warn","this is":"warn log"}`, + `{"level":"error","this is":"error log"}`, + }, "\n"), + }, + { + "info+", + level.AllowingInfoAndAbove(), + strings.Join([]string{ + `{"level":"info","this is":"info log"}`, + `{"level":"warn","this is":"warn log"}`, + `{"level":"error","this is":"error log"}`, + }, "\n"), + }, + { + "warn+", + level.AllowingWarnAndAbove(), + strings.Join([]string{ + `{"level":"warn","this is":"warn log"}`, + `{"level":"error","this is":"error log"}`, + }, "\n"), + }, + { + "error", + level.AllowingErrorOnly(), + strings.Join([]string{ + `{"level":"error","this is":"error log"}`, + }, "\n"), + }, + { + "none", + level.AllowingNone(), + ``, + }, + } { + var buf bytes.Buffer + logger := log.NewJSONLogger(&buf) + + l := testcase.leveler + + l.Debug(logger).Log("this is", "debug log") + l.Info(logger).Log("this is", "info log") + l.Warn(logger).Log("this is", "warn log") + l.Error(logger).Log("this is", "error log") + + if want, have := testcase.want, strings.TrimSpace(buf.String()); want != have { + t.Errorf("given Allowed=%s: want\n%s\nhave\n%s", testcase.allowed, want, have) + } + } +} +func TestLevelContext(t *testing.T) { + var buf bytes.Buffer + + // Wrapping the level logger with a context allows users to use + // log.DefaultCaller as per normal. + var logger log.Logger + logger = log.NewLogfmtLogger(&buf) + level.AllowAll() + logger = level.Info(logger) + logger = log.NewContext(logger).With("caller", log.DefaultCaller) + + logger.Log("foo", "bar") + if want, have := `level=info caller=level_test.go:166 foo=bar`, strings.TrimSpace(buf.String()); want != have { + t.Errorf("want %q, have %q", want, have) + } +} + +func TestContextLevel(t *testing.T) { + var buf bytes.Buffer + + // Wrapping a context with the level logger allows users to use + // log.DefaultCaller as per normal. + var logger log.Logger + logger = log.NewLogfmtLogger(&buf) + logger = log.NewContext(logger).With("caller", log.DefaultCaller) + + level.AllowAll() + level.Info(logger).Log("foo", "bar") + if want, have := `caller=level_test.go:182 level=info foo=bar`, strings.TrimSpace(buf.String()); want != have { + t.Errorf("want %q, have %q", want, have) + } +} From d2fad7b8bf6c85553731a2476e758656dca68cc1 Mon Sep 17 00:00:00 2001 From: "Steven E. Harris" Date: Mon, 3 Oct 2016 08:06:42 -0400 Subject: [PATCH 2/3] Remove vars for manifest constant strings Since these values are only used in one place each, don't bother declaring manifest constants for them. --- log/alt_experimental_level/level.go | 19 ++++++++----------- 1 file changed, 8 insertions(+), 11 deletions(-) diff --git a/log/alt_experimental_level/level.go b/log/alt_experimental_level/level.go index caffefa99..0c5f62934 100644 --- a/log/alt_experimental_level/level.go +++ b/log/alt_experimental_level/level.go @@ -5,13 +5,6 @@ import ( ) var ( - levelKey = "level" - - debugLevelValue = "debug" - infoLevelValue = "info" - warnLevelValue = "warn" - errorLevelValue = "error" - // Alternately, we could use a similarly inert logger that does nothing but // return a given error value. nop = log.NewNopLogger() @@ -24,22 +17,26 @@ type Leveler interface { Error(logger log.Logger) log.Logger } +func withLevel(level string, logger log.Logger) log.Logger { + return log.NewContext(logger).With("level", level) +} + type debugAndAbove struct{} func (debugAndAbove) Debug(logger log.Logger) log.Logger { - return log.NewContext(logger).With(levelKey, debugLevelValue) + return withLevel("debug", logger) } func (debugAndAbove) Info(logger log.Logger) log.Logger { - return log.NewContext(logger).With(levelKey, infoLevelValue) + return withLevel("info", logger) } func (debugAndAbove) Warn(logger log.Logger) log.Logger { - return log.NewContext(logger).With(levelKey, warnLevelValue) + return withLevel("warn", logger) } func (debugAndAbove) Error(logger log.Logger) log.Logger { - return log.NewContext(logger).With(levelKey, errorLevelValue) + return withLevel("error", logger) } type infoAndAbove struct { From 7545d1f41bb98260e1fdd5174aef415490e27ab2 Mon Sep 17 00:00:00 2001 From: "Steven E. Harris" Date: Mon, 3 Oct 2016 08:04:41 -0400 Subject: [PATCH 3/3] Delegate global "allow" functions to factories --- log/alt_experimental_level/global.go | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/log/alt_experimental_level/global.go b/log/alt_experimental_level/global.go index e0aabb4df..f37a790fc 100644 --- a/log/alt_experimental_level/global.go +++ b/log/alt_experimental_level/global.go @@ -5,7 +5,7 @@ import ( ) var ( - global Leveler = errorOnly{} + global = AllowingNone() /* Alternately: global atomic.Value @@ -30,23 +30,23 @@ func AllowAll() { } func AllowDebugAndAbove() { - resetGlobal(debugAndAbove{}) + resetGlobal(AllowingDebugAndAbove()) } func AllowInfoAndAbove() { - resetGlobal(infoAndAbove{}) + resetGlobal(AllowingInfoAndAbove()) } func AllowWarnAndAbove() { - resetGlobal(warnAndAbove{}) + resetGlobal(AllowingWarnAndAbove()) } func AllowErrorOnly() { - resetGlobal(errorOnly{}) + resetGlobal(AllowingErrorOnly()) } func AllowNone() { - resetGlobal(none{}) + resetGlobal(AllowingNone()) } func getGlobal() Leveler {