You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
{{ message }}
Repository navigation
perf(tokenizer): read the clock only when metrics are enabled [W1-02] - #923
Tokenizer.tokenize called time.Now() and time.Since() on every call, even with metrics disabled (the default). The clock is now read only when metrics.IsEnabled(). If metrics are enabled mid-call the call is not recorded (PLAN said "duration 0"; not recording is equivalent for disabled-at-entry and avoids a bogus zero-duration sample). No API, token-output or error-text change. PLAN W1-02 (TOK-6 / MEM-2 time part).
Test Plan
New pkg/sql/tokenizer/metrics_gate_test.go: counters recorded for success, tokenize error and oversize error when enabled; nothing recorded when disabled; token output identical either way.
task check, task test:cbinding, go test -count=1 ./pkg/compatibility/..., staticcheck on ./pkg/sql/tokenizer/: pass. Goldens: no diffs.
Local scripts/perf/ab.sh -r 10 -t 200ms vs origin/main (GOGC=off, -cpu 1, M4, shared machine so indicative only):
Tokenize/scratch geomean 635.8n -> 583.5n, -8.23% (all 11 queries p<0.001, from -3.0% to -16.1%); plan threshold <= -4%: met.
CI perf gate (amd64, shadow, run 41331999297, base 69a5a72 head 1a02ee1): PASS. Gated geomean -1.87% (p<0.001), A/A control clean (0/26 moved >3%), no allocs/op or B/op change, instructions/op down on every e2e case (-0.15% to -1.59%).
Tokenize/scratch (amd64 gate subset): insert -4.38%, join -0.50%, complex +1.09% (p<0.001, below the 3% regress line; instructions/op for e2e/complex is -0.15%).
ParseRW medium: all within +-1.0%, not significant. Plan expected -0.5% to -2.5% on amd64 for short statements; the PLAN 4%/3% thresholds (measured on M4) are met locally but only partly on amd64 (simple_select -3.4%, meets -3%).
Review of PR #923: gate time.Now() on metrics.IsEnabled()
Verdict: looks good. I found one stale comment and a few small test nits. Nothing blocks merging.
I reviewed the diff only. I did not run the tests or benchmarks in this session.
Code (pkg/sql/tokenizer/tokenizer.go)
The change is correct and minimal. metricsOn is read once at entry. Every time.Since call is behind the same flag, so startTime is never read as the zero time.Time.
Stale comment (around line 608): it says "the duration is recorded as 0" if metrics are toggled on mid-call. The code doesn't do that. metricsOn is false, so nothing is recorded. The PR description and CHANGELOG both say "not recorded", so the code comment is the odd one out. Suggested wording: "If metrics are toggled on mid-call, that call is not recorded."
Enabled mid-call, then disabled: if metrics are on at entry and turned off before the end, RecordTokenization still runs. I don't know whether it re-checks IsEnabled internally. It would be a harmless sample either way, since it's the same race as before.
Cost of the check:metrics.IsEnabled() is probably a single atomic load, which is cheap. This is consistent with the measured gains.
Tests (metrics_gate_test.go)
The gate test covers success, tokenize error and oversize error, with metrics on and off. That's good coverage of the three RecordTokenization sites.
Global state: these tests change process-wide metrics state with Enable/Disable/Reset. They restore the enabled flag in t.Cleanup, but Reset() still wipes counters other tests might rely on. They also aren't safe under t.Parallel(). Nothing here is parallel, so this is fine today. Other tests in the package that read metrics could become flaky if someone adds parallelism later.
Weak assertion:TestTokenize_MetricsDoNotChangeTokens compares only token counts. Comparing the token types and values with reflect.DeepEqual or a loop would match the "token output identical" claim better. The tokens aren't safe to hold after PutTokenizer, so copy or compare them before the deferred release.
Missing case: there's no test for the tokscratch path (scratch == true). The gate is shared, so the risk is low.
Oversize allocation:strings.Repeat("x", MaxInputSize+1) allocates the full oversize buffer on each run() call, so twice per test. That's fine if MaxInputSize is a few MB. If it's much larger, consider building the slice once.
Performance, security, docs
Performance: the claimed gains are plausible. The PR itself says the amd64 gain may be only 0.5–2.5%, since tsc-based clocks are cheap. The pending CI gate result is the number that matters.
Security: nothing to flag. The size check still runs before the copy.
CHANGELOG: the entry is accurate, and its "not recorded" wording matches the behavior.
Suggested fixes
Correct the stale "recorded as 0" comment.
Optionally compare token content, not just the count, in the second test.
· branch perf/w1-02-clock-gate
Perf gate: PASS (shadow mode: report only, this check never fails)
Base 160c41726db7, head db46c7417016. 10 interleaved rounds, benchtime 200ms, -cpu 1, pinned to CPU 3 (SMT siblings 2-3) with taskset.
11 benchmark(s) faster by 3% or more
Rules: time regresses at >= +3% with p < 0.01 (Mann-Whitney U), or a suite geomean >= +1.5% (per-round geomeans, same test); allocs/op must not increase; B/op must not rise more than 2%; instructions/op must not rise more than 1.5%. An A/A control with more than 10% of benchmarks moving over 3% is noisy: re-run once, then inconclusive (neutral).
Gated suite (GOGC=off, GOMAXPROCS=1)
benchmark
time
p
A/A
B/op
allocs/op
status
ParseE2E/simple_select
-3.69%
<0.001
+0.19%
+0.00%
5 → 5
faster
ParseE2E/select_where
-2.78%
<0.001
+0.05%
+0.00%
18 → 18
ok
ParseE2E/join
-1.94%
<0.001
+0.60%
+0.00%
17 → 17
ok
ParseE2E/aggregate
-3.48%
<0.001
+0.25%
+0.00%
18 → 18
faster
ParseE2E/subquery
-3.98%
0.003
+0.47%
+0.00%
14 → 14
faster
ParseE2E/cte
-3.16%
<0.001
+0.09%
+0.00%
21 → 21
faster
ParseE2E/window
-4.19%
<0.001
+0.10%
+0.00%
11 → 11
faster
ParseE2E/complex
-0.38%
0.165
+0.04%
+0.00%
50 → 50
ok
ParseE2E/insert
-4.34%
<0.001
-0.41%
+0.00%
17 → 17
faster
ParseE2E/update
-5.20%
<0.001
-0.10%
+0.00%
13 → 13
faster
ParseE2E/delete
-8.62%
<0.001
+0.23%
+0.00%
5 → 5
faster
ParseRW/postgresql/medium
-0.35%
0.043
-0.15%
+0.00%
646 → 646
ok
ParseRW/mysql/medium
-1.01%
0.035
-0.63%
+0.00%
365 → 365
ok
ParseRW/mariadb/medium
+0.11%
0.796
-0.70%
-0.00%
523 → 523
ok
ParseRW/sqlserver/medium
+0.98%
0.010
-0.18%
+0.00%
936 → 936
ok
ParseRW/oracle/medium
-0.72%
0.143
-0.39%
-0.00%
1093 → 1093
ok
ParseRW/sqlite/medium
-0.92%
0.015
-0.11%
+0.00%
346 → 346
ok
ParseRW/snowflake/medium
-0.29%
0.353
-0.09%
+0.00%
777 → 777
ok
ParseRW/clickhouse/medium
-0.18%
0.393
-0.32%
+0.00%
384 → 384
ok
ParseFresh/simple_select
-0.80%
0.015
-0.09%
+0.00%
6 → 6
ok
ParseFresh/join
-1.38%
<0.001
-0.41%
+0.00%
18 → 18
ok
ParseFresh/complex
-0.40%
0.089
+0.07%
+0.00%
51 → 51
ok
PoolGetPut/serial
-0.17%
0.226
+0.07%
+0.00%
0 → 0
ok
Tokenize/scratch/join
-0.08%
0.426
+0.06%
+0.00%
0 → 0
ok
Tokenize/scratch/complex
+1.78%
<0.001
+0.01%
+0.00%
0 → 0
ok
Tokenize/scratch/insert
-4.50%
<0.001
-0.19%
+0.00%
0 → 0
faster
Normalize/simple_select
-3.26%
<0.001
+0.03%
+0.00%
10 → 10
faster
Normalize/join
-1.59%
<0.001
-0.08%
+0.00%
40 → 40
ok
Normalize/complex
-0.58%
0.023
-0.12%
+0.00%
110 → 110
ok
TransformParse/simple_select
-6.29%
0.003
-0.22%
+0.00%
5 → 5
faster
TransformParse/join
-2.99%
0.003
+0.33%
+0.00%
17 → 17
ok
TransformParse/complex
-0.87%
0.011
+0.22%
+0.00%
50 → 50
ok
geomean
-2.07%
<0.001
-0.04%
A/A control: 0 of 32 benchmarks moved more than 3%.
Pushed f0ca0dc: fixed the tokenize() comment (a call that starts with metrics off and has them enabled mid-call is not recorded, matching the code, CHANGELOG and this PR body; accepted over the PLAN's 'duration 0' to avoid fake zero-duration samples) and made TestTokenize_MetricsDoNotChangeTokens compare each token's Type and Value. Comment and test only, no production code change; the amd64 perf-gate numbers above still apply (gated geomean -1.87%, ParseE2E/simple_select -3.37%, allocs unchanged).
Review of PR #923: gate time.Now() on metrics.IsEnabled()
Verdict: looks good to merge. I read the diff against origin/main but did not run the tests or benchmarks. The CI perf gate result in the PR comments is the only performance data I relied on.
Code (pkg/sql/tokenizer/tokenizer.go)
metricsOn is read once at entry. All three RecordTokenization sites (oversize, tokenize error, success) sit behind it, so time.Since is never called on a zero startTime.
The code comment now says "that call is not recorded", which matches the code, the PR description and the CHANGELOG. The stale "recorded as 0" wording flagged in the earlier review is gone from the diff.
If metrics are on at entry and turned off mid-call, the sample is still recorded. That is the same race as before this change and is harmless.
metrics.IsEnabled() is cheap relative to a clock read. The measured gains fit that.
Tests (metrics_gate_test.go)
TestTokenize_MetricsGate checks the enabled and disabled cases. When enabled it expects 3 operations and 2 errors, which covers the success, tokenize-error and oversize paths. When disabled it expects zero of both.
TestTokenize_MetricsDoNotChangeTokens compares token type and value, not just the count. It copies the values before the deferred PutTokenizer, so there is no use-after-release.
Nits, none blocking:
Both tests call Enable, Disable and Reset on process-wide metrics state. That is fine while no test in the package uses t.Parallel(). It would become flaky if someone adds parallel tests that read metrics.
Neither test exercises the scratch == true path. The gate is shared, so the risk is low.
strings.Repeat("x", MaxInputSize+1) allocates the oversize buffer on each run() call. Building it once is cheap if MaxInputSize is large.
Performance
The perf gate passed. The ParseE2E short statements are 2–8% faster, and allocs/op and B/op are unchanged.
Tokenize/scratch/complex is +1.09% (p<0.001), which is below the 3% regress line. Instructions/op is down on every e2e case, so I think this is layout or noise.
On amd64, ParseRW medium is flat. That is expected, because the clock read is a small share of those longer inputs.
Security
Nothing to flag. The size check still runs before the input copy.
· branch perf/w1-02-clock-gate
Review of PR #923: gate time.Now() on metrics.IsEnabled()
Verdict: looks good to merge. I read the diff against origin/main. I did not run tests or benchmarks. For performance I relied on the CI perf-gate report.
Code (pkg/sql/tokenizer/tokenizer.go)
metricsOn is read once at entry. All three RecordTokenization sites (oversize, tokenize error, success) sit behind it, so time.Since is never called on a zero startTime.
The comment now says an enabled-mid-call invocation "is not recorded". That matches the code, the CHANGELOG and the PR body.
If metrics are on at entry and turned off mid-call, the sample is still recorded. This is the same race as before and is harmless.
The size check still runs before the input copy, so oversized input is still rejected before it is copied.
Tests (metrics_gate_test.go)
TestTokenize_MetricsGate covers the success, tokenize-error and oversize paths, both enabled and disabled.
TestTokenize_MetricsDoNotChangeTokens compares token type and value, not just the count.
Nits, none blocking:
The tests change process-wide metrics state with Enable, Disable and Reset. That is fine while the package has no t.Parallel() tests that read metrics.
The scratch == true path isn't exercised. It shares the same gate, so the risk is low.
strings.Repeat("x", MaxInputSize+1) is rebuilt on each run() call. Building it once would be cheap if MaxInputSize is large.
Performance
The perf gate passed in shadow mode: ParseE2E short statements are 1–8% faster. allocs/op and B/op are unchanged, and instructions/op is down on every e2e case.
The ParseRW medium cases are flat, which is expected because the clock read is a small share of longer inputs.
Security
Nothing to flag.
CHANGELOG
The entry is accurate and sits under Performance.
· branch perf/w1-02-clock-gate
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
documentationImprovements or additions to documentationtokenizerTokenizer / lexer changes
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
Tokenizer.tokenizecalledtime.Now()andtime.Since()on every call, even with metrics disabled (the default). The clock is now read only whenmetrics.IsEnabled(). If metrics are enabled mid-call the call is not recorded (PLAN said "duration 0"; not recording is equivalent for disabled-at-entry and avoids a bogus zero-duration sample). No API, token-output or error-text change. PLAN W1-02 (TOK-6 / MEM-2 time part).Test Plan
pkg/sql/tokenizer/metrics_gate_test.go: counters recorded for success, tokenize error and oversize error when enabled; nothing recorded when disabled; token output identical either way.task check,task test:cbinding,go test -count=1 ./pkg/compatibility/..., staticcheck on./pkg/sql/tokenizer/: pass. Goldens: no diffs.scripts/perf/ab.sh -r 10 -t 200msvs origin/main (GOGC=off, -cpu 1, M4, shared machine so indicative only):Tokenize/scratchgeomean 635.8n -> 583.5n, -8.23% (all 11 queries p<0.001, from -3.0% to -16.1%); plan threshold <= -4%: met.ParseE2E/simple_select582.6n -> 541.4n, -7.07% (p<0.001); plan threshold <= -3%: met. ParseE2E geomean -3.78%.Breaking Changes
None.
🤖 Generated with Claude Code
https://claude.ai/code/session_01DnbRnTFErhoMJdAjVEeCg2