From 92e050a1810d31d4a728b3650d69a01b093a2a2e 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 | 6 +++ .../com/google/errorprone/TimingReporter.java | 43 +++++++++++++++++++ .../com/google/errorprone/errors.properties | 2 + .../errorprone/fixes/SuggestedFixes.java | 10 +++++ 4 files changed, 61 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 5c90bdc00016..dfec733def03 100644 --- a/check_api/src/main/java/com/google/errorprone/BaseErrorProneJavaCompiler.java +++ b/check_api/src/main/java/com/google/errorprone/BaseErrorProneJavaCompiler.java @@ -25,6 +25,7 @@ import com.sun.tools.javac.api.JavacTool; import com.sun.tools.javac.util.Context; import com.sun.tools.javac.util.JavacMessages; +import com.sun.tools.javac.util.Log; import com.sun.tools.javac.util.Options; import java.io.InputStream; import java.io.OutputStream; @@ -91,6 +92,11 @@ static void addTaskListener( javacTask.addTaskListener( new ErrorProneAnalyzer.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 000000000000..0cfe92bf6008 --- /dev/null +++ b/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 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, errorProneTimings.initializationTime(), 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 d63da201f23c..893b5e21d0e6 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} (plus {1} for initialization); slowest checks:\n{2} 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 5f3d981fc1ba..3013e4e14f82 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 @@ -105,6 +105,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; @@ -1311,6 +1312,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);