Axis2
  1. Axis2
  2. AXIS2-4629

Poor performance in 1.5.1 due to threads waiting on monitor for synchronized jre method

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Critical Critical
    • Resolution: Duplicate
    • Affects Version/s: 1.5.1
    • Fix Version/s: None
    • Component/s: adb
    • Labels:
      None
    • Environment:
      RedHat 5.4, Solaris 10

      Description

      We recently upgraded from axis2 1.4.1to 1.5.1 and with no changes to our java methods which are exposed using axis we have seen a significant drop in performance from around 500-600 TPS to 50 TPS at most. We took a jstack while load is on our system and can see alot of threads blocked waiting for an object monitor to enter the private method java.beans.Introspector.getPublicDeclaredMethods in the JRE which is called by axis - stack trace is below.

      "http-9080-7" daemon prio=10 tid=0x0a95d800 nid=0x2f1d waiting for monitor entry [0xdce76000]
      java.lang.Thread.State: BLOCKED (on object monitor)
      at java.beans.Introspector.getPublicDeclaredMethods(Unknown Source)

      • waiting to lock <0xf0882fa0> (a java.lang.Class for java.beans.Introspector)
        at java.beans.Introspector.getTargetPropertyInfo(Unknown Source)
        at java.beans.Introspector.getBeanInfo(Unknown Source)
        at java.beans.Introspector.getBeanInfo(Unknown Source)
        at java.beans.Introspector.getBeanInfo(Unknown Source)
        at org.apache.axis2.databinding.utils.BeanUtil.getPropertyQnameList(BeanUtil.java:132)
        at org.apache.axis2.databinding.utils.BeanUtil.getPullParser(BeanUtil.java:67)
        at org.apache.axis2.rpc.receivers.RPCUtil.processResponse(RPCUtil.java:97)
        at org.apache.axis2.rpc.receivers.RPCUtil.processResponseAsDocLitWrapped(RPCUtil.java:437)
        at org.apache.axis2.rpc.receivers.RPCMessageReceiver.invokeBusinessLogic(RPCMessageReceiver.java:138)
        at org.apache.axis2.receivers.AbstractInOutMessageReceiver.invokeBusinessLogic(AbstractInOutMessageReceiver.java:40)
        at org.apache.axis2.receivers.AbstractMessageReceiver.receive(AbstractMessageReceiver.java:114)
        at org.apache.axis2.engine.AxisEngine.receive(AxisEngine.java:173)
        at org.apache.axis2.transport.http.HTTPTransportUtils.processHTTPPostRequest(HTTPTransportUtils.java:167)
        at org.apache.axis2.transport.http.AxisServlet.doPost(AxisServlet.java:142)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
        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.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286)
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845)
        at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
        at java.lang.Thread.run(Unknown Source)

      From looking at the stack trace it seems like this is called when generating every response hence the performance hit and having compared the 1.4.1 and 1.5.1 source we can see that the call to the synchronized JRE method is not made in 1.4.1. This issue is critical to our release as we expect this interface to have a high throughput.

        Issue Links

          Activity

          Andreas Veithen made changes -
          Status Open [ 1 ] Resolved [ 5 ]
          Resolution Duplicate [ 3 ]
          Andreas Veithen made changes -
          Link This issue is superceded by AXIS2-4878 [ AXIS2-4878 ]
          Chris van Es made changes -
          Field Original Value New Value
          Description We recently upgraded from axis2 1.4.1to 1.5.1 and with no changes to our java methods which are exposed using axis we have seen a significant drop in performance from around 500-600 TPS to 50 TPS at most. We took a jstack while load is on our system and can see alot of threads blocked waiting for an object monitor to enter the private method java.beans.Introspector.getPublicDeclaredMethods in the JRE which is called by axis - stack trace is below.

          "http-9080-7" daemon prio=10 tid=0x0a95d800 nid=0x2f1d waiting for monitor entry [0xdce76000]
             java.lang.Thread.State: BLOCKED (on object monitor)
                  at java.beans.Introspector.getPublicDeclaredMethods(Unknown Source)
                  - waiting to lock <0xf0882fa0> (a java.lang.Class for java.beans.Introspector)
                  at java.beans.Introspector.getTargetPropertyInfo(Unknown Source)
                  at java.beans.Introspector.getBeanInfo(Unknown Source)
                  at java.beans.Introspector.getBeanInfo(Unknown Source)
                  at java.beans.Introspector.getBeanInfo(Unknown Source)
                  at org.apache.axis2.databinding.utils.BeanUtil.getPropertyQnameList(BeanUtil.java:132)
                  at org.apache.axis2.databinding.utils.BeanUtil.getPullParser(BeanUtil.java:67)
                  at org.apache.axis2.rpc.receivers.RPCUtil.processResponse(RPCUtil.java:97)
                  at org.apache.axis2.rpc.receivers.RPCUtil.processResponseAsDocLitWrapped(RPCUtil.java:437)
                  at org.apache.axis2.rpc.receivers.RPCMessageReceiver.invokeBusinessLogic(RPCMessageReceiver.java:138)
                  at org.apache.axis2.receivers.AbstractInOutMessageReceiver.invokeBusinessLogic(AbstractInOutMessageReceiver.java:40)
                  at org.apache.axis2.receivers.AbstractMessageReceiver.receive(AbstractMessageReceiver.java:114)
                  at org.apache.axis2.engine.AxisEngine.receive(AxisEngine.java:173)
                  at org.apache.axis2.transport.http.HTTPTransportUtils.processHTTPPostRequest(HTTPTransportUtils.java:167)
                  at org.apache.axis2.transport.http.AxisServlet.doPost(AxisServlet.java:142)
                  at javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
                  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.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
                  at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
                  at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
                  at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
                  at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
                  at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286)
                  at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845)
                  at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
                  at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
                  at java.lang.Thread.run(Unknown Source)

          Having compared the 1.4.1 and 1.5.1 source we can see that the call to the synchronized JRE method is not made in 1.4.1. This issue is critical to our release as we expect this interface to have a high throughput.
          We recently upgraded from axis2 1.4.1to 1.5.1 and with no changes to our java methods which are exposed using axis we have seen a significant drop in performance from around 500-600 TPS to 50 TPS at most. We took a jstack while load is on our system and can see alot of threads blocked waiting for an object monitor to enter the private method java.beans.Introspector.getPublicDeclaredMethods in the JRE which is called by axis - stack trace is below.

          "http-9080-7" daemon prio=10 tid=0x0a95d800 nid=0x2f1d waiting for monitor entry [0xdce76000]
             java.lang.Thread.State: BLOCKED (on object monitor)
                  at java.beans.Introspector.getPublicDeclaredMethods(Unknown Source)
                  - waiting to lock <0xf0882fa0> (a java.lang.Class for java.beans.Introspector)
                  at java.beans.Introspector.getTargetPropertyInfo(Unknown Source)
                  at java.beans.Introspector.getBeanInfo(Unknown Source)
                  at java.beans.Introspector.getBeanInfo(Unknown Source)
                  at java.beans.Introspector.getBeanInfo(Unknown Source)
                  at org.apache.axis2.databinding.utils.BeanUtil.getPropertyQnameList(BeanUtil.java:132)
                  at org.apache.axis2.databinding.utils.BeanUtil.getPullParser(BeanUtil.java:67)
                  at org.apache.axis2.rpc.receivers.RPCUtil.processResponse(RPCUtil.java:97)
                  at org.apache.axis2.rpc.receivers.RPCUtil.processResponseAsDocLitWrapped(RPCUtil.java:437)
                  at org.apache.axis2.rpc.receivers.RPCMessageReceiver.invokeBusinessLogic(RPCMessageReceiver.java:138)
                  at org.apache.axis2.receivers.AbstractInOutMessageReceiver.invokeBusinessLogic(AbstractInOutMessageReceiver.java:40)
                  at org.apache.axis2.receivers.AbstractMessageReceiver.receive(AbstractMessageReceiver.java:114)
                  at org.apache.axis2.engine.AxisEngine.receive(AxisEngine.java:173)
                  at org.apache.axis2.transport.http.HTTPTransportUtils.processHTTPPostRequest(HTTPTransportUtils.java:167)
                  at org.apache.axis2.transport.http.AxisServlet.doPost(AxisServlet.java:142)
                  at javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
                  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.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
                  at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
                  at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
                  at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
                  at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
                  at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286)
                  at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845)
                  at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
                  at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
                  at java.lang.Thread.run(Unknown Source)

          From looking at the stack trace it seems like this is called when generating every response hence the performance hit and having compared the 1.4.1 and 1.5.1 source we can see that the call to the synchronized JRE method is not made in 1.4.1. This issue is critical to our release as we expect this interface to have a high throughput.
          Chris van Es created issue -

            People

            • Assignee:
              Unassigned
              Reporter:
              Chris van Es
            • Votes:
              1 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development