[JENKINS-7535] Rebuilding dependency graph slow on large installations

[timja]

In the ASF Hudson installation, rebuilding the dependency graph is quite slow (minutes). As rebuilding seems to happen twice on saving project configuration (AbstractProject.doConfigSubmit()), working with the project configuration is very slow and will frequently time out.

We have a large number of jobs (>300) and from a quick look at the code, it seems like building the dependency graph is done even if there are no changes to the dependencies. Also, building the graph seems to be done by iterating over all jobs which will in turn iterator over all other jobs. This doesn't seem to scale to our size

Here's a typical thread dump from saving a project configuration:

"Handling POST /hudson/job/ftpserver-trunk-jdk1.6-osx/configSubmit : http-8090-27" daemon prio=10 tid=0x000000004340a000 nid=0x4576 runnable [0x00007f2fa8e48000]
java.lang.Thread.State: RUNNABLE
at java.lang.String.intern(Native Method)
at hudson.maven.ModuleDependency.(ModuleDependency.java:48)
at hudson.maven.ModuleDependency.(ModuleDependency.java:54)
at hudson.maven.MavenModule.asDependency(MavenModule.java:296)
at hudson.maven.MavenModule.buildDependencyGraph(MavenModule.java:385)
at hudson.maven.MavenModuleSet.buildDependencyGraph(MavenModuleSet.java:487)
at hudson.model.DependencyGraph.(DependencyGraph.java:100)
at hudson.model.Hudson.rebuildDependencyGraph(Hudson.java:3346)
at hudson.model.AbstractProject.doConfigSubmit(AbstractProject.java:588)
at sun.reflect.GeneratedMethodAccessor1225.invoke(Unknown Source)
...

---

Originally reported by protocol7b, imported from: Rebuilding dependency graph slow on large installations

• assignee: kutzi
• status: Resolved
• priority: Major
• resolution: Fixed
• resolved: 2011-03-30T16:48:58+00:00
• imported: 2022/01/10

[timja]

tdunning:

It would be lovely if the dependency computation were to use a more clever algorithm so that it is very fast, but there are some quick wins available:

a) don't do it if nothing changed

b) don't do it if another thread is already doing a global recomputation. At the least, just have a single thread that does this dependency computation and have save mark the graph is needing an update. That way nobody is delayed and the worst that happens is one thread does the updates back-to-back forever.

c) only change as much as is needed by the recently changed dependencies. This is an extension of (a) to make the entire computation incremental. Basically, you can keep an update time on each node and on the graph in general. In doing the dependency computation, you can skip part of the computation as soon as you note that the node under consideration hasn't changed more recently than the last graph update.

[timja]

protocol7b:

This problem has now grown to become even more serious in our environment. Since the dependency graph is also rebuilt after parsing the POM when building, builds are taking a pretty long time (10-15 minutes in the "Parsing POMs" state).

Any chance of this problem being fixed in near time?

[timja]

lore84:

Can someone please look at this issue? We have large installation with cca 400 jobs (and increasing) and "parsing pom" phase takes cca 20-30minutes for each job. It begun to be a big issue for us, because we are able to build only small amounts of build per day.

[timja]

evernat:

The stack-trace in the issue is about the calls to the native method java.lang.String.intern() in the ModuleDependency constructor.

To optimize the dependency graph, I have written a patch (JENKINS-7535-maven-plugin_evernat.patch attached) which divides the number of calls to intern() by 3 or a bit more.
I couldn't test the patch and I certainly can't test with such a large installation, but I am quite sure that it won't break anything. So if possible, can someone test the patch and eventually make a pull request in github for it.

The patch certainly needs review: in particular, some committers may not think that the assumption in the added private constructor of ModuleDependency is worth this part of the optimisation, even for this issue (if it is the case the 3 arguments constructor can be used instead).

[timja]

kutzi:

Has anyone already confirmed that String.intern is really the part which is taking most of the time?
Having a single stack trace which shows that is IMO not enough evidence to point out intern() as the culprit.

[timja]

protocol7b:

I've done quite a few thread dumps on our installation at ASF. All those has been pointing to String.intern. I can do additional debugging in our environment if needed.

[timja]

kutzi:

Okay, that's good enough for me. Just wanted to make sure that no invalid assumptions are made based on a single dump.

[timja]

olamy:

Applying evernat patch looks good. I will do it.

But I wonder simply removing those intern() call too ?
IMHO not sure it's really usefull.
Someone else ?

[timja]

kutzi:

Looks like they're in there to save some heap space.
But it surely smells like premature optimization.
Can we find out, why it was introduced - i.e. was there a concrete memory problem?

[timja]

scm_issue_link:

