Record check timings only when requested (-XepPrintTimings or -XepRecordTimings) - #6094
Merged
Conversation
…ordTimings) ## 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](#6079) has the full measurements. ## What Timing spans are now gated on opt-in flags: - `-XepPrintTimings`: records timings and prints a per-check report at the end of compilation: ```text 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 ``` - `-XepRecordTimings`: records timings into `ErrorProneTimings` without printing console output (for tools or build systems that query `timings()` programmatically, such as build metrics reporters). Without either flag, timing spans are no-ops (`NO_TIMING_SPAN`), avoiding map lookups, timestamp reads, and closure allocations. ## How to verify ```bash mvn -pl check_api,core test -Dtest=ErrorProneOptionsTest,ErrorProneJavaCompilerTest ``` `recognizesPrintTimings`, `recognizesRecordTimings`, and `printTimingsIsOffByDefault` cover option parsing. `printTimingsReportsEveryCheckThatRan`, `withoutPrintTimingsNoReportIsPrinted`, and `recordTimingsCollectsWithoutPrintingReport` verify timing recording and output behavior. 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. Fixes #6080 COPYBARA_INTEGRATE_REVIEW=#6080 from vlsi:vs/timings-opt-in 2dd112f PiperOrigin-RevId: 978412258
copybara-service
Bot
force-pushed
the
test_975574307
branch
from
September 9, 2026 09:26
e8a6d05 to
92562c9
Compare
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.
Record check timings only when requested (-XepPrintTimings or -XepRecordTimings)
Why
ErrorProneScanner.processMatchersopens a timing span for every matcher it runs on every AST node, and nothing reads what the spans record:ErrorProneTimings.timings()andinitializationTime()have no callers inerror_prone_check_apiorerror_prone_core, and no test asserts on either.The spans are not cheap at that frequency. Compiling
error_prone_coreitself opens 14771508 of them, and Calcite's:coreopens 28493608, each aHashMaplookup, twoSystem.nanoTimecalls, and a closure. Against a build whosespanreturns 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
Timing spans are now gated on opt-in flags:
-XepPrintTimings: records timings and prints a per-check report at the end of compilation:-XepRecordTimings: records timings intoErrorProneTimingswithout printing console output (for tools or build systems that querytimings()programmatically, such as build metrics reporters).Without either flag, timing spans are no-ops (
NO_TIMING_SPAN), avoiding map lookups, timestamp reads, and closure allocations.How to verify
mvn -pl check_api,core test -Dtest=ErrorProneOptionsTest,ErrorProneJavaCompilerTestrecognizesPrintTimings,recognizesRecordTimings, andprintTimingsIsOffByDefaultcover option parsing.printTimingsReportsEveryCheckThatRan,withoutPrintTimingsNoReportIsPrinted, andrecordTimingsCollectsWithoutPrintingReportverify timing recording and output behavior.One limitation the tests do not cover: under Gradle the report does not reach the build log, because Gradle passes no writer to
JavaCompiler.getTaskand javac'sNOTICEwriter 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 whatRefactoringCollectionalready prints; I left both alone here.Fixes #6080
FUTURE_COPYBARA_INTEGRATE_REVIEW=#6080 from vlsi:vs/timings-opt-in 2dd112f