Tracing and Profiling Distributed WorkManagers

With the availability of early access builds of Tangosol's Coherence 3.1 product, I have been able to create a short and simple distributed tracing example highlighting JXInsight's distributed tracing and profiling of the commonj.work.* API. The WorkManager is a joint BEA-IBM specification that is supported in IBM Websphere 6.0 and BEA WebLogic 9.x.

"The Work Manager API provides a higher level of abstraction for concurrent programming than java.lang.Thread, which is inappropriate for use by applications hosted in managed environments such as EJB containers and Servlet containers."


Example Application
To demonstrate the simplicity of the WorkManager API, the distributed work processing capabilities of the Tangosol's product, and the distributed tracing and profile analysis of JXInsight's agent, extensions and management console I have created the following sample Java client application that schedules the execution of work (SleepWork) on a number of Coherence WorkManager servers.

As you can see from the source code listing below this is a relatively straight forward Java client example. The steps are:
1. Create a WorkManager client instance
2. Proxy the instance via JXInsight's Tracer API
3. Schedule the execution of a Work object adding the returned WorkItem into a collection
4. Wait indefinitely for all Work objects to finish executing.





Before running the client application I created 2 Coherence WorkManager server processes that would execute concurrently the scheduled client work. Each JVM was started with the JXInsight's native agent and Java libraries for monitoring, profiling and tracing. The following script was used to start each of the JVM server processes.

#!/bin/sh JXI_HOME=/Users/wlouth/Applications/JXInsight COH_HOME=/Users/wlouth/Applications/tangosol DYLD_LIBRARY_PATH=$DYLD_LIBRARY_PATH:$JXINSIGHT_HOME/bin/osx export DYLD_LIBRARY_PATH JAVA_OPTS='-Xrunjdbinsight -Djxinsight.server.profiler.timeline.autostart=true' CLASSPATH=$COH_HOME/lib/coherence.jar:$COH_HOME/lib/coherence-work.jar:$COH_HOME/lib/commonj.jar CLASSPATH=$CLASSPATH:$JXI_HOME/lib/jxinsight-core.jar:$JXI_HOME/lib/jxinsight-ext-commonj.jar CLASSPATH=$CLASSPATH:./classes MAIN_CLASS=com.tangosol.coherence.commonj.WorkManager SERVER_NAME=server NUM_OF_THREADS=2 exec java $JAVA_OPTS -cp $CLASSPATH $MAIN_CLASS $SERVER_NAME $NUM_OF_THREADS

The following script was used to start the single client JVM process.

#!/bin/sh JXI_HOME=/Users/wlouth/Applications/JXInsight COH_HOME=/Users/wlouth/Applications/tangosol DYLD_LIBRARY_PATH=$DYLD_LIBRARY_PATH:$JXINSIGHT_HOME/bin/osx export DYLD_LIBRARY_PATH JAVA_OPTS='-Xrunjdbinsight -Djxinsight.server.profiler.timeline.autostart=true' CLASSPATH=$COH_HOME/lib/coherence.jar:$COH_HOME/lib/coherence-work.jar:$COH_HOME/lib/commonj.jar CLASSPATH=$CLASSPATH:$JXI_HOME/lib/jxinsight-core.jar:$JXI_HOME/lib/jxinsight-ext-commonj.jar CLASSPATH=$CLASSPATH:./classes MAIN_CLASS=com.jinspired.jxinsight.examples.tangosol.work.Client SERVER_NAME=server NUM_OF_WORKITEMS=10 WAIT_TIME=1000 exec java $JAVA_OPTS -cp $CLASSPATH $MAIN_CLASS $SERVER_NAME $NUM_OF_WORKITEMS $WAIT_TIME

Cluster Timeline and Profile Analysis
By creating a cluster in the JXInsight management console and mounting a JXInsight server for each of the managed JVM's (client=1515, server#1=1516, server#2=1517) the timeline analysis mode can visualize the concurrent execution of the Work across the client and server processes. Each row in the timeline graphic represents a traced thread within a process. The thread with the largest amount of trace interval time is the client's main thread calling WorkManager.schedule and WorkManager.waitForAll. The rows beneath the client thread represent threads and traced executions within each of the 2 server JVM's. The bar chart at the top of the timeline graphic shows the level of concurrent execution across the cluster.

Note: The following figures are not an true measurement of the efficiency of the Coherence product. Overhead caused by classloading, JVM bytecode compilation, agent initialization, server initialization, has not been discounted from the results.




Within the profile analysis mode of the JXInsight monitoring and management console tracking the actual trace stack and call stack across client and server JVM's is easy. The expanded trace path in the Traces tree table shows a server process (1517) executing a run call on a scheduled Work (Client$SleepWork) instance. The trace stack active when the client process (1515) scheduled the work prefixes the traced execution of the Work instance. The call stack for the schedule operation and the run operation are both contained within the JXInsight profile model - for each traced call a Java call stack is captured and stored.




The traces tree table view shows the local and remote costs for client and server traces. Waiting for 10 Work instances to complete took 7.6 seconds. The clock total (see Service Times) is less than 10 seconds because of the concurrent execution across 2 server processes. The scheduling of 10 Work instances took 0.8 seconds within the client JVM. The schedule trace lists a clock total of 11.4 seconds for remote calls - server traces with the client trace prefixed.




The following screen shot shows how easy with JXInsight 4.1 [early access build #7] it is to see the client call stacks for a trace within a server. In the top section of the graphic a server-side trace, Work.run, is selected in a tree table view. The client-side trace points are shown in the bottom section of the graphic alongside the Java call stack that scheduled the Work instance.



William Louth, JXInsight's Product Architect