From ca30cf7fc7cc55c9cfe62065428f1f24c9c2f73c Mon Sep 17 00:00:00 2001 From: Stephan Schroevers 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 | 10 +++++ 4 files changed, 59 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 70faabf96a5..43c711b33b5 100644 --- a/check_api/src/main/java/com/google/errorprone/BaseErrorProneJavaCompiler.java +++ b/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 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 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.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 95e26529781..a4d70e360c4 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 @@ -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; @@ -1281,6 +1282,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);