Skip to content

[logger]: Add DebugEnabled and gate the routing debug entry - #219

Merged
pseudomuto merged 2 commits into
temporalio:mainfrom
rainman456:gate-debug-logs
Oct 16, 2026
Merged

pseudomuto merged 2 commits into
temporalio:mainfrom
rainman456:gate-debug-logs

Conversation

@rainman456

Copy link
Copy Markdown
Contributor

Building the tags for a Debug entry allocates even when the configured level
discards the entry, 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. Director_Resolve measured 5
allocations per Resolve, and most of them were 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 PR, 10 rounds per side,
compared with benchstat. Allocs/op and B/op are deterministic and are the
primary evidence here.

benchmark base fix change
Director_Resolve allocs 5 0 -100% (p=0.000)
Director_Resolve ns/op ~501 ~83 -83% (p=0.000)
UnaryThroughProxy allocs 400 395 -1.25% (p=0.000)
UnaryDirect allocs 159 159 unchanged
protoutil benchmarks all samples identical

Behavior at debug level is unchanged; the entry is still logged exactly as
before when the level allows it.

Full benchstat output
pkg: github.com/temporalio/temporal-proxy/internal/router
                                   │ base.txt  │        cand.txt         │
                                   │   sec/op  │   sec/op    vs base     │
Director_Resolve/namespace-match-2  501.05n ± 14%  87.54n ± 26%  -82.53% (p=0.000 n=10)
Director_Resolve/default-2          503.25n ±  5%  79.72n ± 15%  -84.16% (p=0.000 n=10)
Mux_Switch/namespace-match-2         24.03n ±  2%  22.30n ±  2%   -7.22% (p=0.000 n=10)
Mux_Switch/metadata-match-2         125.4n ±  4%  124.5n ±  1%        ~ (p=0.671 n=10)
Mux_Switch/default-2                 97.11n ±  2%  96.00n ±  6%        ~ (p=0.481 n=10)
Mux_Switch/system-2                  88.11n ±  2%  87.97n ±  3%        ~ (p=0.811 n=10)
UnaryThroughProxy-2                 297.3µ ±  6%  282.6µ ±  7%        ~ (p=0.190 n=10)
UnaryDirect-2                       120.4µ ± 11%  124.1µ ± 11%        ~ (p=0.796 n=10)
geomean                             833.4n        524.6n        -37.05%

                                   │  base.txt  │       cand.txt        │
                                   │    B/op    │   B/op    vs base     │
Director_Resolve/namespace-match-2   192.0 ± 0%   0.0 ± 0%  -100.00% (p=0.000 n=10)
Director_Resolve/default-2           192.0 ± 0%   0.0 ± 0%  -100.00% (p=0.000 n=10)
Mux_Switch/namespace-match-2        0.000 ± 0%  0.000 ± 0%        ~ (p=1.000 n=10)
Mux_Switch/metadata-match-2         0.000 ± 0%  0.000 ± 0%        ~ (p=1.000 n=10)
Mux_Switch/default-2                0.000 ± 0%  0.000 ± 0%        ~ (p=1.000 n=10)
Mux_Switch/system-2                 0.000 ± 0%  0.000 ± 0%        ~ (p=1.000 n=10)
UnaryThroughProxy-2                 30.56Ki ± 0%  30.37Ki ± 0%  -0.63% (p=0.000 n=10)
UnaryDirect-2                       10.76Ki ± 0%  10.76Ki ± 0%        ~ (p=0.956 n=10)

                                   │ base.txt │      cand.txt      │
                                   │ allocs/op│  allocs/op vs base │
Director_Resolve/namespace-match-2  5.000 ± 0%  0.000 ± 0%  -100.00% (p=0.000 n=10)
Director_Resolve/default-2          5.000 ± 0%  0.000 ± 0%  -100.00% (p=0.000 n=10)
Mux_Switch/namespace-match-2        0.000 ± 0%  0.000 ± 0%        ~ (p=1.000 n=10)
Mux_Switch/metadata-match-2         0.000 ± 0%  0.000 ± 0%        ~ (p=1.000 n=10)
Mux_Switch/default-2                0.000 ± 0%  0.000 ± 0%        ~ (p=1.000 n=10)
Mux_Switch/system-2                 0.000 ± 0%  0.000 ± 0%        ~ (p=1.000 n=10)
UnaryThroughProxy-2                 400.0 ± 0%   395.0 ± 0%  -1.25% (p=0.000 n=10)
UnaryDirect-2                       159.0 ± 0%   159.0 ± 0%        ~ (p=1.000 n=10)

