Tracing SQL statements in JBoss AS 7 using a custom logging handler

Martin MoisJuly 1st, 2014Last Updated: July 1st, 2014

1 82 3 minutes read

Using an ORM to abstract from your specific database and to let it create and issue all the SQL statements you would have to write by hand yourself seems handy. This is what made ORM solutions popular.

But it also comes with a downside: As the ORM does a lot of work for you, you lose to some degree control over the generated SQL and you have to rely on the ORM to create a high-performance statement for you. But it can happen that the SQL generated by the ORM is not what you might have written by hand and expected the ORM to do for you. In this case you have to get back control over the SQL and put your hands on the code again.

In huge applications this task is not as trivial, as there might be hundreds of statements issued to the database that stem from hundreds of lines of Java code that makes heavy usage of JPA features. Tracing the SQL statement that your database profiling tool has identified as problematic down to the actual code line becomes tedious.

We know that we can enable SQL statement logging for Hibernate with the following two lines in our persistence.xml:

<property name="hibernate.show_sql" value="true"/>
<property name="hibernate.format_sql" value="true"/>

But this will only output the already generated SQL; the actual Java code line is still not visible. For smaller applications it might be feasible to attach a debugger to the application server and debug through the code until you have found the line that logs the problematic SQL statement, but for bigger applications this is time consuming.

As Hibernate itself does not provide any means of intercepting the logging and enhance it with more information, we will have to do this on our own. The JBoss documentation indicates that it is possible to write your own custom logging handler. As this logging handler receives all the logging messages and therewith also the messages produces by Hibernate with enabled SQL logging, we can try to find the line we are looking for and then output a stack trace to our own log file.

Writing a custom logging handler turns out to be very simple. All you have to do is setup a small project with a class that extends the class Handler from the JDK package java.util.logging:

package mypackage;

import java.util.logging.Handler;
import java.util.logging.LogRecord;

public class MyJBossLogger extends Handler {

	@Override
	public void publish(LogRecord record) {
	
	}
	
	@Override
	public void flush() {
	}
	
	@Override
	public void close() throws SecurityException {

	}
}

The publish() method receives all logging output in form of an instance of LogRecord. Its method getMessage() lets us access the output directly. Hence we can match this message against some keywords we have loaded from some configuration file:

@Override
public void publish(LogRecord record) {
	String message = record.getMessage();
	buffer.add(message + "\n");
	if (keywords == null) {
		keywords = loadKeywords();
	}
	if (matches(message, keywords)) {
		String stacktrace = "\nStacktrace:\n";
		StackTraceElement[] stackTrace = Thread.currentThread().getStackTrace();
		for (StackTraceElement element : stackTrace) {
			stacktrace += element.toString() + "\n";
		}
		buffer.add(stacktrace);
		flush();
	}
}

Buffer is here some simple data structure (e.g. guava’s EvictingQueue) that buffers the last lines, as the method publish() is called for each line(!) of output. As a complete SQL statement spans more than one line, we have to remember a couple of them. Next to the buffered lines and the current line we also output a String representation of the current stack trace. This tells us later in the log file from where we are called and therewith which line of Java code in our project causes the current statement.

Once we have compiled the project we can copy the resulting jar file to the newly created folder structure under: $JBOSS_HOME/modules/system/layers/base/com/mydomain/mymodule/main (for JBoss AS 7.2). In order to tell JBoss AS about our new module, we have to create a XML file called module.xml with the following content:

<?xml version="1.0" encoding="UTF-8"?>
<module xmlns="urn:jboss:module:1.1" name="com.mydomain.mymodule">
	<resources>
		<resource-root path="MyJBossLogger-0.0.1-SNAPSHOT.jar"/>
	</resources>
</module>

The name of the module corresponds to the path within the JBoss modules folder. It will also be used in the configuration file to configure our custom logging handler:

...
<subsystem xmlns="urn:jboss:domain:logging:1.2">
	<custom-handler name="CUSTOM" module="com.mydomain.mymodule" class="com.mydomain.mymodule.MyJBossLogger">
		<level name="DEBUG"/>
	</custom-handler>
	...

When we implement the flush() method of our logging handler to write the output to some log file, we will see something like the following (of course in condensed form):

Hibernate:     select ... from customer ...
Stacktrace:
java.lang.Thread.getStackTrace(Thread.java:1568)
com.mydomain.mymodule.MyJBossLogger.publish(MyJBossLogger.java:20)
org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:292)
org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:300)
org.jboss.logmanager.Logger.logRaw(Logger.java:721)
org.jboss.logmanager.Logger.log(Logger.java:506)
...
com.mydomain.myapp.ArticleEntity.getCustomers(ArticleRepository.java:234)
...

Here we can see clearly which OneToMany relation causes the problematic select statement we were looking for.

Conclusion

Using a custom logging handler to inject the current stack trace into the logging of the SQL statements may help you when you want to find the exact location in the source code where a concrete query is issued. It turned also out that writing your own custom logging handler for JBoss AS is also a straight forward task.

Reference:

Tracing SQL statements in JBoss AS 7 using a custom logging handler from our JCG partner Martin Mois at the Martin’s Developer World blog.