Adventures in Java

Correction: The files you need to download to try out the profiler are:

ajweaver-agent.jar

ajweaver-agent-profiler.jar

The main body of the article contains incorrect links to these files. Sorry for the confusion caused.

In this post, I present a Java agent that calls back a custom listener class (which you provide) whenever methods in a set of classes (which you specify via configuration) are invoked. The only requirement on the listener class is that it contain a public static method with a specified signature:

public static void someMethod(int operation, String methodSignature, Object targetObject, Object…args), where:

It is trivially simple writing listener classes. Here, in its entirety, is a “logging” listener:

public class SimpleListener{

public static void callme(int op, String signature, Object obj,
        Object... args) {

if ( op == 0 ){

System.out.println( signature );

}

}

}

Later, I provide a more involved (and useful) listener class in the code examples that allows the profiling of method executions.

What I really like about this project is that the agent is implemented using AspectJ, but AspectJ is fully embedded (“hidden” from view) from the user’s viewpoint. In other words, the user does not provide any resources, additional JAR’s or configuration that AspectJ requires, nor even “needs to know” that AspectJ is being used under the covers. Look at the “NotifierMain” and “PrepareAjWeaverInputs” and “Transformer” classes for details on how I did this. I do not go into this further in this post since this is irrelevant to the ideas I wish to discuss here.

Using the agent

To use the agent, you need the file “ajweaver-agent.jar” which can be downloaded from here. Next, you must provide some command line arguments to the command that launches your application, to wit “-javaagent:{absolute path to the ajweaver-agent.jar file}. Finally, you must provide a set of system properties that tell the agent what classes must have their method invocations reported, what your custom listener class is called, and what the name of the method is (in that class) that must be called back by the agent. For the example listener shown above (SimpleListener), these system properties would be defined as:

The command line looks like this:

With these instructions out of way, let us jump right in and try out the agent (and a cool profiler listener class).

Profiling method calls

To get started with the agent, let us look at a custom listener class (com.subhajit.ajprofiler.Profiler) that provides basic profiling of method invocations by tracking the number of times individual methods are called, and the minimum, average and maximum execution time of the invocations. These classes can be configured to optionally setup JMX functionality from which the profile information can be extracted remotely.

As with all agent callback classes, the Profiler class has a public, static method with the signature: public static void {methodName}(int,String,Object,Object..). In Profiler, the method is named “profilerCallback”:

The profilerCallback method treats the two cases when the first parameter is “0” (execution start) and “1” or “2” (execution ended normally or execution ended with uncaught exception) separately. The first case is executed as method bodies are entered, and the other case is executed when method bodies are exited. These cases invoke the “begin” and “end” methods of a default instance of Profiler, respectively.

The “begin” method creates a “CflowKey” object to represent the program flow at this point using the target object (whose instance method body has started executing), the current thread, the method signature and the current timestamp. This object is next appended to a list of such objects dedicated to this method instance. This effectively records the start of execution of this method’s body in the program flow:

The “end” method creates a new CflowKey instance using the target object, the current thread and the method signature, and then iterates through the list of stored CflowKey objects for this method signature looking for the last element that matches this CflowKey (with respect to the target object, method signature and current thread) and for which the stored timestamp is less than the timestamp of this CflowKey object. What we are effectively doing in this step is finding the last recorded “start of execution” of this method in this program flow. Given that one object can be executing only one method in the same thread at any time, the last time we recorded the start of this method for the same object and the same thread must correspond to the start of this selfsame flow of execution. Having found this CflowKey item, we record its timestamp, and then remove it from the list of stored CflowKey items.

The second part of this method (starting with the line “if (executionTimeHasBeenSet)”), updates a “MethodExecutionInfo” object with the time taken by this execution of the method. The “update” method of the MethodExecutionInfo class updates its internal state using the execution time:

Trying it out

To try out this agent and the profiler, download the two files ajweaver-agent.jar and ajweaver-agent-profiler.jar (see the top of this article under "Correction" for the download links) and place them in a temporary directory (say “C:\tmp”). Next, modify the launch script for your application by introducing the following terms (prior to the specification of the class to be executed):

java….-Djavaagent:c:\tmp\ajweaver-agent.jar –Dinstrument-packages={list of packages} –Dcallback-class=com.subhajit.ajprofiler.Profiler –Dcallback-method=profilerCallback …

If this is a long running application (such as a server), also add the term: –Dprofiler-port={a port number}, and you will be able to access profiling information via JConsole. For example, if you entered port “1234”, start JConsole, choose “Remote Process”, enter “localhost:1234” and click on the “Connect” button. Once connected, go to the “MBeans” tab, locate the tree node for “com.subhajit.ajprofiler” and open it out fully. Selecting “Operations”, followed by clicking on the “getData” button, fetches a Map of accumulated profile information from the Profiler class.

To try this with Apache tomcat, make the following changes:

1. Make a copy of the “bin\catalina.bat” file and call it “bin\cataprofiler.bat”.

2. Add the following lines to “bin\cataprofiler.bat”:

set JAVA_OPTS=-Dinstrument-packages=org.apache.catalina..*,org.apache.coyote..*,org.apache.naming..*,org.apache.tomcat..* -javaagent:C:\var\tmp\ajweaver-agent.jar -Dcallback-method=profilerCallback -Dcallback-class=com.subhajit.ajprofiler.Profiler -Xms1024m -Xmx1256m -Dprofiler-port=1234

set CLASSPATH=C:\tmp\ajweaver-agent-profiler\dist\ajweaver-agent-profiler.jar;%CLASSPATH%

changing the package names in the first line to whatever packages you are interested in.

3. In the “bin\setclasspath.bat” file, locate the following stanza and modify it as shown:

rem Set standard CLASSPATH
rem Note that there are no quotes as we do not want to introduce random
rem quotes into the CLASSPATH
if not exist "%JAVA_HOME%\lib\tools.jar" goto noJavac
set CLASSPATH=%JAVA_HOME%\lib\tools.jar;C:\tmp\ajweaver-agent-profiler\dist\ajweaver-agent-profiler.jar

4. Start tomcat using the command: “bin\cataprofiler.bat run”.

5. After tomcat starts up, start JConsole using the command: “jconsole”, which assumes that you have the JDK’s “bin” directory in your path. You should see:

Select “Remote Process”, enter “localhost:1234” as shown and click on the “Connect” button. This takes you to:

Select the “MBeans” tab:

Clicking on the “getData” button pops up a dialog showing accumulated profile data:

To use a custom GUI program, download ajweaver-agent-profiler-gui.jar. To use it, run “java –jar ajweaver-agent-profiler-gui.jar”. This brings up:

Click the “Refresh” button to bring up a dialog:

Enter the hostname and port where the profiler is available. If the profiled application is running on the same host as the GUI, you could enter “localhost” for the host. For the port, enter the value of the “profiler-port” system property that was specified when the application was started. Clicking the “Ok” button brings up:

Clicking the “Refresh” button refreshes the display.

Other applications

Some applications of this facility that immediately come to mind are method tracing, method logging, heap tracing (dynamically tracing the amount of heap space used by an application as it runs), application health monitoring (trends of method invocations resulting in uncaught exceptions vs. “normal” execution), etc.. At development time, this framework can provide lightweight profiling capabilities.