Maven Builds - Slow Build Times on Jenkins Slaves

[Kai]

Hi,

We are currently on Jenkins 1.551 and are experiencing significant maven build slowness on our jenkins slaves.

It seems deleting the target directory takes forever.

Also, during the site phase, a step: "Archiving site from ..." comes and takes a while (even though archiving is disabled), then it says "archiving disabled" and moves on.

However, when the build runs on the master, I don't experience this slowness and deleting the target directory is really quick.

Has anyone else experienced this issue or know what could be causing the slowness when building on Jenkin slaves?

Thank you so much!

[Baptiste Mathus]

Is it also slow if you run the maven build manually on that slave?

--
You received this message because you are subscribed to the Google Groups "Jenkins Users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to jenkinsci-use...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Baptiste Mathus]

Outside Jenkins, I mean.

[Kai]

Sorry for the late reply. Actually, it runs pretty quick when I run my maven command manually on the slave - takes about ~8 mins.

However, when I run through Jenkins, it takes between ~18-19mins for the job to complete.

Here are a few snippets from the console logs. Most of the areas where it tends to be slow is when it says "deleting .../target" directory, then says "archiving disabled" and stays there for like 2 mins usually, then moves on. And it does this for each maven module that's part of the project, so it adds up.

Also, takes some time, after "archiving steps", then says "archiving disabled", usually like up to 2 min delay before moving on.

Snippets from Console Log

19:56:10 [INFO] --- maven-clean-plugin:2.5:clean (default-clean) @ test-project-parent ---

19:56:10 [INFO] Deleting /var/lib/jenkins/workspace/test-project/target

19:56:13 [JENKINS] Archiving disabled

19:58:33 [INFO]

20:03:32 [JENKINS] Archiving site from /var/lib/jenkins/workspace/test-project-main/test-project/target/site to /var/lib/jenkins/jobs/test-project-main/site/test-project

20:03:32 [JENKINS] Archiving disabled

20:05:51 [INFO]   

[Kai]

Hi, just wanted to check-in if anyone has insights into this or if anyone else is experiencing similar issues with mvn build jobs running on jenkins slaves?

Thanks.

[Baptiste Mathus]

If using the maven type job, try using a freestyle one and see if you got a different result.

Apart from that, it would be really helpful if you could generate many stacktraces in a dedicated jira, take them during those apparently idle times to see what it's doing.

Cheers

[Kai]

Thanks for the follow-up Mathus!

I was able to track down the issue. The culprit seems to be the disk-usage plugin.

Once I disabled the disk-usage plugin, the builds on the jenkins slave started performing as fast as on the master.

I'm not sure why it was churning to calculate the disk usage when running on slaves. If anyone has insights into this, I would love to know, thanks!

Here is the stacktrace I saw in the logs:

Mar 28, 2014 11:58:42 AM hudson.plugins.disk_usage.DiskUsageUtil calculateWorkspaceDiskUsageForPath

WARNING: Disk usage fails to calculate workspace for file path /var/lib/jenkins/workspace/test-project through channel hudson.remoting.Channel@7ad8a715:jenkins-slave-3

java.util.concurrent.TimeoutException

at hudson.remoting.Request$1.get(Request.java:275)

at hudson.remoting.Request$1.get(Request.java:210)

at hudson.remoting.FutureAdapter.get(FutureAdapter.java:59)

at hudson.plugins.disk_usage.DiskUsageUtil.calculateWorkspaceDiskUsageForPath(DiskUsageUtil.java:294)

at hudson.plugins.disk_usage.DiskUsageBuildListener.onCompleted(DiskUsageBuildListener.java:60)

at hudson.plugins.disk_usage.DiskUsageBuildListener.onCompleted(DiskUsageBuildListener.java:23)

at hudson.model.listeners.RunListener.fireCompleted(RunListener.java:199)

at hudson.maven.MavenBuild$ProxyImpl2.end(MavenBuild.java:574)

at sun.reflect.GeneratedMethodAccessor448.invoke(Unknown Source)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

at java.lang.reflect.Method.invoke(Method.java:597)

at hudson.model.Executor$1.call(Executor.java:559)

at hudson.util.InterceptingProxy$1.invoke(InterceptingProxy.java:23)

at $Proxy50.end(Unknown Source)

at sun.reflect.GeneratedMethodAccessor447.invoke(Unknown Source)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

at java.lang.reflect.Method.invoke(Method.java:597)

at hudson.remoting.RemoteInvocationHandler$RPCRequest.perform(RemoteInvocationHandler.java:299)

at hudson.remoting.RemoteInvocationHandler$RPCRequest.call(RemoteInvocationHandler.java:280)

at hudson.remoting.RemoteInvocationHandler$RPCRequest.call(RemoteInvocationHandler.java:239)

at hudson.remoting.UserRequest.perform(UserRequest.java:118)

at hudson.remoting.UserRequest.perform(UserRequest.java:48)

at hudson.remoting.Request$2.run(Request.java:328)

at hudson.remoting.InterceptingExecutorService$1.call(InterceptingExecutorService.java:72)

at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)

at java.util.concurrent.FutureTask.run(FutureTask.java:138)

at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

at java.lang.Thread.run(Thread.java:662)