Count every check invocation, and sample the clock - #6081
Open
vlsi wants to merge 2 commits into
Open
Conversation
ErrorProneScanner opens a timing span for every matcher on every AST node, and nothing reads what the spans record: ErrorProneTimings.timings() and initializationTime() have no callers in check_api or core, and no test asserts on either. Compiling error_prone_core opens 14771508 spans, and Calcite's :core opens 28493608; measured against a build whose spans are no-ops, they cost a median of 656 ms of a 13.0 s compile and 1216 ms of a 37 s one. The spans are now gated on -XepPrintTimings, which also prints the per-check totals once the compilation finishes, so a build that does not ask for the data does not collect it and a build that does can read it. Issue google#6079 has the measurements and proposes making the collection itself cheap enough to leave on; that is a larger change and is not this one. Assisted-by: Claude Code (claude-opus-5)
Timing a check on every invocation costs about as much as the cheapest invocations it measures: on error_prone_core 45% of spans are shorter than 128 ns and carry 2.9% of the recorded time, while a pair of System.nanoTime calls measures 24 ns to 27 ns. So the count is now exact and the elapsed time is sampled, and a sample counts for the invocations it stands in for. A check keeps its own CheckTiming, so the scanner reaches it without looking the check up by name, and a check whose mean invocation stays above a microsecond is timed on every one of them -- those are the checks a report is read for, and timing them perturbs each by a few percent at most. Measured against a build that opens no span at all, this costs a median of 209 ms of a 13.0 s compile where the Stopwatch it replaces costs 656 ms, and on Calcite's :core it is not distinguishable from having no spans, allocation included. The report gains the invocation count and the longest single invocation, which separate a check that is slow from one that paid a one-off cost: on Calcite InjectOnBugCheckers reads 7 ms over 21416 calls, and one run charged it 307 ms because the first constructor it saw triggered a type lookup the classpath could not answer. Estimates are worth what they can be checked against: CheckTimingTest drives the schedule and the weighted total through a supplied elapsed time rather than a clock, and ErrorProneTimingsTest covers both ways span reaches a check's state. See google#6079. This sits on top of the flag in google#6080 and is not proposed for merge until the shape of the collection is settled. Assisted-by: Claude Code (claude-opus-5)
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
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
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.
Stacked on #6080. The first commit here is that pull request unchanged; only the second one,
Count every check invocation, and sample the clock, is this change. It wants to merge after #6080, and I will rebase once that lands.Why
This is the third path @cpovirk listed in #6079: make the timing cheap enough that it does not hurt. #6080 is the second path, and the two compose — a flag still decides whether anything is collected, and this decides what collecting costs.
Timing a check on every invocation costs about what the cheapest invocations cost. On
error_prone_core, 45% of spans are shorter than 128 ns and carry 2.9% of the recorded time, while a pair ofSystem.nanoTimecalls measures 24 ns to 27 ns on the machine below. The checks a report is read for are at the other end and are rare: on that workload every top entry by total time runs 948 times, once per compilation unit.What
A check keeps its own
CheckTiming, so the scanner reaches its state through a field rather than a lookup by canonical name. The invocation count is exact. The elapsed time is sampled: below 256 invocations every one is timed, above it one incount / 256, and each sample counts for the invocations it stands in for. A check whose mean invocation stays above a microsecond is timed on every one of them, so the ones the report is about are measured rather than estimated, and one measurement perturbs such an invocation by a few percent at most.That bound is the only tunable, and it does not want to be a flag: a clock read can be measured at startup in well under a millisecond, and the bound follows from it.
The report gains two columns. The invocation count, and the longest single invocation — which is what separates a check that is slow from one that paid a one-off cost. On Calcite
InjectOnBugCheckersreads 7 ms over 21416 calls, and one run charged it 307 ms because the first constructor it saw triggered a type lookup the classpath could not answer.What it costs
Both workloads compiled in process so the numbers are the compiling thread's own, macOS on Apple silicon. Each variant is compared against a build whose spans are no-ops, alternating the two inside one JVM so every pair meets the same machine state.
Stopwatch, as todayerror_prone_core, 948 sources, JDK 24:core, 1655 sources, JDK 21, NullAwayOn Calcite the closure also costs 0.42 GiB of the compiling thread's allocation, which this removes:
Stopwatch, spans onThe closure does not show up on
error_prone_core, where C2 inlinesspanintoprocessMatchersand scalar-replaces it. It does on Calcite, whose larger check set defeats that inlining, so whether the allocation is real depends on the JIT and a project cannot tell which case it is in.Sampling costs accuracy, and the question is how much against the noise a timing report already carries. Comparing per-check shares, over checks above 50 ms, across four runs of each build:
How to verify
mvn -pl check_api,core test -Dtest=CheckTimingTest,ErrorProneTimingsTest,ErrorProneOptionsTest,ErrorProneJavaCompilerTestCheckTimingTestdrives the sampling schedule and the weighted total through a supplied elapsed time rather than a clock, so the arithmetic the report prints is pinned without timing anything, and its expected values are worked out by hand from the documented rule rather than from the implementation's own expression.ErrorProneTimingsTestcovers both waysspanreaches a check's state, and that one canonical name folds every slot reported under it.Each test was watched failing against the change it guards: reverting the stride weighting, the mean test that keeps an expensive check exactly timed, the
openflag that rejects a nested span, thesamplingreset that keeps a second close from recording again, the list registry, and theinstanceof BugCheckerarm each fail their own test and no other.If this is not the shape you want
Close it. #6080 stands on its own, and the measurements above are the part of this that is worth keeping either way — in particular for internal CL 933288891: a span is roughly half clock and half lookup on these workloads, so hoisting the lookup out of the per-node loop should take out about that half and leave the rest.