From 31f5224bee0ab06cfcbc8981fd36e5574da6c41a Mon Sep 17 00:00:00 2001
From: Stephan Schroevers <stephan.schroevers@teampicnic.com>
Date: Sat, 11 Jan 2020 22:01:01 +0100
Subject: [PATCH] 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/error-prone#1474.
---
 .../BaseErrorProneJavaCompiler.java           |  5 +++
 .../com/google/errorprone/TimingReporter.java | 42 +++++++++++++++++++
 .../com/google/errorprone/errors.properties   |  2 +
 .../errorprone/fixes/SuggestedFixes.java      |  9 ++++
 4 files changed, 58 insertions(+)
 create mode 100644 check_api/src/main/java/com/google/errorprone/TimingReporter.java

diff --git a/check_api/src/main/java/com/google/errorprone/BaseErrorProneJavaCompiler.java b/check_api/src/main/java/com/google/errorprone/BaseErrorProneJavaCompiler.java
index 2362c159e95..a8ce4fe52a2 100644
--- a/check_api/src/main/java/com/google/errorprone/BaseErrorProneJavaCompiler.java
+++ b/check_api/src/main/java/com/google/errorprone/BaseErrorProneJavaCompiler.java
@@ -100,6 +100,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
diff --git a/check_api/src/main/java/com/google/errorprone/TimingReporter.java b/check_api/src/main/java/com/google/errorprone/TimingReporter.java
new file mode 100644
index 00000000000..7551a027d36
--- /dev/null
+++ b/check_api/src/main/java/com/google/errorprone/TimingReporter.java
@@ -0,0 +1,42 @@
+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, slowestChecks);
+  }
+}
diff --git a/check_api/src/main/java/com/google/errorprone/errors.properties b/check_api/src/main/java/com/google/errorprone/errors.properties
index d63da201f23..daa07960838 100644
--- a/check_api/src/main/java/com/google/errorprone/errors.properties
+++ b/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}; slowest checks:\n{1}
diff --git a/check_api/src/main/java/com/google/errorprone/fixes/SuggestedFixes.java b/check_api/src/main/java/com/google/errorprone/fixes/SuggestedFixes.java
index 746d1ee5c8f..043f6484296 100644
--- a/check_api/src/main/java/com/google/errorprone/fixes/SuggestedFixes.java
+++ b/check_api/src/main/java/com/google/errorprone/fixes/SuggestedFixes.java
@@ -99,6 +99,7 @@
 import com.sun.tools.javac.tree.JCTree;
 import com.sun.tools.javac.tree.JCTree.JCCompilationUnit;
 import com.sun.tools.javac.util.Context;
+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;
@@ -1226,6 +1227,14 @@ private static boolean compilesWithFix(
     }
 
     JCCompilationUnit compilationUnit = (JCCompilationUnit) state.getPath().getCompilationUnit();
+    if (Options.instance(state.context).isSet("-verbose")) {
+      Log.instance(state.context)
+          .printVerbose(
+              "error.prone.compiles.with.fix",
+              fix.toString(compilationUnit),
+              compilationUnit.sourcefile);
+    }
+
     JavaFileObject modifiedFile = compilationUnit.getSourceFile();
     BasicJavacTask javacTask = (BasicJavacTask) state.context.get(JavacTask.class);
     if (javacTask == null) {