pkg: github.com/temporalio/temporal-proxy/internal/protoutil
(all five benchmarks: every metric identical on both sides, p=1.000,
"all samples are equal")

Notes on the run: shared 2 vCPU host (GOMAXPROCS=2, go1.27.1), so timing is
the weakest number here and the one we lean on least. Running both sides at
the same commit reproduces zero differences on every metric, so the deltas
above are the change, not the machine. The Mux_Switch/namespace-match timing
shift is on a path this diff cannot reach, so we treat it as layout noise.
The benchmarks ship in the previous PR, so every number here can be
reproduced anywhere.

@rainman456
rainman456 requested review from a team and pseudomuto as code owners October 11, 2026 00:23
@CLAassistant

CLAassistant commented Oct 11, 2026 •

Copy link
Copy Markdown

CLA assistant check
All committers have signed the CLA.

@pseudomuto pseudomuto left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hey @rainman456, thanks so much for the PR (and the benchmarks)!

Anything that reduces unnecessary allocs on the hot path is a win. I have one suggestion on the shape here though. Rather than DebugEnabled(), what do you think about having Enabled(lvl Level) bool instead?

I'm thinking down the line, there'll be another spot where we might want InfoEnabled() and we'd go through a second interface (breaking) change. Having a single Enabled func would avoid that.

Some things to consider if we go this route:

  • zeroLevel maps unrecognized values to Info, so Enabled(Level(42)) quietly answers as Enabled(LevelInfo). Maybe worth a callout in the doc comment, or treating unknown levels as enabled so a bad value never hides logs?
  • Currently, the package mirrors each Logger method as a package-level function over Default(), so a matching logger.Enabled(lvl) would keep that symmetry.

Your numbers should carry over unchanged, since it's still one interface call and a comparison. What do you think?

@rainman456

Copy link
Copy Markdown
Contributor Author

Good call on Enabled — taking it, and pushed in e704cf0.

  • Replaced DebugEnabled() with Enabled(lvl Level) bool on the interface, so the next gate (an InfoEnabled, say) can reuse it without another breaking change.
  • Added the package-level logger.Enabled(lvl) over defaultLogger, for symmetry with the Debug/Info/Error helpers.
  • Unknown levels answer true, so a bad value never hides logs. zeroLevel keeps mapping unrecognized levels to Info for config and display; the doc comment on Enabled states the rule.
  • Implementations: Noop is false (everything is discarded, whatever the level), Test is true, Zero consults the configured level.
  • The director gate is now d.logger.Enabled(logger.LevelDebug), and TestZeroLoggerEnabled covers every configured/asked pair, including Level(42) at debug, info, and error.
  • The benchmark numbers above carry over unchanged — the work they measured did not move. Happy to re-run the A/B if you'd like fresh output against this commit.

@pseudomuto

Copy link
Copy Markdown
Collaborator

@rainman456 this LGTM 👍 Can we separate this from #218?

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.
Review on temporalio#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.
@rainman456

rainman456 commented Oct 16, 2026 •

Copy link
Copy Markdown
Contributor Author

Done. Rebased onto main with the #218 commits dropped, so this PR now carries just the two logger commits. Head is 22472a2, content is the same apart from the rebase itself. Fork CI (lint, test, build) is green on it.

@codecov-commenter

Copy link
Copy Markdown

Codecov Report

❌ Patch coverage is 92.85714% with 1 line in your changes missing coverage. Please review.

📢 Thoughts on this report? Let us know!

🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

@pseudomuto
pseudomuto merged commit 3ec5011 into temporalio:main Oct 16, 2026
6 checks passed
@pseudomuto

Copy link
Copy Markdown
Collaborator

Thanks again @rainman456!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants