14 Replies Latest reply on Aug 19, 2013 9:53 AM by mattdarwin

Crazy performance issue with JBossWS

jbonham100 Sep 13, 2010 11:04 AM

Hi all

I have a bottom-up JAX-WS web service deployed in JBoss. I was running some performance tests at different volumes and I ran into this issue: exactly one hour after the first request, the performance drops dramatically and garbage collection goes off the roof. I took some thread dumps and most HTTP threads are stuck trying to open a class for JBossWSEntityResolver. Our code is not even reached. Has anyone seen anything like it?

Here's the thread dump for one of the threads, they look pretty much the same:

"http-0.0.0.0-8080-149" daemon prio=10 tid=0x0000002b4245b000 nid=0x4e84 runnable [0x000000004958e000]
   java.lang.Thread.State: RUNNABLE
        at java.util.zip.ZipFile.freeEntry(Native Method)
        at java.util.zip.ZipFile.access$800(ZipFile.java:29)
        at java.util.zip.ZipFile$2.nextElement(ZipFile.java:330)
        - locked <0x0000002a99c1e280> (a java.util.zip.ZipFile)
        at java.util.zip.ZipFile$2.nextElement(ZipFile.java:299)
        at org.jboss.virtual.plugins.context.zip.ZipEntryContext.initEntries(ZipEntryContext.java:491)
        - locked <0x0000002a99c1ba90> (a org.jboss.virtual.plugins.context.zip.ZipEntryContext)
        at org.jboss.virtual.plugins.context.zip.ZipEntryContext.ensureEntries(ZipEntryContext.java:619)
        - locked <0x0000002a99c1ba90> (a org.jboss.virtual.plugins.context.zip.ZipEntryContext)
        at org.jboss.virtual.plugins.context.zip.ZipEntryContext.checkIfModified(ZipEntryContext.java:773)
        - locked <0x0000002a99c1ba90> (a org.jboss.virtual.plugins.context.zip.ZipEntryContext)
        at org.jboss.virtual.plugins.context.zip.ZipEntryContext.getChild(ZipEntryContext.java:817)
        at org.jboss.virtual.plugins.context.zip.ZipEntryHandler.createChildHandler(ZipEntryHandler.java:191)
        at org.jboss.virtual.plugins.context.AbstractVirtualFileHandler.structuredFindChild(AbstractVirtualFileHandler.java:684)
        at org.jboss.virtual.plugins.context.zip.ZipEntryHandler.getChild(ZipEntryHandler.java:165)
        at org.jboss.virtual.plugins.context.DelegatingHandler.getChild(DelegatingHandler.java:107)
        at org.jboss.virtual.VirtualFile.findChild(VirtualFile.java:457)
        at org.jboss.virtual.plugins.vfs.VirtualFileURLConnection.resolveVirtualFile(VirtualFileURLConnection.java:106)
        at org.jboss.virtual.plugins.vfs.VirtualFileURLConnection.getVirtualFile(VirtualFileURLConnection.java:118)
        - locked <0x0000002a99c19a98> (a org.jboss.virtual.plugins.vfs.VirtualFileURLConnection)
        at org.jboss.virtual.plugins.vfs.VirtualFileURLConnection.getInputStream(VirtualFileURLConnection.java:93)
        at java.net.URL.openStream(URL.java:1010)
        at java.lang.ClassLoader.getResourceAsStream(ClassLoader.java:1195)
        at org.jboss.ws.core.utils.JBossWSEntityResolver$1.run(JBossWSEntityResolver.java:80)
        at org.jboss.ws.core.utils.JBossWSEntityResolver$1.run(JBossWSEntityResolver.java:78)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.jboss.ws.core.utils.JBossWSEntityResolver.loadEntitiesMappingFromClasspath(JBossWSEntityResolver.java:76)
        at org.jboss.ws.core.utils.JBossWSEntityResolver.<init>(JBossWSEntityResolver.java:59)
        at org.jboss.ws.core.utils.JBossWSEntityResolver.<init>(JBossWSEntityResolver.java:51)
        at sun.reflect.GeneratedConstructorAccessor180.newInstance(Unknown Source)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
        at java.lang.Class.newInstance0(Class.java:355)
        at java.lang.Class.newInstance(Class.java:308)
        at org.jboss.wsf.common.DOMUtils$1.setEntityResolver(DOMUtils.java:121)
        at org.jboss.wsf.common.DOMUtils$1.initialValue(DOMUtils.java:101)
        at org.jboss.wsf.common.DOMUtils$1.initialValue(DOMUtils.java:110)
        at java.lang.ThreadLocal.setInitialValue(ThreadLocal.java:141)
        at java.lang.ThreadLocal.get(ThreadLocal.java:131)
        at org.jboss.wsf.common.DOMUtils.getDocumentBuilder(DOMUtils.java:149)
        at org.jboss.wsf.common.DOMUtils.getOwnerDocument(DOMUtils.java:690)
        at org.jboss.ws.core.soap.SOAPDocument.<init>(SOAPDocument.java:54)
        at org.jboss.ws.core.soap.SOAPPartImpl.<init>(SOAPPartImpl.java:75)
        at org.jboss.ws.core.soap.SOAPMessageImpl.<init>(SOAPMessageImpl.java:86)
        at org.jboss.ws.core.soap.MessageFactoryImpl.createMessage(MessageFactoryImpl.java:215)
        at org.jboss.ws.core.soap.MessageFactoryImpl.createMessage(MessageFactoryImpl.java:193)
        at org.jboss.wsf.stack.jbws.RequestHandlerImpl.processRequest(RequestHandlerImpl.java:455)
        at org.jboss.wsf.stack.jbws.RequestHandlerImpl.handleRequest(RequestHandlerImpl.java:295)
        at org.jboss.wsf.stack.jbws.RequestHandlerImpl.doPost(RequestHandlerImpl.java:205)
        at org.jboss.wsf.stack.jbws.RequestHandlerImpl.handleHttpRequest(RequestHandlerImpl.java:131)

        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.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 org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158)
        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:619)

