Gradle scan shows first task taken up by worker takes a long time

[RobReece]

I’m doing perf work on my gradle build which is a decent size multiproject build. It has 133 subprojects. My current objective is to run a war task that is already up to date and see what tasks are not running and what tasks are taking a long time to run. I want to reduce the incremental time it takes to produce my war.

My first reading of the scan showed some “NO SOURCE” tasks taking about 5 seconds, but then I sorted by duration and noticed that there are 5 tasks that all take more than 5 seconds and that they are all the first tasks to fire. I have 5 worker threads.

Has anybody seen this before? Is Gradle counting some worker initialization time in those times?

[luke_daley]

Hi Rob,

It very much looks like they were all waiting on some shared resource. I cannot think of any obvious answers as to what though.

Would it be possible to share a build scan on scans.gradle.com?

If not,

1. Which Gradle version?
2. Does this happen every time? If not, what setup is needed?

[RobReece]

This is gradle 4.3, although we are in the process of upgrading to 4.10. So we shouldn’t do anything drastic until I can try this on 4.10.

I’m hesitant to post the full gradle scan since it shows some of the stuff we do in our production build. I’d be happy to PM it to you I just couldn’t see how to do that.

I’m also going to try some other tasks and see if changing the execution tree shows the same behavior.

[RobReece]

Interesting. I just ran a task that only has about 15 dependent tasks and so only two worker threads were used and both initial tasks took 7 seconds.

Of course it is the same tasks as before that are the first because that is just how the project task tree works out. That is kind of hard to escape.

[RobReece]

I was running some different tasks in my project today and I can see that the first 5 tasks assigned out to threads are different tasks and they run with no problem. I still need to try on gradle 4.10 and when I get that done I will report back here.

[RobReece]

I can reproduce the problem with a single task - compileJava. It takes 5 seconds all by itself. Watching in VisualVM I can see one daemon thread is Runnable so it is not blocked. Watching the daemon process in Process Monitor (I’m on windows) I can see Gradle doing a lot, and I mean millions, of file operations. Taking a stack snapshot, the thread is doing this. I do have a lot of files in my repository, but when I run a subproject compileJava, I see Gradle playing around with files in all the other projects even once the compileJava task begins. If anybody can shed light on this stacktrace I would appreciate it.

