10 Replies Latest reply on Oct 9, 2014 2:58 PM by xiaodong xie

    JAX-WS handler creates high CPU load

    Markus Dlugi Newbie

      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?

        • 1. Re: JAX-WS handler creates high CPU load
          Tomaz Cerar Master

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

          • 2. Re: Re: JAX-WS handler creates high CPU load
            Markus Dlugi Newbie

            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)

            • 3. Re: Re: JAX-WS handler creates high CPU load
              Tomaz Cerar Master

              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?

              • 4. Re: Re: Re: JAX-WS handler creates high CPU load
                Markus Dlugi Newbie

                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?

                • 5. Re: Re: Re: JAX-WS handler creates high CPU load
                  aditya bhushan Newbie

                  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.

                  • 6. Re: Re: Re: JAX-WS handler creates high CPU load
                    Markus Dlugi Newbie

                    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!

                    • 7. Re: JAX-WS handler creates high CPU load
                      aditya bhushan Newbie

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

                      • 8. Re: Re: Re: JAX-WS handler creates high CPU load
                        xiaodong xie Newbie

                        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...

                        • 9. Re: JAX-WS handler creates high CPU load
                          Markus Dlugi Newbie

                          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.

                          • 10. Re: Re: Re: JAX-WS handler creates high CPU load
                            xiaodong xie Newbie

                            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.