7

We recently upgraded our large webapp (running on jboss 5) from java 6 to java 7.

Within hours, we saw an OutOfMemory error, and it looks like it's the native heap which ran out.

We are running 32 bit JVM so are limited to 4GB, and the JVM was allocated 2GB.

Under java 6 the whole process occupied about 2.3GB, but with java 7 this is greatly increased, and we hit the 4GB limit without a full GC being triggered because the Java heap was still not full.

The stack trace showed that the XML unmarshalling code is creating new SAXParserFactory on each request, and the Inflater class for unzipping the jar file stores loads of data in the native heap (~200,000 Inflater instances). This strikes me as fairly inefficient - both the new SAXParserFactory and the multiple Inflaters. Maybe this is a red herring, but I don't have the java 6 version of this to compare behaviours.

By running the gc manually every few hours, the application ticks happily along for days without any problems. But that's not a solution.

The question is why has the memory allocation increased by a whopping 1.5GB, and how do I stop that happening?

I would expect a newer java version be more efficient, faster and so on. But instead we have what looks like a memory leak in the JVM.

Anyway the stack trace is as follows:

# There is insufficient memory for the Java Runtime Environment to continue.
# Native memory allocation (malloc) failed to allocate 512128 bytes for Chunk::new
# An error report file with more information is saved as:
# /opt/SP/apps/er_core/current/hs_err_pid25455.log
00:49:30,072 ERROR [[DecouplingProcessServlet]] Servlet.service() for servlet DecouplingProcessServlet threw exception
java.lang.OutOfMemoryError
    at java.util.zip.Inflater.init(Native Method)
    at java.util.zip.Inflater.<init>(Inflater.java:101)
    at java.util.zip.ZipFile.getInflater(ZipFile.java:450)
    at java.util.zip.ZipFile.getInputStream(ZipFile.java:369)
    at org.jboss.virtual.plugins.context.zip.ZipFileWrapper.openStream(ZipFileWrapper.java:214)
    at org.jboss.virtual.plugins.context.zip.ZipEntryContext.openStream(ZipEntryContext.java:1066)
    at org.jboss.virtual.plugins.context.zip.ZipEntryHandler.openStream(ZipEntryHandler.java:153)
    at org.jboss.virtual.VirtualFile.openStream(VirtualFile.java:230)
    at org.jboss.virtual.plugins.vfs.VirtualFileURLConnection.getInputStream(VirtualFileURLConnection.java:93)
    at java.net.URLClassLoader.getResourceAsStream(URLClassLoader.java:233)
    at javax.xml.parsers.SecuritySupport$4.run(SecuritySupport.java:94)
    at java.security.AccessController.doPrivileged(Native Method)
    at javax.xml.parsers.SecuritySupport.getResourceAsStream(SecuritySupport.java:87)
    at javax.xml.parsers.FactoryFinder.findJarServiceProvider(FactoryFinder.java:283)
    at javax.xml.parsers.FactoryFinder.find(FactoryFinder.java:255)
    at javax.xml.parsers.SAXParserFactory.newInstance(SAXParserFactory.java:126)
    at javax.xml.bind.helpers.AbstractUnmarshallerImpl.getXMLReader(AbstractUnmarshallerImpl.java:100)
    at javax.xml.bind.helpers.AbstractUnmarshallerImpl.unmarshal(AbstractUnmarshallerImpl.java:157)
    at javax.xml.bind.helpers.AbstractUnmarshallerImpl.unmarshal(AbstractUnmarshallerImpl.java:204)
    at com.mycompany.global.er.decoupling.util.xml.JAXBHelper.bind(JAXBHelper.java:88)
    at com.mycompany.global.er.decoupling.util.xml.JAXBHelper.bind(JAXBHelper.java:56)
    at com.mycompany.global.er.decoupling.DecouplingProcessServlet.doPost(DecouplingProcessServlet.java:163)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:235)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
    at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:190)
    at org.apache.catalina.valves.RequestFilterValve.process(RequestFilterValve.java:269)
    at org.apache.catalina.valves.RemoteAddrValve.invoke(RemoteAddrValve.java:81)
    at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:92)
    at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.java:126)
    at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
    at pk.vodafone.valves.PKAccessLogValve.invoke(PKAccessLogValve.java:547)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330)
    at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:829)
    at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:598)
    at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
    at java.lang.Thread.run(Thread.java:724)
