OutOfMemoryError caused by Spring not cleaning caches?

[robinkrom]

Hello,

As the problem I am am having is more Springframework related as batch related I posted here...

I have implemented an application which runs multiple batches with the Spring Batch Framework (2.0.4.RELEASE) and Spring 3.0.0.

After some time this application fails with an OutOfMemoryError.

After evaluating the Heap-Dump I noticed this:

ApplicationContext (XmlWebApplicationContext)

beanFactory (DefaultListableBeanFactory)

beanExpressionResolver (StandardBeanExpressionResolver)

evaluationCache (ConcurrentHashMap) <---- HUGE (>500MB)!!!

I had a look at the code and noticed that the StandardBeanExpressionResolver must be adding new entries to the evaluationCache all the time, but these are never released.
There are two questions here, first one is why it keeps adding and secondly why is the cache never cleared?

Has anyone seen this problem before? If so are there any solutions?

Best wishes,
Robin

[dr_pompeii]

Hello Robin

After some time this application fails with an OutOfMemoryError.

copy the complete error stack trace, some times below in the complete error show other useful information

which container you are using? Tomcat?

I had a look at the code and noticed that the StandardBeanExpressionResolver must be adding new entries to the evaluationCache all the time, but these are never released.

how do you got such conclusion?

There are two questions here, first one is why it keeps adding and secondly why is the cache never cleared?

If you can post important configuration about your configuration for cache and others things would be useful

BTW use code tags

[robinkrom]

Hello,

thank you for your reply!!

As far as my experience goes I have seen that an OutOfMemoryError stacktrace never gives a clue about what is causing the out of memory itself. In fact it could be any thread that was in need of memory, could be the database driver or a HTTP request...

As soon as the JVM is out of memory we get the error in many places, this is just one example:

java.lang.OutOfMemoryError: Java heap space
at java.io.BufferedOutputStream.<init>(BufferedOutputStream.java:59)
at java.io.BufferedOutputStream.<init>(BufferedOutputStream.java:42)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:642)
at java.lang.Thread.run(Thread.java:595)

Our JVM is generating Heap-Dumps as soon as the error occurs by running our JVM with "-XX:+HeapDumpOnOutOfMemoryError". A Heapdump analysis usually brings more information.

This brings me to my assumption that the StandardBeanExpressionResolver is not cleaning its cache. When analysing the Heapdump, the biggest object is:

org.springframework.beans.factory.support.DefaultListableBeanFactory @ 0xd1fa8578
Shallow Size: 200 B Retained Size: 543,4 MB

Looking at in in Detail (scroll to the right for size information!):

