diff --git a/check_api/src/main/java/com/google/errorprone/CheckTiming.java b/check_api/src/main/java/com/google/errorprone/CheckTiming.java new file mode 100644 index 00000000000..bfb90082998 --- /dev/null +++ b/check_api/src/main/java/com/google/errorprone/CheckTiming.java @@ -0,0 +1,172 @@ +/* + * Copyright 2026 The Error Prone Authors. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.google.errorprone; + +import java.io.Serializable; +import java.time.Duration; + +/** + * How long one check ran during one compilation, and how many times. + * + *

A {@link com.google.errorprone.bugpatterns.BugChecker} owns its instance; every other {@link + * com.google.errorprone.matchers.Suppressible} shares one per canonical name with {@link + * ErrorProneTimings}. Either way {@link ErrorProneTimings} claims the instance for the compilation + * that is running. + * + *

The count is exact. The elapsed time is an estimate: a check whose invocations are shorter than + * a clock read is timed on a sample of them, and each sample counts for the invocations it stands in + * for. + * + *

An instance is confined to one thread, and {@link #begin} rejects a span opened inside another + * span on the same instance. javac is single-threaded and a check never runs inside itself, so + * nothing here is synchronized. + */ +public final class CheckTiming implements AutoCloseable, Serializable { + + /** + * Invocation count below which every invocation is timed. + * + *

Above it, one invocation in {@code count / SAMPLES_PER_STRIDE} is timed, so a check that runs + * a million times contributes a few thousand samples rather than a million clock reads. + */ + private static final long SAMPLES_PER_STRIDE = 256; + + /** + * Mean cost, in nanoseconds, above which a check is timed on every invocation. + * + *

A pair of {@link System#nanoTime} calls costs a few tens of nanoseconds, so timing an + * invocation that lasts a microsecond perturbs it by a few percent. Raising this bound would sample + * the checks a report is read for: a check that visits a hundred thousand nodes and takes a second + * averages about ten microseconds per invocation. + */ + private static final long TIME_EVERY_INVOCATION_ABOVE_NANOS = 1_000; + + private static final long serialVersionUID = 1L; + + /** + * The {@link ErrorProneTimings} this state belongs to. + * + *

A scanner can outlive the compilation that built it, so a check whose instance is reused + * starts from zero rather than accumulating across compilations. Two compilations that share one + * scanner and run at the same time would race here; nothing in Error Prone shares a scanner that + * way, and {@link com.google.errorprone.scanner.ScannerSupplier#fromScanner} is the one entry + * point that lets an embedder do it. + */ + private transient Object owner; + + private transient long count; + private transient long stride; + private transient long nextSample; + private transient long weightedNanos; + private transient long sampledNanos; + private transient long sampledCount; + private transient long maxNanos; + private transient long startNanos; + private transient boolean sampling; + private transient boolean open; + + boolean claim(Object newOwner) { + if (owner == newOwner) { + return false; + } + owner = newOwner; + count = 0; + stride = 1; + nextSample = 1; + weightedNanos = 0; + sampledNanos = 0; + sampledCount = 0; + maxNanos = 0; + sampling = false; + open = false; + return true; + } + + /** + * Records that an invocation has started, and reads the clock if this one is being timed. + * + * @throws IllegalStateException if a span on this check is already open + */ + void begin() { + if (open) { + throw new IllegalStateException("a timing span for this check is already open; close it before opening another"); + } + open = true; + long n = ++count; + if (n < nextSample) { + sampling = false; + return; + } + sampling = true; + startNanos = System.nanoTime(); + } + + /** Returns whether {@link #begin} chose to time the invocation that is open. */ + boolean sampled() { + return sampling; + } + + /** Records the end of the invocation {@link #begin} started, timing it if it was sampled. */ + @Override + public void close() { + // The clock is read only for an invocation begin() chose to time. + closeWith(sampling ? System.nanoTime() - startNanos : 0); + } + + /** + * Records the end of the open invocation, as {@link #close} does, with the elapsed time supplied + * rather than measured. + */ + void closeWith(long elapsedNanos) { + open = false; + if (!sampling) { + return; + } + // A span records once, so a second close takes the return above. + sampling = false; + weightedNanos += elapsedNanos * stride; + sampledNanos += elapsedNanos; + sampledCount++; + maxNanos = Math.max(maxNanos, elapsedNanos); + stride = + sampledNanos / sampledCount >= TIME_EVERY_INVOCATION_ABOVE_NANOS + ? 1 + : Math.max(1, count / SAMPLES_PER_STRIDE); + nextSample = count + stride; + } + + /** Returns how long this check ran, estimated from the invocations that were timed. */ + public Duration elapsed() { + return Duration.ofNanos(weightedNanos); + } + + /** Returns exactly how many times this check ran. */ + public long count() { + return count; + } + + /** + * Returns the longest timed invocation, in nanoseconds. + * + *

A check whose total is large while this value is small is expensive on every invocation. One + * whose total is close to this value paid a one-off cost, such as the first lookup of a type that + * the compilation classpath does not have, and is cheap the rest of the time. + */ + public long maxNanos() { + return maxNanos; + } +} diff --git a/check_api/src/main/java/com/google/errorprone/ErrorProneAnalyzer.java b/check_api/src/main/java/com/google/errorprone/ErrorProneAnalyzer.java index 45d073e88dc..909b32c1088 100644 --- a/check_api/src/main/java/com/google/errorprone/ErrorProneAnalyzer.java +++ b/check_api/src/main/java/com/google/errorprone/ErrorProneAnalyzer.java @@ -19,9 +19,11 @@ import static com.google.common.base.Preconditions.checkNotNull; import static com.google.common.base.Throwables.getStackTraceAsString; import static com.google.common.base.Verify.verify; +import static java.util.Comparator.comparing; import com.google.common.base.Supplier; import com.google.common.base.Suppliers; +import com.google.common.collect.ImmutableMap; import com.google.common.collect.ImmutableSet; import com.google.errorprone.BugPattern.SeverityLevel; import com.google.errorprone.ErrorProneOptions.Severity; @@ -45,7 +47,10 @@ import com.sun.tools.javac.util.Log.WriterKind; import com.sun.tools.javac.util.PropagatedException; import java.io.PrintWriter; +import java.time.Duration; import java.util.HashSet; +import java.util.Locale; +import java.util.Map; import java.util.Set; import javax.tools.JavaFileObject; import org.safere.Pattern; @@ -190,8 +195,43 @@ private ErrorProneAnalyzer( private int errorProneErrors = 0; + /** Prints how long each check ran and how often, slowest first. */ + private void printTimings() { + ErrorProneTimings timings = ErrorProneTimings.instance(context); + ImmutableMap checks = timings.timings(); + ImmutableMap counts = timings.counts(); + ImmutableMap maxNanos = timings.maxNanos(); + Duration total = checks.values().stream().reduce(Duration.ZERO, Duration::plus); + PrintWriter out = Log.instance(context).getWriter(WriterKind.NOTICE); + out.printf( + Locale.ROOT, + "Error Prone ran %d checks in %d ms, and spent %d ms initializing%n", + checks.size(), + total.toMillis(), + timings.initializationTime().toMillis()); + checks.entrySet().stream() + .sorted(comparing((Map.Entry e) -> e.getValue()).reversed()) + .forEach( + e -> + out.printf( + Locale.ROOT, + " %8d ms %5.1f%% %12d calls max %9d ns %s%n", + e.getValue().toMillis(), + total.isZero() ? 0.0 : 100.0 * e.getValue().toNanos() / total.toNanos(), + counts.getOrDefault(e.getKey(), 0L), + maxNanos.getOrDefault(e.getKey(), 0L), + e.getKey())); + out.flush(); + } + @Override public void finished(TaskEvent taskEvent) { + if (taskEvent.getKind() == Kind.COMPILATION) { + if (errorProneOptions.printTimings()) { + printTimings(); + } + return; + } if (taskEvent.getKind() != Kind.ANALYZE) { return; } diff --git a/check_api/src/main/java/com/google/errorprone/ErrorProneOptions.java b/check_api/src/main/java/com/google/errorprone/ErrorProneOptions.java index 4acb43b6084..e4faea6294f 100644 --- a/check_api/src/main/java/com/google/errorprone/ErrorProneOptions.java +++ b/check_api/src/main/java/com/google/errorprone/ErrorProneOptions.java @@ -69,6 +69,7 @@ public final class ErrorProneOptions { "-XepDisableWarningsInGeneratedCode"; private static final String COMPILING_TEST_ONLY_CODE = "-XepCompilingTestOnlyCode"; private static final String COMPILING_PUBLICLY_VISIBLE_CODE = "-XepCompilingPubliclyVisibleCode"; + private static final String PRINT_TIMINGS = "-XepPrintTimings"; private static final String ARGUMENT_FILE_PREFIX = "@"; /** see {@link javax.tools.OptionChecker#isSupportedOption(String)} */ @@ -88,6 +89,7 @@ public static int isSupportedOption(String option) { || option.equals(IGNORE_SUPPRESSION_ANNOTATIONS) || option.equals(COMPILING_TEST_ONLY_CODE) || option.equals(COMPILING_PUBLICLY_VISIBLE_CODE) + || option.equals(PRINT_TIMINGS) || option.equals(DISABLE_ALL_WARNINGS); return isSupported ? 0 : -1; } @@ -161,6 +163,7 @@ abstract static class Builder { private final Pattern excludedPattern; private final boolean ignoreSuppressionAnnotations; private final boolean ignoreLargeCodeGenerators; + private final boolean printTimings; private ErrorProneOptions( ImmutableMap severityMap, @@ -178,7 +181,8 @@ private ErrorProneOptions( PatchingOptions patchingOptions, Pattern excludedPattern, boolean ignoreSuppressionAnnotations, - boolean ignoreLargeCodeGenerators) { + boolean ignoreLargeCodeGenerators, + boolean printTimings) { this.severityMap = severityMap; this.remainingArgs = remainingArgs; this.ignoreUnknownChecks = ignoreUnknownChecks; @@ -195,6 +199,7 @@ private ErrorProneOptions( this.excludedPattern = excludedPattern; this.ignoreSuppressionAnnotations = ignoreSuppressionAnnotations; this.ignoreLargeCodeGenerators = ignoreLargeCodeGenerators; + this.printTimings = printTimings; } public ImmutableList getRemainingArgs() { @@ -241,6 +246,14 @@ public boolean ignoreLargeCodeGenerators() { return ignoreLargeCodeGenerators; } + /** + * Returns whether Error Prone records how long each check runs and prints the totals when the + * compilation finishes. + */ + public boolean printTimings() { + return printTimings; + } + public ErrorProneFlags getFlags() { return flags; } @@ -265,6 +278,7 @@ private static class Builder { private boolean isPubliclyVisibleTarget = false; private boolean ignoreSuppressionAnnotations = false; private boolean ignoreLargeCodeGenerators = true; + private boolean printTimings = false; private final Map severityMap = new LinkedHashMap<>(); private final ErrorProneFlags.Builder flagsBuilder = ErrorProneFlags.builder(); private final PatchingOptions.Builder patchingOptionsBuilder = PatchingOptions.builder(); @@ -339,6 +353,10 @@ void setIgnoreLargeCodeGenerators(boolean ignoreLargeCodeGenerators) { this.ignoreLargeCodeGenerators = ignoreLargeCodeGenerators; } + void setPrintTimings(boolean printTimings) { + this.printTimings = printTimings; + } + void setDisableAllChecks(boolean disableAllChecks) { // Discard previously set severities so that the DisableAllChecks flag is position sensitive. severityMap.clear(); @@ -374,7 +392,8 @@ ErrorProneOptions build(ImmutableList remainingArgs) { patchingOptionsBuilder.build(), excludedPattern, ignoreSuppressionAnnotations, - ignoreLargeCodeGenerators); + ignoreLargeCodeGenerators, + printTimings); } void setExcludedPattern(Pattern excludedPattern) { @@ -478,6 +497,7 @@ public static ErrorProneOptions processArgs(Iterable args) { case COMPILING_TEST_ONLY_CODE -> builder.setTestOnlyTarget(true); case COMPILING_PUBLICLY_VISIBLE_CODE -> builder.setPubliclyVisibleTarget(true); case DISABLE_ALL_WARNINGS -> builder.setDisableAllWarnings(true); + case PRINT_TIMINGS -> builder.setPrintTimings(true); default -> { if (arg.startsWith(SEVERITY_PREFIX)) { builder.parseSeverity(arg); diff --git a/check_api/src/main/java/com/google/errorprone/ErrorProneTimings.java b/check_api/src/main/java/com/google/errorprone/ErrorProneTimings.java index 1e2d61ec03d..fa24abe89ce 100644 --- a/check_api/src/main/java/com/google/errorprone/ErrorProneTimings.java +++ b/check_api/src/main/java/com/google/errorprone/ErrorProneTimings.java @@ -20,11 +20,16 @@ import com.google.common.base.Stopwatch; import com.google.common.collect.ImmutableMap; +import com.google.errorprone.bugpatterns.BugChecker; import com.google.errorprone.matchers.Suppressible; import com.sun.tools.javac.util.Context; import java.time.Duration; -import java.util.HashMap; +import java.util.ArrayList; +import java.util.LinkedHashMap; +import java.util.List; import java.util.Map; +import java.util.function.LongBinaryOperator; +import java.util.function.ToLongFunction; /** A collection of timing data for the runtime of individual checks. */ public final class ErrorProneTimings { @@ -43,15 +48,43 @@ private ErrorProneTimings(Context context) { context.put(timingsKey, this); } - private final Map timers = new HashMap<>(); + /** + * The checks seen so far, in the order they first ran. + * + *

A canonical name maps to every {@link CheckTiming} reported under it, so two checks sharing + * one name are reported as their sum rather than as whichever ran last. + */ + private final Map> timings = new LinkedHashMap<>(); + + /** + * Timing state for a {@link Suppressible} that is not a {@link BugChecker} and owns no field. + * + *

Keyed by canonical name, so the map holds one entry per name a compilation reports and needs + * no equality contract from {@link Suppressible}, which declares none. + */ + private final Map unownedTimings = new LinkedHashMap<>(); private final Stopwatch initializationTime = Stopwatch.createUnstarted(); - /** Creates a timing span for the given {@link Suppressible}. */ + /** + * Starts timing one invocation of the given {@link Suppressible}, and returns the state to close + * when the invocation finishes. + * + *

The returned value is state this collection keeps rather than a fresh object, so the caller + * must close it before another invocation reporting the same canonical name begins, and must not + * retain it. + */ public AutoCloseable span(Suppressible suppressible) { - String key = suppressible.canonicalName(); - Stopwatch sw = timers.computeIfAbsent(key, k -> Stopwatch.createUnstarted()).start(); - return () -> sw.stop(); + CheckTiming timing = + suppressible instanceof BugChecker bugChecker + ? bugChecker.checkTiming() + : unownedTimings.computeIfAbsent( + suppressible.canonicalName(), unused -> new CheckTiming()); + if (timing.claim(this)) { + timings.computeIfAbsent(suppressible.canonicalName(), unused -> new ArrayList<>()).add(timing); + } + timing.begin(); + return timing; } /** Creates a timing span for initialization. */ @@ -60,10 +93,41 @@ public AutoCloseable initializationTimeSpan() { return () -> initializationTime.stop(); } - /** Returns the elapsed durations of each timer. */ + /** Returns how long each check ran, estimated as {@link CheckTiming#elapsed} describes. */ public ImmutableMap timings() { - return timers.entrySet().stream() - .collect(toImmutableMap(e -> e.getKey(), e -> e.getValue().elapsed())); + return timings.entrySet().stream() + .collect( + toImmutableMap( + e -> e.getKey(), + e -> + e.getValue().stream() + .map(CheckTiming::elapsed) + .reduce(Duration.ZERO, Duration::plus))); + } + + /** Returns the longest timed invocation of each check, in nanoseconds. */ + public ImmutableMap maxNanos() { + return fold(CheckTiming::maxNanos, Math::max); + } + + /** Returns how many times each check ran. */ + public ImmutableMap counts() { + return fold(CheckTiming::count, Long::sum); + } + + private ImmutableMap fold( + ToLongFunction value, LongBinaryOperator combine) { + return timings.entrySet().stream() + .collect( + toImmutableMap( + e -> e.getKey(), + e -> { + long result = 0; + for (CheckTiming timing : e.getValue()) { + result = combine.applyAsLong(result, value.applyAsLong(timing)); + } + return result; + })); } /** Returns the elapsed initialization time. */ diff --git a/check_api/src/main/java/com/google/errorprone/VisitorState.java b/check_api/src/main/java/com/google/errorprone/VisitorState.java index 76f799e0c2d..924755e7cf8 100644 --- a/check_api/src/main/java/com/google/errorprone/VisitorState.java +++ b/check_api/src/main/java/com/google/errorprone/VisitorState.java @@ -601,8 +601,16 @@ public boolean isAndroidCompatible() { return Options.instance(context).getBoolean("androidCompatible"); } - /** Returns a timing span for the given {@link Suppressible}. */ + private static final AutoCloseable NO_TIMING_SPAN = () -> {}; + + /** + * Returns a timing span for the given {@link Suppressible}, or a span that records nothing unless + * {@link ErrorProneOptions#printTimings} asked for the timings. + */ public AutoCloseable timingSpan(Suppressible suppressible) { + if (!sharedState.recordTimings) { + return NO_TIMING_SPAN; + } return sharedState.timings.span(suppressible); } @@ -675,6 +683,7 @@ private static final class SharedState { private final Names names; private final Symtab symtab; private final ErrorProneTimings timings; + private final boolean recordTimings; private final Types types; private final TreeMaker treeMaker; private final JavacInvocationInstance javacInvocationInstance; @@ -699,6 +708,7 @@ private static final class SharedState { this.names = Names.instance(context); this.symtab = Symtab.instance(context); this.timings = ErrorProneTimings.instance(context); + this.recordTimings = errorProneOptions.printTimings(); this.types = Types.instance(context); this.treeMaker = TreeMaker.instance(context); this.javacInvocationInstance = JavacInvocationInstance.instance(context); diff --git a/check_api/src/main/java/com/google/errorprone/bugpatterns/BugChecker.java b/check_api/src/main/java/com/google/errorprone/bugpatterns/BugChecker.java index a5155088614..c06ebd916d9 100644 --- a/check_api/src/main/java/com/google/errorprone/bugpatterns/BugChecker.java +++ b/check_api/src/main/java/com/google/errorprone/bugpatterns/BugChecker.java @@ -27,6 +27,7 @@ import com.google.common.collect.TreeRangeSet; import com.google.errorprone.BugCheckerInfo; import com.google.errorprone.BugPattern.SeverityLevel; +import com.google.errorprone.CheckTiming; import com.google.errorprone.ErrorProneOptions; import com.google.errorprone.SuppressionInfo; import com.google.errorprone.VisitorState; @@ -126,9 +127,22 @@ * @author Eddie Aftandilian (eaftan@google.com) */ public abstract class BugChecker implements Suppressible, Serializable { + + private final CheckTiming checkTiming = new CheckTiming(); + private final BugCheckerInfo info; private final BiPredicate, VisitorState> checkSuppression; + /** + * Returns where this check's run time accumulates while a compilation records timings. + * + *

{@link com.google.errorprone.ErrorProneTimings} reads this once per invocation, so the state + * is a field rather than a lookup by name. + */ + public CheckTiming checkTiming() { + return checkTiming; + } + public BugChecker() { info = BugCheckerInfo.create(getClass()); checkSuppression = suppressionPredicate(info.customSuppressionAnnotations()); diff --git a/check_api/src/test/java/com/google/errorprone/CheckTimingTest.java b/check_api/src/test/java/com/google/errorprone/CheckTimingTest.java new file mode 100644 index 00000000000..79d0d948e19 --- /dev/null +++ b/check_api/src/test/java/com/google/errorprone/CheckTimingTest.java @@ -0,0 +1,186 @@ +/* + * Copyright 2026 The Error Prone Authors. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.google.errorprone; + +import static com.google.common.truth.Truth.assertThat; +import static org.junit.Assert.assertThrows; + +import java.time.Duration; +import org.junit.Test; +import org.junit.runner.RunWith; +import org.junit.runners.JUnit4; + +/** + * Fails when the sampled estimator stops producing the numbers a timing report prints. + * + *

Every case supplies the elapsed time through {@link CheckTiming#closeWith} rather than letting + * the clock decide it, so the sampling schedule and the weighted total are determined. The expected + * values are worked out from the rule the class documents: invocations are timed one at a time until + * the count reaches 256, and each timed invocation afterwards counts for the {@code count / 256} + * invocations it stands in for. + */ +@RunWith(JUnit4.class) +public final class CheckTimingTest { + + /** The invocation count at which the stride first moves off one. */ + private static final int FIRST_SKIP = 512; + + private final CheckTiming timing = new CheckTiming(); + + @Test + public void aTimingThatNeverRanIsEmpty() { + assertThat(timing.count()).isEqualTo(0); + assertThat(timing.elapsed()).isEqualTo(Duration.ZERO); + assertThat(timing.maxNanos()).isEqualTo(0); + } + + @Test + public void everyInvocationIsTimedBelowTheStrideThreshold() { + timing.claim(this); + for (int i = 0; i < FIRST_SKIP; i++) { + timing.begin(); + assertThat(timing.sampled()).isTrue(); + timing.closeWith(100); + } + assertThat(timing.count()).isEqualTo(FIRST_SKIP); + assertThat(timing.elapsed()).isEqualTo(Duration.ofNanos(FIRST_SKIP * 100L)); + } + + @Test + public void aSampleCountsForTheInvocationsItStandsIn() { + timing.claim(this); + for (int i = 0; i < FIRST_SKIP; i++) { + timing.begin(); + timing.closeWith(100); + } + long timedOneAtATime = timing.elapsed().toNanos(); + + // The 512th invocation moved the stride to two, so the 513th is skipped. + timing.begin(); + assertThat(timing.sampled()).isFalse(); + timing.closeWith(999); + assertThat(timing.elapsed().toNanos()).isEqualTo(timedOneAtATime); + + // The 514th is timed, and stands in for itself and the one that was skipped. + timing.begin(); + assertThat(timing.sampled()).isTrue(); + timing.closeWith(1000); + assertThat(timing.elapsed().toNanos()).isEqualTo(timedOneAtATime + 2 * 1000); + assertThat(timing.count()).isEqualTo(FIRST_SKIP + 2); + } + + @Test + public void anExpensiveCheckIsTimedOnEveryInvocation() { + timing.claim(this); + int invocations = 600; + for (int i = 0; i < invocations; i++) { + timing.begin(); + assertThat(timing.sampled()).isTrue(); + timing.closeWith(2000); + } + assertThat(timing.count()).isEqualTo(invocations); + assertThat(timing.elapsed()).isEqualTo(Duration.ofNanos(invocations * 2000L)); + } + + @Test + public void spansKeepWorkingOnceSamplingStops() { + timing.claim(this); + int invocations = 600; + int skipped = 0; + for (int i = 0; i < invocations; i++) { + timing.begin(); + if (!timing.sampled()) { + skipped++; + } + timing.closeWith(100); + } + assertThat(skipped).isGreaterThan(0); + assertThat(timing.count()).isEqualTo(invocations); + } + + @Test + public void theLongestInvocationIsKept() { + timing.claim(this); + for (long elapsedNanos : new long[] {100, 5000, 200}) { + timing.begin(); + timing.closeWith(elapsedNanos); + } + assertThat(timing.maxNanos()).isEqualTo(5000); + assertThat(timing.elapsed()).isEqualTo(Duration.ofNanos(5300)); + } + + @Test + public void aSecondOwnerStartsFromZero() { + timing.claim(this); + assertThat(timing.claim(this)).isFalse(); + timing.begin(); + timing.closeWith(4000); + assertThat(timing.count()).isEqualTo(1); + + assertThat(timing.claim(new Object())).isTrue(); + assertThat(timing.count()).isEqualTo(0); + assertThat(timing.elapsed()).isEqualTo(Duration.ZERO); + assertThat(timing.maxNanos()).isEqualTo(0); + } + + @Test + public void aSecondCloseRecordsNothing() { + timing.claim(this); + timing.begin(); + timing.closeWith(4000); + long recorded = timing.elapsed().toNanos(); + + timing.closeWith(9_000_000); + + assertThat(timing.elapsed().toNanos()).isEqualTo(recorded); + assertThat(timing.maxNanos()).isEqualTo(4000); + } + + @Test + public void aNestedSpanIsRejected() { + timing.claim(this); + timing.begin(); + assertThat(timing.sampled()).isTrue(); + + assertThrows(IllegalStateException.class, timing::begin); + } + + @Test + public void aNestedSpanIsRejectedOnceSamplingHasStopped() { + timing.claim(this); + for (int i = 0; i < FIRST_SKIP; i++) { + timing.begin(); + timing.closeWith(100); + } + timing.begin(); + assertThat(timing.sampled()).isFalse(); + + assertThrows(IllegalStateException.class, timing::begin); + } + + @Test + public void aNewOwnerReleasesAnOpenSpan() { + timing.claim(this); + timing.begin(); + + assertThat(timing.claim(new Object())).isTrue(); + + timing.begin(); + timing.closeWith(100); + assertThat(timing.count()).isEqualTo(1); + } +} diff --git a/check_api/src/test/java/com/google/errorprone/ErrorProneOptionsTest.java b/check_api/src/test/java/com/google/errorprone/ErrorProneOptionsTest.java index bc0e917b2b6..2b562b640de 100644 --- a/check_api/src/test/java/com/google/errorprone/ErrorProneOptionsTest.java +++ b/check_api/src/test/java/com/google/errorprone/ErrorProneOptionsTest.java @@ -170,6 +170,18 @@ public void recognizesDisableAllChecks() { assertThat(options.isDisableAllChecks()).isTrue(); } + @Test + public void recognizesPrintTimings() { + ErrorProneOptions options = ErrorProneOptions.processArgs(new String[] {"-XepPrintTimings"}); + assertThat(options.printTimings()).isTrue(); + assertThat(ErrorProneOptions.isSupportedOption("-XepPrintTimings")).isEqualTo(0); + } + + @Test + public void printTimingsIsOffByDefault() { + assertThat(ErrorProneOptions.processArgs(new String[] {}).printTimings()).isFalse(); + } + @Test public void recognizesCompilingTestOnlyCode() { ErrorProneOptions options = diff --git a/check_api/src/test/java/com/google/errorprone/ErrorProneTimingsTest.java b/check_api/src/test/java/com/google/errorprone/ErrorProneTimingsTest.java new file mode 100644 index 00000000000..ecd41d6030c --- /dev/null +++ b/check_api/src/test/java/com/google/errorprone/ErrorProneTimingsTest.java @@ -0,0 +1,161 @@ +/* + * Copyright 2026 The Error Prone Authors. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.google.errorprone; + +import static com.google.common.truth.Truth.assertThat; +import static com.google.errorprone.BugPattern.SeverityLevel.WARNING; + +import com.google.errorprone.bugpatterns.BugChecker; +import com.google.errorprone.matchers.Suppressible; +import com.sun.tools.javac.util.Context; +import com.sun.tools.javac.util.Name; +import java.lang.annotation.Annotation; +import java.time.Duration; +import java.util.Set; +import org.junit.Test; +import org.junit.runner.RunWith; +import org.junit.runners.JUnit4; + +/** + * Fails when a check's run time stops reaching the report it belongs in. + * + *

{@link ErrorProneTimings#span} reaches a check's state one way for a {@link BugChecker}, which + * keeps the state in a field, and another for a {@link Suppressible} that does not. {@link + * TimedCheck} covers the first and {@link NamedCheck} the second. + */ +@RunWith(JUnit4.class) +public final class ErrorProneTimingsTest { + + /** A {@link Suppressible} that answers only what the timings read. */ + private static final class NamedCheck implements Suppressible { + + private final String canonicalName; + + NamedCheck(String canonicalName) { + this.canonicalName = canonicalName; + } + + @Override + public String canonicalName() { + return canonicalName; + } + + @Override + public Set allNames() { + return Set.of(canonicalName); + } + + @Override + public boolean supportsSuppressWarnings() { + return true; + } + + @Override + public Set> customSuppressionAnnotations() { + return Set.of(); + } + + @Override + public boolean suppressedByAnyOf(Set annotations, VisitorState state) { + return false; + } + } + + /** A {@link BugChecker} that exists to be timed. */ + @BugPattern(summary = "A check that exists to be timed.", severity = WARNING) + public static final class TimedCheck extends BugChecker {} + + private final ErrorProneTimings timings = ErrorProneTimings.instance(new Context()); + + private void run(Suppressible check, int invocations) throws Exception { + for (int i = 0; i < invocations; i++) { + timings.span(check).close(); + } + } + + /** Runs one span and returns the state it used, which is closed by the time it comes back. */ + private AutoCloseable runOnce(Suppressible check) throws Exception { + AutoCloseable span = timings.span(check); + span.close(); + return span; + } + + @Test + public void aCheckThatIsNotABugCheckerIsStillTimed() throws Exception { + run(new NamedCheck("Alpha"), 3); + + assertThat(timings.counts()).containsExactly("Alpha", 3L); + assertThat(timings.timings().keySet()).containsExactly("Alpha"); + } + + @Test + public void aBugCheckerUsesItsOwnSlot() throws Exception { + TimedCheck check = new TimedCheck(); + + assertThat(runOnce(check)).isSameInstanceAs(check.checkTiming()); + assertThat(timings.counts()).containsExactly("TimedCheck", 1L); + } + + @Test + public void twoChecksSharingACanonicalNameAreSummed() throws Exception { + TimedCheck first = new TimedCheck(); + TimedCheck second = new TimedCheck(); + assertThat(first.checkTiming()).isNotSameInstanceAs(second.checkTiming()); + + run(first, 3); + run(second, 5); + + assertThat(timings.counts()).containsExactly("TimedCheck", 8L); + } + + @Test + public void aNameReportedThroughBothArmsIsSummed() throws Exception { + TimedCheck owned = new TimedCheck(); + NamedCheck unowned = new NamedCheck("TimedCheck"); + + AutoCloseable ownedSlot = runOnce(owned); + AutoCloseable unownedSlot = runOnce(unowned); + + assertThat(ownedSlot).isNotSameInstanceAs(unownedSlot); + assertThat(timings.counts()).containsExactly("TimedCheck", 2L); + } + + @Test + public void everyColumnFoldsAcrossTheSlotsOfOneName() throws Exception { + // Two slots under one name, and a second name with one slot: a fold across all names rather + // than within one would report both keys as 12000 ns. + ((CheckTiming) timings.span(new TimedCheck())).closeWith(1000); + ((CheckTiming) timings.span(new TimedCheck())).closeWith(4000); + ((CheckTiming) timings.span(new NamedCheck("Other"))).closeWith(7000); + + assertThat(timings.counts()).containsExactly("TimedCheck", 2L, "Other", 1L); + assertThat(timings.timings()) + .containsExactly("TimedCheck", Duration.ofNanos(5000), "Other", Duration.ofNanos(7000)); + assertThat(timings.maxNanos()).containsExactly("TimedCheck", 4000L, "Other", 7000L); + } + + @Test + public void twoUnownedChecksSharingANameShareOneSlot() throws Exception { + AutoCloseable first = runOnce(new NamedCheck("Shared")); + AutoCloseable second = runOnce(new NamedCheck("Shared")); + AutoCloseable other = runOnce(new NamedCheck("Other")); + + assertThat(first).isSameInstanceAs(second); + assertThat(first).isNotSameInstanceAs(other); + assertThat(timings.counts()).containsExactly("Shared", 2L, "Other", 1L); + } +} diff --git a/core/src/test/java/com/google/errorprone/ErrorProneJavaCompilerTest.java b/core/src/test/java/com/google/errorprone/ErrorProneJavaCompilerTest.java index d27a8ab7ba4..994cf404f5b 100644 --- a/core/src/test/java/com/google/errorprone/ErrorProneJavaCompilerTest.java +++ b/core/src/test/java/com/google/errorprone/ErrorProneJavaCompilerTest.java @@ -130,6 +130,28 @@ public void sourceVersion() { assertThat(compiler.getSourceVersions()).doesNotContain(SourceVersion.RELEASE_5); } + @Test + public void printTimingsReportsEveryCheckThatRan() { + CompilationResult result = + doCompile( + Arrays.asList("bugpatterns/testdata/SelfAssignmentPositiveCases1.java"), + Arrays.asList("-XepPrintTimings"), + Collections.>emptyList()); + // A header alone would pass with nothing recorded, because it is printed before the rows. + assertThat(result.output).containsMatch("Error Prone ran [1-9]\\d* checks"); + assertThat(result.output).containsMatch("\\d+ ms\\s+[\\d.]+%\\s+\\d+ calls"); + } + + @Test + public void withoutPrintTimingsNoReportIsPrinted() { + CompilationResult result = + doCompile( + Arrays.asList("bugpatterns/testdata/SelfAssignmentPositiveCases1.java"), + Collections.emptyList(), + Collections.>emptyList()); + assertThat(result.output).doesNotContain("Error Prone ran"); + } + @Test public void fileWithErrorIntegrationTest() { CompilationResult result =