“Task worker for ‘:’” #45 prio=5 os_prio=0 tid=0x000000002620a000 nid=0x5bc8 runnable [0x0000000032e0d000]
java.lang.Thread.State: RUNNABLE
at java.io.WinNTFileSystem.canonicalize0(Native Method)
at java.io.WinNTFileSystem.canonicalize(WinNTFileSystem.java:428)
at java.io.File.getCanonicalPath(File.java:618)
at java.io.File.getCanonicalFile(File.java:643)
at org.gradle.api.internal.file.FileNormaliser.normalise(FileNormaliser.java:54)
at org.gradle.api.internal.file.AbstractFileResolver.resolve(AbstractFileResolver.java:88)
at org.gradle.api.internal.file.AbstractFileResolver.resolve(AbstractFileResolver.java:68)
at org.gradle.api.internal.file.collections.DefaultFileCollectionResolveContext$FileCollectionConverter.convertInto(DefaultFileCollectionResolveContext.java:177)
at org.gradle.api.internal.file.collections.DefaultFileCollectionResolveContext.doResolve(DefaultFileCollectionResolveContext.java:138)
at org.gradle.api.internal.file.collections.DefaultFileCollectionResolveContext.resolveAsFileCollections(DefaultFileCollectionResolveContext.java:94)
at org.gradle.api.internal.file.collections.DefaultFileCollectionResolveContext$FileCollectionConverter.convertInto(DefaultFileCollectionResolveContext.java:161)
at org.gradle.api.internal.file.collections.DefaultFileCollectionResolveContext.doResolve(DefaultFileCollectionResolveContext.java:111)
at org.gradle.api.internal.file.collections.DefaultFileCollectionResolveContext.resolveAsFileCollections(DefaultFileCollectionResolveContext.java:94)
at org.gradle.api.internal.file.collections.DefaultFileCollectionResolveContext$FileCollectionConverter.convertInto(DefaultFileCollectionResolveContext.java:161)
at org.gradle.api.internal.file.collections.DefaultFileCollectionResolveContext.doResolve(DefaultFileCollectionResolveContext.java:111)
at org.gradle.api.internal.file.collections.DefaultFileCollectionResolveContext.resolveAsFileCollections(DefaultFileCollectionResolveContext.java:94)
at org.gradle.api.internal.file.CompositeFileCollection.getSourceCollections(CompositeFileCollection.java:172)
at org.gradle.api.internal.tasks.DefaultSourceSetOutput_Decorated.getSourceCollections(Unknown Source)
at org.gradle.api.internal.file.CompositeFileCollection.getFiles(CompositeFileCollection.java:55)
at org.gradle.api.internal.tasks.DefaultSourceSetOutput_Decorated.getFiles(Unknown Source)
at org.gradle.internal.cleanup.DefaultBuildOutputCleanupRegistry.doResolvePaths(DefaultBuildOutputCleanupRegistry.java:69)
- locked <0x000000056cd3d648> (a org.gradle.internal.cleanup.DefaultBuildOutputCleanupRegistry)
at org.gradle.internal.cleanup.DefaultBuildOutputCleanupRegistry.getResolvedPaths(DefaultBuildOutputCleanupRegistry.java:60)
at org.gradle.internal.cleanup.DefaultBuildOutputCleanupRegistry.isOutputOwnedByBuild(DefaultBuildOutputCleanupRegistry.java:47)
at org.gradle.api.internal.tasks.execution.CleanupStaleOutputsExecuter.execute(CleanupStaleOutputsExecuter.java:62)
at org.gradle.api.internal.tasks.execution.ResolveTaskArtifactStateTaskExecuter.execute(ResolveTaskArtifactStateTaskExecuter.java:52)
at org.gradle.api.internal.tasks.execution.SkipTaskWithNoActionsExecuter.execute(SkipTaskWithNoActionsExecuter.java:52)
at org.gradle.api.internal.tasks.execution.SkipOnlyIfTaskExecuter.execute(SkipOnlyIfTaskExecuter.java:54)
at org.gradle.api.internal.tasks.execution.ExecuteAtMostOnceTaskExecuter.execute(ExecuteAtMostOnceTaskExecuter.java:43)
at org.gradle.api.internal.tasks.execution.CatchExceptionTaskExecuter.execute(CatchExceptionTaskExecuter.java:34)
at org.gradle.execution.taskgraph.DefaultTaskGraphExecuter$EventFiringTaskWorker$1.run(DefaultTaskGraphExecuter.java:248)
at org.gradle.internal.progress.DefaultBuildOperationExecutor$RunnableBuildOperationWorker.execute(DefaultBuildOperationExecutor.java:336)
at org.gradle.internal.progress.DefaultBuildOperationExecutor$RunnableBuildOperationWorker.execute(DefaultBuildOperationExecutor.java:328)
at org.gradle.internal.progress.DefaultBuildOperationExecutor.execute(DefaultBuildOperationExecutor.java:199)
at org.gradle.internal.progress.DefaultBuildOperationExecutor.run(DefaultBuildOperationExecutor.java:110)
at org.gradle.execution.taskgraph.DefaultTaskGraphExecuter$EventFiringTaskWorker.execute(DefaultTaskGraphExecuter.java:241)
at org.gradle.execution.taskgraph.DefaultTaskGraphExecuter$EventFiringTaskWorker.execute(DefaultTaskGraphExecuter.java:230)
at org.gradle.execution.taskgraph.DefaultTaskPlanExecutor$TaskExecutorWorker.processTask(DefaultTaskPlanExecutor.java:123)
at org.gradle.execution.taskgraph.DefaultTaskPlanExecutor$TaskExecutorWorker.access$200(DefaultTaskPlanExecutor.java:79)
at org.gradle.execution.taskgraph.DefaultTaskPlanExecutor$TaskExecutorWorker$1.execute(DefaultTaskPlanExecutor.java:104)
at org.gradle.execution.taskgraph.DefaultTaskPlanExecutor$TaskExecutorWorker$1.execute(DefaultTaskPlanExecutor.java:98)
at org.gradle.execution.taskgraph.DefaultTaskExecutionPlan.execute(DefaultTaskExecutionPlan.java:626)
at org.gradle.execution.taskgraph.DefaultTaskExecutionPlan.executeWithTask(DefaultTaskExecutionPlan.java:581)
at org.gradle.execution.taskgraph.DefaultTaskPlanExecutor$TaskExecutorWorker.run(DefaultTaskPlanExecutor.java:98)
at org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:63)
at org.gradle.internal.concurrent.ManagedExecutorImpl$1.run(ManagedExecutorImpl.java:46)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at org.gradle.internal.concurrent.ThreadFactoryImpl$ManagedThreadRunnable.run(ThreadFactoryImpl.java:55)
at java.lang.Thread.run(Thread.java:748)