Code changed in jenkins
User: Olivier Lamy
Path:
maven-plugin/src/main/java/hudson/maven/MavenModule.java
maven-plugin/src/main/java/hudson/maven/ModuleDependency.java
http://jenkins-ci.org/commit/core/7d46b22599c6001eaeff7f47715fa80491b3fdd5
Log:
JENKINS-7535 Rebuilding dependency graph slow on large installations
Submitted by evernat.

[timja]

olamy:

if someone interested to test I have pushed a build here : http://people.apache.org/~olamy/jenkins/ .
Niklas a real test @asf instance ?

[timja]

olamy:

if someone interested to test I have pushed a build here : http://people.apache.org/~olamy/jenkins/ .
Niklas a real test @asf instance ?

[timja]

protocol7b:

From what is the build built? If we could get a 1.399 (or 1.400) with this specific patch applied, I would be happy to try it out on the ASF installation.

[timja]

olamy:

build based on my last push https://github.com/jenkinsci/jenkins/commit/7d46b22599c6001eaeff7f47715fa80491b3fdd5
so a 1.402-SNAPSHOT

[timja]

dogfood:

Integrated in jenkins_main_trunk #583
JENKINS-7535 Rebuilding dependency graph slow on large installations

Olivier Lamy : 7d46b22599c6001eaeff7f47715fa80491b3fdd5
Files :

• maven-plugin/src/main/java/hudson/maven/ModuleDependency.java
• maven-plugin/src/main/java/hudson/maven/MavenModule.java

[timja]

lore84:

We will deploy on weekend and then test it. Thanks for effort.

[timja]

lore84:

There is not noticeable change after deploy the patched Jenkins.

[timja]

evernat:

Sorry about that, I am surprised by the news. I suggest to keep the patch anyway in the source code.
And I suggest to take a few thread dumps on the patched Jenkins (other tools such as VisualVM sampler may help to have more precise data than thread dumps).

[timja]

kutzi:

The biggest improvements are - as always in Software industry - usually achieved by imrpoving the algorithm.
For instance, I've seen one seemingly obvious way to improve it:
MavenModules are rebuilding their object graph twice:

• once when their MavenModuleSet does it
• and once as the MavenModules themselves are top-level AbstractProjects in Jenkins

[timja]

kutzi:

Then there is that for every MavenModule a map of all MavenModules in the system is built up, again.
There surely must be a way to do that only once.

It was mentioned before that, if nothing has changed, the graph rebuilding could be skipped.
Unfortunately, it doesn't seem to be easy to determine if anything has changed.

[timja]

kutzi:

Okay, so quick win without too much risk:

Remove rebuilding the dependency graph of all contained MavenModules from MavenModuleSet#buildDependencyGraph
as they are already rebuild in DependencyGraph#init.

That should already nearly halve the work to be done for maven projects.
Any objections?

[timja]

kutzi:

For the other problem (map of all MavenModules build up each time), I thought that we could use something like computational data attached to the DependencyGraph. The 1st MavenModule, which builds it graph, could calculate this map and then attach is to the DependencyGraph, so all following modules could pick it up.
When the dependency graph has finished its initialisation, it could throw away all computational data.

[timja]

kutzi:

Attached a patch where I implemented it, as described in the previous comments

[timja]

scm_issue_link:

Code changed in jenkins
User: Christoph Kutzinski
Path:
core/src/main/java/hudson/model/DependencyGraph.java
maven-plugin/src/main/java/hudson/maven/MavenModule.java
maven-plugin/src/main/java/hudson/maven/MavenModuleSet.java
http://jenkins-ci.org/commit/jenkins/90b605c756a058b256772ab4ec1c8c05f039be93
Log:
[FIXED JENKINS-7535] building up the dependency graph for maven jobs
takes too long

[timja]

kutzi:

Oops, I didn't mean to push that already. Anyway, this is only committed on a branch, so I won't become part of the next release (yet)

[timja]

scm_issue_link:

Code changed in jenkins
User: Christoph Kutzinski
Path:
core/src/main/java/hudson/model/DependencyGraph.java
maven-plugin/src/main/java/hudson/maven/MavenModule.java
maven-plugin/src/main/java/hudson/maven/MavenModuleSet.java
http://jenkins-ci.org/commit/jenkins/6a5330fd936fb949da74d738b82dcf5333282b61
Log:
[FIXED JENKINS-7535] building up the dependency graph for maven jobs
takes too long

[timja]

scm_issue_link:

Code changed in jenkins
User: Christoph Kutzinski
Path:
changelog.html
http://jenkins-ci.org/commit/jenkins/d3978478486e4030a058b05ff86a01f132c720a3
Log:
record changes for JENKINS-7535

[timja]

