Activating hibernate loggers
While developing an application using JPA to access a database it is really useful to see how inefficient and numerous the executed SQL statements are. In fact, if you use any relations in entities you can be surprised to learn how many SQL statements are executed by Hibernate or Eclipselink to load an entity with relations. According to Hibernate documentation, the SQL statements can be displayed by enabling org.hibernate.SQL logger. It is enough to add a line into log4j.properties:
log4j.logger.org.hibernate.SQL=debug
However, the logged statements will be incomplete with question marks in place of any values. For example, the output can be similar to:
update users set date_format=? where user_id=?
delete from users where user_id=?
To see the hidden by default bind parameters, one needs to enable additional loggers:
log4j.logger.org.hibernate.type=trace
log4j.logger.org.hibernate.type.descriptor.sql=trace
But then the log becomes immense due to predominantly irrelevant output and thus quite illegible. So the point is - there is no standard way in Hibernate to see the executed SQL statements clean and complete. But there is an easy and universal workaround.
Using a customized MySQL logger
Even without JPA, while installing or debugging a poorly documented Java application, it helps to know what SQL commands fail or produce unexpected results. Recently, I have been installing and customizing such an application. Fortunately, it is an open source application and its code can be easily modified. Exposing the failing SQL statements helped me to make undocumented adjustments in the underlying MySQL database so that the application gradually started to function.
The SQL statements processed by MySQL driver can be displayed by adding property profileSQL to the connection URL.
jdbc:mysql://hostname/database?user=user&password=pass&useSSL=false&profileSQL=true
The default logger included in the SQL driver will be used to produce the output. The problem is that the output will include not only the executed SQL statements but also several times as many lines with irrelevant content such as pointless diagnostic messages, timestamps or empty space. Overall the output will be illegible. To record only SQL statements, I composed a customized logger class that filters out all the pollution.
package com.mysql.jdbc.log;
import java.util.Date;
import com.mysql.jdbc.profiler.ProfilerEvent;
import java.text.DateFormat;
import java.text.SimpleDateFormat;
public class MyStandardLogger implements Log {
public MyStandardLogger(String name) {
this(name, false);
}
public MyStandardLogger(String name, boolean logLocationInfo) {
}
public boolean isDebugEnabled() {
return true;
}
public boolean isErrorEnabled() {
return true;
}
public boolean isFatalEnabled() {
return true;
}
public boolean isInfoEnabled() {
return true;
}
public boolean isTraceEnabled() {
return true;
}
public boolean isWarnEnabled() {
return true;
}
public void logDebug(Object message) {
logInternal( message );
}
public void logDebug(Object message, Throwable exception) {
logInternal( message );
}
public void logError(Object message) {
logInternal( message );
}
public void logError(Object message, Throwable exception) {
logInternal( message );
}
public void logFatal(Object message) {
logInternal( message );
}
public void logFatal(Object message, Throwable exception) {
logInternal( message );
}
public void logInfo(Object message) {
logInternal( message );
}
public void logInfo(Object message, Throwable exception) {
logInternal( message );
}
public void logTrace(Object message) {
logInternal( message );
}
public void logTrace(Object message, Throwable exception) {
logInternal( message );
}
public void logWarn(Object message) {
logInternal( message );
}
public void logWarn(Object message, Throwable exception) {
logInternal( message );
}
DateFormat df = new SimpleDateFormat("HH:mm:ss.SSS");
protected void logInternal(Object msg) {
if (msg instanceof ProfilerEvent) {
ProfilerEvent evt = (ProfilerEvent) msg;
String evtMessage = evt.getMessage();
if (evtMessage != null) {
System.out.println(">SQL: " + df.format(new Date())+"\t"+evtMessage);
}
}
}
}
The jar containing this class must be placed into the application class path. I put it into the same folder as the MySQL driver - CATALINA_HOME/lib.
In any ordinary application one would have only one place with the connection string. But to debug the application I needed to see the SQL statements received by JDBC driver from Connection created by DriverManger, and DataSource classes obtained from Tomcat or some Spring connection pools. So in some java class I modified the connection string:
String url ="jdbc:mysql://" + host + "/" + database +
"?user=" + userName + "&password=" + password +
"&zeroDateTimeBehavior=convertToNull&useSSL=false&profileSQL=true&logger=com.mysql.jdbc.log.MyStandardLogger";
In a Spring application context configuration xml one cannot use & sign, so the connections string looked like:
<bean id="businessDataSource" destroy-method="close" class="org.apache.commons.dbcp.BasicDataSource">
<property name="driverClassName" value="${db.driver}"/>
<property name="url" value="${db.connection_string}${db.portal_db_name}?zeroDateTimeBehavior=convertToNull&useSSL=false&profileSQL=true&logger=com.mysql.jdbc.log.MyStandardLogger"/>
<property name="username" value="${db.user}"/>
<property name="password" value="${db.password}"/>
</bean>
And in the Tomcat context.xml the URL was specifed like:
<Resource name="jdbc/cbioportal" auth="Container" type="javax.sql.DataSource" maxActive="100" maxIdle="30" maxWait="10000"
username="cbio_user" password="pass" driverClassName="com.mysql.jdbc.Driver"
connectionProperties="zeroDateTimeBehavior=convertToNull;useSSL=false;profileSQL=true;logger=com.mysql.jdbc.log.MyStandardLogger;"
testOnBorrow="true"
validationQuery="SELECT 1"
url="jdbc:mysql://localhost:3306/cbioportal"/>
Another version of MySQL logger passing SQL statements to the included slf4-compatible logger
Wildfly is different from other servers in a few respects. I have not tried to understand why, but the output from System.out.println() is not always saved to the server log. So used a similar class to log SQL statements. The jar was added as a dependency for MySQL driver. I will describe the unusual Wildfly-specific deployment of database drivers that must be installed before a dependent datasource is created in a later post.
package com.mysql.jdbc.log;
import com.mysql.jdbc.profiler.ProfilerEvent;
import java.text.DateFormat;
import java.text.SimpleDateFormat;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class MySlf4JLogger extends StandardLogger {
Logger logger = LoggerFactory.getLogger(getClass().getName());
public MySlf4JLogger(String name) {
super(name, false);
}
public MySlf4JLogger(String name, boolean logLocationInfo) {
super(name, logLocationInfo);
}
DateFormat df = new SimpleDateFormat("HH:mm:ss.SSS");
@Override
protected void logInternal(int level, Object msg, Throwable exception) {
if (msg instanceof ProfilerEvent) {
ProfilerEvent evt = (ProfilerEvent) msg;
String str = evt.getMessage();
if (str != null) {
logger.debug(str);
}
}
}
}
Registering the logger of SQL statements in persistence.xml
This technique will nicely expose complete SQL statements with either Hibernate or Eclipselink. For example, how I use the logger in my persistence.xml used by JUnit tests.
<persistence-unit name="JavaApplication316PUTEST" transaction-type="RESOURCE_LOCAL">
<provider>org.hibernate.jpa.HibernatePersistenceProvider</provider>
<class>entities.User</class>
<class>entities.Food</class>
<class>entities.Meal</class>
<shared-cache-mode>NONE</shared-cache-mode>
<properties>
<property name="javax.persistence.jdbc.url" value="jdbc:mysql://localhost:3306/wildfly?useSSL=false&profileSQL=true&logger=com.mysql.jdbc.log.MySlf4JLogger"/>
<property name="javax.persistence.jdbc.user" value="wildfly"/>
<property name="javax.persistence.jdbc.driver" value="com.mysql.jdbc.Driver"/>
<property name="javax.persistence.jdbc.password" value="1234"/>
<property name="javax.persistence.schema-generation.database.action" value="none"/>
</properties>
</persistence-unit>
