Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

GIT_ATTRIBUTES massive slowdown in Spotless 6.6.0+ #1527

Closed
atavanamir opened this issue Jan 26, 2023 · 12 comments
Closed

GIT_ATTRIBUTES massive slowdown in Spotless 6.6.0+ #1527

atavanamir opened this issue Jan 26, 2023 · 12 comments
Labels

Comments

@atavanamir
Copy link

atavanamir commented Jan 26, 2023

We have a custom Gradle plugin for spotless, bellow is a shortened (with relevant parts) version.

We use this custom plugin in other gradle projects. Once we upgraded spotless plugin to the version 6.6.0 onwards (including the latest 6.13.0) it causes us problems during build on Windows 11 platform. With the version 6.5.2 it works all right.

For example following command takes 1-5 seconds to finish (once all libraries are cached)
./gradlew buildEnvironment

But once we switch to Spotless version 6.6.0+ it takes 1-2 minutes to finish (even on repeated runs with everything cached)

The same happens with all build tasks like
./gradlew build -x test

Using:
Gradle 7.5.1 and Java 11
Windows 11 Pro - 22H2 (OS build: 22621.525), but happens on any Windows laptop (tested on 5 different Windows machines using Win 11)

NOTE1:
Now I found out that there is a delay even on Linux when switchnig from 5.5.2 to 6.6.0 version, but it is from 1 second to 7 seconds for the following task. On Windows however it takes minutes.
./gradlew buildEnvironment

NOTE2:
I was not able to see a big difference while running spotlessApply tasks.

NOTE3:
I tried to change jgit version versions (betweem 5.10 to latest) and it didn't help

I tried to inspect the gradle tasks using --debug option with spotless 6.6.0+ and bellow are some critical slow parts (there are big jumps between some of the log output):

