OOM performing bulk load

[jonathandfields]

Hi All,

I am trying to perform a bulk load of data into an initially empty repository. I need to be able to load upwards of 1-5M nodes for real world data. I am hitting an OOM after loading less than 100K nodes. My configuration is:

• Java 6, JVM: -Xms1024m -Xmx1024m -XX:MaxPermSize=512m
• JBoss AS 7.1
• Modeshape 3.1
• Berkeley DB cache loader for Infinispan
• Infinispan eviction enabled and max-entries set to 500
• An asynchronous stateless EJB, with Bean Managed Transactions, using an injected UserTransaction.
• Modeshape injected via @Resource

My code loops,  starting a transaction, creates 1000 nodes, performs session.save(), commits the transaction, and starts a new transaction. After a certain amount of time, an exception is thrown due to out of memory (see attached log from JBoss).

I have also tried a variation where in addition to performing the session.save() and transaction commit every 1000 nodes, I also session.logout() and then session.login(). I get the same results.

Increasing the memory just delays the OOM. Watching jconsole, the memory consumption (PS Old Gen) increases steadily.

The code for the EJB is attached.

Am I doing something wrong or is there a memory leak? If you like I can create a JIRA and provide my EJB and complete configuration to reproduce.

Thanks!

[hchiorean]

Hi Jonathan,

From the profiler, are you able to trace the hard references that are causing the Old Gen to grow ? I'm curious whether it's IPSN related or ModeShape related.

Also, did you try another cache store (e.g. file system)

[jonathandfields]

Hi Horia,

I will try and run a test today with a JDBC cache store and see what happens.

Would the output of jmap -histo be of use to try and see what objects are not being GC'd? If so I can provide that.

Otherwise please advise and I'll be happy to get that information.

Thanks,

Jon

[hchiorean]

I think a jmap file would help (assuming I can load it into VisualVM).

[jonathandfields]

I attached the jmap histogram (hist.txt) and a zip file containing the EJB, the Eclipse project and instructions how to reproduce, if that would be helpful.

I will run the test later using visual vm and also try it with another cache loader later today.

Thanks!

[jonathandfields]

No luck with visual vm. After starting profiling on a local AS 7, the JVM appears hung at that point - no log messages, calls to modeshape rest service hang, etc. Any hints how to use visual vm with AS 7?

[rhauch]

Did you see Using VisualVM with JBoss AS 7?

[jonathandfields]

Thanks I'll take a look.

I tried this with a file cache loader, but that failed. Infinispan on Linux just keeps opening files apparently, even though I have eviction enabled (LRU) with max-entries 500 (see the last remark in https://community.jboss.org/thread/205205). It just kept opening more and more files and kept hitting the open file limit.

I'll see if I can get JDBC setup and see if that makes a difference.....

But, I ultimately need to get Berkely DB working.

Thanks!

[jonathandfields]

Used the script provided in the article, but still no luck with Visual VM - once profiling starts, AS 7 hangs. (I am running RHEL5 x64 - perhaps this works on other platforms).

Tried to get JDBC setup, but was not successful. As this discussion points out it does not seem to be completely working out of the box:  https://community.jboss.org/thread/204068.

Not sure what to do next as it seems that it is not possible to persistently store more than a small number (< 100K) nodes without hitting some kind of resource limit. Has anybody else been succesful in this with AS 7?

[jonathandfields]

I have made good progress. Watching the instances of  org.modeshape.jcr.JcrSingleValueProperty and org.modeshape.jcr.JcrNode using jmap, I saw that they just continued to grow, never been GC'd. I changed the logic of my program to not just do a session.save() and commit every 1000 nodes, but to do a session.logout(), session.login(), and commit. I thought I had tried this in an earlier iteration and it had yielded the same results, but obviously I was wrong. After adding the session.logout() and session.login(), I could see the properties and nodes being reclaimed which every GC. I am now getting farther than before. Memory usage still seems to be creeping up, but at a much lower rate than before. I'll keep testing and see how far I can get.

[rhauch]

Watching the instances of  org.modeshape.jcr.JcrSingleValueProperty and org.modeshape.jcr.JcrNode using jmap, I saw that they just continued to grow, never been GC'd. I changed the logic of my program to not just do a session.save() and commit every 1000 nodes, but to do a session.logout(), session.login(), and commit. I thought I had tried this in an earlier iteration and it had yielded the same results, but obviously I was wrong. After adding the session.logout() and session.login(), I could see the properties and nodes being reclaimed which every GC.

Ah, this makes perfect sense. The JCR semantics are going to make it difficult here.

The current behavior was designed so that, given a single Session, multiple calls to obtain a Node or a Property object would in fact return the same object, regardless of whether the objects are returned before or after save. I'll look in the spec to see if there's any reason we cannot simply discard the objects from the Session upon save.

[rhauch]

Jonathan, do you want to log an issue for this so we can start tracking options?

It is certainly plausible for an application to use a single session for many save operations, and we should not be leaking memory like this. I'm glad that there is a suitable workaround, but we should try to improve the situation.

[jonathandfields]

Comparing it to JPA EntityManager, it seems consistent: you have to clear the local cache periodically (calling EntityManager.clear() in JPA) when doing bulk manipulations. Perhaps just a section in the docs similar to the section in the Hibernate book on bulk operations that provide an example of clearing the local cache periodically.

I'm still not out of the woods. Something is still slowly consuming Old Gen. Most of it is taken up by byte[].

Are Lucene index updates being done asyncrhonously? If so is the queue of "changes" bounded? I am wondering if my high rate of session.saves() is filling that queue with a lot of work which is consuming a lot of memory? I'm seeing Lucene related classes in jmap now.... Just a stab in the dark....

[rhauch]

Are Lucene index updates being done asyncrhonously? If so is the queue of "changes" bounded? I am wondering if my high rate of session.saves() is filling that queue with a lot of work which is consuming a lot of memory? I'm seeing Lucene related classes in jmap now.... Just a stab in the dark....

Yes, indexing is done asychronously. To know whether indexing/Lucene is the problem, you could either test with query disabled completely, or periodically pause your updates and let indexing catch up.

[jonathandfields]

Yes I'll log an issue and attach my code. I'll continue to work it as well. Right now it looks like I can load a real world amount data by running batches, starting and stopping JBoss with each batch. But it would be great if this was eventually not necessary.