In verbose mode, log Error Prone performance details #1474

Stephan202 · 2020-01-12T14:54:34Z

In e5ffbe4 Error Prone added support for tracking the time spent by each check. This feature was not exposed in a way that OSS users of Error Prone can easily use it. This PR is a proposal of how such support may be added. Feedback very welcome!

From the commit message:

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.

After this change the information is exposed when compiling with -verbose.

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.

Stephan202 · 2020-05-30T12:33:54Z

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

@@ -982,6 +984,14 @@ private static boolean compilesWithFix(
    }

    JCCompilationUnit compilationUnit = (JCCompilationUnit) state.getPath().getCompilationUnit();
+    if (Options.instance(state.context).isSet(Option.VERBOSE)) {


Based on @cushon's feedback in #1473 (comment) this should be changed to

Suggested change

if (Options.instance(state.context).isSet(Option.VERBOSE)) {

if (Options.instance(state.context).isSet("-verbose")) {

Will make that change if there's interest in getting this PR merged.

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.

Stephan202

Rebased and resolved a conflict due to the changes in 6d28815. Also replaced the com.sun.tools.javac.main.Option usages as suggested elsewhere.

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.

Stephan202 · 2021-11-13T10:27:36Z

Rebased and resolved conflicts. What does the Error Prone team think of this PR?

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.

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.

Stephan202 · 2022-12-31T09:21:29Z

I have rebased the branch and squashed in a small change to also expose the initialization time recorded since 8ddb7cb.

NB: I see thumbs-up from Uber, Red Hat and Picnic people; though this PR might not have much utility inside Google thanks to other (certainly superior) integrations, it might help open source users.

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.

cushon · 2023-09-13T15:46:28Z

Taking another look at this as I continue slowly working through the PR backlog, the only part of this I'm wondering about is:

Another question is about the use of -verbose, vs. a separate Error Prone-specific flag. Using -verbose could be nice for users that benefit from the additional information and might not know about a separate flag, but could also be unwanted if they just wanted the standard -verbose output. WDYT?

Would using a new Error Prone-separate flag instead of -verbose work for your use-case of this feature, or do you strongly prefer -verbose? I still like the idea of a separate flag to avoid changing the behaviour of the existing -verbose flag. But maybe there are aspects of this I'm not considering, and usage of -verbose is probably fairly low anyways.

Stephan202 · 2023-09-14T05:30:51Z

Would using a new Error Prone-separate flag instead of -verbose work for your use-case of this feature,

I think it would work for us: based on some tests, Log#printVerbose output does show up in the build log even if verbose compiler output isn't enabled (i.e. without -Dmaven.compiler.verbose), so using a separate flag wouldn't require users to set both flags. Arguably this approach is even nicer, since users will be able to see the timing results without having to wade through tons of other output.

If we introduce a new flag for console output, I suppose it could take an integer argument, such that users can specify e.g. -XepListNSlowestChecks=10. (Not yet in love with that name; suggestions welcome.)

NB: re-reading the thread, there is some appetite for outputting the timings to a separate file. Makes sense, since this would allow for easier analysis. Such a feature could perhaps be enabled using a flag such as -XepCheckTimingOutputFile=somePath (again, name TBD). This would however raise new questions about the output format: ideally we investigate whether there are any standard file formats for such a use case. I'm not aware of any, but didn't carefully search.

Since these features aren't mutually exclusive, I suppose we can focus on the former (console output) here, and defer any decision about the latter. WDYT? I'm up for updating the PR accordingly if you agree.

cushon · 2023-09-14T15:44:21Z

If we introduce a new flag for console output, I suppose it could take an integer argument, such that users can specify e.g. -XepListNSlowestChecks=10. (Not yet in love with that name; suggestions welcome.)

-XepListNSlowestChecks= is fine with me. Another option would be -XepLogVerbosePerformanceDetails= or something, which is maybe more descriptive of the overall feature but doesn't example why it takes an int value.

It also occurred to me we could use -XepOpt: and skip having to define another top-level flag, but to be clear I have no objections to adding top level flags.

Since these features aren't mutually exclusive, I suppose we can focus on the former (console output) here, and defer any decision about the latter. WDYT? I'm up for updating the PR accordingly if you agree.

Yes, absolutely :) I don't think this needs to block on designing the other idea about file output.

Stephan202 · 2023-09-17T19:06:13Z

Tnx for the input @cushon! I'll give some thought to the flag names. Planned to have a look at this PR this weekend, but it didn't happen. Will hopefully circle back to it somewhere in the coming days. 🤞

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.

googlebot added the cla: yes label Jan 12, 2020

Stephan202 commented May 30, 2020

View reviewed changes

Stephan202 force-pushed the improvement/log-timings-in-verbose-mode branch from e864751 to eba616f Compare January 16, 2021 14:48

Stephan202 commented Jan 16, 2021

View reviewed changes

Stephan202 force-pushed the improvement/log-timings-in-verbose-mode branch from eba616f to ae93835 Compare November 13, 2021 10:27

Stephan202 force-pushed the improvement/log-timings-in-verbose-mode branch from ae93835 to 5c30fd4 Compare December 31, 2022 09:15

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

In verbose mode, log Error Prone performance details #1474

In verbose mode, log Error Prone performance details #1474

Stephan202 commented Jan 12, 2020

Stephan202 May 30, 2020

Stephan202 left a comment

Stephan202 commented Nov 13, 2021

Stephan202 commented Dec 31, 2022

cushon commented Sep 13, 2023

Stephan202 commented Sep 14, 2023

cushon commented Sep 14, 2023

Stephan202 commented Sep 17, 2023

	if (Options.instance(state.context).isSet(Option.VERBOSE)) {
	if (Options.instance(state.context).isSet("-verbose")) {

In verbose mode, log Error Prone performance details #1474

Are you sure you want to change the base?

In verbose mode, log Error Prone performance details #1474

Conversation

Stephan202 commented Jan 12, 2020

Stephan202 May 30, 2020

Choose a reason for hiding this comment

Stephan202 left a comment

Choose a reason for hiding this comment

Stephan202 commented Nov 13, 2021

Stephan202 commented Dec 31, 2022

cushon commented Sep 13, 2023

Stephan202 commented Sep 14, 2023

cushon commented Sep 14, 2023

Stephan202 commented Sep 17, 2023