In verbose mode, log Error Prone performance details

This change introduces a `TaskListener` which logs collected
`ErrorProneTimings` post compilation.

Additionally, since `SuggestedFixes#compilesWithFix` is a very heavy
operation which significantly contributes to overall runtime, any usage
of this method is also logged. Rationale behind this decision is that if
many `compilesWithFix` checks fail, then this can "silently" slow down
the build. By logging such cases one can either invest time in
optimizing the associated check, or manually improving the code that
triggers the compilation attempts.

See google#1474.

check_api/src/main/java/com/google/errorprone/BaseErrorProneJavaCompiler.java

@@ -101,6 +101,11 @@ static void addTaskListener(
     if (refactoringCollection[0] != null) {
       javacTask.addTaskListener(new RefactoringTask(context, refactoringCollection[0]));
     }
+
+    if (Options.instance(context).isSet("-verbose")) {
+      javacTask.addTaskListener(
+          new TimingReporter(ErrorProneTimings.instance(context), Log.instance(context)));
+    }
   }
 
   @Override

check_api/src/main/java/com/google/errorprone/TimingReporter.java

@@ -0,0 +1,43 @@
+package com.google.errorprone;
+
+import static java.util.stream.Collectors.joining;
+
+import com.sun.source.util.TaskEvent;
+import com.sun.source.util.TaskEvent.Kind;
+import com.sun.source.util.TaskListener;
+import com.sun.tools.javac.util.Log;
+import java.time.Duration;
+import java.util.Map;
+
+final class TimingReporter implements TaskListener {
+  private final ErrorProneTimings errorProneTimings;
+  private final Log log;
+
+  TimingReporter(ErrorProneTimings errorProneTimings, Log log) {
+    this.errorProneTimings = errorProneTimings;
+    this.log = log;
+  }
+
+  @Override
+  public void finished(TaskEvent event) {
+    if (event.getKind() != Kind.COMPILATION) {
+      return;
+    }
+
+    Map<String, Duration> timings = errorProneTimings.timings();
+    if (timings.isEmpty()) {
+      return;
+    }
+
+    Duration totalTime = timings.values().stream().reduce(Duration.ZERO, Duration::plus);
+    String slowestChecks =
+        timings.entrySet().stream()
+            .sorted(Map.Entry.<String, Duration>comparingByValue().reversed())
+            .limit(10)
+            .map(e -> e.getValue() + ": " + e.getKey())
+            .collect(joining("\n   ", "   ", ""));
+
+    log.printVerbose(
+        "error.prone.timing", totalTime, errorProneTimings.initializationTime(), slowestChecks);
+  }
+}

check_api/src/main/java/com/google/errorprone/errors.properties

@@ -20,3 +20,5 @@ compiler.err.error.prone={0}
 compiler.err.error.prone.crash=An unhandled exception was thrown by the Error Prone static analysis plugin.\n   Please report this at https://github.com/google/error-prone/issues/new and include the following:\n\n   error-prone version: {1}\n   BugPattern: {2}\n   Stack Trace:\n   {0}
 compiler.warn.error.prone={0}
 compiler.note.error.prone={0}
+compiler.misc.verbose.error.prone.compiles.with.fix=Running `compilesWithFix` for {0} in {1}
+compiler.misc.verbose.error.prone.timing=Error Prone analysis took {0} (plus {1} for initialization); slowest checks:\n{2}

check_api/src/main/java/com/google/errorprone/fixes/SuggestedFixes.java

@@ -103,6 +103,7 @@
 import com.sun.tools.javac.tree.JCTree.JCCompilationUnit;
 import com.sun.tools.javac.util.Context;
 import com.sun.tools.javac.util.JCDiagnostic;
+import com.sun.tools.javac.util.Log;
 import com.sun.tools.javac.util.Options;
 import com.sun.tools.javac.util.Position;
 import java.io.IOException;
@@ -1298,6 +1299,15 @@ private static boolean compilesWithFix(
       return false;
     }
 
+    if (Options.instance(state.context).isSet("-verbose")) {
+      JCCompilationUnit compilationUnit = (JCCompilationUnit) state.getPath().getCompilationUnit();
+      Log.instance(state.context)
+          .printVerbose(
+              "error.prone.compiles.with.fix",
+              fix.toString(compilationUnit),
+              compilationUnit.sourcefile);
+    }
+
     Result compilationResult = fixCompiler.compile(extraOptions);
     URI modifiedFileUri = FixCompiler.getModifiedFileUri(state);