JINSPIRED JXInsight Insights - Ant JUnit Tracing and Profiling

Introduction

This articles looks at how JXInsight can be used to trace and profile the execution of Ant build projects, targets, and tasks. Showing a new integrated extension for JUnit that supports tracing of local and distributed (forked process) tests executed by the Ant JUnit task. Using Hibernate 3.0 as the build project example the article demonstrates how to trace across multiple JVM's and JXInsight trace extensions (Apache Ant, JUnit, and JDBC/JDBInsight) - correlating transaction paths and SQL statements with resulting distributed traces.

The JXInsight Apache Ant trace extension has the capability of intercepting and tracing the execution of JUnit Test via the Ant Optional Task - JUnitTask. This capability has numerous testing and performance engineering advantages including:

Tracing and Profiling - JUnit Tests can be traced and profiled with aggregated measurements collected for clock time, cpu time, object allocation counts, thread monitor block (contention) time, thread monitor wait time as well as GC time.

Data Access Analysis - JUnit Tests executing transactional database access logic via JDBC API calls can be analysed in terms of JDBInsight transactions patterns (paths), statements executions (SQL), resource management (JDBC objects), and access patterns (table and columns: INSERT, SELECT, UPDATE, DELETE, QUERY). The JDBC calls need not be directly executed by the JUnit tests as JXInsight has extensions for tracing across processes and up and down component and persistence technologies stacks. It is even possible to fork JUnit tasks from the original Ant JVM and still have full analysis capabilities.

Software Performance Engineering (SPE) - JXInsight profile snapshots automatically exported post test execution can be used in determing and understanding software and system execution models over the course of a project/products development. The archiving of snapshots creates a repository suitable for change management especially when there is due consideration for verification of transaction semantics of tests designed as application level use cases.

The rest of this article will describe the installation and build configuration steps in running the Hibernate 3 JUnit tests that are distributed with the source, binaries and documentation. But first lets take a look at the following screenshot showing a subset of the available columns of a JXInsight console trace statistics table. The profile snapshot was created by merging a collection of JUnit test profile snapshots, automatically exported when the executing JVM shutdown. The selected trace (row=3) within the table is a Ant project that was executed once within a JVM that had a JXInsight server listening on port 1515. Another process on the same host but listening on port 1516 has a remote client trace stack (enclosed by "<" and ">") prefixed in front of the all JUnit test suite traces - BatchTest, AuctionTest, and BatchFetchTest. The client trace stack is the trace stack for the thread that forked the JVM process. From this we can see that the execution of the Hibernate test suites and test cases originated from a process on host INSPIRED-TOSHIBA that had executed an unnamed Ant project, a target called junit and a task of type junit.

Step 1 - Download and Install

IMPORTANT JXINSIGHT 4.0 CHANGE NOTE
The old library jdbidriver.jar has been renamed and partitioned into multiple jars to support the class loading of particular trace extension into child class loaders which is typical within J2EE application server and web container classloader hierarchies. When deploying a jxinsight-ext-*.jar library the jxinsight-core.jar must be deployed instead of jxinsight-all.jar. The jxinsight-core.jar must be visible to all trace extensions via the same classloader or a direct/indirect parent classloader. For backward compatibility the jxinsight-all.jar (previously named jdbidriver.jar) is built with all JXInsight and JDBInsight classes and resources.

Download the latest production builds for Hibernate 3.0, Apache Ant and HSQLDB. Download and install JXInsight.
Copy the libraries jdbidriver.jar from JXINSIGHT_INSTALL_ROOT/lib to ANT_INSTALL_ROOT/lib
Copy the JVMPI native agent, jdbinsight.(dll | .so | .sl), from JXINSIGHT_INSTALL_ROOT/bin/<os> to HIBERNATE_INSTALL_ROOT
Copy the hsqldb.jar from HSQLDB_INSTALL_ROOT/lib to HIBERNATE_INSTALL_ROOT/jdbc

Step 2 - Configuration
Change the Hibernate supplied build.(bat) script to specify the loading of the JVMPI agent on startup of the Apache Ant JVM via the ANT_OPTS environment variable.