Class Name                                                                                                                         | Shallow Heap | Retained Heap 
------------------------------------------------------------------------------------------------------------------------------------------------------------------
org.springframework.beans.factory.support.DefaultListableBeanFactory @ 0xd1fa8578                                                  |          200 |   569.825.696 
|- <class> class org.springframework.beans.factory.support.DefaultListableBeanFactory @ 0xf0dd6e40                                 |            8 |         1.584 
|- beanClassLoader org.jboss.web.tomcat.service.WebAppClassLoader @ 0xd1d3a118                                                     |          176 |        47.024 
|- frozenBeanDefinitionNames java.lang.String[170] @ 0xd2185e78                                                                    |          696 |           696 
|- disposableBeans java.util.LinkedHashMap @ 0xd29bf470                                                                            |           48 |        39.840 
|- aliasMap java.util.concurrent.ConcurrentHashMap @ 0xd2b8bc90                                                                    |           40 |         1.544 
|- singletonObjects java.util.concurrent.ConcurrentHashMap @ 0xd2b8bcb8                                                            |           40 |       737.280 
|- singletonFactories java.util.HashMap @ 0xd2b8bce0                                                                               |           40 |           120 
|- earlySingletonObjects java.util.HashMap @ 0xd2b8bd08                                                                            |           40 |           120 
|- containedBeanMap java.util.concurrent.ConcurrentHashMap @ 0xd2b8bd30                                                            |           40 |        17.928 
|- dependentBeanMap java.util.concurrent.ConcurrentHashMap @ 0xd2b8bd58                                                            |           40 |        31.880 
|- dependenciesForBeanMap java.util.concurrent.ConcurrentHashMap @ 0xd2b8bd80                                                      |           40 |        27.528 
|- factoryBeanObjectCache java.util.concurrent.ConcurrentHashMap @ 0xd2b8bda8                                                      |           40 |         3.600 
|- customEditors java.util.HashMap @ 0xd2b8bdd0                                                                                    |           40 |           112 
|- scopes java.util.HashMap @ 0xd2b8bdf8                                                                                           |           40 |           256 
|- mergedBeanDefinitions java.util.concurrent.ConcurrentHashMap @ 0xd2b8be20                                                       |           40 |       387.048 
|- embeddedValueResolvers java.util.LinkedList @ 0xd2bae7c0                                                                        |           24 |         4.576 
|- beanPostProcessors java.util.ArrayList @ 0xd2bae7d8                                                                             |           24 |            80 
|- logger org.apache.commons.logging.impl.Log4JLogger @ 0xd2bb1590                                                                 |           16 |           240 
|- registeredSingletons java.util.LinkedHashSet @ 0xd2bb15b0                                                                       |           16 |         4.800 
|- singletonsCurrentlyInCreation java.util.Collections$SynchronizedSet @ 0xd2bb15c0                                                |           16 |           152 
|- propertyEditorRegistrars java.util.LinkedHashSet @ 0xd2bb15d0                                                                   |           16 |           176 
|- alreadyCreated java.util.Collections$SynchronizedSet @ 0xd2bb15e0                                                               |           16 |         2.160 
|- prototypesCurrentlyInCreation org.springframework.core.NamedThreadLocal @ 0xd2bb15f0                                            |           24 |            24 
|- serializationId java.lang.String @ 0xd2bb30d0  org.springframework.web.context.WebApplicationContext:/batch-startup             |           24 |           176 
|- instantiationStrategy org.springframework.beans.factory.support.CglibSubclassingInstantiationStrategy @ 0xd2c37f88              |            8 |             8 
|- parameterNameDiscoverer org.springframework.core.LocalVariableTableParameterNameDiscoverer @ 0xd2c37f98                         |           16 |        68.608 
|- ignoredDependencyTypes java.util.HashSet @ 0xd2c37fa8                                                                           |           16 |           152 
|- ignoredDependencyInterfaces java.util.HashSet @ 0xd2c37fb8                                                                      |           16 |           368 
|- factoryBeanInstanceCache java.util.concurrent.ConcurrentHashMap @ 0xd2dbd040                                                    |           40 |         6.144 
|- filteredPropertyDescriptorsCache java.util.HashMap @ 0xd2dbd068                                                                 |           40 |         3.152 
|- resolvableDependencies java.util.HashMap @ 0xd2dbd090                                                                           |           40 |           328 
|- beanDefinitionMap java.util.concurrent.ConcurrentHashMap @ 0xd2dbd0b8                                                           |           40 |       216.424 
|- autowireCandidateResolver org.springframework.beans.factory.annotation.QualifierAnnotationAutowireCandidateResolver @ 0xd2dc2c20|           24 |           232 
|- beanDefinitionNames java.util.ArrayList @ 0xd2dc2c38                                                                            |           24 |           840 
|- beanExpressionResolver org.springframework.context.expression.StandardBeanExpressionResolver @ 0xd2eedf48                       |           32 |   567.763.320 
'- Total: 35 entries                                                                                                               |              |               
------------------------------------------------------------------------------------------------------------------------------------------------------------------

The beanExpressionResolver (StandardBeanExpressionResolver ) is extremely big..
In my next post I will add the details for this, as posts are limited to 1000 chars.

[robinkrom]

Here are the heap details for the StandardBeanExpressionResolver (scroll to the right for size information!):