00:49:30,117 ERROR [CoyoteAdapter] An exception or error occurred in the container during the request processing
java.lang.NoClassDefFoundError: javax/servlet/ServletRequestAttributeEvent
    at org.apache.catalina.connector.Request.setAttribute(Request.java:1452)
    at org.apache.catalina.core.StandardWrapperValve.exception(StandardWrapperValve.java:523)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:280)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
    at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:190)
    at org.apache.catalina.valves.RequestFilterValve.process(RequestFilterValve.java:269)
    at org.apache.catalina.valves.RemoteAddrValve.invoke(RemoteAddrValve.java:81)
    at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:92)
    at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.java:126)
    at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
    at pk.vodafone.valves.PKAccessLogValve.invoke(PKAccessLogValve.java:547)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330)
    at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:829)
    at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:598)
    at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
    at java.lang.Thread.run(Thread.java:724)
Caused by: java.lang.ClassNotFoundException: Unexpected error during load of: javax.servlet.ServletRequestAttributeEvent, msg=null
    at org.jboss.classloader.spi.base.ClassLoaderManager.process(ClassLoaderManager.java:173)
    at org.jboss.classloader.spi.base.BaseClassLoaderDomain.loadClass(BaseClassLoaderDomain.java:259)
    at org.jboss.classloader.spi.base.BaseClassLoaderDomain.loadClass(BaseClassLoaderDomain.java:1102)
    at org.jboss.classloader.spi.base.BaseClassLoader.loadClassFromDomain(BaseClassLoader.java:772)
    at org.jboss.classloader.spi.base.BaseClassLoader.loadClass(BaseClassLoader.java:415)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
    ... 19 more
Caused by: java.lang.OutOfMemoryError
    at java.util.zip.Inflater.init(Native Method)
    at java.util.zip.Inflater.<init>(Inflater.java:101)
    at java.util.zip.ZipFile.getInflater(ZipFile.java:450)
    at java.util.zip.ZipFile.getInputStream(ZipFile.java:369)
    at org.jboss.virtual.plugins.context.zip.ZipFileWrapper.openStream(ZipFileWrapper.java:214)
    at org.jboss.virtual.plugins.context.zip.ZipEntryContext.openStream(ZipEntryContext.java:1066)
    at org.jboss.virtual.plugins.context.zip.ZipEntryHandler.openStream(ZipEntryHandler.java:153)
    at org.jboss.virtual.VirtualFile.openStream(VirtualFile.java:230)
    at org.jboss.classloading.spi.vfs.policy.VFSClassLoaderPolicy.getResourceAsStream(VFSClassLoaderPolicy.java:483)
    at org.jboss.classloader.spi.base.BaseClassLoader$2.run(BaseClassLoader.java:508)
    at org.jboss.classloader.spi.base.BaseClassLoader$2.run(BaseClassLoader.java:506)
    at java.security.AccessController.doPrivileged(Native Method)
    at org.jboss.classloader.spi.base.BaseClassLoader.loadClassLocally(BaseClassLoader.java:504)
    at org.jboss.classloader.spi.base.BaseClassLoader.loadClassLocally(BaseClassLoader.java:481)
    at org.jboss.classloader.spi.base.BaseDelegateLoader.loadClass(BaseDelegateLoader.java:134)
    at org.jboss.classloader.spi.filter.FilteredDelegateLoader.loadClass(FilteredDelegateLoader.java:131)
    at org.jboss.classloader.spi.base.ClassLoadingTask$ThreadTask.run(ClassLoadingTask.java:452)
    at org.jboss.classloader.spi.base.ClassLoaderManager.nextTask(ClassLoaderManager.java:258)
    at org.jboss.classloader.spi.base.ClassLoaderManager.process(ClassLoaderManager.java:152)
    ... 24 more
[thread 123611 also had an error]

