About Martin Mois

Martin is a Java EE enthusiast and works for an international operating company. He is interested in clean code and the software craftsmanship approach. He also strongly believes in automated testing and continuous integration.

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

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.

Do you want to know how to develop your skillset to become a Java Rockstar?

Subscribe to our newsletter to start Rocking right now!

To get you started we give you two of our best selling eBooks for FREE!

JPA Mini Book

Learn how to leverage the power of JPA in order to create robust and flexible Java applications. With this Mini Book, you will get introduced to JPA and smoothly transition to more advanced concepts.

JVM Troubleshooting Guide

The Java virtual machine is really the foundation of any Java EE platform. Learn how to master it with this advanced guide!

Given email address is already subscribed, thank you!
Oops. Something went wrong. Please try again later.
Please provide a valid email address.
Thank you, your sign-up request was successful! Please check your e-mail inbox.
Please complete the CAPTCHA.
Please fill in the required fields.

One Response to "Tracing SQL statements in JBoss AS 7 using a custom logging handler"

  1. masum says:

    i have found following sql log .

    insert into account (balance, name) values (?, ?)

    i want to log following format , is it possible in jboss 7 ?

    insert into account (balance, name) values (150, masum)

Leave a Reply


three + = 12



Java Code Geeks and all content copyright © 2010-2014, Exelixis Media Ltd | Terms of Use | Privacy Policy | Contact
All trademarks and registered trademarks appearing on Java Code Geeks are the property of their respective owners.
Java is a trademark or registered trademark of Oracle Corporation in the United States and other countries.
Java Code Geeks is not connected to Oracle Corporation and is not sponsored by Oracle Corporation.
Do you want to know how to develop your skillset and become a ...
Java Rockstar?

Subscribe to our newsletter to start Rocking right now!

To get you started we give you two of our best selling eBooks for FREE!

Get ready to Rock!
You can download the complementary eBooks using the links below:
Close