Note: For UNIX systems additional script changes are required to ensure that the JVMPI agent is on the library path for the all JVM processes executed or forked.
Turning on object allocations counts via -Xrunjdbinsight:on can impact the performance of the executing process. Please consult the install and user guide for additional instructions in how to turn on and off thread blocking, thread waiting, and gc JVMPI events and counter collection. Defaults are installed with -Xrunjdbinsight

Change the hibernate.properties file in HIBERNATE_INSTALL_ROOT/etc

Step 3 - Execute Tests

IMPORTANT JXINSIGHT 4.0 CHANGE NOTE
Public trace extension classes have been migrated from com.jinspired.jdbinsight.trace.* to com.jinspired.jxinsight.trace.*. For backward compatibility the classes in com.jinspired.jdbinsight.trace.* still remain though in most cases they merely extend from the migrated versions in com.jinspired.jxinsight.trace.*. The JDBInsight Driver and DataSource classes remain unchanged.

RENAME com.jinspired.jdbinsight.trace.ext.ant.TraceListener
TO com.jinspired.jxinsight.trace.ext.ant.TraceListener

Execute the build script from within the HIBERNATE_INSTALL_ROOT
build -listener com.jinspired.jdbinsight.trace.ext.ant.TraceListener junit

It is important to not that in this particular case the build.xml is not altered in integrating the JXInsight JUnit trace extension and that even forked tests are traced and associated with the invoking (parent) process.

For additional configuration options associated with the JUnit trace extension please read the release notes on the downloads page.

Step 4 - Merge Snapshot Profile
After the execution of all JUnit tests the HIBERNATE_INSTALL_ROOT directory will contain a large number of JXInsight profile and metric snapshots. The *.metric.snp files maybe removed at this moment. The JXInsight console should now be started and the HIBERNATE_INSTALL_ROOT directory mounted via File -> Mount Directory... menu command sequence. After mounting the directory bring up the Merge Snapshot Dialog via File -> Merge Snapshots... menu command sequence. Select all exported profile snapshot files and click the finish button. Do not merge the *.metric.snp files.

Following the merging of the selected snapshot files, which may take a minute or two , a dialog will be displayed requesting the name for the merged snapshot file and storage location directory. After the file has been written to the file system a dialog prompts for activating of snapshot within console.

A smaller subset of the Hibernate test profile snapshots has been merged and distributed with all JXInsight installers. The snapshot can be found at JXINSIGHT_INSTALL_ROOT/snapshots/ant-junit-jxinsight-hibernate-sample-profile.snp

Step 5 - Analysis
If you are new to JXInsight/JDBInsight now is the time to fire up the user guide and start working through the many profile perspectives and visualizations within the console.

To see the transaction patterns associated with each JUnit test activated the Transactions perspective in the Profile analysis mode. The paths table shows both the local Java callstack as well as the remote and local trace stacks associated with the executing thread.

The following screenshot shows column values for remote activity (R=Remote *, RT=Remote Transactions, RJ=Remote JDBC) associated with the Apache Ant build execution. From this view we can see that it took 21 minutes to execute the junit target and task. The JUnit test profile snapshots, in this case a merged subset took 1 minute 17 secs. The transaction activity (including non JDBC work) took 39 seconds. The JDBC work was performed in 19 seconds. On the same table object allocation counts, thread monitor blocking and waiting times are also available for local and distributed traced activity.

Under the Hood
The TraceListener (a Ant BuildListener implementation) will trace and profile the start and finish events for project, target and task executions. Prior to a task executing the JXInsight trace extension checks whether there are any JUnit task defs defined. If so then the JXInsight JUnitTask extension is redefined for the particular task def type. The trace extension will then register a result formatter with the JUnitTask instance tracing and profiling the thread activity between start and finish events. For forked JUnitTask executions additional JVM arguments are added to install the JVMPI agent (-Xrunjdbinsight) and to pass the client trace stack. The jdbidriver.jar is also added to the classpath entries list for forked executions.

Issues
The JVMPI agent, jdbinsight.* must be installed on the library path for invoked Ant and JUnit processes. Currently the JXInsight SQL parser does not parse and analyse SQL Create/Drop/Alter statements.

William Louth, JXInsight's Product Architect