Slowness / Memory issues when starting JBoss with many JSF 2 apps on java 8 where "ZipFileInflaterInputStream" count is growing and pending finalization

Solution Unverified - Updated

Environment

  • JBoss Enterprise Application Platform (EAP)
    • 6.x
    • 7.x
  • JSF 2.x
  • Java 8

Issue

  • When starting many JSF apps together, we see start up times severely degrade moving to JSF 2 from JSF 1.2. This leads to Full GC thrashing and possibly even a full OOME. There are a large number of threads actively starting different deployments in jsf initialization like below:
Thread 0x65e468a38
  at java.util.zip.ZipFile.getEntry(J[BZ)J (Native Method)^M
  at java.util.zip.ZipFile.getInputStream(Ljava/util/zip/ZipEntry;)Ljava/io/InputStream; (ZipFile.java:374)^M
  at java.util.jar.JarFile.getInputStream(Ljava/util/zip/ZipEntry;)Ljava/io/InputStream; (JarFile.java:467)^M
  at org.jboss.vfs.spi.JavaZipFileSystem.openInputStream(Lorg/jboss/vfs/VirtualFile;Lorg/jboss/vfs/VirtualFile;)Ljava/io/InputStream; (JavaZipFileSystem.java:182)^M
  at org.jboss.vfs.VirtualFile.openStream()Ljava/io/InputStream; (VirtualFile.java:318)^M
  at org.jboss.vfs.VirtualJarInputStream.openCurrent(Lorg/jboss/vfs/VirtualFile;)V (VirtualJarInputStream.java:223)^M
  at org.jboss.vfs.VirtualJarInputStream.getNextJarEntry()Ljava/util/jar/JarEntry; (VirtualJarInputStream.java:109)^M
  at org.jboss.vfs.VirtualJarInputStream.getNextEntry()Ljava/util/zip/ZipEntry; (VirtualJarInputStream.java:80)^M
  at com.sun.faces.facelets.util.Classpath.searchFromURL(Ljava/util/Set;Ljava/lang/String;Ljava/lang/String;Ljava/net/URL;)V (Classpath.java:175)^M
  at com.sun.faces.facelets.util.Classpath.searchFromURL(Ljava/util/Set;Ljava/lang/String;Ljava/lang/String;Ljava/net/URL;)V (Classpath.java:198)^M
  at com.sun.faces.facelets.util.Classpath.search(Ljava/lang/ClassLoader;Ljava/lang/String;Ljava/lang/String;Lcom/sun/faces/facelets/util/Classpath$SearchAdvice;)[Ljava/net/URL; (Classpath.java:114)^M
  at com.sun.faces.facelets.util.Classpath.search(Ljava/lang/String;Ljava/lang/String;)[Ljava/net/URL; (Classpath.java:68)^M
  at com.sun.faces.config.configprovider.MetaInfFacesConfigResourceProvider.loadURLs(Ljavax/servlet/ServletContext;)Ljava/util/Collection; (MetaInfFacesConfigResourceProvider.java:143)^M
  at com.sun.faces.config.configprovider.MetaInfFacesConfigResourceProvider.getResources(Ljavax/servlet/ServletContext;)Ljava/util/Collection; (MetaInfFacesConfigResourceProvider.java:87)^M
  at com.sun.faces.config.manager.tasks.FindConfigResourceURIsTask.call()Ljava/util/Collection; (FindConfigResourceURIsTask.java:72)^M
  at com.sun.faces.config.manager.tasks.FindConfigResourceURIsTask.call()Ljava/lang/Object; (FindConfigResourceURIsTask.java:40)^M
  at java.util.concurrent.FutureTask.run()V (FutureTask.java:266)^M
  at com.sun.faces.config.manager.Documents.getXMLDocuments(Ljavax/servlet/ServletContext;Ljava/util/List;Ljava/util/concurrent/ExecutorService;Z)[Lcom/sun/faces/config/manager/documents/DocumentInfo; (Documents.java:82)^M
  at com.sun.faces.config.ConfigManager.initialize(Ljavax/servlet/ServletContext;Lcom/sun/faces/config/InitFacesContext;)V (ConfigManager.java:266)^M
  at com.sun.faces.config.ConfigureListener.contextInitialized(Ljavax/servlet/ServletContextEvent;)V (ConfigureListener.java:205)^M
  at io.undertow.servlet.core.ApplicationListeners.contextInitialized()V (ApplicationListeners.java:187)^M
  • The heap is filling with already closed ZipFileInflaterInputStreams pending finalization:
Class Name                                      |   Objects | Shallow Heap |    Retained Heap
----------------------------------------------------------------------------------------------
java.lang.ref.Finalizer                         | 1,969,458 |   78,778,320 | >= 3,919,937,544
java.util.zip.ZipFile$ZipFileInflaterInputStream|   958,440 |   53,672,640 | >= 3,781,229,064
----------------------------------------------------------------------------------------------

Resolution

Root Cause

Search for all resources that match either “META-INF/faces-config.xml” or end with “.faces-config.xml” directly in the “META-INF” directory. Each resource that matches that expression must be considered an application configuration resource.

That's why JSF 2.x now opens up all the jars and starts scanning their content. That was added in Content from github.com is not included.this old commit. That resulting jar scanning activity churns up ZipFileInflaterInputStreams through its JBoss VFS calls. Those are closed when done with, but they still potentially keep empty byte[] buf references for non-negligible heap overhead and then persist in heap awaiting finalization when running on java 8. A JVM only has one finalizer thread to then do that finalization so the number of JSF apps and the concurrency of their start up and ZipFileInflaterInputStreams they produce for finalization then can outpace the rate at which the JVM finalizer thread can finalize them. That then leads to ZipFileInflaterInputStreams accumulating in heap pending finalization to the point that their heap overhead results in GC thrashing and possibly a full OOME. Java 11 improves this by removing the finalize call from ZipFileInflaterInputStreams and replacing it with a Cleaner that is removed with any explicit ZipFileInflaterInputStream.close call, thereby avoiding any accumulation under higher ZipFileInflaterInputStream concurrency.

Diagnostic Steps

  • Capture GC logs and a heap dump during deployment slowness.
SBR
Product(s)
Components
Category
Tags

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.