Skip to content

Record check timings only when requested (-XepPrintTimings or -XepRecordTimings) - #6094

Merged
copybara-service[bot] merged 1 commit into
masterfrom
test_975574307
Sep 9, 2026
Merged

Record check timings only when requested (-XepPrintTimings or -XepRecordTimings)#6094
copybara-service[bot] merged 1 commit into
masterfrom
test_975574307

Conversation

@copybara-service

Copy link
Copy Markdown
Contributor

Record check timings only when requested (-XepPrintTimings or -XepRecordTimings)

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

Timing spans are now gated on opt-in flags:

  • -XepPrintTimings: records timings and prints a per-check report at the end of compilation:
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

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

FUTURE_COPYBARA_INTEGRATE_REVIEW=#6080 from vlsi:vs/timings-opt-in 2dd112f

…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
copybara-service Bot merged commit 92562c9 into master Sep 9, 2026
8 checks passed
@copybara-service
copybara-service Bot deleted the test_975574307 branch September 9, 2026 09:26
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