...
... previous logs
...
2023-01-24T12:33:56.076+0100 [DEBUG] [org.gradle.internal.operations.DefaultBuildOperationRunner] Build operation 'Execute Project.afterEvaluate listener' completed
2023-01-24T12:33:56.076+0100 [DEBUG] [org.gradle.internal.operations.DefaultBuildOperationRunner] Build operation 'Execute Project.afterEvaluate listener' completed
2023-01-24T12:33:56.078+0100 [DEBUG] [org.eclipse.jgit.internal.storage.file.FileSnapshot] file=C:\Dev\mdm\.git\config, create new FileSnapshot: lastRead=2023-01-24 12:33:56.079005900, lastModified=2023-01-24 11:44:04.962093000, size=322, fileKey=java.lang.Object@a6f1ceb
2023-01-24T12:33:58.570+0100 [LIFECYCLE] [org.gradle.cache.internal.DefaultFileLockManager] 
2023-01-24T12:33:58.570+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
2023-01-24T12:33:58.570+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
2023-01-24T12:33:58.570+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
2023-01-24T12:33:58.570+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
2023-01-24T12:33:58.570+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
2023-01-24T12:33:58.570+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
2023-01-24T12:34:08.570+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
2023-01-24T12:34:08.570+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
2023-01-24T12:34:08.572+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
2023-01-24T12:34:08.572+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
2023-01-24T12:34:08.572+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
2023-01-24T12:34:08.572+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
2023-01-24T12:33:57.611+0100 [LIFECYCLE] [org.gradle.internal.logging.progress.ProgressLoggerFactory] 
2023-01-24T12:33:57.611+0100 [LIFECYCLE] [org.gradle.internal.logging.progress.ProgressLoggerFactory] > Configure project :
2023-01-24T12:34:14.586+0100 [DEBUG] [org.eclipse.jgit.internal.storage.file.FileSnapshot] file=C:\Dev\mdm\.git\config, create new FileSnapshot: lastRead=2023-01-24 12:34:14.587001900, lastModified=2023-01-24 11:44:04.962093000, size=322, fileKey=java.lang.Object@a6f1ceb
2023-01-24T12:34:14.587+0100 [DEBUG] [org.eclipse.jgit.internal.storage.file.FileSnapshot] file=C:\Dev\mdm\.git\config, create new FileSnapshot: lastRead=2023-01-24 12:34:14.587995600, lastModified=2023-01-24 11:44:04.962093000, size=322, fileKey=java.lang.Object@a6f1ceb
2023-01-24T12:34:14.587+0100 [DEBUG] [org.eclipse.jgit.internal.storage.file.FileSnapshot] file=C:\Dev\mdm\.git\config, create new FileSnapshot: lastRead=2023-01-24 12:34:14.587995600, lastModified=2023-01-24 11:44:04.962093000, size=322, fileKey=java.lang.Object@a6f1ceb
2023-01-24T12:34:14.587+0100 [DEBUG] [org.eclipse.jgit.internal.storage.file.FileSnapshot] file=C:\Users\temp\.config\jgit\config.lock, cannot be racily clean
2023-01-24T12:34:14.587+0100 [DEBUG] [org.eclipse.jgit.internal.storage.file.FileSnapshot] file=C:\Users\temp\.gitconfig, isRacyClean=false, read=2023-01-24 11:44:42.347606300, lastModified=1970-01-01 01:00:00.000000000, delta=1674557082347606300 ns, racy<=2500000000 ns
2023-01-24T12:34:14.587+0100 [DEBUG] [org.eclipse.jgit.internal.storage.file.FileSnapshot] file=C:\Users\temp\.gitconfig, is unmodified
2023-01-24T12:34:14.587+0100 [DEBUG] [org.eclipse.jgit.internal.storage.file.FileSnapshot] file=C:\Dev\mdm\.git\config, create new FileSnapshot: lastRead=2023-01-24 12:34:14.587995600, lastModified=2023-01-24 11:44:04.962093000, size=322, fileKey=java.lang.Object@a6f1ceb
2023-01-24T12:34:14.587+0100 [DEBUG] [org.eclipse.jgit.internal.storage.file.FileSnapshot] file=C:\Users\temp\.config\jgit\config.lock, cannot be racily clean
2023-01-24T12:34:14.587+0100 [DEBUG] [org.eclipse.jgit.internal.storage.file.FileSnapshot] file=C:\Users\temp\.gitconfig, isRacyClean=false, read=2023-01-24 11:44:42.347606300, lastModified=1970-01-01 01:00:00.000000000, delta=1674557082347606300 ns, racy<=2500000000 ns
2023-01-24T12:34:14.587+0100 [DEBUG] [org.eclipse.jgit.internal.storage.file.FileSnapshot] file=C:\Users\temp\.gitconfig, is unmodified
...
... another logs
...
2023-01-24T12:34:54.053+0100 [DEBUG] [org.gradle.api.internal.artifacts.ivyservice.ivyresolve.CachingModuleComponentRepository] Found artifact 'klob-0.2.1.jar (com.github.shyiko.klob:klob:0.2.1)' in resolver cache: C:\Users\temp\.gradle\caches\modules-2\files-2.1\com.github.shyiko.klob\klob\0.2.1\f6bc8b98c3fcce8a559beb2b6e8ec58efadb5bbe\klob-0.2.1.jar
2023-01-24T12:34:54.053+0100 [DEBUG] [org.gradle.api.internal.artifacts.ivyservice.ivyresolve.CachingModuleComponentRepository] Found artifact 'kotlin-compiler-embeddable-1.7.0.jar (org.jetbrains.kotlin:kotlin-compiler-embeddable:1.7.0)' in resolver cache: C:\Users\temp\.gradle\caches\modules-2\files-2.1\org.jetbrains.kotlin\kotlin-compiler-embeddable\1.7.0\4d09852239f61842072b40b524882fa3caaed371\kotlin-compiler-embeddable-1.7.0.jar
2023-01-24T12:34:54.054+0100 [DEBUG] [org.gradle.api.internal.artifacts.ivyservice.ivyresolve.CachingModuleComponentRepository] Found artifact 'picocli-4.6.3.jar (info.picocli:picocli:4.6.3)' in resolver cache: C:\Users\temp\.gradle\caches\modules-2\files-2.1\info.picocli\picocli\4.6.3\18177f4c3d65cc94e6d4039775ec5aed8089f8d0\picocli-4.6.3.jar
2023-01-24T12:34:54.055+0100 [DEBUG] [org.gradle.internal.resources.AbstractTrackedResourceLock] Daemon worker Thread 4: acquired lock on state of project :
2023-01-24T12:34:54.055+0100 [DEBUG] [org.gradle.internal.resources.AbstractTrackedResourceLock] Daemon worker Thread 4: acquired lock on worker lease
2023-01-24T12:34:54.055+0100 [DEBUG] [org.gradle.internal.operations.DefaultBuildOperationRunner] Build operation 'Resolve files of :spotless-1972453405' completed
2023-01-24T12:34:54.069+0100 [DEBUG] [org.eclipse.jgit.internal.storage.file.FileSnapshot] file=C:\Dev\mdm\.git\config, create new FileSnapshot: lastRead=2023-01-24 12:34:54.069859200, lastModified=2023-01-24 11:44:04.962093000, size=322, fileKey=java.lang.Object@a6f1ceb
2023-01-24T12:34:58.570+0100 [LIFECYCLE] [org.gradle.cache.internal.DefaultFileLockManager] 
2023-01-24T12:34:58.570+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
2023-01-24T12:34:58.570+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
2023-01-24T12:34:58.570+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
2023-01-24T12:34:58.571+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
2023-01-24T12:34:58.571+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
2023-01-24T12:34:58.571+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
2023-01-24T12:35:08.570+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
2023-01-24T12:35:08.570+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
2023-01-24T12:35:08.570+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
2023-01-24T12:35:08.570+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
2023-01-24T12:35:08.570+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
2023-01-24T12:35:08.570+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
2023-01-24T12:35:18.571+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
2023-01-24T12:35:18.571+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
2023-01-24T12:35:18.571+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
2023-01-24T12:35:18.571+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
2023-01-24T12:35:18.571+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
2023-01-24T12:35:18.572+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
2023-01-24T12:35:28.572+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
2023-01-24T12:35:28.572+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
2023-01-24T12:35:28.572+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
2023-01-24T12:35:28.572+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
2023-01-24T12:35:28.572+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
2023-01-24T12:35:28.572+0100 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
2023-01-24T12:35:31.157+0100 [DEBUG] [org.gradle.internal.operations.DefaultBuildOperationRunner] Completing Build operation 'Execute container callback action'
2023-01-24T12:35:31.157+0100 [DEBUG] [org.gradle.internal.operations.DefaultBuildOperationRunner] Completing Build operation 'Execute Project.afterEvaluate listener'
2023-01-24T12:35:31.157+0100 [DEBUG] [org.gradle.internal.operations.DefaultBuildOperationRunner] Build operation 'Execute Project.afterEvaluate listener' started
2023-01-24T12:35:31.157+0100 [DEBUG] [org.gradle.internal.operations.DefaultBuildOperationRunner] Completing Build operation 'Execute Project.afterEvaluate listener'
2023-01-24T12:35:31.157+0100 [DEBUG] [org.gradle.internal.operations.DefaultBuildOperationRunner] Completing Build operation 'Notify afterEvaluate listeners of :'
2023-01-24T12:34:54.108+0100 [LIFECYCLE] [org.gradle.internal.logging.progress.ProgressLoggerFactory] 
2023-01-24T12:34:54.108+0100 [LIFECYCLE] [org.gradle.internal.logging.progress.ProgressLoggerFactory] > Configure project :
2023-01-24T12:35:31.157+0100 [DEBUG] [org.gradle.internal.operations.DefaultBuildOperationRunner] Build operation 'Execute container callback action' completed
2023-01-24T12:35:31.157+0100 [DEBUG] [org.gradle.internal.operations.DefaultBuildOperationRunner] Build operation 'Execute Project.afterEvaluate listener' completed
2023-01-24T12:35:31.157+0100 [DEBUG] [org.gradle.internal.operations.DefaultBuildOperationRunner] Build operation 'Execute Project.afterEvaluate listener' completed
2023-01-24T12:35:31.157+0100 [DEBUG] [org.gradle.internal.operations.DefaultBuildOperationRunner] Build operation 'Notify afterEvaluate listeners of :' completed
2023-01-24T12:35:31.158+0100 [DEBUG] [org.gradle.internal.resources.AbstractTrackedResourceLock] Daemon worker Thread 4: released lock on state of project :
2023-01-24T12:35:31.158+0100 [DEBUG] [org.gradle.internal.operations.DefaultBuildOperationRunner] Completing Build operation 'Configure project :'
2023-01-24T12:35:31.158+0100 [DEBUG] [org.gradle.internal.operations.DefaultBuildOperationRunner] Build operation 'Configure project :' completed
2023-01-24T12:35:31.158+0100 [DEBUG] [org.gradle.internal.operations.DefaultBuildOperationRunner] Build operation 'Configure project :assembly' started
class SpotlessDefaultsPlugin implements Plugin<Project> {

