MethodCallSpy – building advanced socket listening tracing tool

The MethodCallSpy is sophisticated, multi threaded application with simple socket base IPC, listening to remote commands, gathering and aggregating tracing data.

Links to source codes:
https://bitbucket.org/espinosa/methodcallspy

MethodCallSpy is still not an enterprise grade tracing tool, not a YourKit replacement, but a specialized purpose tool and perhaps a base for similar projects of my dear readers. Tool similar to this we did use in real world scenario, in a commercial project for purpose of finding all classes still in use for specific tasks. It uses AspectJ.

MethodCallSpy

• aggregates tracing data and stores them to file
• listens on socket for commands
• it can suspend and resume application, in similar fashion as debugger does
• tracing can be switched on and off for readings to be made only when relevant functionality is launched

Besides AOP it is an example of:

• multi threaded application
• socket server and client
• simple text based IPC (Inter Process Communication) for delivering commands to the agent
• complex integration test with forking another JVM, capturing and filtering streams, tested application forced timeout (for misbehaved not blocking whole Continuous Integration server)
• good software design, notably Separation of Concerns. Aspect related code is used a bootstrapping class for simple context. Context instantiates other services like socket listening server, command processor or results writing service.
• Advanced testing. Custom context can be replaced with testing one for advanced integration test scenarios.

Motivation

Previously introduced MethodCallSpy0 has several shortcomings. It runs with application all the time, tracing everything along the way. Take a Spring based application, when it context is created, most beans are called in some way, even those not really used later. Such statistic would be unusable for “still needed” list of classes. Imagine, we need to list of used classes only for a specific functionality triggered by a user or event.

We need something we can control remotely. Stop tracing through initialisation phase, start tracing and gathering statistics when it counts. We have to add some IPC mechanism to make it controllable. To implement IPC I choose the simplest solution at hand – socket server.

We also need to persist (flush) readings to file. It can be done on request, by issuing specific command, or automatically when application ends.

Some scenarios may require to temporarily suspend application so I add this functionality too.

How to run MethodCallSpy

How to run with your application from command line:
java -cp <classpath> -javaagent:<full path to AspectJ library> -DtraceAgentOutputDir=<absolute path> targetAppClass

The classpath must include target application JAR and its libraries indeed, besides that AspectJ libraries, agent classes like TraceAllAgent.class, and AOP configuration file – aop.xml. The configuration file must be inside META-INF directory, top level directory. Ideally agent classes, like TraceAllAgent.class, should be ideally packed with the aop.xml in one jar.

All readings are stored in specified directory. File names with the readings are timestamped, so readings can be stored repeatedly. From historic reasons, there are two files created with every flush. One contains only classes – the c-file, the other classes and methods – the cm-file. Files names are combination of timestamp and suffix “.c.traceagent.log” or “.cm.traceagent.log”.

Every class/method is traced (registered) only once and content is alphabetically sorted.

The content of the class and method may look like:
my.home.sampleapplication.SampleSimpleApp#main(..)
my.home.sampleapplication.SampleSimpleApp#somePublicMethod(..)

One configuration step is required in aop.xml. Define what packages from the target application should be traced. Change the default value to something meaningful for you application. The double dot is crucial, it recursively include also all sub packages. Or use all inclusive <include within="*" /> but use it with care.

Target application is suspended by default. It waits for user interaction, like starting or not tracing. User has to issue resume command for application to resume.

Socket communication

Tracing agent listens port 4444 by default, it can be changed with traceAgentPort environment option. Example: -DtraceAgentPort=8008

To issues command user needs some tool enabling writing and reading from a socket on specified port. In Unix environments it is simple, standard shell echo can be redirected to a socket device. Example:
$ echo "start" > /dev/tcp/127.0.0.1/4444

A special custom socket client, very simple, practically one method only, is used in tests.

Command list

• ping – check if MethodCallSpy is active and listening, just print OK
• start – activate tracing
• stop – deactivate (stops) tracing
• print – print trace snapshot to file
• stat – shows if tracing is active and target application resumed or suspended
• resume – resume target application. Reminder that target application is suspended by default. User has time to set up tracing even for very short lived applications.
• suspend – suspend target application

See CommandProcessor class for details. Commands are case sensitive. Simple commands, none of them require any additional parameters.

Session example

$ java -cp …. -javaagent:/usr/javalibs/aspectj/aspectjweaver.jar \
-DtraceAgentOutputDir=/home/foo/tmp/trace-agent-readings \
-DtraceAgentPort=4445 \
my.home.SampleApp1
$ echo "start" > /dev/tcp/127.0.0.1/4444
$ echo "resume" > /dev/tcp/127.0.0.1/4444
$ echo "stop" > /dev/tcp/127.0.0.1/4444
$ echo "print" > /dev/tcp/127.0.0.1/4444

How to configure tracing for Tomcat hosted application

Configure container based application is more challenging then standalone applications. The challenge usually takes form of figuring out how to add extra environment properties and amend classpath. With Tomcat you need:

1) Find <path_to>/tomcat7/conf/catalina.properties

2) Locate property common.loader,

3) append tracing agent jar and AspectJ libraries, separated by comma. Instead trace agent jar, an “expanded archive”, root directory with compiled classes can be used

Example:
common.loader=...,/home/foo/workspace/project/bin,/usr/javalibs/aspectj/*.jar

4) in shell start Tomcat as

export CATALINA_OPTS="-javaagent:<path_to>/aspectjweaver.jar \ -DtraceAgentOutputDir=<output_directory_for_trace_files> \
-DtraceAgentPort=4444 \
./catalina.sh run

Logging

By default, tracing agent does not print anything to standard output. It only logs using standard Java logging framework. Set -Djava.util.logging.ConsoleHandler.level=FINE to see agent log messages in console.

Tests

Usage and abilities is well demonstrated on included tests. One can see what commands can be issues. Integration tests starting another JVM to get instrumentation and socket end to end communication properly tested. There are Tests focused on nested classes tracing.

Test contains simple socket client, see TestUtils.sendCommand() for sending a text command and receiving reply from the tracing agent.

Test2TraceMultithreadedApp – test specifically to ensure handling of multi-threaded applications, where threads outlive main thread and correctly trace all threads.

More complex multi threaded testing scenarios are complicated by lack of simple cross JVM instance lock and other classes from concurrency package. Something like CountDownLatch with remote interface would be very useful. Such implementation is however out of scope for a once off tracing tool.

To be continued..

In the next article we look at some more technical details