From 92a07169b507f7776ca84924ed7ae1be90fceb43 Mon Sep 17 00:00:00 2001 From: rainman456 <81997753+rainman456@users.noreply.github.com> Date: Sun, 11 Oct 2026 00:58:03 +0100 Subject: [PATCH 1/2] [logger]: Add DebugEnabled and gate the routing debug entry Building the tags for a Debug entry allocates even when the configured level discards it, and the router builds that entry on every request. Profiling a request-shaped benchmark run attributed 25.89% of the router binary's total allocations to tag.String, and Director_Resolve measured 5 allocations per Resolve, most of them the four tags handed to Debug that an operator at the default level never sees. The routing decision itself is already counted in decisions_total. Logger gains DebugEnabled, which reports whether Debug entries are recorded, so hot-path callers can skip constructing Debug-only tags. ZeroLogger answers from its configured level, NoopLogger answers false, and TestLogger answers true since it records every level. The director gates its routing entry on it. Measured against the benchmarks from the previous commit, 10 rounds per side (benchstat, shared 2-vCPU host; allocs/op and B/op are deterministic and primary): Director_Resolve drops from 5 to 0 allocations and from ~501ns to ~83ns (-83%, p=0.000); the whole-path benchmark drops from 400 to 395 allocations (p=0.000); protoutil benchmarks and the no-proxy baseline are unchanged (all samples equal). Behavior at debug level is unchanged. --- internal/router/director.go | 20 +++++++++++++------- pkg/logger/logger.go | 4 ++++ pkg/logger/noop.go | 6 ++++++ pkg/logger/noop_test.go | 3 +++ pkg/logger/test.go | 6 ++++++ pkg/logger/test_test.go | 3 +++ pkg/logger/zero.go | 6 ++++++ pkg/logger/zero_test.go | 24 ++++++++++++++++++++++++ 8 files changed, 65 insertions(+), 7 deletions(-) diff --git a/internal/router/director.go b/internal/router/director.go index af6b417..f0f30a1 100644 --- a/internal/router/director.go +++ b/internal/router/director.go @@ -77,13 +77,19 @@ func (d *director) Resolve( return Target{}, status.Errorf(codes.Unavailable, "router: no handler for upstream %q", upstream) } - d.logger.Debug( - "routing request", - tag.String("method", method), - tag.String("namespace", namespace), - tag.String("upstream", upstream), - tag.Stringer("outcome", outcome), - ) + // The decision is already counted in decisions_total; the entry is for an + // operator running at debug level. Gating on DebugEnabled keeps requests + // at the default level from building the tags an entry they will never + // see would carry. + if d.logger.DebugEnabled() { + d.logger.Debug( + "routing request", + tag.String("method", method), + tag.String("namespace", namespace), + tag.String("upstream", upstream), + tag.Stringer("outcome", outcome), + ) + } return Target{Upstream: upstream, Handle: handle}, nil } diff --git a/pkg/logger/logger.go b/pkg/logger/logger.go index 02aebc9..b0ede1a 100644 --- a/pkg/logger/logger.go +++ b/pkg/logger/logger.go @@ -29,6 +29,10 @@ type ( Logger interface { // Debug logs msg and tags at [LevelDebug]. Debug(msg string, tags ...tag.Tag) + // DebugEnabled reports whether Debug entries are recorded. Callers on + // hot paths may gate the construction of Debug-only tags on it, since + // building arguments for an entry that is then discarded allocates. + DebugEnabled() bool // Error logs msg and tags at [LevelError]. Error(msg string, tags ...tag.Tag) // Fatal logs msg and tags, then typically calls os.Exit(1). diff --git a/pkg/logger/noop.go b/pkg/logger/noop.go index 87fbc2b..7f1b639 100644 --- a/pkg/logger/noop.go +++ b/pkg/logger/noop.go @@ -18,6 +18,12 @@ func NewNoopLogger() *NoopLogger { func (n *NoopLogger) Debug(string, ...tag.Tag) { } +// DebugEnabled implements [Logger]. NoopLogger discards every entry, so +// nothing it could log is worth building. +func (n *NoopLogger) DebugEnabled() bool { + return false +} + // Error implements [Logger] by discarding the entry. func (n *NoopLogger) Error(string, ...tag.Tag) { } diff --git a/pkg/logger/noop_test.go b/pkg/logger/noop_test.go index f8f5309..f2f91bf 100644 --- a/pkg/logger/noop_test.go +++ b/pkg/logger/noop_test.go @@ -24,4 +24,7 @@ func TestNoopLogger(t *testing.T) { }) require.Same(t, l, l.With(tag.String("k", "v"))) + + // DebugEnabled reports false because every entry is discarded. + require.False(t, l.DebugEnabled()) } diff --git a/pkg/logger/test.go b/pkg/logger/test.go index f03f1ff..fe3e910 100644 --- a/pkg/logger/test.go +++ b/pkg/logger/test.go @@ -104,6 +104,12 @@ func (t *TestLogger) TagsOf(l Level, msg string) map[string]any { // Debug implements [Logger] by recording the entry at [LevelDebug]. func (t *TestLogger) Debug(msg string, tags ...tag.Tag) { t.record(LevelDebug, msg, tags) } +// DebugEnabled implements [Logger]. TestLogger records every level, so Debug +// entries are always worth building. +func (t *TestLogger) DebugEnabled() bool { + return true +} + // Error implements [Logger] by recording the entry at [LevelError]. func (t *TestLogger) Error(msg string, tags ...tag.Tag) { t.record(LevelError, msg, tags) } diff --git a/pkg/logger/test_test.go b/pkg/logger/test_test.go index 3e3bc1a..8ce6733 100644 --- a/pkg/logger/test_test.go +++ b/pkg/logger/test_test.go @@ -19,6 +19,9 @@ func TestTestLoggerContains(t *testing.T) { l.Info("hello") require.True(t, l.Contains("hello")) require.False(t, l.Contains("goodbye")) + + // TestLogger records every level, so Debug entries are always recorded. + require.True(t, l.DebugEnabled()) } func TestTestLoggerContainsEntry(t *testing.T) { diff --git a/pkg/logger/zero.go b/pkg/logger/zero.go index 554cb13..f8a74a3 100644 --- a/pkg/logger/zero.go +++ b/pkg/logger/zero.go @@ -29,6 +29,12 @@ func (l *ZeroLogger) Debug(msg string, tags ...tag.Tag) { logEvent(l.log.Debug(), msg, tags) } +// DebugEnabled implements [Logger], reporting whether the configured level +// records Debug entries. +func (l *ZeroLogger) DebugEnabled() bool { + return l.log.GetLevel() <= zerolog.DebugLevel +} + // Error implements [Logger]. func (l *ZeroLogger) Error(msg string, tags ...tag.Tag) { logEvent(l.log.Error(), msg, tags) diff --git a/pkg/logger/zero_test.go b/pkg/logger/zero_test.go index 95aa630..2862d45 100644 --- a/pkg/logger/zero_test.go +++ b/pkg/logger/zero_test.go @@ -48,6 +48,30 @@ func TestZeroLoggerLevels(t *testing.T) { } } +func TestZeroLoggerDebugEnabled(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + lvl logger.Level + want bool + }{ + {"debug enables debug", logger.LevelDebug, true}, + {"info disables debug", logger.LevelInfo, false}, + {"warn disables debug", logger.LevelWarn, false}, + {"error disables debug", logger.LevelError, false}, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + t.Parallel() + + l := logger.NewZeroLogger(&bytes.Buffer{}, tt.lvl) + require.Equal(t, tt.want, l.DebugEnabled()) + }) + } +} + func TestZeroLoggerTags(t *testing.T) { t.Parallel() From 22472a2115c5b8fbcf9e0c9a7e4f3851e3c47a6d Mon Sep 17 00:00:00 2001 From: rainman456 <81997753+rainman456@users.noreply.github.com> Date: Tue, 13 Oct 2026 23:41:54 +0100 Subject: [PATCH 2/2] [logger]: Replace DebugEnabled for Enabled(Level) Review on #219 asked for a single Enabled(lvl Level) method so the next gate does not need another breaking interface change. The package-level Enabled over Default keeps the mirror with the other log functions, and an unrecognized level answers true so a bad value never hides logs. --- internal/router/director.go | 8 ++++---- pkg/logger/logger.go | 15 +++++++++++---- pkg/logger/noop.go | 6 +++--- pkg/logger/noop_test.go | 6 ++++-- pkg/logger/test.go | 6 +++--- pkg/logger/test_test.go | 5 +++-- pkg/logger/zero.go | 13 +++++++++---- pkg/logger/zero_test.go | 26 ++++++++++++++++++-------- 8 files changed, 55 insertions(+), 30 deletions(-) diff --git a/internal/router/director.go b/internal/router/director.go index f0f30a1..0b5f208 100644 --- a/internal/router/director.go +++ b/internal/router/director.go @@ -78,10 +78,10 @@ func (d *director) Resolve( } // The decision is already counted in decisions_total; the entry is for an - // operator running at debug level. Gating on DebugEnabled keeps requests - // at the default level from building the tags an entry they will never - // see would carry. - if d.logger.DebugEnabled() { + // operator running at debug level. Gating on Enabled keeps requests at the + // default level from building the tags an entry they will never see would + // carry. + if d.logger.Enabled(logger.LevelDebug) { d.logger.Debug( "routing request", tag.String("method", method), diff --git a/pkg/logger/logger.go b/pkg/logger/logger.go index b0ede1a..83daab9 100644 --- a/pkg/logger/logger.go +++ b/pkg/logger/logger.go @@ -29,10 +29,11 @@ type ( Logger interface { // Debug logs msg and tags at [LevelDebug]. Debug(msg string, tags ...tag.Tag) - // DebugEnabled reports whether Debug entries are recorded. Callers on - // hot paths may gate the construction of Debug-only tags on it, since - // building arguments for an entry that is then discarded allocates. - DebugEnabled() bool + // Enabled reports whether an entry at lvl would be recorded. Callers + // on hot paths may gate the construction of tags on it, since building + // arguments for an entry that is then discarded allocates. An + // unrecognized level answers true, so a bad value never hides logs. + Enabled(lvl Level) bool // Error logs msg and tags at [LevelError]. Error(msg string, tags ...tag.Tag) // Fatal logs msg and tags, then typically calls os.Exit(1). @@ -82,6 +83,12 @@ func Debug(msg string, tags ...tag.Tag) { defaultLogger.Debug(msg, tags...) } +// Enabled reports whether an entry at lvl would be recorded using the default +// logger. See [Logger.Enabled]. +func Enabled(lvl Level) bool { + return defaultLogger.Enabled(lvl) +} + // Error logs msg and tags at [LevelError] using the default logger. func Error(msg string, tags ...tag.Tag) { defaultLogger.Error(msg, tags...) diff --git a/pkg/logger/noop.go b/pkg/logger/noop.go index 7f1b639..c12047b 100644 --- a/pkg/logger/noop.go +++ b/pkg/logger/noop.go @@ -18,9 +18,9 @@ func NewNoopLogger() *NoopLogger { func (n *NoopLogger) Debug(string, ...tag.Tag) { } -// DebugEnabled implements [Logger]. NoopLogger discards every entry, so -// nothing it could log is worth building. -func (n *NoopLogger) DebugEnabled() bool { +// Enabled implements [Logger]. NoopLogger discards every entry, whatever the +// level, so nothing it could log is worth building. +func (n *NoopLogger) Enabled(Level) bool { return false } diff --git a/pkg/logger/noop_test.go b/pkg/logger/noop_test.go index f2f91bf..51ea267 100644 --- a/pkg/logger/noop_test.go +++ b/pkg/logger/noop_test.go @@ -25,6 +25,8 @@ func TestNoopLogger(t *testing.T) { require.Same(t, l, l.With(tag.String("k", "v"))) - // DebugEnabled reports false because every entry is discarded. - require.False(t, l.DebugEnabled()) + // Enabled reports false at every level, recognized or not, because every + // entry is discarded. + require.False(t, l.Enabled(logger.LevelDebug)) + require.False(t, l.Enabled(logger.Level(42))) } diff --git a/pkg/logger/test.go b/pkg/logger/test.go index fe3e910..650145e 100644 --- a/pkg/logger/test.go +++ b/pkg/logger/test.go @@ -104,9 +104,9 @@ func (t *TestLogger) TagsOf(l Level, msg string) map[string]any { // Debug implements [Logger] by recording the entry at [LevelDebug]. func (t *TestLogger) Debug(msg string, tags ...tag.Tag) { t.record(LevelDebug, msg, tags) } -// DebugEnabled implements [Logger]. TestLogger records every level, so Debug -// entries are always worth building. -func (t *TestLogger) DebugEnabled() bool { +// Enabled implements [Logger]. TestLogger records every level, so entries are +// always worth building. +func (t *TestLogger) Enabled(Level) bool { return true } diff --git a/pkg/logger/test_test.go b/pkg/logger/test_test.go index 8ce6733..3cf132e 100644 --- a/pkg/logger/test_test.go +++ b/pkg/logger/test_test.go @@ -20,8 +20,9 @@ func TestTestLoggerContains(t *testing.T) { require.True(t, l.Contains("hello")) require.False(t, l.Contains("goodbye")) - // TestLogger records every level, so Debug entries are always recorded. - require.True(t, l.DebugEnabled()) + // TestLogger records every level, recognized or not. + require.True(t, l.Enabled(logger.LevelDebug)) + require.True(t, l.Enabled(logger.Level(42))) } func TestTestLoggerContainsEntry(t *testing.T) { diff --git a/pkg/logger/zero.go b/pkg/logger/zero.go index f8a74a3..7d77e5d 100644 --- a/pkg/logger/zero.go +++ b/pkg/logger/zero.go @@ -29,10 +29,15 @@ func (l *ZeroLogger) Debug(msg string, tags ...tag.Tag) { logEvent(l.log.Debug(), msg, tags) } -// DebugEnabled implements [Logger], reporting whether the configured level -// records Debug entries. -func (l *ZeroLogger) DebugEnabled() bool { - return l.log.GetLevel() <= zerolog.DebugLevel +// Enabled implements [Logger], reporting whether the configured level records +// entries at lvl. An unrecognized level answers true rather than inheriting +// [zeroLevel]'s Info mapping, so a bad value never hides logs. +func (l *ZeroLogger) Enabled(lvl Level) bool { + if lvl > LevelError { + return true + } + + return l.log.GetLevel() <= zeroLevel(lvl) } // Error implements [Logger]. diff --git a/pkg/logger/zero_test.go b/pkg/logger/zero_test.go index 2862d45..3dbd26f 100644 --- a/pkg/logger/zero_test.go +++ b/pkg/logger/zero_test.go @@ -48,26 +48,36 @@ func TestZeroLoggerLevels(t *testing.T) { } } -func TestZeroLoggerDebugEnabled(t *testing.T) { +func TestZeroLoggerEnabled(t *testing.T) { t.Parallel() tests := []struct { name string - lvl logger.Level + cfg logger.Level // configured level of the logger + ask logger.Level // level being asked about want bool }{ - {"debug enables debug", logger.LevelDebug, true}, - {"info disables debug", logger.LevelInfo, false}, - {"warn disables debug", logger.LevelWarn, false}, - {"error disables debug", logger.LevelError, false}, + {"debug config enables debug", logger.LevelDebug, logger.LevelDebug, true}, + {"debug config enables error", logger.LevelDebug, logger.LevelError, true}, + {"info config disables debug", logger.LevelInfo, logger.LevelDebug, false}, + {"info config enables info", logger.LevelInfo, logger.LevelInfo, true}, + {"warn config disables info", logger.LevelWarn, logger.LevelInfo, false}, + {"warn config enables warn", logger.LevelWarn, logger.LevelWarn, true}, + {"error config disables warn", logger.LevelError, logger.LevelWarn, false}, + {"error config enables error", logger.LevelError, logger.LevelError, true}, + // An unrecognized level is enabled at every configured level, so a + // bad value never hides logs. + {"unknown level is enabled at debug", logger.LevelDebug, logger.Level(42), true}, + {"unknown level is enabled at info", logger.LevelInfo, logger.Level(42), true}, + {"unknown level is enabled at error", logger.LevelError, logger.Level(42), true}, } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { t.Parallel() - l := logger.NewZeroLogger(&bytes.Buffer{}, tt.lvl) - require.Equal(t, tt.want, l.DebugEnabled()) + l := logger.NewZeroLogger(&bytes.Buffer{}, tt.cfg) + require.Equal(t, tt.want, l.Enabled(tt.ask)) }) } }