Class Name                                                                                                         | Shallow Heap | Retained Heap 
--------------------------------------------------------------------------------------------------------------------------------------------------
org.springframework.context.expression.StandardBeanExpressionResolver @ 0xd2eedf48                                 |           32 |   567.763.320 
|- <class> class org.springframework.context.expression.StandardBeanExpressionResolver @ 0xf0ecae28                |            8 |             8 
|- expressionCache java.util.concurrent.ConcurrentHashMap @ 0xd2ed9990                                             |           40 |       738.544 
|- evaluationCache java.util.concurrent.ConcurrentHashMap @ 0xd2ed99b8                                             |           40 |   567.024.696 
|  |- <class> class java.util.concurrent.ConcurrentHashMap @ 0xef97cca0 System Class                               |           32 |            32 
|  |- segments java.util.concurrent.ConcurrentHashMap$Segment[16] @ 0xd2dea920                                     |           80 |   567.024.656 
|  |  |- <class> class java.util.concurrent.ConcurrentHashMap$Segment[] @ 0xef980ac0                               |            0 |             0 
|  |  |- [0] java.util.concurrent.ConcurrentHashMap$Segment @ 0xd2eedfa8                                           |           40 |    34.486.176 
|  |  |- [1] java.util.concurrent.ConcurrentHashMap$Segment @ 0xd2eedfc8                                           |           40 |    35.529.472 
|  |  |- [2] java.util.concurrent.ConcurrentHashMap$Segment @ 0xd2eedfe8                                           |           40 |    35.718.448 
|  |  |- [3] java.util.concurrent.ConcurrentHashMap$Segment @ 0xd2eee008                                           |           40 |    35.477.672 
|  |  |- [4] java.util.concurrent.ConcurrentHashMap$Segment @ 0xd2eee028                                           |           40 |    36.356.848 
|  |  |- [5] java.util.concurrent.ConcurrentHashMap$Segment @ 0xd2eee048                                           |           40 |    35.182.360 
|  |  |- [6] java.util.concurrent.ConcurrentHashMap$Segment @ 0xd2eee068                                           |           40 |    34.166.864 
|  |  |- [7] java.util.concurrent.ConcurrentHashMap$Segment @ 0xd2eee088                                           |           40 |    35.299.336 
|  |  |- [8] java.util.concurrent.ConcurrentHashMap$Segment @ 0xd2eee0a8                                           |           40 |    35.287.208 
|  |  |- [9] java.util.concurrent.ConcurrentHashMap$Segment @ 0xd2eee0c8                                           |           40 |    35.619.656 
|  |  |- [10] java.util.concurrent.ConcurrentHashMap$Segment @ 0xd2eee0e8                                          |           40 |    36.317.848 
|  |  |- [11] java.util.concurrent.ConcurrentHashMap$Segment @ 0xd2eee108                                          |           40 |    35.076.536 
|  |  |- [12] java.util.concurrent.ConcurrentHashMap$Segment @ 0xd2eee128                                          |           40 |    35.913.608 
|  |  |- [13] java.util.concurrent.ConcurrentHashMap$Segment @ 0xd2eee148                                          |           40 |    34.678.624 
|  |  |- [14] java.util.concurrent.ConcurrentHashMap$Segment @ 0xd2eee168                                          |           40 |    35.278.016 
|  |  |- [15] java.util.concurrent.ConcurrentHashMap$Segment @ 0xd2eee188                                          |           40 |    36.635.904 
|  |  '- Total: 17 entries                                                                                         |              |               
|  '- Total: 2 entries                                                                                             |              |               
|- expressionParser org.springframework.expression.spel.standard.SpelExpressionParser @ 0xd2ef5828                 |           16 |            32 
|- beanExpressionParserContext org.springframework.context.expression.StandardBeanExpressionResolver$1 @ 0xd2ef5838|           16 |            16 
|- expressionSuffix java.lang.String @ 0xefce43d8  }                                                               |           24 |            40 
|- expressionPrefix java.lang.String @ 0xf0ecaeb0  #{                                                              |           24 |            40 
'- Total: 7 entries                                                                                                |              |               
--------------------------------------------------------------------------------------------------------------------------------------------------

As the evaluationCache is the biggest part, I had a look at the code which uses this. The code is in the evaluate of the StandardBeanExpressionResolver, and only uses get/put. As a ConcurrentHashMap doesn't manage its content but will keep adding until all memory is gone.

If someone now asks why so many entries are added to the cache, than this is a good question. I don't exactly know how Spring-batch is using the Expression Resolver, but I do know that the expressions are changing all the time. e.g. We have the start-date of a batch in it.

I couldn't find anything yet about the best way of replacing the StandardBeanExpressionResolver with my own, the AbstractApplicationContext is setting the StandardBeanExpressionResolver.

Best wishes,
Robin

[robinkrom]

Almost forgot, we are using JBoss 4.3.0.GA_CP01_EAP

[robinkrom]

Hello,

after a long search I noticed that our Gargabage collector was set to a 72 hour time period, which is more than the application managed to work. This might have caused the huge amount of mentioned objects still being on the heap.

Although the GC should collect unreferenced objects if the memory is low, this didn't happen. Most likely due to the following reasons:

• The OutOfMemory being a native problem! (http://bugs.sun.com/view_bug.do?bug_id=4797189)
• The GC running in parallel mode, causing the application to run allong with not enoug memory-> exception- > heap dump (before it's cleared)

Anyway, our problem was the mentioned "deflater" bug, as we use iText with a wrong version. As the GC was running so infrequently the deflater allocated memory was never freed because the finalizer (see bug) was not called often enough.

I still think there is a small bug in the StandardBeanExpressionResolver, the cache should be limited. But most likely no one will run into an OutOfMemoryError because of that.

After we changed the GC to default settings, never understood why it was set this way anyway, we are now running for 11 days without the problem! This thread can be closed.

Thanks for the questions, too bad no other replies were posted.

Best wishes,
Robin