dogfood:

Integrated in jenkins_main_trunk #625
[FIXED JENKINS-7535] building up the dependency graph for maven jobs

Christoph Kutzinski : 6a5330fd936fb949da74d738b82dcf5333282b61
Files :

• core/src/main/java/hudson/model/DependencyGraph.java
• maven-plugin/src/main/java/hudson/maven/MavenModuleSet.java
• maven-plugin/src/main/java/hudson/maven/MavenModule.java

[timja]

momega:

I tried latest build (625) and I must confirm that issue about the peformance of "Parsing Pom" or start of the server is better.

"Parsing Pom" now takes about 20s instead of several minutes. Good improvment!

But for some builds with many dependencies I have got "out of memory" problem.

Caused by: java.lang.OutOfMemoryError: Java heap space
at java.util.Arrays.copyOfRange(Arrays.java:3209)
at java.lang.String.(String.java:215)
at java.lang.StringBuilder.toString(StringBuilder.java:430)
at org.apache.maven.model.Dependency.getManagementKey(Dependency.java:579)
at org.apache.maven.model.merge.MavenModelMerger.getDependencyKey(MavenModelMerger.java:556)
at org.apache.maven.model.merge.ModelMerger.mergeDependencyManagement_Dependencies(ModelMerger.java:1459)
at org.apache.maven.model.merge.ModelMerger.mergeDependencyManagement(ModelMerger.java:1439)
at org.apache.maven.model.merge.ModelMerger.mergeModelBase_DependencyManagement(ModelMerger.java:669)
at org.apache.maven.model.merge.ModelMerger.mergeModelBase(ModelMerger.java:523)
at org.apache.maven.model.merge.ModelMerger.mergeModel(ModelMerger.java:116)
at org.apache.maven.model.merge.MavenModelMerger.mergeModel(MavenModelMerger.java:78)
at org.apache.maven.model.merge.ModelMerger.merge(ModelMerger.java:111)
at org.apache.maven.model.inheritance.DefaultInheritanceAssembler.assembleModelInheritance(DefaultInheritanceAssembler.java:56)
at org.apache.maven.model.building.DefaultModelBuilder.assembleInheritance(DefaultModelBuilder.java:637)
at org.apache.maven.model.building.DefaultModelBuilder.build(DefaultModelBuilder.java:332)
at org.apache.maven.model.building.DefaultModelBuilder.build(DefaultModelBuilder.java:232)
at org.apache.maven.project.DefaultProjectBuilder.build(DefaultProjectBuilder.java:141)
at org.apache.maven.project.DefaultProjectBuilder.build(DefaultProjectBuilder.java:102)
at org.apache.maven.project.MavenProject.getParent(MavenProject.java:359)
at hudson.maven.PomInfo.(PomInfo.java:124)
at hudson.maven.MavenModuleSetBuild$PomParser.toPomInfo(MavenModuleSetBuild.java:1332)
at hudson.maven.MavenModuleSetBuild$PomParser.toPomInfo(MavenModuleSetBuild.java:1350)
at hudson.maven.MavenModuleSetBuild$PomParser.invoke(MavenModuleSetBuild.java:1305)
at hudson.maven.MavenModuleSetBuild$PomParser.invoke(MavenModuleSetBuild.java:1097)
at hudson.FilePath$FileCallableWrapper.call(FilePath.java:1944)
at hudson.remoting.UserRequest.perform(UserRequest.java:118)
at hudson.remoting.UserRequest.perform(UserRequest.java:48)
at hudson.remoting.Request$2.run(Request.java:270)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
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)

There I believe the issue has to reopened.

[timja]

momega:

I have also incresed memory settings to -Xmx2300m (the maximum I can). No change.

[timja]

kutzi:

Yeah, it's basically trading performance for memory. I'll see if I can at least use soft references to prevent OOMEs.

[timja]

scm_issue_link:

Code changed in jenkins
User: Christoph Kutzinski
Path:
maven-plugin/src/main/java/hudson/maven/MavenModule.java
http://jenkins-ci.org/commit/jenkins/cccb301fbe28ff8b33b044f81f1d02fcd7ea02ee
Log:
JENKINS-7535 don't remember per-moduleset modules to prevent OOMEs

[timja]

kutzi:

I've reverted parts of the change so that the modules per modulesets are not remembered anymore. This should have basically the same memory characteristics as before and - as I hope - affect the performance not too much.

We should look into additional improvements like tdunning mentioned in the first comment.
The quickest win IMO would be to have always only one thread recomputing the dependencies.

[timja]

kutzi:

Additional ideas:

