Skip to content

Record check timings only when -XepPrintTimings asks for them - #6080

Open
vlsi wants to merge 1 commit into
google:masterfrom
vlsi:vs/timings-opt-in
Open

Record check timings only when -XepPrintTimings asks for them#6080
vlsi wants to merge 1 commit into
google:masterfrom
vlsi:vs/timings-opt-in

Conversation

@vlsi

@vlsi vlsi commented Aug 31, 2026

Copy link
Copy Markdown
Contributor

Why

ErrorProneScanner.processMatchers opens a timing span for every matcher it runs on every AST node, and nothing reads what the spans record: ErrorProneTimings.timings() and initializationTime() have no callers in error_prone_check_api or error_prone_core, and no test asserts on either.

The spans are not cheap at that frequency. Compiling error_prone_core itself opens 14771508 of them, and Calcite's :core opens 28493608, each a HashMap lookup, two System.nanoTime calls, and a closure. Against a build whose span returns a shared no-op, alternating the two inside one JVM so each pair meets the same machine state, they cost a median of 656 ms of a 13.0 s compile and 1216 ms of a 37 s one, and on Calcite 0.42 GiB of allocation.

#6079 has the full measurements.

What

-XepPrintTimings gates the spans, so a compilation that does not pass it opens none. The same flag prints the per-check totals when the compilation finishes, so the data reaches whoever paid for it:

Error Prone ran 440 checks in 582 ms, and spent 338 ms initializing
       172 ms   29.6%  ParameterName
        27 ms    4.8%  AvoidCommonTypeNames
        24 ms    4.2%  AutoValueSubclassLeaked

Every check that ran gets a row, so the count in the header is the number of rows below it.

An embedder that reads timings() programmatically now needs the flag too. That is the part worth arguing with, and #6079 says why I think the default belongs this way round: the collection has no consumer in this repository, and the flag is what gives it one.

Making the collection itself cheap enough to leave on is a larger change, and #6079 proposes it separately.

How to verify

mvn -pl check_api,core test -Dtest=ErrorProneOptionsTest,ErrorProneJavaCompilerTest

recognizesPrintTimings and printTimingsIsOffByDefault cover the option. printTimingsReportsEveryCheckThatRan compiles a real file and asserts both a non-zero count in the header and at least one row: the header alone is printed before the rows, so a build that collected nothing would still print one. withoutPrintTimingsNoReportIsPrinted covers the default.

Each test was watched failing: deleting the option's parse case fails the first, inverting the gate in VisitorState.timingSpan fails the third on both of its assertions, and dropping the Kind.COMPILATION branch fails it on the absent header.

One limitation the tests do not cover: under Gradle the report does not reach the build log, because Gradle passes no writer to JavaCompiler.getTask and javac's NOTICE writer then goes to the compiler daemon's stderr. It arrives through any caller that supplies a writer. Emitting it as a diagnostic instead would fix that, and the same applies to what RefactoringCollection already prints; I left both alone here.

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)
vlsi added a commit to vlsi/error-prone that referenced this pull request Aug 31, 2026
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)
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.

1 participant