[RobReece]

(Sorry for the screenshot, pasting the stacktrace as a blockquote doesn’t work. My post just disappears)

[sterling (Sterling Greene)]

Do you know if you have any special configuration of your clean tasks?

Can you estimate how many build directories you have and approximately how many files are in each of them?

[RobReece]

We have 261 projects and a good number of them will have build output folders.

I looked a bit for any clean configuration in our projects. I see quite a few tasks that are defined and then marked as “mustRunAfter clean”.

I also have a task in my root project named “clean” that does this:

task clean(type: Delete) {
delete ‘build’
}

[RobReece]

Also I’m not sure that the problem is exactly folders named “build”. The below screenshow shows a sample output of Process Monitor. And there are 1000s of lines like this (more than a 1M actually).

[sterling (Sterling Greene)]

Is there a possibility that C:\git-repos (or rootDir or rootProject.projectDir) has been added as a directory that could be deleted by Gradle? e.g.,

clean {
  delete rootDir
}

For any of the projects, do you reconfigure where the buildDir is?
For the Java projects, do you reconfigure where the output goes for compilation?

[RobReece]

the rootProject location should be c:\git-repos\prpc-platform.

I will check around carefully for any clean configurations.
We do not reconfigure buildDir anywhere, it is always “build”.
We have not reconfigured any java output locations either. It is always build/classes/java/…

[RobReece]

Also, I have about 95,000 files under various build/classes folders. There are lots of other files under build/ for other projects that build wars and that kind of stuff. But as far as class files go, it is about 95k.

[sterling (Sterling Greene)]

Great, thanks. That gives us some clues.

Your earlier posts were getting marked as spam, but I’ve cleared them and they should show up now.

[RobReece]

I put Gradle in the debugger and I can see that org.gradle.internal.cleanup.DefaultBuildOutputCleanupRegistry#doResolvePaths takes me 5 seconds to run. You can also see the size of two important variables - the outputs HashSet has 1320 entries and the result has 2759 entries. BTW, this runs 100x faster on Linux (which probably isn’t a surprise). Does anybody know if this code has changed at all in Gradle 4.10? I can work today on getting Gradle 4.10 working so I can test there if there is a chance this might work better there.

[sterling (Sterling Greene)]

Thanks for your report @RobReece - I opened https://github.com/gradle/gradle/issues/7707

This isn’t intentional behavior, but I don’t believe it’s changed in a meaningful way in 4.10 or 5.x.

[Stefan_Wolf]

@RobReece Path normalization on Windows should be faster on Gradle 4.10. Please try it out.

[Stefan_Wolf]

Looks like the change is even in Gradle 4.5: https://docs.gradle.org/4.5/release-notes.html#project.file()-no-longer-normalizes-case

[RobReece]

We have a branch that uses 4.10. I’m working through some environmental issues to get that branch to build correctly and once I do that I will produce a scan and see what is going on.

[RobReece]

Wow, gradle 4.10 looks a lot better - the same compileJava task runs in 0.132s.