    @Override
    void apply(Project project) {
        // we want this only once, so we put it on root project
        project.rootProject.with {

            repositories {
                maven { url "$companyBaseRepoUrl/gradle-plugins" }
            }
            configurations {
                spotlessConfig
            }
            dependencies {
                spotlessConfig 'com.company.gradle:codestyle-config:+@zip'
            }
        }

        // and finally for the project which it was applied to
        project.with {
            apply plugin: SpotlessPlugin

            spotless {
                format 'misc', {
                    target '**/*.gradle', '**/*.md', '**/.gitignore'
                    trimTrailingWhitespace()
                    endWithNewline()
                }

                java {
                    target "**/java/**/*.java"
                    targetExclude "**/generated/**/*.*", "**/generated-src/**/*.*", "**/out/**/classes/generated*/**/*.*", "**/gradle/**/*.*", "$rootDir/.codestyle/**/*.*"

                    removeUnusedImports()
                    eclipse('4.12.0').configFile "$rootDir/.codestyle/spotless.eclipseformat.xml"
                    importOrderFile "$rootDir/.codestyle/spotless.eclipseimports.importorder"
                    licenseHeaderFile "$rootDir/.codestyle/spotless.license.txt"
                }

                if (Boolean.valueOf(project.findProperty("spotlessNoCheck") ?: false)) {
                    enforceCheck false
                }
            }

        }
    }
}
@nedtwigg nedtwigg added the bug label Jan 26, 2023
@nedtwigg
Copy link
Member

