Why does a hudson "mvn clean install" build take 3-6x longer than the same on the command line?

Question

We are seeing relatively long build times on our CI server (hudson) and they're starting to get in our way. I am aware hudson does more than invoke maven and I would happily grant it 10-20% more time for the job, but an order of magnitude slowdown seems too much.

Anyone have an idea of why this might be and how to solve the problem? I will start by saying what is not the cause:

• the virtual machine hudson is running in: on the command line, it takes roughly the same amount of time as my development PC
• other concurrent tasks: I made sure there was nothing diverting resources from the build task

The maven goals are literally clean and install, nothing fancy and resource-intensive like javadoc, checkstyle etc. Looking at the hudson build task console output, there seem to be delays when "Retrieving previous build number from [our Nexus artefact repository]", but I don't know of a simple way to measure performance of this step and publishing an artefact seems too simple an operation to justify the total difference in speed.

(problem also described in this thread)

Update:

We have upgraded Hudson/Jenkins to the latest release and have been able to use the timing plugin. Short version:

• the good news: we now know nexus is causing the problem
• the bad news: we still don't know why

More details

On one of our actual maven projects (maven build time: 3 min, hudson build time: 9 min) we could see that hudson also performs the build in 3 min, but then takes 6 minutes to upload the artefact to nexus.

Performing a manual upload of another artefact using nexus' web UI, I was able to confirm the following:

• the actual artefact upload is done in a fraction of the time (i.e., in several seconds)
• after these several seconds, the artefact appears as <nexusworkdir>/nexus/storage/test/test2/test2/1.0.0/test2-1.0.0.rpm

The real puzzler is why nexus takes over a minute to create this file: <nexusworkdir>/nexus/proxy/attributes/test/test2/test2/1.0.0/test2-1.0.0.rpm

As far as I can tell, it just calculates an MD5 and SHA1 signature and records general artefact information, but md5sum and sha1sum of a 75MB file take <1s to run...

Finally, it does not appear to be some sort of network time-out, because the delay seems to be roughly proportional to artefact size.

Any idea what nexus does after it receives an artefact is appreciated.

Update 2:

Setting the nexus log level to debug, nexus logs the following when an artefact is uploaded:

...

2011-04-05 14:38:53 DEBUG [jpsc28za2RtYQ==] -

o.s.n.p.s.l.f.Defau~ - Copying stream with buffer size of: 4096

2011-04-05 14:39:55 DEBUG [ython-2.5.2.jar] - org.mortbay.log   

- RESPONSE /nexus/content/groups/public/org/python/jython/2.5.2/jython-2.5.2.jar 200

2011-04-05 14:40:07 DEBUG [-2.5.2.jar.sha1] - org.mortbay.log   

- REQUEST /nexus/content/groups/public/org/python/jython/2.5.2/jython-2.5.2.jar.sha1 on

...

2011-04-05 14:40:12 DEBUG [-2.5.2.jar.sha1] - org.mortbay.log   

- RESPONSE /nexus/content/groups/public/org/python/jython/2.5.2/jython-2.5.2.jar.sha1 200

2011-04-05 14:43:45 DEBUG [ndex.properties] - org.mortbay.log   

- REQUEST /nexus/content/groups/public/.index/nexus-maven-repository-index.properties on org.mortbay.jetty.HttpConnection@141a720

...

2011-04-05 14:44:04 DEBUG [ndex.properties] -

o.s.n.p.m.m.M2Group~ - public retrieveItem() :: FOUND public:/.index/nexus-maven-repository-index.properties

2011-04-05 14:44:04 DEBUG [ndex.properties] - org.mortbay.log   

- RESPONSE /nexus/content/groups/public/.index/nexus-maven-repository-index.properties 200

2011-04-05 14:48:07 DEBUG [jpsc28za2RtYQ==] -

o.s.n.p.a.DefaultAt~ - Storing attributes on UID=test:/test/test/1.0.1/test-1.0.1.rpm

...

2011-04-05 14:48:07 DEBUG [w/icon-info.gif] - org.mortbay.log   

- servlet holder=nexus

2011-04-05 14:48:08 DEBUG [w/icon-info.gif] - org.mortbay.log   

- RESPONSE /nexus/ext-2.3/resources/images/default/window/icon-info.gif 200

2011-04-05 14:49:01 DEBUG [c=1302007326656] - org.mortbay.log   

- REQUEST /nexus/service/local/log/config on org.mortbay.jetty.HttpConnection@1dbd88f ....

It appears to just be sitting there for a minute or so and than continues with its work. Any idea why nexus does this is appreciated.

Answer 1

As discussed in the thread I suspect your forked Maven isn't getting the JVM parameters passed. Can you use jconsole to check the max heap allowed is what you have allocated in your MAVEN_OPTS?

Does it make any difference if you start Hudson as a service vs. starting Hudson from the command line?

Update:

Deploying on Nexus takes a load of RAM, much more than compiling (in my experience). The swapping on low memory might be what's slowing it down.