Thanks in advance

Andre

1. Re: Crazy performance issue with JBossWS

peterj Sep 15, 2010 11:28 AM (in response to jbonham100)

exactly one hour after the first request, the performance drops dramatically and garbage collection goes off the roof.

After one hour? That is interesting. These options in the run script sets the RMI cleanup thread to run a full GC every hour:
-Dsun.rmi.dgc.client.gcInterval=3600000 -Dsun.rmi.dgc.server.gcInterval=3600000
Try adding a 0 (or 00) to the end of each to increase the delay time. Or add -XX:+DisableExplicitGC to turn it off completely.
(By the way, I know why the RMI GC interval is set to 1 hour - it was set to that for a spoecific test environment but in production that is the wrong time interval.)

The other thing you could do is turn on -verbose:gc and track the garbage collections. You will have to graph the output to see what is going on.
For suggestions on how to gather GC data and analyze it, see these white papers:
Java Garbage Collection Statistical Analysis 101
Java Garbage Collection Performance Analysis 201
at http://www.cmg.org/cgi-bin/search.cgi?q=java+peter+johnson&x=30&y=10
Actions
2. Re: Crazy performance issue with JBossWS

jozsef_attila Oct 5, 2010 5:09 AM (in response to jbonham100)

Hi Andre,

Any luck with this?

Thanks.
Actions
3. Re: Crazy performance issue with JBossWS

jbonham100 Oct 7, 2010 10:11 AM (in response to jozsef_attila)

No luck. I'm already running with -XX:+DisableExplicitGC. -verbose:gc shows GC going off the hook exactly one hour after the first request.

Andre
Actions
4. Re: Crazy performance issue with JBossWS

peterj Oct 7, 2010 11:38 AM (in response to jbonham100)

Did you read the white papers I referenced? If so, I would have expected that you would have provided a lot more information than "shows GC going off the hook".
Actions
5. Re: Crazy performance issue with JBossWS

jbonham100 Oct 7, 2010 1:57 PM (in response to peterj)

I'm attaching some charts to show what's going on. This only happens when we use the SOAP endpoint. jstat collects every 30 seconds.
Actions
6. Re: Crazy performance issue with JBossWS

jbonham100 Oct 7, 2010 2:25 PM (in response to jbonham100)

As a comparison, the exact same test on the REST endoint:
Actions
7. Re: Crazy performance issue with JBossWS

jozsef_attila Oct 21, 2010 5:01 AM (in response to jbonham100)

Hi,

These is exactly what I am experiencing too. Exactly one hour after the first web service call. Could not find the reason yet.

brgds,
Jozsef
Actions
8. Re: Crazy performance issue with JBossWS

baradon Oct 25, 2010 3:35 AM (in response to jbonham100)

Hi,

any updates on this issue? Any workaround possible? We are fighting with (apparently) the same problem here.

BR,

Heiner
Actions
9. Re: Crazy performance issue with JBossWS

baradon Oct 26, 2010 2:47 AM (in response to baradon)

For the records: Updating the WS-stack to jbossws-native-3.3.1 solves the issue.

BR,

Heiner
Actions
10. Re: Crazy performance issue with JBossWS

jozsef_attila Oct 28, 2010 5:50 AM (in response to baradon)

Hi Heiner,

Thanks for the update, nice work Indeed, patching JBoss with jbossws-native-3.3.1.GA completetely solves the issue.
Some other issues I have been experiencing (in addition to the GC problem) that this patch fixes are:
- unnamed event handle leak...
- ...causing native memory leak...
- ...causing increase in the process size until JVM crashes.

brgds,
Jozsef
Actions
11. Re: Crazy performance issue with JBossWS

bushurui Apr 28, 2011 10:34 AM (in response to jbonham100)

Hi,all

can anybody kindly tell me ,what test tool did Andre used to record the test result ?

best regards!

sury
Actions
12. Re: Crazy performance issue with JBossWS

jbonham100 Apr 28, 2011 7:47 PM (in response to bushurui)

Hi Sury

I just wrote a bunch of scripts to parse the data from the log files and used gnuplot to generate the charts.

Andre
Actions
13. Re: Crazy performance issue with JBossWS

bushurui May 2, 2011 11:46 PM (in response to jbonham100)

Hi,Andre

Thank you for tell this.By the way, i can successfully update jbossws-native-3.3.1 in jboss-5.1.0.GA with jdk1.6

is there anyway to update it to jboss-5.1.0.GA under jdk1.5?

thanks,

sury
Actions
14. Re: Crazy performance issue with JBossWS

mattdarwin Aug 19, 2013 9:53 AM (in response to baradon)

Hi,

Can anyone tell me the official way to patch jboss to jbossws-native-3.3.1 ?

I did it by downloading this file and then following the instructions I found here:

http://docs.jboss.org/teiid/7.2.0.Final/admin-guide/en-US/html/installation.html

Is that right?
Actions

Go to original post