Build performance issue - stalled creating a POM and can't figure out why

I’m trying to speed up the build, and I saw that the slowest test task couldn’t even start running because it was waiting for a POM to be generated, and that one POM task was taking 20-30 minutes to run.

So I initially blamed slow dependency resolution, but when I ran the same POM task by itself, it completed in 15 seconds from a cold start, so clearly something different is going on only when it’s run as part of a full build.

When I ran jstack on the process, I saw a stack trace like this:

"Execution worker for ':' Thread 4" #171 prio=5 os_prio=31 tid=0x00007fc791373000 nid=0x740b in Object.wait() [0x0000700004880000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at java.lang.Object.wait(Object.java:502)
        at org.gradle.internal.resources.DefaultResourceLockCoordinationService.withStateLock(DefaultResourceLockCoordinationService.java:51)
        - locked <0x0000000700094f00> (a java.lang.Object)
        at org.gradle.internal.work.DefaultWorkerLeaseService$2.run(DefaultWorkerLeaseService.java:198)
        at org.gradle.internal.work.DefaultWorkerLeaseService$ProjectLockStatisticsImpl.measure(DefaultWorkerLeaseService.java:459)
        at org.gradle.internal.work.DefaultWorkerLeaseService.acquireLocks(DefaultWorkerLeaseService.java:195)
        at org.gradle.internal.work.DefaultWorkerLeaseService.withLocks(DefaultWorkerLeaseService.java:181)
        at org.gradle.internal.work.StopShieldingWorkerLeaseService.withLocks(StopShieldingWorkerLeaseService.java:40)
        at org.gradle.api.internal.project.DefaultProjectStateRegistry$ProjectStateImpl.withProjectLock(DefaultProjectStateRegistry.java:226)
        at org.gradle.api.internal.project.DefaultProjectStateRegistry$ProjectStateImpl.access$700(DefaultProjectStateRegistry.java:143)
        at org.gradle.api.internal.project.DefaultProjectStateRegistry$ProjectStateImpl$1.create(DefaultProjectStateRegistry.java:215)
        at org.gradle.internal.work.DefaultWorkerLeaseService.withoutLocks(DefaultWorkerLeaseService.java:254)
        at org.gradle.internal.work.StopShieldingWorkerLeaseService.withoutLocks(StopShieldingWorkerLeaseService.java:50)
        at org.gradle.api.internal.project.DefaultProjectStateRegistry$ProjectStateImpl.withMutableState(DefaultProjectStateRegistry.java:211)
        at org.gradle.api.internal.project.DefaultProjectStateRegistry$ProjectStateImpl.withMutableState(DefaultProjectStateRegistry.java:186)
        at org.gradle.api.publication.maven.internal.pom.DefaultPomDependenciesConverter.addMavenDependencies(DefaultPomDependenciesConverter.java:134)
        at org.gradle.api.publication.maven.internal.pom.DefaultPomDependenciesConverter.addFromDependencyDescriptor(DefaultPomDependenciesConverter.java:114)
        at org.gradle.api.publication.maven.internal.pom.DefaultPomDependenciesConverter.convert(DefaultPomDependenciesConverter.java:56)
        at org.gradle.api.publication.maven.internal.pom.DefaultMavenPom.getGeneratedDependencies(DefaultMavenPom.java:170)
        at org.gradle.api.publication.maven.internal.pom.DefaultMavenPom.getEffectivePom(DefaultMavenPom.java:176)
        at org.gradle.api.publication.maven.internal.pom.DefaultMavenPom.writeTo(DefaultMavenPom.java:193)
        at org.gradle.api.publication.maven.internal.pom.DefaultMavenPom$2.execute(DefaultMavenPom.java:203)
        at org.gradle.api.publication.maven.internal.pom.DefaultMavenPom$2.execute(DefaultMavenPom.java:201)
        at org.gradle.internal.IoActions$TextFileWriterIoAction.execute(IoActions.java:146)
        at org.gradle.internal.IoActions$TextFileWriterIoAction.execute(IoActions.java:127)
        at org.gradle.internal.IoActions.writeTextFile(IoActions.java:45)
        at org.gradle.api.publication.maven.internal.pom.DefaultMavenPom.writeTo(DefaultMavenPom.java:201)
        at org.gradle.api.publication.maven.internal.pom.DefaultMavenPom.writeTo(DefaultMavenPom.java:44)
        at org.gradle.api.artifacts.maven.MavenPom$writeTo.call(Unknown Source)
        at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:47)
        at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:115)
        at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:127)
        at build_apzbie5b77xjksxvq3kd61lp2$_run_closure3$_closure17.doCall(/Users/tester/Documents/acme/core/lucene7-elasticsearch6/integration/build.gradle:86)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:104)
        at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:326)
        at org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:264)
        at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1041)
        at groovy.lang.Closure.call(Closure.java:411)
        at groovy.lang.Closure.call(Closure.java:427)
        at org.gradle.api.internal.AbstractTask$ClosureTaskAction.execute(AbstractTask.java:648)
        at org.gradle.api.internal.AbstractTask$ClosureTaskAction.execute(AbstractTask.java:621)
        at org.gradle.api.internal.tasks.execution.ExecuteActionsTaskExecuter$4.run(ExecuteActionsTaskExecuter.java:338)
        at org.gradle.internal.operations.DefaultBuildOperationExecutor$RunnableBuildOperationWorker.execute(DefaultBuildOperationExecutor.java:402)
        at org.gradle.internal.operations.DefaultBuildOperationExecutor$RunnableBuildOperationWorker.execute(DefaultBuildOperationExecutor.java:394)
        at org.gradle.internal.operations.DefaultBuildOperationExecutor$1.execute(DefaultBuildOperationExecutor.java:165)
        at org.gradle.internal.operations.DefaultBuildOperationExecutor.execute(DefaultBuildOperationExecutor.java:250)
        at org.gradle.internal.operations.DefaultBuildOperationExecutor.execute(DefaultBuildOperationExecutor.java:158)
        at org.gradle.internal.operations.DefaultBuildOperationExecutor.run(DefaultBuildOperationExecutor.java:92)
        at org.gradle.internal.operations.DelegatingBuildOperationExecutor.run(DelegatingBuildOperationExecutor.java:31)
        at org.gradle.api.internal.tasks.execution.ExecuteActionsTaskExecuter.executeAction(ExecuteActionsTaskExecuter.java:327)
        at org.gradle.api.internal.tasks.execution.ExecuteActionsTaskExecuter.executeActions(ExecuteActionsTaskExecuter.java:312)
        at org.gradle.api.internal.tasks.execution.ExecuteActionsTaskExecuter.access$200(ExecuteActionsTaskExecuter.java:75)
        at org.gradle.api.internal.tasks.execution.ExecuteActionsTaskExecuter$TaskExecution.execute(ExecuteActionsTaskExecuter.java:158)
        at org.gradle.internal.execution.impl.steps.ExecuteStep.execute(ExecuteStep.java:46)
        at org.gradle.internal.execution.impl.steps.CancelExecutionStep.execute(CancelExecutionStep.java:34)
        at org.gradle.internal.execution.impl.steps.TimeoutStep.executeWithoutTimeout(TimeoutStep.java:69)
        at org.gradle.internal.execution.impl.steps.TimeoutStep.execute(TimeoutStep.java:49)
        at org.gradle.internal.execution.impl.steps.CatchExceptionStep.execute(CatchExceptionStep.java:34)
        at org.gradle.internal.execution.impl.steps.CreateOutputsStep.execute(CreateOutputsStep.java:49)
        at org.gradle.internal.execution.impl.steps.SnapshotOutputStep.execute(SnapshotOutputStep.java:42)
        at org.gradle.internal.execution.impl.steps.SnapshotOutputStep.execute(SnapshotOutputStep.java:28)
        at org.gradle.internal.execution.impl.steps.CacheStep.executeWithoutCache(CacheStep.java:133)
        at org.gradle.internal.execution.impl.steps.CacheStep.lambda$execute$5(CacheStep.java:83)
        at org.gradle.internal.execution.impl.steps.CacheStep$$Lambda$162/1894365893.get(Unknown Source)
        at java.util.Optional.orElseGet(Optional.java:267)
        at org.gradle.internal.execution.impl.steps.CacheStep.execute(CacheStep.java:82)
        at org.gradle.internal.execution.impl.steps.CacheStep.execute(CacheStep.java:37)
        at org.gradle.internal.execution.impl.steps.PrepareCachingStep.execute(PrepareCachingStep.java:33)
        at org.gradle.internal.execution.impl.steps.StoreSnapshotsStep.execute(StoreSnapshotsStep.java:38)
        at org.gradle.internal.execution.impl.steps.StoreSnapshotsStep.execute(StoreSnapshotsStep.java:23)
        at org.gradle.internal.execution.impl.steps.SkipUpToDateStep.executeBecause(SkipUpToDateStep.java:95)
        at org.gradle.internal.execution.impl.steps.SkipUpToDateStep.lambda$execute$0(SkipUpToDateStep.java:88)
        at org.gradle.internal.execution.impl.steps.SkipUpToDateStep$$Lambda$8/693264141.apply(Unknown Source)
        at java.util.Optional.map(Optional.java:215)
        at org.gradle.internal.execution.impl.steps.SkipUpToDateStep.execute(SkipUpToDateStep.java:52)
        at org.gradle.internal.execution.impl.steps.SkipUpToDateStep.execute(SkipUpToDateStep.java:36)
        at org.gradle.internal.execution.impl.DefaultWorkExecutor.execute(DefaultWorkExecutor.java:34)
        at org.gradle.api.internal.tasks.execution.ExecuteActionsTaskExecuter.execute(ExecuteActionsTaskExecuter.java:109)
        at org.gradle.api.internal.tasks.execution.ResolveIncrementalChangesTaskExecuter.execute(ResolveIncrementalChangesTaskExecuter.java:84)
        at org.gradle.api.internal.tasks.execution.ResolveTaskOutputCachingStateExecuter.execute(ResolveTaskOutputCachingStateExecuter.java:91)
        at org.gradle.api.internal.tasks.execution.ResolveBeforeExecutionStateTaskExecuter.execute(ResolveBeforeExecutionStateTaskExecuter.java:74)
        at org.gradle.api.internal.tasks.execution.ValidatingTaskExecuter.execute(ValidatingTaskExecuter.java:58)
        at org.gradle.api.internal.tasks.execution.SkipEmptySourceFilesTaskExecuter.execute(SkipEmptySourceFilesTaskExecuter.java:109)
        at org.gradle.api.internal.tasks.execution.ResolveBeforeExecutionOutputsTaskExecuter.execute(ResolveBeforeExecutionOutputsTaskExecuter.java:67)
        at org.gradle.api.internal.tasks.execution.ResolveAfterPreviousExecutionStateTaskExecuter.execute(ResolveAfterPreviousExecutionStateTaskExecuter.java:46)
        at org.gradle.api.internal.tasks.execution.CleanupStaleOutputsExecuter.execute(CleanupStaleOutputsExecuter.java:93)
        at org.gradle.api.internal.tasks.execution.FinalizePropertiesTaskExecuter.execute(FinalizePropertiesTaskExecuter.java:45)
        at org.gradle.api.internal.tasks.execution.ResolveTaskExecutionModeExecuter.execute(ResolveTaskExecutionModeExecuter.java:94)
        at org.gradle.api.internal.tasks.execution.SkipTaskWithNoActionsExecuter.execute(SkipTaskWithNoActionsExecuter.java:57)
        at org.gradle.api.internal.tasks.execution.SkipOnlyIfTaskExecuter.execute(SkipOnlyIfTaskExecuter.java:56)
        at org.gradle.api.internal.tasks.execution.CatchExceptionTaskExecuter.execute(CatchExceptionTaskExecuter.java:36)
        at org.gradle.api.internal.tasks.execution.EventFiringTaskExecuter$1.executeTask(EventFiringTaskExecuter.java:63)
        at org.gradle.api.internal.tasks.execution.EventFiringTaskExecuter$1.call(EventFiringTaskExecuter.java:49)
        at org.gradle.api.internal.tasks.execution.EventFiringTaskExecuter$1.call(EventFiringTaskExecuter.java:46)
        at org.gradle.internal.operations.DefaultBuildOperationExecutor$CallableBuildOperationWorker.execute(DefaultBuildOperationExecutor.java:416)
        at org.gradle.internal.operations.DefaultBuildOperationExecutor$CallableBuildOperationWorker.execute(DefaultBuildOperationExecutor.java:406)
        at org.gradle.internal.operations.DefaultBuildOperationExecutor$1.execute(DefaultBuildOperationExecutor.java:165)
        at org.gradle.internal.operations.DefaultBuildOperationExecutor.execute(DefaultBuildOperationExecutor.java:250)
        at org.gradle.internal.operations.DefaultBuildOperationExecutor.execute(DefaultBuildOperationExecutor.java:158)
        at org.gradle.internal.operations.DefaultBuildOperationExecutor.call(DefaultBuildOperationExecutor.java:102)
        at org.gradle.internal.operations.DelegatingBuildOperationExecutor.call(DelegatingBuildOperationExecutor.java:36)
        at org.gradle.api.internal.tasks.execution.EventFiringTaskExecuter.execute(EventFiringTaskExecuter.java:46)
        at org.gradle.execution.plan.LocalTaskNodeExecutor.execute(LocalTaskNodeExecutor.java:43)
        at org.gradle.execution.taskgraph.DefaultTaskExecutionGraph$InvokeNodeExecutorsAction.execute(DefaultTaskExecutionGraph.java:355)
        at org.gradle.execution.taskgraph.DefaultTaskExecutionGraph$InvokeNodeExecutorsAction.execute(DefaultTaskExecutionGraph.java:343)
        at org.gradle.execution.taskgraph.DefaultTaskExecutionGraph$BuildOperationAwareExecutionAction.execute(DefaultTaskExecutionGraph.java:336)
        at org.gradle.execution.taskgraph.DefaultTaskExecutionGraph$BuildOperationAwareExecutionAction.execute(DefaultTaskExecutionGraph.java:322)
        at org.gradle.execution.plan.DefaultPlanExecutor$ExecutorWorker$1.execute(DefaultPlanExecutor.java:134)
        at org.gradle.execution.plan.DefaultPlanExecutor$ExecutorWorker$1.execute(DefaultPlanExecutor.java:129)
        at org.gradle.execution.plan.DefaultPlanExecutor$ExecutorWorker.execute(DefaultPlanExecutor.java:202)
        at org.gradle.execution.plan.DefaultPlanExecutor$ExecutorWorker.executeNextNode(DefaultPlanExecutor.java:193)
        at org.gradle.execution.plan.DefaultPlanExecutor$ExecutorWorker.run(DefaultPlanExecutor.java:129)
        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)

