Per-check timing spans cost a few percent of the compile, and nothing reads the timings

[vlsi]

ErrorProneScanner.processMatchers opens a timing span for every matcher it runs on every AST node:

try (AutoCloseable unused = oldState.timingSpan(matcher)) {

VisitorState.timingSpan forwards to ErrorProneTimings.span, which looks the check up by canonical name, starts a Stopwatch, and returns a closure that stops it. Every span is therefore a HashMap lookup, two System.nanoTime calls, and a closure.

Nothing in this repository reads what the timers record: ErrorProneTimings.timings() and initializationTime() have no callers in error_prone_check_api or error_prone_core, and no test asserts on either. I assume there is an internal consumer, since the class arrived in cl/245821511 for that purpose, but every build that uses the released artifact pays for data it has no way to read.

span has one caller, so it is not that some spans are coarse and useful while others are fine-grained: all of them wrap one matcher on one node.

Cost

Two workloads, both compiled in process so that the numbers are the compiling thread's own, on macOS on Apple silicon.

error_prone_core itself, 948 sources, JDK 24, default check set. One compilation opens 14771508 spans, so it makes 29543016 System.nanoTime calls. Comparing that build against one whose span returns a shared no-op, alternating the two inside a single JVM so each pair meets the same machine state, the spans cost a median of 656 ms against a floor of 13.0 s, positive in 8 pairs out of 8.

Calcite's :core, 1655 sources, JDK 21, with NullAway and the project's own check selection. One compilation opens 28493608 spans. The spans cost a median of 1216 ms against a floor of 37 s, positive in 4 pairs out of 4, and — unlike the first workload — 0.42 GiB of allocation:

	allocated by the compiling thread
spans on	21.03 GiB
spans off	20.61 GiB

The closure is what accounts for that. It does not show up on error_prone_core, where C2 inlines span into processMatchers and scalar-replaces the closure; it does show up 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.

What the spans measure

Recording each span's duration alongside the per-check totals, on error_prone_core:

span duration	share of spans	share of measured time
under 128 ns	45.1%	2.9%
under 512 ns	78.2%	11.4%
under 2 us	95.2%	27.3%

4.6% of spans come back as 0 ns, which the clock cannot resolve. Grouping the same run by each check's mean cost per call, over the 499 checks that ran:

mean cost per call	checks	share of spans	share of measured time
under 100 ns	53	22.8%	2.5%
100 ns to 300 ns	141	41.9%	10.2%
300 ns to 1 us	137	21.8%	16.7%
1 us to 10 us	121	13.1%	35.3%
10 us to 100 us	38	0.40%	20.0%
over 100 us	9	0.04%	15.4%

The two cheapest rows are 64.7% of the spans and 12.7% of the time. A pair of nanoTime calls measures 24 ns to 27 ns on this machine, and the checks in the first row average 38 ns to 73 ns per call, so measuring them costs about as much as they do: MislabeledAndroidString runs 141571 times for 8 ms of work, and the clock reads that measure it come to about 5 ms.

The checks a report is read for sit at the other end, and they are rare. On error_prone_core every one of the top entries by total time runs 948 times, once per compilation unit: AlreadyChecked at 408 ms, NotJavadoc at 339 ms, AlmostJavadoc at 244 ms — each 0.01% of the spans.

What I would propose

Gate the spans on a flag, and make that flag print the report. A build that does not ask for timings then opens no span, and a build that does gets the numbers rather than collecting them for a consumer it does not have. I have this working as -XepPrintTimings, printing from finished(TaskEvent.Kind.COMPILATION):

Error Prone ran 457 checks in 34585 ms, and spent 326 ms initializing
      8567 ms   24.8%        859655 calls  max 175288458 ns  NullAway
      1222 ms    3.5%        101964 calls  max  67279500 ns  ParameterName
      1179 ms    3.4%         21416 calls  max  15422250 ns  MissingFail

That is Calcite's :core. The call count and the longest single invocation are there because a total alone misleads: a one-off cost — the first lookup of a type the classpath does not have, say — lands on whichever check triggered it. InjectOnBugCheckers reads 7 ms over 21416 calls with a maximum in the tens of microseconds, and one run charged it 307 ms; the maximum is what tells those two cases apart.

Then make the collection cheap enough that asking for it is not a decision. How many spans a check opens is already known statically — it is the number of nodes of the kind its *TreeMatcher interfaces select — while what a span costs is not. That split suggests keeping the count and sampling the clock: a per-check counter, a clock read on one invocation in N, and a total scaled by the counter. Timing a check on every invocation while its mean stays above roughly a microsecond keeps the checks the report is about measured exactly, and drops the cheap, numerous ones to a rounding error.

I have that working too. On error_prone_core it costs a median of 209 ms where the current implementation costs 656 ms, and on Calcite it is not distinguishable from having no spans at all, allocation included. Its accuracy against an exactly-timed run is no worse than two exactly-timed runs differ from each other:

comparison	within 10%	within 20%
exact against exact, the noise floor	78%	91%
exact against sampled	65%	86%

The threshold is not a knob I would want to document. A clock read can be measured at startup in well under a millisecond, and the bound follows from it: time a check exactly while one measurement perturbs it by less than a few percent.

One caveat I have not solved: under Gradle the report does not reach the build log. It goes to javac's NOTICE writer, and Gradle passes no writer to getTask, so the text goes to the compiler daemon's stderr and is dropped. It arrives fine through JavaCompiler.getTask with a writer, which is how ErrorProneJavaCompilerTest sees it. Emitting the report as a diagnostic, or behind a flag that names a file, would fix that; the same applies to what RefactoringCollection already prints.

I am happy to send a pull request. The gate and the report are the small half and stand alone; the sampled collection is the larger half and I would rather hear which shape suits the internal consumer before proposing it.

[cpovirk]

Thanks, this matches the numbers that we saw when the set the timings up. As you suspected, we do use them internally, and that ends up benefitting external users indirectly by helping us identify and fix performance issues. But as you say, there's no reason to punish external users directly by collecting the data there.

There are at least a few paths forward here:

• Have Copybara strip the timing code from the OSS repo entirely.
• Require a flag to collect timing data, and set it internally.
  • ...and potentially have another flag that outputs that data for OSS use (or additional internal use).
• Optimize things enough that the timing doesn't hurt.
  • I have been sitting on a possible change (internal CL 933288891) that started off as an attempt to avoid looking up timers but morphed into another approach that involved running all trees through a given matcher first (rather than all matchers for a given tree). I thought I might have found that timers no longer hurt at that point, but I'd need to validate more.

We should eventually figure this out :\

[vlsi]

Thanks — that settles the part I could not see from outside.

I have put your second and third paths up as two pull requests, since both are useful to external users on their own and they compose:

• Record check timings only when -XepPrintTimings asks for them #6080 — a flag decides whether anything is collected, and prints the per-check totals when the compilation ends. One flag does both jobs here; splitting it so that collection and output are separate is a small change if internal use wants to collect without printing.
• Count every check invocation, and sample the clock #6081 — the collection made cheap: a per-check slot instead of a lookup by name, an exact invocation count, and a sampled clock. Stacked on Record check timings only when -XepPrintTimings asks for them #6080; its first commit is that one. On error_prone_core it costs 209 ms of a 13.0 s compile where the current Stopwatch costs 656 ms, and on Calcite's :core it is not distinguishable from opening no spans at all, including the 0.42 GiB of closure allocation.

Close either if it is the wrong shape. #6080 is the one I would keep if only one survives, because it is small and it stops external users paying for data they cannot read.

One measurement that bears on CL 933288891, since you wanted to validate whether timers stop hurting once matchers are hoisted: on these two workloads a span looks to be about half clock and half lookup. error_prone_core opens 14771508 spans and Calcite's :core opens 28493608; at the 24 ns to 27 ns a nanoTime pair measures here, the clock alone accounts for 355 ms to 399 ms of the 656 ms a span costs on the first, and 684 ms to 769 ms of the 1216 ms on the second. So running all trees through one matcher should take out the lookup half and leave the clock half standing, which is the half #6081 addresses. Worth measuring both together before concluding either is enough.

[cushon]

Thanks for raising this, doing some combination of these PRs and what @cpovirk mentioned SGTM, I'll think a little more about the details.

As Chris said we were using this internally, but I agree with having a way to cheaply disable it for builds that don't use it, and even for those internal builds we should look at optimizing the collection and having a way to sample it may be interesting.