Wow! Thanks a lot for this trace, super useful. I bet that this will workaround your issue

https://github.com/diffplug/spotless/tree/main/plugin-gradle#dependency-resolution-modes

But the issue stands. Can you try predeclare and see what sort of speedup that gives your windows build?

@atavanamir
Copy link
Author

atavanamir commented Jan 27, 2023

Hi @nedtwigg , thanks for quick response.

When I test recommended workaround: https://github.com/diffplug/spotless/tree/main/plugin-gradle#dependency-resolution-modes

againts module with spotless 6.11 and defined

kotlin{
    ktlint("0.46.1")
}

 java {
     eclipse('4.12.0').configFile "$rootDir/.codestyle/spotless.eclipseformat.xml"
 }

and root build.gradle like this:

spotless {
    enforceCheck false
    ratchetFrom 'origin/master'
    predeclareDeps()
}

spotlessPredeclare {
    // java { eclipse() }
    java { googleJavaFormat("1.15.0") }
    kotlin { ktlint('0.46.1') }
}

I receive

FAILURE: Build failed with an exception.

* What went wrong:
A problem occurred configuring root project 'mdm'.
> Failed to notify project evaluation listener.
   > Add a step with [com.google.googlejavaformat:google-java-format:1.15.0] into the `spotlessPredeclare` block in the root project.
   > Add a step with [com.pinterest:ktlint:0.46.1] into the `spotlessPredeclare` block in the root project.

which is weird to me as I defined ktlint in spotlessPredeclare.
I was not able to get rid of those errors with different configurations. I also tried to exclude transitive dependency load of com.google.googlejavaformat:google-java-format, but it didn't help and it is weird to me too, because we have version 1.13, and it complains about 1.15 :o

