maven projects become slow after a couple of months
98 views
Skip to first unread message
Jorg Heymans
May 25, 2016, 5:21:09 AM5/25/16
to Jenkins Users
Hi,
I reported this a couple of months ago, is anyone else seeing this ?
Several times already we have noticed that the build time of certain of our maven jobs increases substantially over the course of several months. We are talking from 30s initially to 3-4 minutes after six months. This happens for jobs configured to run on our solaris build server , but also jobs configured to run on windows slaves.
It is easy to tell a job is getting slow because during maven init it takes a long time to get passed "Scanning for projects" :
13:06:54 [INFO] Scanning for projects... 13:08:03 [INFO] ------------------------------------------------------------------------
As you can see more than 70 seconds during maven init is not normal.
We found out that when we recreate the job (basically just a copy of the job under a different name from the UI, then delete the slow one and rename the copy to the original) performance is back to normal. But after a few months the slowdown becomes noticeable again.
Any thoughts as to what could be causing this ?
Jorg
David Karlsen
May 25, 2016, 9:39:32 AM5/25/16
to jenkins...@googlegroups.com
Are you keeping a lot of build history?
--
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.
To view this discussion on the web visit https://groups.google.com/d/msgid/jenkinsci-users/c0fbdb20-5f5a-49fe-b829-dca09f3bcaed%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
Jorg Heymans
May 25, 2016, 10:14:32 AM5/25/16
to Jenkins Users, da...@davidkarlsen.com
Jorg
Karl Heinz Marbaise
May 25, 2016, 1:24:17 PM5/25/16
to jenkins...@googlegroups.com
Hi,
That sounds like you are either archiving the results of each build or
do generate fingerprints of the artifacts...fingerprints are only needed
if you try to make dependencies between jobs with SNAPSHOT's otherwise
is useless.
Furthermore are you using a local maven cache (ake local repository) for
each job?
Kind regards
Karl Heinz Marbaise
That sounds like you are either archiving the results of each build or
do generate fingerprints of the artifacts...fingerprints are only needed
if you try to make dependencies between jobs with SNAPSHOT's otherwise
is useless.
Furthermore are you using a local maven cache (ake local repository) for
each job?
Kind regards
Karl Heinz Marbaise
Jorg Heymans
May 26, 2016, 1:38:23 AM5/26/16
to Jenkins Users, in...@soebes.de
Hi,
As i said the slowdown occurs during maven init, when it says 'Scanning for projects' , has Jenkins instrumented this part as well to execute some additional stuff perhaps ?
Thanks,
Jorg
Mykola Nikishov
May 27, 2016, 5:35:12 PM5/27/16
to jenkins...@googlegroups.com
Jorg Heymans <jorg.h...@gmail.com>
writes:
> It is easy to tell a job is getting slow because during maven init it takes
> a long time to get passed "Scanning for projects" :
>
>
> 13:06:54 [INFO] Scanning for projects...
> 13:08:03 [INFO] ------------------------------------------------------------------------
>
--
Mykola
https://manandbytes.github.io/
writes:
> It is easy to tell a job is getting slow because during maven init it takes
> a long time to get passed "Scanning for projects" :
>
>
> 13:06:54 [INFO] Scanning for projects...
> 13:08:03 [INFO] ------------------------------------------------------------------------
>
> Any thoughts as to what could be causing this ?
How about getting more info with 'mvn --debug'?
--
Mykola
https://manandbytes.github.io/
Jorg Heymans
May 29, 2016, 6:12:36 AM5/29/16
to Jenkins Users
Good point! Trying this and will report back ...
Jorg Heymans
May 30, 2016, 3:52:04 AM5/30/16
to Jenkins Users
Sadly there is no additional debug output being emitted during the 'scanning for projects' phase, with -X set.
00:00:10.329 [DEBUG] Reading user settings from C:\.m2\settings.xml 00:00:10.378 [INFO] Scanning for projects... 00:00:56.941 [INFO] 00:00:56.950 [INFO] ------------------------------------------------------------------------
Also tried increasing heap and perm size, does not change anything. Is there an easy way to attach a profiler during a maven build ?
Jorg
Jorg Heymans
May 30, 2016, 4:14:40 AM5/30/16
to Jenkins Users
Interestingly, executing offline with -o makes the problem disappear. But this is obviously not a solution for me..
Jorg
Daniel Beck
May 31, 2016, 7:08:19 AM5/31/16
to jenkins...@googlegroups.com
Is there a workspace-private local Maven repository? Maybe repository operations (up to date check?) take long…
I think for Maven jobs, you should be able to see internal state (current threads' stacks?) in the Jenkins UI.
I think for Maven jobs, you should be able to see internal state (current threads' stacks?) in the Jenkins UI.
> --
> 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.
> To view this discussion on the web visit https://groups.google.com/d/msgid/jenkinsci-users/77bdb41c-a14d-412b-94ac-6ebb005e918b%40googlegroups.com.
> 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.
Jorg Heymans
Jun 1, 2016, 4:45:28 AM6/1/16
to Jenkins Users, m...@beckweb.net
The maven repository used is one local to the executor. It is not particularly huge. Note that developers executing builds locally of the same module do not see this problem.
Doing a threaddump at the moment where it is scanning for projects revealed nothing special:
Channel reader thread: channel
"Channel reader thread: channel" Id=11 Group=main RUNNABLE (in native) at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:152) at java.net.SocketInputStream.read(SocketInputStream.java:122) at java.io.BufferedInputStream.fill(BufferedInputStream.java:235) at java.io.BufferedInputStream.read(BufferedInputStream.java:254) - locked java.io.BufferedInputStream@461b57 at hudson.remoting.FlightRecorderInputStream.read(FlightRecorderInputStream.java:82) at hudson.remoting.ChunkedInputStream.readHeader(ChunkedInputStream.java:72) at hudson.remoting.ChunkedInputStream.readUntilBreak(ChunkedInputStream.java:103) at hudson.remoting.ChunkedCommandTransport.readBlock(ChunkedCommandTransport.java:39) at hudson.remoting.AbstractSynchronousByteArrayCommandTransport.read(AbstractSynchronousByteArrayCommandTransport.java:34) at hudson.remoting.SynchronousCommandTransport$ReaderThread.run(SynchronousCommandTransport.java:48)
main
"main" Id=1 Group=main WAITING on hudson.remoting.Engine@1e8b327 at java.lang.Object.wait(Native Method) - waiting on hudson.remoting.Engine@1e8b327 at java.lang.Thread.join(Thread.java:1281) at java.lang.Thread.join(Thread.java:1355) at hudson.remoting.jnlp.Main.main(Main.java:137) at hudson.remoting.jnlp.Main._main(Main.java:130) at hudson.remoting.Launcher.run(Launcher.java:228) at hudson.remoting.Launcher.main(Launcher.java:192)
Ping thread for channel hudson.remoting.Channel@dc51c8:channel
"Ping thread for channel hudson.remoting.Channel@dc51c8:channel" Id=13 Group=main TIMED_WAITING at java.lang.Thread.sleep(Native Method) at hudson.remoting.PingThread.run(PingThread.java:90)
pool-1-svnkit-thread-1
"pool-1-svnkit-thread-1" Id=40 Group=main WAITING on java.util.concurrent.SynchronousQueue$TransferStack@9842bf at sun.misc.Unsafe.park(Native Method) - waiting on java.util.concurrent.SynchronousQueue$TransferStack@9842bf at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186) at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:458) at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:359) at java.util.concurrent.SynchronousQueue.take(SynchronousQueue.java:925) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:745)
pool-1-svnkit-thread-2
"pool-1-svnkit-thread-2" Id=77 Group=main WAITING on java.util.concurrent.SynchronousQueue$TransferStack@9842bf at sun.misc.Unsafe.park(Native Method) - waiting on java.util.concurrent.SynchronousQueue$TransferStack@9842bf at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186) at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:458) at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:359) at java.util.concurrent.SynchronousQueue.take(SynchronousQueue.java:925) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:745)
pool-1-thread-94
"pool-1-thread-94" Id=172 Group=main TIMED_WAITING on java.util.concurrent.SynchronousQueue$TransferStack@3d2642 at sun.misc.Unsafe.park(Native Method) - waiting on java.util.concurrent.SynchronousQueue$TransferStack@3d2642 at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226) at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460) at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:359) at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:942) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at hudson.remoting.Engine$1$1.run(Engine.java:62) at java.lang.Thread.run(Thread.java:745)
pool-1-thread-95 for channel
"pool-1-thread-95 for channel" Id=173 Group=main RUNNABLE at sun.management.ThreadImpl.dumpThreads0(Native Method) at sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:446) at hudson.Functions.getThreadInfos(Functions.java:1200) at hudson.util.RemotingDiagnostics$GetThreadDump.call(RemotingDiagnostics.java:98) at hudson.util.RemotingDiagnostics$GetThreadDump.call(RemotingDiagnostics.java:95) at hudson.remoting.UserRequest.perform(UserRequest.java:120) at hudson.remoting.UserRequest.perform(UserRequest.java:48) at hudson.remoting.Request$2.run(Request.java:326) at hudson.remoting.InterceptingExecutorService$1.call(InterceptingExecutorService.java:68) at java.util.concurrent.FutureTask.run(FutureTask.java:262) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at hudson.remoting.Engine$1$1.run(Engine.java:62) at java.lang.Thread.run(Thread.java:745) Number of locked synchronizers = 1 - java.util.concurrent.ThreadPoolExecutor$Worker@6cf7f4
pool-1-thread-96
"pool-1-thread-96" Id=174 Group=main TIMED_WAITING on java.util.concurrent.SynchronousQueue$TransferStack@3d2642 at sun.misc.Unsafe.park(Native Method) - waiting on java.util.concurrent.SynchronousQueue$TransferStack@3d2642 at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226) at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460) at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:359) at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:942) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at hudson.remoting.Engine$1$1.run(Engine.java:62) at java.lang.Thread.run(Thread.java:745)
pool-1-thread-97
"pool-1-thread-97" Id=175 Group=main TIMED_WAITING on java.util.concurrent.SynchronousQueue$TransferStack@3d2642 at sun.misc.Unsafe.park(Native Method) - waiting on java.util.concurrent.SynchronousQueue$TransferStack@3d2642 at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226) at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460) at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:359) at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:942) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at hudson.remoting.Engine$1$1.run(Engine.java:62) at java.lang.Thread.run(Thread.java:745)
RemoteInvocationHandler [#1]
"RemoteInvocationHandler [#1]" Id=10 Group=main TIMED_WAITING on java.lang.ref.ReferenceQueue$Lock@ad0aa4 at java.lang.Object.wait(Native Method) - waiting on java.lang.ref.ReferenceQueue$Lock@ad0aa4 at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135) at hudson.remoting.RemoteInvocationHandler$Unexporter.run(RemoteInvocationHandler.java:415) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) at java.util.concurrent.FutureTask.run(FutureTask.java:262) at hudson.remoting.AtmostOneThreadExecutor$Worker.run(AtmostOneThreadExecutor.java:110) at java.lang.Thread.run(Thread.java:745)
Thread-1
"Thread-1" Id=9 Group=main TIMED_WAITING on hudson.remoting.Channel@dc51c8 at java.lang.Object.wait(Native Method) - waiting on hudson.remoting.Channel@dc51c8 at hudson.remoting.Channel.join(Channel.java:948) at hudson.remoting.Engine.run(Engine.java:267)
Attach Listener
"Attach Listener" Id=4 Group=system RUNNABLE
Finalizer
"Finalizer" Id=3 Group=system WAITING on java.lang.ref.ReferenceQueue$Lock@95be5d at java.lang.Object.wait(Native Method) - waiting on java.lang.ref.ReferenceQueue$Lock@95be5d at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)
Reference Handler
"Reference Handler" Id=2 Group=system WAITING on java.lang.ref.Reference$Lock@104d42c at java.lang.Object.wait(Native Method) - waiting on java.lang.ref.Reference$Lock@104d42c at java.lang.Object.wait(Object.java:503) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
Jorg
Jorg Heymans
Jun 1, 2016, 5:29:46 AM6/1/16
to Jenkins Users, m...@beckweb.net
FWIW i also tested with an empty maven repository, no difference. So it must be something that is happening when it parses the POM for dependencies ?
Reply all
Reply to author
Forward
0 new messages