JAX-WS handler creates high CPU load

[markusdlugi]

I'm having a problem with JAX-WS handlers in WildFly. When adding a handler to a web service client which is used by many threads, the application server uses nearly 100% of the CPU. This is not a problem of the handler code, as this occurs even if the handler is completely empty. When I remove the handler, the web service calls go through with barely generating any load.

I have created a small test application to reproduce the issue (see attachment). It consists of 3 identical web services and a client which creates 1000 threads that keep on calling the services. Most importantly, the web service clients which have been generated by wsimport are annotated with @HandlerChain, referencing a virtually empty JAX-WS handler. Running the application with the annotations results in high CPU load, while removal of the annotations results in minimal CPU load.

I have tested this on JBoss 7.1.1 and WildFly 8.1.0 and both have this issue. I don't think it is a configuration issue, as this also occurs when using the standard configuration. Interestingly, I have not been able to reproduce the problem on my notebook running Windows 8 - the issue only occurs on our IBM Server (IBM System x3550 M3, 12 x 2.4 GHz + Hyper-Threading, 96GB RAM on openSUSE 12.3 64-bit).

Can anybody else reproduce this issue? Is this a bug?

[ctomc]

Any chance you can produce thread dump when you get 100% cpu load, so we can see where the cpu is spending time

[markusdlugi]

I have attached the full output of jstack to the original post. I also used top to get the threads with the most CPU demand, and in 90% of cases, the top thread was in one of the following two states:

"Thread-771" daemon prio=10 tid=0x00007f496c462800 nid=0x7cd9 runnable [0x00007f47a5352000]

   java.lang.Thread.State: RUNNABLE

  at org.apache.cxf.phase.PhaseInterceptorChain.insertInterceptor(PhaseInterceptorChain.java:494)

  at org.apache.cxf.phase.PhaseInterceptorChain.add(PhaseInterceptorChain.java:208)

  at org.apache.cxf.phase.PhaseInterceptorChain.add(PhaseInterceptorChain.java:185)

  at org.apache.cxf.phase.PhaseInterceptorChain.add(PhaseInterceptorChain.java:176)

  at org.apache.cxf.phase.PhaseChainCache.getChain(PhaseChainCache.java:93)

  at org.apache.cxf.phase.PhaseChainCache.get(PhaseChainCache.java:77)

  at org.apache.cxf.endpoint.ClientImpl.onMessage(ClientImpl.java:744)

  at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponseInternal(HTTPConduit.java:1694)

  at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponse(HTTPConduit.java:1530)

  at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.close(HTTPConduit.java:1438)

  at org.apache.cxf.transport.AbstractConduit.close(AbstractConduit.java:56)

  at org.apache.cxf.transport.http.HTTPConduit.close(HTTPConduit.java:659)

  at org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:62)

  at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:262)

  - locked <0x000000069573afc8> (a org.apache.cxf.phase.PhaseInterceptorChain)

  at org.apache.cxf.endpoint.ClientImpl.doInvoke(ClientImpl.java:530)

  at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:463)

  at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:366)

  at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:319)

  at org.apache.cxf.frontend.ClientProxy.invokeSync(ClientProxy.java:96)

  at org.apache.cxf.jaxws.JaxWsClientProxy.invoke(JaxWsClientProxy.java:134)

  at com.sun.proxy.$Proxy61.test(Unknown Source)

  at org.test.client.TestClient.run(TestClient.java:32)

