From 61119715b4c14cb5b1db2a62bde1edab1bf26ff9 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 | 43 +++++++++++++++++++ .../com/google/errorprone/errors.properties | 2 + .../errorprone/fixes/SuggestedFixes.java | 10 +++++ 4 files changed, 60 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 eff5d443bc9..2d83e415a43 100644 --- a/check_api/src/main/java/com/google/errorprone/BaseErrorProneJavaCompiler.java +++ b/check_api/src/main/java/com/google/errorprone/BaseErrorProneJavaCompiler.java @@ -98,6 +98,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..0cfe92bf600 --- /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 d63da201f23..893b5e21d0e 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 2f4b04d2435..be4dd37816c 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; @@ -1313,6 +1314,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);