A couple of useful links I found on this topic:

http://practicalcloudcomputing.com/post/444939181/outofmemoryjnigzip

http://www.javacodegeeks.com/2013/01/java-heap-space-native-heap-and-memory-problems.html

JVM options are as follows:

-server -Xms2048m -Xmx2048m -XX:NewSize=384m 
-XX:MaxNewSize=384m 
-XX:SurvivorRatio=4 
-XX:MinHeapFreeRatio=11 
-XX:PermSize=80m 
-verbose:gc 
-XX:+PrintGCDateStamps 
-XX:+PrintGCDetails 
-XX:+DisableExplicitGC 
-Djava.awt.headless=TRUE -DUseSunHttpHandler=TRUE -Dsun.net.client.defaultConnectTimeout=25000 
-Dsun.net.client.defaultReadTimeout=50000 
-Dfile.encoding=UTF-8 
-Xloggc:gc.log 
Dcom.sun.management.jmxremote.port=9003 
-Dcom.sun.management.jmxremote.authenticate=FALSE 
-Dcom.sun.management.jmxremote.ssl=FALSE 
-Duser.language=de 
-Duser.region=DE 
-Duser.country=DE 
-Djboss.vfs.cache.TimedPolicyCaching.lifetime=1440000 
-DVFjavaWL=er.core.de

Update

A bit more analysis. Here's my naive interpretation of what's happening with the xml parsing:

  1. We have a singleton JAXBHelper class, with an instance-level JAXBContext (this is a threadsafe object).
  2. Every time a request comes in, we attempt to bind the incoming xml string to a Java object (generated previously by JAXB from the xsd).
  3. The bind method creates an instance-level unmarshaller (these are not threadsafe, but cheap to create).
  4. The bind method then calls the unmarshaller's unmarshal(InputStream) method.
  5. Now the javax.xml.bind.helpers.AbstractUnmarshallerImpl then calls SAXParserFactory.newInstance, which in turn calls a classloader, which in turn requires an Inflater.