"Thread-761" daemon prio=10 tid=0x00007f496c2b3000 nid=0x7ccf waiting for monitor entry [0x00007f47a5d5c000]

   java.lang.Thread.State: BLOCKED (on object monitor)

  at sun.net.www.http.KeepAliveCache.put(KeepAliveCache.java:80)

  - waiting to lock <0x0000000680dc6388> (a sun.net.www.http.KeepAliveCache)

  at sun.net.www.http.HttpClient.putInKeepAliveCache(HttpClient.java:353)

  - locked <0x0000000692ca8830> (a sun.net.www.http.HttpClient)

  at sun.net.www.http.HttpClient.finished(HttpClient.java:341)

  at sun.net.www.http.KeepAliveStream.close(KeepAliveStream.java:100)

  at sun.net.www.MeteredStream.justRead(MeteredStream.java:93)

  at sun.net.www.MeteredStream.read(MeteredStream.java:135)

  - locked <0x00000007882ca8a8> (a sun.net.www.http.KeepAliveStream)

  at java.io.FilterInputStream.read(FilterInputStream.java:133)

  at sun.net.www.protocol.http.HttpURLConnection$HttpInputStream.read(HttpURLConnection.java:3052)

  at com.ctc.wstx.io.BaseReader.readBytes(BaseReader.java:155)

  at com.ctc.wstx.io.UTF8Reader.loadMore(UTF8Reader.java:368)

  at com.ctc.wstx.io.UTF8Reader.read(UTF8Reader.java:111)

  at com.ctc.wstx.io.ReaderBootstrapper.initialLoad(ReaderBootstrapper.java:250)

  at com.ctc.wstx.io.ReaderBootstrapper.bootstrapInput(ReaderBootstrapper.java:133)

  at com.ctc.wstx.stax.WstxInputFactory.doCreateSR(WstxInputFactory.java:531)

  at com.ctc.wstx.stax.WstxInputFactory.createSR(WstxInputFactory.java:585)

  at com.ctc.wstx.stax.WstxInputFactory.createSR(WstxInputFactory.java:610)

  at com.ctc.wstx.stax.WstxInputFactory.createXMLStreamReader(WstxInputFactory.java:316)

  at __redirected.__XMLInputFactory.createXMLStreamReader(__XMLInputFactory.java:139)

  at org.apache.cxf.staxutils.StaxUtils.createXMLStreamReader(StaxUtils.java:1260)

  at org.apache.cxf.interceptor.StaxInInterceptor.handleMessage(StaxInInterceptor.java:112)

  at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:262)

  - locked <0x00000007afc4d510> (a org.apache.cxf.phase.PhaseInterceptorChain)

  at org.apache.cxf.endpoint.ClientImpl.onMessage(ClientImpl.java:800)

  at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponseInternal(HTTPConduit.java:1694)

  at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponse(HTTPConduit.java:1530)

  at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.close(HTTPConduit.java:1438)

  at org.apache.cxf.transport.AbstractConduit.close(AbstractConduit.java:56)

  at org.apache.cxf.transport.http.HTTPConduit.close(HTTPConduit.java:659)

  at org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:62)

  at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:262)

  - locked <0x0000000785e24a68> (a org.apache.cxf.phase.PhaseInterceptorChain)

  at org.apache.cxf.endpoint.ClientImpl.doInvoke(ClientImpl.java:530)

  at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:463)

  at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:366)

  at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:319)

  at org.apache.cxf.frontend.ClientProxy.invokeSync(ClientProxy.java:96)

  at org.apache.cxf.jaxws.JaxWsClientProxy.invoke(JaxWsClientProxy.java:134)

  at com.sun.proxy.$Proxy60.test(Unknown Source)

  at org.test.client.TestClient.run(TestClient.java:31)

[ctomc]

Hi,

that jstack report is from jboss as 7.x not from wildfly 8....

also JVM used looks quite old. can you try it on JDK7 u45 or newer?

[markusdlugi]

Sorry for not responding earlier, I was being sick.

Anyway, I ran the test application again, this time on WildFly 8.1.0 and JDK 1.7.0_51. Full jstack report is attached, but it didn't change much - it's still the insertInterceptor method and KeepAliveCache handling that seems to create highest CPU demand. Any ideas?

[adityamcadu]

I am facing the exact same issue with JBoss EAP 6.3 (based on JBoss 7.3 i guess). As soon as i remove the handler chain, the CPU usage goes down. This is affecting our production environment, and I will open a support case with RedHat (we have enterprise support). I hope you don't mind if I refer to this post and have them use the test scenario you have created.

[markusdlugi]

Of course you can use my test application, I don't mind. I'd be really curious about the outcome though, so please post a small update if you find out something!

[adityamcadu]

Opened a RedHat support case for the issue. Will keep the post updated once I get a response

[xxd]

Hello, Markus,

I checked the thread dump you uploaded, why there were so many threads out there? And many of them were waiting (327) for a lock. You know, this kind of blocking is quite performance consuming...

[markusdlugi]

Hello,

Thanks for having a look. The reason for so many threads is that there are in fact 1000 client threads accessing the web services in my test application. I know that's a lot of threads, but that's part of the (already existing) application for which we are developing the SOAP handler, so I have no influence on that. Interestingly, the performance is perfectly fine when I don't use a SOAP handler (around 10% CPU usage), but drops drastically when adding the SOAP handler (nearly 100% CPU usage), although the SOAP handler does nothing really. I don't know why there is so much blocking happening - my personal assumption is that there might be some kind of livelock in the code invoking the handler. However, I don't know anything about that code, so I'd be really grateful if someone with more knowledge could have a look at it.

[xxd]

Hello, Markus,

Thanks for the information. Here is just some my wild guessing, could you please rerun your test with this JVM option - "-Dhttp.maxConnections=500"?

Thanks a lot.