1 Reply Latest reply on Jan 8, 2013 8:27 AM by Jens Hamisch

    JBOSS AS 5.1.0-EAP Admin Console seems to slow down resource loading

    Jens Hamisch Newbie

      Hi,

       

       

      I'm having trouble with JBOSS 5.1.0-EAP as soon as the admin-console is called the first time using the WEB-Interface.

      Login to the admin-console is not neccessary to reproduce the trouble.

       

      The problem encountered is slow loading of the Xerces classes and resources.

       

       

      I've deployed an application to JBoss AS 5.1.0-EAP which collects data from a web-service and displays those.

      After start of the AS and deployment of the application everything works fine.

      The application collects about 2000 data sets and displays them.

      This normally takes about 3-4 seconds.

       

      As soon as I navigate to the admin-console window (http://<server>:8080/admin-console) things begin to slow down dramatically.

      The same (already deployed) application now takes about 50 seconds for the same task.

       

       

      I've figured out, that the additional time is consumed (along with high CPU load) while loading some Xerces resources.

      During the 50 seconds of operation in "problem mode" the system becomes extremely loaded. This results in TCP-Buffers filled, but not

      being read, and therefor in a remarkable decrease of the TCP-Window (down to Zero-Window) on the session between the JBoss and

      the Web-Service addressed by the application. The network investigation along with the high CPU load (all in user space) precludes

      network issues and focussed to JBoss or the application as the source of the problem.

       

       

      To isolate the perfomance issue at a first glance, I've turned on JAXP Debugging.

      This shows, that loading of the resource DocumentBuilderFactory takes about 10 times longer in the bad than in the good case:

       

      Good-Case:

      15:23:57,454 ERROR [STDERR] JAXP: find factoryId =javax.xml.parsers.DocumentBuilderFactory

      15:23:57,454 ERROR [STDERR] JAXP: found jar resource …

      15:23:57,454 ERROR [STDERR] JAXP: found in resource …

      15:23:57,455 ERROR [STDERR] JAXP: created new instance of classDocumentBuilderFactoryImpl …

       

      Bad-Case:

      15:28:42,724 ERROR [STDERR] JAXP: find factoryId =javax.xml.parsers.DocumentBuilderFactory

      15:28:42,736 ERROR [STDERR] JAXP: found jar resource …

      15:28:42,737 ERROR [STDERR] JAXP: found in resource …

      15:28:42,737 ERROR [STDERR] JAXP: created new instance of classDocumentBuilderFactoryImpl …

       

       

      Further tracing boiled down the problem to the url.openStream() method called from the classloader,

      The JAXP output showed above is printed right before and after the classloader is called to load the resource.

      The classloader performing the "getResourceAsStream" method is java.lang.ClassLoader and the code involved is:

       

      public InputStream getResourceAsStream(String name) {

          URL url = getResource(name);

              return url != null ? url.openStream() : null;
          try {

          } catch( IOException e) {      
              return null;

          }

      }

       

       

      The class loader trace shows, that the "getResource" method returns quickly either in the good and the bad case.

      The additional time (and CPU) is consumed after the return from "getResource" and the return from the classloader method itsself.

      Thus url.openStream() seems to consume this.

       

      The classloader trace output in the good case is:

      (JAXP-Debug: ... find factoryId ...)

      [351507,ClassLoaderDomain,http-0.0.0.0-8080-1] ClassLoaderDomain@1128f5a{DefaultDomain} got resource from parent META-INF/services/javax.xml.parsers.DocumentBuilderFactory parent=org.jboss.bootstrap.NoAnnotationURLClassLoader@1fdc96c jar:file:/opt/EnterprisePlatform-5.1.0/jboss-eap-5.1/jboss-as/lib/endorsed/xercesImpl.jar!/META-INF/services/javax.xml.parsers.DocumentBuilderFactory

      [351507,ClassLoaderDomain,http-0.0.0.0-8080-1] ClassLoaderDomain@190d004{vfszip:/opt/EnterprisePlatform-5.1.0/jboss-eap-5.1/jboss-as/server/all/deploy/myapp.war/} got resource from parent META-INF/services/javax.xml.parsers.DocumentBuilderFactory parent=ClassLoaderDomain@1128f5a{DefaultDomain} jar:file:/opt/EnterprisePlatform-5.1.0/jboss-eap-5.1/jboss-as/lib/endorsed/xercesImpl.jar!/META-INF/services/javax.xml.parsers.DocumentBuilderFactory

      (JAXP-Debug: ... found jar resource...)

      [351507,BaseClassLoader,http-0.0.0.0-8080-1] BaseClassLoader@48e385{vfszip:/opt/EnterprisePlatform-5.1.0/jboss-eap-5.1/jboss-as/server/all/deploy/myapp.war/} loadClass org.apache.xerces.jaxp.DocumentBuilderFactoryImpl resolve=false

      [351507,BaseClassLoader,http-0.0.0.0-8080-1] BaseClassLoader@48e385{vfszip:/opt/EnterprisePlatform-5.1.0/jboss-eap-5.1/jboss-as/server/all/deploy/myapp.war/} getResource META-INF/services/org.apache.xerces.xni.parser.XMLParserConfiguration domain=ClassLoaderDomain@190d004{vfszip:/opt/EnterprisePlatform-5.1.0/jboss-eap-5.1/jboss-as/server/all/deploy/myapp.war/}

       

       

      Navigation to the admin-console results in some similar trace output:

      [756726,ClassLoaderDomain,http-0.0.0.0-8080-1] ClassLoaderDomain@1128f5a{DefaultDomain} get resource from parent META-INF/services/javax.xml.parsers.DocumentBuilderFactory parent=org.jboss.bootstrap.NoAnnotationURLClassLoader@1fdc96c

      [756726,ClassLoaderDomain,http-0.0.0.0-8080-1] ClassLoaderDomain@1128f5a{DefaultDomain} got resource from parent META-INF/services/javax.xml.parsers.DocumentBuilderFactory parent=org.jboss.bootstrap.NoAnnotationURLClassLoader@1fdc96c jar:file:/opt/EnterprisePlatform-5.1.0/jboss-eap-5.1/jboss-as/lib/endorsed/xercesImpl.jar!/META-INF/services/javax.xml.parsers.DocumentBuilderFactory

      [756726,ClassLoaderDomain,http-0.0.0.0-8080-1] ClassLoaderDomain@7502f6{org.jboss.on:loader=embedded} got resource from parent META-INF/services/javax.xml.parsers.DocumentBuilderFactory parent=ClassLoaderDomain@1128f5a{DefaultDomain} jar:file:/opt/EnterprisePlatform-5.1.0/jboss-eap-5.1/jboss-as/lib/endorsed/xercesImpl.jar!/META-INF/services/javax.xml.parsers.DocumentBuilderFactory

      (now additional time and CPU gets consumed)

      [756742,BaseClassLoader,http-0.0.0.0-8080-1] BaseClassLoader@15a349{vfsfile:/opt/EnterprisePlatform-5.1.0/jboss-eap-5.1/jboss-as/server/all/deploy/admin-console.war/} loadClass org.apache.xerces.jaxp.DocumentBuilderFactoryImpl resolve=false

      [756742,BaseClassLoader,http-0.0.0.0-8080-1] BaseClassLoader@15a349{vfsfile:/opt/EnterprisePlatform-5.1.0/jboss-eap-5.1/jboss-as/server/all/deploy/admin-console.war/} getResource META-INF/services/org.apache.xerces.xni.parser.XMLParserConfiguration domain=ClassLoaderDomain@7502f6{org.jboss.on:loader=embedded}

       

       

      However additional time and CPU becomes consumed right between the resource is found and loaded.

      From now on every subsequent loading of the DocumentBuilderFactory takes additional time. The classloader trace paints the same picture as shown for loading the admin-console. The JAXP-Debug output (found in jar resource) shows the same delay (plus additional overhead for tracing) as the class loader traces. The classloader trace output "got resource from parent" is the last statement in the method "getResource" before returning to the "getResourceAsStream" method, the JAXP debug output is printed as the first statement after return from the classloader call.

       

      The problem is reproducible to 100% by navigating to the admin-console after a restart of the JBoss AS.

      Thus admin-console could or not be the source of the problem, but definitely triggers it.

       

       

      Our environment:

      JBoss

          AS 5.1.0-EAP

      Java

          java version "1.6.0_23"

          Java(TM) SE Runtime Environment (build 1.6.0_23-b05)

          Java HotSpot(TM) Client VM (build 19.0-b09, mixed mode, sharing)

      Linux

          centos02 2.6.18-194.el5 #1 SMP Fri Apr 2 14:58:35 EDT 2010 i686 i686 i386 GNU/Linux

       

       

      Has anybody seen this before?

       

       

      Kind regards,

      Jens Hamisch