@nedtwigg
Copy link
Member

Hmm... SpotlessPredeclare definitely works, and it is possible that we'll need to make it mandatory for multimodule projects in the future. I'm not positive that it will fix the performance problem you have right now, but there's a decent chance that it will, so I think it's worth getting to the bottom of this.

The issue about google-java-format:1.13.0 vs 1.15.0 is probably because you are using removeUnusedImports() somewhere, which uses GJF internally. You should be able to resolve at least that one by adding removeUnusedImports(). If you are using eclipse('4.12.0'), then that needs to be in the predeclare block also.

Like I said, decent chance that this will solve your performance problem, and working through this is useful for us because we need to make the error messages work well enough for people to figure out. The removeUnusedImports() thing for example is tricky, we need a better error message there.

@atavanamir
Copy link
Author

Thanks @nedtwigg .

Tested on following command: ./gradlew buildEnvironment (2nd run to eliminate delays with cache)

  • spotless 6.5.2: 5 sec
  • spotless 6.6.0 WITH predeclare - 2m 36sec
  • spotless 6.6.0 WITHOUT predeclare - 2m 44s

So predeclare doesn't seem to help much.

Is there anything else I can provide or the bug is ready for your resolution?

@nedtwigg
Copy link
Member

nedtwigg commented Jan 30, 2023

Thanks very much for the info! I'm pretty sure the problem is

Can you please run one last test? Change the line endings to one of UNIX, WINDOWS, or PLATFORM_NATIVE, doesn't matter which one. That should bring your buildEnvironment back down to the single-digit seconds.

spotless {
  lineEndings 'PLATFORM_NATIVE'
  ...

If that works, then we can justify putting a lot of work in to rewriting the way we handle GIT_ATTRIBUTES.

@mlilienberg
Copy link

We have the same issue on M1 Macbooks when applying spotless on our multi module project. Just performing a gradle sync takes more than 3 minutes when spotless is applied. Below 20 seconds if not. But it does not happen for all our developers. With a fresh setup and a new repo clone this does not happen. Maybe this has a different cause but the symptom is comparable.

@mlilienberg
Copy link

I can confirm that adding

spotless {
  lineEndings 'UNIX'
  ...

is fixing the issue for us

@nedtwigg nedtwigg changed the title Spotless 6.6.0+ slows down gradle tasks for Windows developers (from seconds to minutes) GIT_ATTRIBUTES massive slowdown in Spotless 6.6.0+ Feb 1, 2023
@nedtwigg
Copy link
Member

nedtwigg commented Feb 1, 2023

Git has opinions about line endings, and fighting that is a battle. That's why the default line endings are GIT_ATTRIBUTES. But a .gitattributes file could be anywhere, and it affects up-to-dateness if it changes. So we capture them all in the GIT_ATTRIBUTES line ending policy, but doing that capture became really slow when we had to comply with configuration cache.

The fix is to do something similar to what we did with spotlessPredeclare - assume that there's a .gitattributes in the root folder of a project, and if there's one anywhere else require it to be declared.

Such a massive slowdown is a high-priority thing to fix, I hope to solve this by next week.

@atavanamir
Copy link
Author

atavanamir commented Feb 1, 2023

I was waiting for a reply from my collegue with Win notebook. He confirmed that lineEndings 'PLATFORM_NATIVE' reduced build time to 5s.

Thanks @nedtwigg and @mlilienberg .

@atavanamir
Copy link
Author

Hello @nedtwigg , any updates on this?

@pavelchuchma
Copy link

Hi @nedtwigg, do you have any estimate of the fix, please?
Pushing all Win developers to use unix newlines (in some projects) and reconfigure their tools (not only smart IDEA) doesn't look like a way to a solution :-(

geiralund added a commit to navikt/dagpenger-joark-mottak that referenced this issue Sep 12, 2023
@nedtwigg
Copy link
Member

I believe this is now fixed in plugin-gradle 6.22.0 and plugin-maven 2.40.0. Let me know if it's not fixed for your case.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

4 participants