Count every check invocation, and sample the clock

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.
+ *
+ * <p>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.
+ *
+ * <p>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.
+ *
+ * <p>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.
+   *
+   * <p>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.
+   *
+   * <p>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.
+   *
+   * <p>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.
+   *
+   * <p>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;
+  }
+}

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<String, Duration> checks = timings.timings();
+    ImmutableMap<String, Long> counts = timings.counts();
+    ImmutableMap<String, Long> 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<String, Duration> 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;
     }

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<String, Severity> 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<String> 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<String, Severity> 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<String> remainingArgs) {
           patchingOptionsBuilder.build(),
           excludedPattern,
           ignoreSuppressionAnnotations,
-          ignoreLargeCodeGenerators);
+          ignoreLargeCodeGenerators,
+          printTimings);
     }
 
     void setExcludedPattern(Pattern excludedPattern) {
@@ -478,6 +497,7 @@ public static ErrorProneOptions processArgs(Iterable<String> 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);