Sunday, April 19, 2009

Method Tracing

Assume you have a complex application probably developed by somebody else. Sometime you have an application which runs on top of another platform like application server or portal. Sometime your application may be using some other third party component.
You may want to know trace the execution of specific requests or transactions in the system probably for debugging. This is also helpful to understand the architecture/design of the system.
You can do that using this tool. This tool traces the progress (execution) of each thread.

Steps:
0) Download and copy the following 3 jars to a convenient location. (all jars has to be in the same directory). (Click on the link to download files).
MethodTracer.jar
asm-3.1.jar
asm-commons-3.1.jar
1) Add the following JVM options during startup.
-javaagent:[path_to_MethodTracer.jar]
If you are using some startup script you may need to add it there. If you are using some exe to invoke java then there may be some file where you will be able to add this.

2) Extract trace.properties from the jar and edit it to change the configurations. Put it back. You can use the following commands for extracting the property file and put it back into jar.
jar -xvf MethodTracer.jar tracer.properties
jar -uvf MethodTracer.jar tracer.properties
Following are the options available.
ExcludedPackages – classes from this coma separated list of packages shall be excluded from instrumentation and hence execution of such methods shall not be traced.
IncludedPackages – If specified only classes from this packages shall be traced. You can use includePackages and excludePackages together to get fine control
allThreadsLogged – if true, all requests by threads shall be traced. You can trace the requests by specific threads by turn this flag false and use threadList
threadList – if allthreadsLogged is false, then only the threads specified in this list shall be traced.
This is useful in the case of systems like application server where there shall be lot of threads running always. Different kinds of requests are typically processed by separate threads.
loggingOnAtStartup – if true, tracing shall start from application startup. It may produce lot of verbose output. If you want to trace only certain specific transactions . You can turn it false and start/stop tracing from jconsole.
File/console – turn true/false appropriately to send the trace output to file (method_trace.log in the current directory of the application) or console window.

3) start the application. Name of all instrumented classes are printed out to the console. If classes from any of the packages of not interest are instrumented, you can modify the tracer.properties file (includePackages/excludePackages). (requires re-start of the application).

4) start jconsole and connect to this application. Jconsole is tool comes along with JDK. You can start jconsole by executing the jconsole.exe in the JDK/bin directory. While start up it will display the list of all available JVMs in the machine and ask to choose the one to connect. Choose the JVM of your application. Goto the ‘MBeans’ tab. Expand tracer >> custom >> configuration >> operations. Use enableLogging method to start/stop logging (as Boolean as parameter). Use addThread and removeThread to trace one (or list of) thread (name of the thread as parameter. You can see the list of all threads and it’s name from the ‘Threads’ tab. Copy the name from that tab and paste it here.



5) go to the jconsole > MBean tab, go to tracer >> custom >> configuration >> operations
a) select appropriate threads for tracing.
b) start logging (enableLogging method)

6) invoke the operation/transaction of your application, to be traced.

7) stop the logging from jconsole (enableLogging method in jconsole)

8) Open the method_trace.log file in the current directory.

How Method Tracing works?
It uses dynamic byte code instrumentation. It uses java.lang.instrument.* classes for bytecode instrumentation. It uses ASM Framework for modifying byte code. It modifies the byte code while loading the classes into JVM by Class Loader. The class files in the jar is not being modified.
It inserts tracing code at the beginning and end of each method.

Is it modifies your application binary?
No. It modifies the byte code while loading the classes into JVM by Class Loader.

Is it recommended to use in production?
No. This is only beta quality and there shall be considerable overhead because of method tracing.

8 comments:

Shashi said...

I would like to understand the implementation behind this tool.

Could you please share the source code for this tool?

Rejeev Divakaran said...

Source code is also bundled along with the jar (MethodTrace.jar).
I use byte code instrumentation using java.lang.instrument package (java.lang.instrument.Instrumentation & java.lang.instrument.ClassFileTransformer classes). I use ASM framework ( http://asm.ow2.org/ ) for modifying the byte code. I use the org.objectweb.asm.commons.AdviceAdapter to insert tracing code at the beginning and end of the each method.

Bedrin on Software said...

Hi there!

I've implemented a similar tool some time ago. It also utilizes ASM - http://jtracert.googlecode.com/

libre said...

Hi Rejeev,
I recently worked on a similar tool to record the classes covered by a particular testcases at runtime in a system running on multiple jvm's and i used aspectj AOP. I think AOP
is just meant for this, especially for amateur programmers like me :).

John said...

I did not find any source code within MethodTrace.jar just the class files. Is it possible to post the source?

Bedrin on Software said...

You can always get the latest version of source code from SVN: http://code.google.com/p/jtracert/source/checkout

The other option is to download the the sources of concrete version - browse for download page^ http://code.google.com/p/jtracert/downloads/list

Anonymous said...

How is it different from btrace or Dtrace?

Symbioun said...

Good effort - ran right away unlike btrace and jSonde that I tried. Has room for improvement if it prints similar to how Eclipse prints stack trace.