The top of the stack trace makes it seem like it’s something to do with not having enough worker leases, but in the output from the build I see at least 12 lines saying > IDLE, so surely I’m not out of workers?

The other tasks running are all unit tests - is it possible that Gradle treats test tasks differently somehow, in a way which causes them to block any new workers from starting up? How do I get around this so that I can get the slowest tests to start running sooner in the build cycle?

More details about your build script, environment, etc. would be helpful. Steps to reproduce or a simple replica project would be ideal, of course.

Your stack trace vaguely reminds me of one I’ve seen once. I run a guest OS in a virtual machine. I have Gradle installed on both the host and the guest machines.

The time that I saw a stack trace similar to yours, I was sharing one $GRADLE_USER_HOME between both the host and the guest OSes.

I ran a Gradle build of one project on the host. Then some time later—having forgotten that I’d been running Gradle in the host— I ran a second Gradle build of a second project on the guest.

I couldn’t get Gradle to do anything at that point. It seemed like it was broken beyond repair. That’s when I saw a stacktrace that I remember to be very similar to yours. Turned out the problem was the Gradle daemon on the host had a lock on something in the dependency cache. So Gradle on the guest was effectively broken.

In the absence of more specific details of your setup, just based on my previous experience, one best-guess suggestion I could offer right now is for you to kill all java processes. That’s what fixed the above guest/host issue I ran into.

Wouldn’t hurt to try anyway. If that doesn’t make any difference, get back with more details.

It happens from a clean start with no daemons running too, actually.

What I have discovered is that as soon as the last of the other test tasks finishes, it immediately runs the POM task and then finally starts running the remaining tests. :confused:

For environmental stuff, I don’t know what’s useful to provide here…

  • Gradle 5.2.1
  • Java 8u172
  • macOS 10.13.6
  • CPU is a 3.7 GHz quad-core Xeon E5

The build itself is huge and the problem will probably stop happening as soon as it’s cut down to a size small enough to check in anywhere as a demo. :frowning: