Mysterious Latency

The project was underway and we've started looking into performance tuning. The eG system monitoring tool flagged out webservice transactions lasting more than a few seconds. The application was apparently choking for more than 4 seconds on Java code. But it was not just any chunk of logic. The method being flagged was org.apache.cxf.transport.servlet.AbstractHTTPServlet; which was part of the CXF library. This was not even part of our custom codes.

I'd fired up the Java VisualVM to inspect the thread stack on my local machine. We had a couple of guys help take a look at the latency as well, diving into the log files. We'd pretty much stumbled upon the same issue from different angles.

The framework we're using adopts CXF, which in turn is able to output SOAP requests and responses to the log files. By setting the loggingInInterceptor and/or loggingOutInterceptor, we were debugging the XML content in the staging environment. The "limit" property was set to "-1" for both, in order to log entire payloads. This, of course, did not sit well with the other environment looking at the performance aspects of the system. This logging activity was costing an additional 5 seconds at times, according to the log (ironic, I know). We'd then recommended for the property to be set to "0" instead, so that zero bytes of the payloads will be logged.

Connecting Java VisualVM to WebSphere 8
Referring to this post, I'd added the following JVM arguments into my WebSphere
-Djavax.management.builder.initial= -Dcom.sun.management.jmxremote  -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.port=1099 -Djava.rmi.server.hostname=MYHOSTNAME

Subsequently following this article that's a bit clearer, I'd then connect via VisualVM to the localhost:1099, which was then able to sample the method calls with indications of self execution times.

Configuring CXF logging
The XML configuration of the CXF interceptors look something like this:
<bean id="loggingInInterceptor" class="org.apache.cxf.interceptor.LoggingInInterceptor" parent="abstractLoggingInterceptor">
    <property name="limit" value="-1"/>
</bean>
<bean id="loggingOutInterceptor" class="org.apache.cxf.interceptor.LoggingOutInterceptor" parent="abstractLoggingInterceptor">
    <property name="limit" value="-1"/>
</bean>
Which goes without saying, that the limits should be set to a value other than "-1" if you don't want/need the SOAP for debugging, especially outside of a development environment.

This is extra important if your XML includes one or more image binaries encoded as Base64 strings.