Surely the implementation (we're using jaxb-ri 2.2.7) should keep the SAXParserFactory or the SAXParser and re-use them? I note that neither are threadsafe, so it could be done with a ThreadLocal. Or could the Inflater instances be re-used?

Does that fact that these are not being re-used mean that I'm not dereferencing my objects? The UnMarshaller doesn't seem to have any kind of close method.

mdarwin
  • 1,684
  • 7
  • 28
  • 72
  • So, you found a solution (running gc). What is the question, then? – RealSkeptic Jan 26 '15 at 11:01
  • 2
    Running gc manually every 4 hours is not a solution, it's a workaround. – mdarwin Jan 26 '15 at 11:09
  • But still, you don't have a question there. You are just describing a state of affairs. Assuming we can't change Java 7's native code, what do you expect as an answer? – RealSkeptic Jan 26 '15 at 11:13
  • @RealSkeptic you fit your name :p The fact of the matter is that someone in the vast SO crowd may have encountered, and cured, this problem... Anyway, is there a way to use another XML parser implementation? – fge Jan 26 '15 at 11:17
  • I have added a question. Ideally an answer would explain why this memory leak is happening and give me a way to fix it – mdarwin Jan 26 '15 at 11:19
  • Show us your list of JVM options and hs_err.log if possible. – apangin Jan 26 '15 at 11:22
  • OK. I think the first link you added explains why this is happening: memory is released in finalize(), finalize() is not called until major gc. Now that you have a more efficient JVM, it does not overrun the java heap, therefore does not call gc, which the less efficient Java 6 probably did. Can't offer a non-workaround solution, though. – RealSkeptic Jan 26 '15 at 11:41
  • Let's try a different angle, though: why is it unzipping so much? Can you elaborate on what exactly is being unzipped and why? Perhaps you can use whatever it is without compression. – RealSkeptic Jan 26 '15 at 11:50
  • @RealSkeptic I have added some analysis. And yes I had reached a similar conclusion - that it could be a symptom of the new JVM being more efficient. But why are these Inflater objects being created in such large numbers, and not re-used or dereferenced? – mdarwin Jan 26 '15 at 12:14
  • Why don't you parse the XML yourself prior to giving it to JAXB? You could then manage XML Parsers (StAX/SAX/DOM) as you see fit. This does not answer the OOME question but will probably give you a reliable solution. – lexicore Jan 26 '15 at 12:24
  • @lexicore I'm not sure I understand your idea - can you elaborate? – mdarwin Jan 26 '15 at 12:27
  • 1
    @mdarwin You unmarshall an input stream now. So JAXB under the hood creates a parser and parses the XML and the processes the output (via SAX). Why don't you create a SAX or StAX or whatever parser factory, parse the XML and feed the result to JAXB for unmarshalling? Take an StAX parser and feed the XMLWhateverReader (don't remember how it's called) to JAXB. You won't be loading the `SAXParserFactory` on each request then, right? So you'll workaround the problem. Anyway my point is that if you overtake the parser management from JAXB you may be able to control it better / more efficiently. – lexicore Jan 26 '15 at 12:35
  • How about pooling the marshallers/unmarshallers as described in [this article](http://blog.zont.eu/2012/02/jaxb-and-commons-pool.html)? This will limit the number of new ones you are creating, and, supposedly, the number of their calls to their class loaders. – RealSkeptic Jan 26 '15 at 12:37
  • @RealSkeptic I have never seen guarantees that marshallers/unmarshallers are reusable. So it's tecnically not safe to pool them. – lexicore Jan 26 '15 at 12:46
  • Well, it says [here](https://jaxb.java.net/guide/Performance_and_thread_safety.html) that pooling them is allowed. They are not thread-safe, but they *are* reentrant. – RealSkeptic Jan 26 '15 at 12:52
  • @lexicore thanks for the clarification. I think I have already done this, but it's not enabled in prod. The code can optionally create a XMLStreamReader (from an XMLInputFactory) for the input string, then pass it to the unmarshal method. Now I need to persuade the Ops team to switch it on... – mdarwin Jan 26 '15 at 12:57
  • @RealSkeptic That guide is unofficial and quite old, not written/supported by the current JAXB dev team AFAIK... – lexicore Jan 26 '15 at 13:09
  • 1
    @lexicore [Here](https://jaxb.java.net/2.2.7/docs/release-documentation.html#d0e4072) is the documentation for ri 2.2.7, which says, and I quote: *Different threads may reuse one Unmarshaller instance, as long as you don't use one instance from two threads at the same time.* – RealSkeptic Jan 26 '15 at 13:26

1 Answers1

2

The memory leak is caused by Inflaters that are not closed.
It looks like these Inflaters fall down to Old Generation and their finalizers are not called as long as Full GC is not triggered.

In order to prevent JRE from scanning through all JAR files looking for SAXParserFactory, you may create $JAVA_HOME/jre/lib/jaxp.properties file containing the following line:

javax.xml.parsers.SAXParserFactory=com.sun.org.apache.xerces.internal.jaxp.SAXParserFactoryImpl

It might be also useful to remove -XX:+DisableExplicitGC option since JVM runtime depends on System.gc call when it detects a shortage of native memory.

apangin
  • 92,924
  • 10
  • 193
  • 247
  • Thanks, I will ask the Ops guys to try this out, and let you know if it works. – mdarwin Jan 26 '15 at 14:29
  • Do you have some documentation / link to back up your statement "JVM runtime depends on System.gc call when it detects a shortage of native memory." ? I can show this to the ops guys (who want to keep the DisableExplicitGC flag) – mdarwin Jan 26 '15 at 17:02
  • @mdarwin E.g. [Bits.reserveMemory](http://hg.openjdk.java.net/jdk7u/jdk7u/jdk/file/70e3553d9d6e/src/share/classes/java/nio/Bits.java#l629) and [FileChannelImpl.map](http://hg.openjdk.java.net/jdk7u/jdk7u/jdk/file/70e3553d9d6e/src/share/classes/sun/nio/ch/FileChannelImpl.java#l903) call `System.gc` to force object finalization if native `mmap` or `malloc` fail. – apangin Jan 26 '15 at 18:28