• remember per-moduleset modules again, but with soft references, so heap is cleared when needed (as mentioned above)
• remove possibly obsolete versionless dependencies:

    // when we load old data that doesn't record version in dependency, we'd like
    // to emulate the old behavior that it tries to identify the upstream by ignoring the version.
    // do this by always putting groupId:artifactId:UNKNOWN to the modules list.
    
    for (MavenModule m : Hudson.getInstance().getAllItems(MavenModule.class)) {
...
modules.put(moduleDependency,m);
modules.put(moduleDependency.withUnknownVersion(),m);
    }

I guess the 'old data' mentioned there, must be really really old. I can find this comment already in the oldest available revision (2009-03-30), so I guess the moduleDependency.withUnknownVersion() could be removed.
It would only possibly affect users which upgrade from a really old Hudson version.

[timja]

dogfood:

Integrated in jenkins_main_trunk #628
JENKINS-7535 don't remember per-moduleset modules to prevent OOMEs

Christoph Kutzinski : cccb301fbe28ff8b33b044f81f1d02fcd7ea02ee
Files :

• maven-plugin/src/main/java/hudson/maven/MavenModule.java

[timja]

momega:

Just one remark. The "out off memory" problems so appears only in one slave server so far.
I have disabled that node.

I will try the latest build (628) on that nodes.

[timja]

momega:

I have installed the current snapshot (1.406-SNAPSHOT) it seems fine. Start of the server is faster, memory consumption also seems better.

[timja]

kutzi:

Thanks for testing.
So I guess, I can mark this as resolved, again.

[timja]

scm_issue_link:

Code changed in jenkins
User: Christoph Kutzinski
Path:
core/src/main/java/hudson/model/DependencyGraphCalculator.java
core/src/main/java/hudson/model/Hudson.java
http://jenkins-ci.org/commit/jenkins/f10e737b1147ca742f3a50c03b01945d803c6ea2
Log:
JENKINS-7535 make sure only one thread at a time rebuilds the dependency graph

[timja]

kutzi:

See JENKINS-9301 for additional ideas to improve the time and resource consumption of building the dependency graph.

[timja]

scm_issue_link:

Code changed in jenkins
User: Christoph Kutzinski
Path:
core/src/main/java/hudson/model/DependencyGraph.java
maven-plugin/src/main/java/hudson/maven/MavenModule.java
maven-plugin/src/main/java/hudson/maven/MavenModuleSet.java
http://jenkins-ci.org/commit/jenkins/6a5330fd936fb949da74d738b82dcf5333282b61
Log:
[FIXED JENKINS-7535] building up the dependency graph for maven jobs
takes too long

[timja]

scm_issue_link:

Code changed in jenkins
User: Christoph Kutzinski
Path:
changelog.html
http://jenkins-ci.org/commit/jenkins/d3978478486e4030a058b05ff86a01f132c720a3
Log:
record changes for JENKINS-7535

[timja]

scm_issue_link:

Code changed in jenkins
User: Christoph Kutzinski
Path:
maven-plugin/src/main/java/hudson/maven/MavenModule.java
http://jenkins-ci.org/commit/jenkins/cccb301fbe28ff8b33b044f81f1d02fcd7ea02ee
Log:
JENKINS-7535 don't remember per-moduleset modules to prevent OOMEs

[timja]

scm_issue_link:

Code changed in jenkins
User: Olivier Lamy
Path:
src/main/java/hudson/maven/MavenModule.java
src/main/java/hudson/maven/ModuleDependency.java
http://jenkins-ci.org/commit/maven-plugin/004eadacbe5bb56011e3134e7b904bb4f08c9f3f
Log:
JENKINS-7535 Rebuilding dependency graph slow on large installations
Submitted by evernat.

Originally-Committed-As: 7d46b22599c6001eaeff7f47715fa80491b3fdd5

[timja]

scm_issue_link:

Code changed in jenkins
User: Christoph Kutzinski
Path:
src/main/java/hudson/maven/MavenModule.java
src/main/java/hudson/maven/MavenModuleSet.java
http://jenkins-ci.org/commit/maven-plugin/70da285e456a34febb9705199a4aa6287506b38e
Log:
[FIXED JENKINS-7535] building up the dependency graph for maven jobs
takes too long
Originally-Committed-As: 6a5330fd936fb949da74d738b82dcf5333282b61

[timja]

scm_issue_link:

Code changed in jenkins
User: Christoph Kutzinski
Path:
src/main/java/hudson/maven/MavenModule.java
http://jenkins-ci.org/commit/maven-plugin/28e769c1549bea397ce17081e50d1477489735df
Log:
JENKINS-7535 don't remember per-moduleset modules to prevent OOMEs
Originally-Committed-As: cccb301fbe28ff8b33b044f81f1d02fcd7ea02ee