Is it possible in Hibernate to print generated SQL queries with real values instead of question marks?
How would you suggest to print queries with real values if it is not possible with Hibernate API?
You need to enable logging for the the following categories:
org.hibernate.SQL
- set to debug
to log all SQL DML statements as they are executedorg.hibernate.type
- set to trace
to log all JDBC parametersSo a log4j configuration could look like:
# logs the SQL statements
log4j.logger.org.hibernate.SQL=debug
# Logs the JDBC parameters passed to a query
log4j.logger.org.hibernate.type=trace
The first is equivalent to hibernate.show_sql=true
legacy property, the second prints the bound parameters among other things.
Another solution (non hibernate based) would be to use a JDBC proxy driver like P6Spy.
Just for convenience, here is the same configuration example for Logback (SLF4J)
<appender name="SQLROLLINGFILE">
<File>/tmp/sql.log</File>
<rollingPolicy>
<FileNamePattern>logFile.%d{yyyy-MM-dd}.log</FileNamePattern>
</rollingPolicy>
<layout>
<Pattern>%-4date | %msg %n</Pattern>
</layout>
</appender>
<logger name="org.hibernate.SQL" additivity="false" >
<level value="DEBUG" />
<appender-ref ref="SQLROLLINGFILE" />
</logger>
<logger name="org.hibernate.type" additivity="false" >
<level value="TRACE" />
<appender-ref ref="SQLROLLINGFILE" />
</logger>
The output in your sql.log (example) then looks like this:
2013-08-30 18:01:15,083 | update stepprovider set created_at=?, lastupdated_at=?, version=?, bundlelocation=?, category_id=?, customer_id=?, description=?, icon_file_id=?, name=?, shareStatus=?, spversion=?, status=?, title=?, type=?, num_used=? where id=?
2013-08-30 18:01:15,084 | binding parameter [1] as [TIMESTAMP] - 2012-07-11 09:57:32.0
2013-08-30 18:01:15,085 | binding parameter [2] as [TIMESTAMP] - Fri Aug 30 18:01:15 CEST 2013
2013-08-30 18:01:15,086 | binding parameter [3] as [INTEGER] -
2013-08-30 18:01:15,086 | binding parameter [4] as [VARCHAR] - com.mypackage.foo
2013-08-30 18:01:15,087 | binding parameter [5] as [VARCHAR] -
2013-08-30 18:01:15,087 | binding parameter [6] as [VARCHAR] -
2013-08-30 18:01:15,087 | binding parameter [7] as [VARCHAR] - TODO
2013-08-30 18:01:15,087 | binding parameter [8] as [VARCHAR] -
2013-08-30 18:01:15,088 | binding parameter [9] as [VARCHAR] - [email protected]
2013-08-30 18:01:15,088 | binding parameter [10] as [VARCHAR] - PRIVATE
2013-08-30 18:01:15,088 | binding parameter [11] as [VARCHAR] - 1.0
2013-08-30 18:01:15,088 | binding parameter [12] as [VARCHAR] - 32
2013-08-30 18:01:15,088 | binding parameter [13] as [VARCHAR] - MatchingStep
2013-08-30 18:01:15,089 | binding parameter [14] as [VARCHAR] -
2013-08-30 18:01:15,089 | binding parameter [15] as [INTEGER] - 0
2013-08-30 18:01:15,089 | binding parameter [16] as [VARCHAR] - 053c2e65-5d51-4c09-85f3-2281a1024f64
In case of spring boot is being used , just config this :
aplication.yml
logging:
level:
org.hibernate.SQL: DEBUG
org.hibernate.type: TRACE
aplication.properties
logging.level.org.hibernate.SQL=DEBUG
logging.level.org.hibernate.type=TRACE
and nothing more.
Your log will be something like this:
2020-12-07 | DEBUG | o.h.SQL:127 - insert into Employee (id, name, title, id) values (?, ?, ?, ?)
2020-12-07 | TRACE | o.h.t.d.s.BasicBinder:64 - binding parameter [1] as [VARCHAR] - [001]
2020-12-07 | TRACE | o.h.t.d.s.BasicBinder:64 - binding parameter [2] as [VARCHAR] - [John Smith]
2020-12-07 | TRACE | o.h.t.d.s.BasicBinder:52 - binding parameter [3] as [VARCHAR] - [null]
2020-12-07 | TRACE | o.h.t.d.s.BasicBinder:64 - binding parameter [4] as [BIGINT] - [1]
HTH
Change hibernate.cfg.xml
to:
<property name="show_sql">true</property>
<property name="format_sql">true</property>
<property name="use_sql_comments">true</property>
Include log4j and below entries in "log4j.properties":
log4j.logger.org.hibernate=INFO, hb
log4j.logger.org.hibernate.SQL=DEBUG
log4j.logger.org.hibernate.type=TRACE
log4j.appender.hb=org.apache.log4j.ConsoleAppender
log4j.appender.hb.layout=org.apache.log4j.PatternLayout
Log4JDBC is a nice solution which prints the exact SQL going to the database with parameters in place rather than the most popular answer here which does not do this. One major convenience of this is that you can copy the SQL straight to your DB front-end and execute as is.
http://log4jdbc.sourceforge.net/
https://code.google.com/p/log4jdbc-remix/
The latter also outputs a tabular representation of query results.
Sample Output showing generated SQL with params in place together with result set table from query:
5. insert into ENQUIRY_APPLICANT_DETAILS (ID, INCLUDED_IN_QUOTE, APPLICANT_ID, TERRITORY_ID, ENQUIRY_ID, ELIGIBLE_FOR_COVER) values (7, 1, 11, 1, 2, 0)
10 Oct 2013 16:21:22 4953 [main] INFO jdbc.resultsettable - |---|--------|--------|-----------|----------|---------|-------|
10 Oct 2013 16:21:22 4953 [main] INFO jdbc.resultsettable - |ID |CREATED |DELETED |CODESET_ID |NAME |POSITION |PREFIX |
10 Oct 2013 16:21:22 4953 [main] INFO jdbc.resultsettable - |---|--------|--------|-----------|----------|---------|-------|
10 Oct 2013 16:21:22 4953 [main] INFO jdbc.resultsettable - |2 |null |null |1 |Country 2 |1 |60 |
10 Oct 2013 16:21:22 4953 [main] INFO jdbc.resultsettable - |---|--------|--------|-----------|----------|---------|-------|
Most recently I have now been using log4jdbc-log4j2 (https://code.google.com/archive/p/log4jdbc-log4j2/ ) with SLF4j and logback. Maven dependencies required for my set-up are as below:
<dependency>
<groupId>org.bgee.log4jdbc-log4j2</groupId>
<artifactId>log4jdbc-log4j2-jdbc4.1</artifactId>
<version>1.16</version>
</dependency>
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-api</artifactId>
<version>${slf4j.version}</version>
</dependency>
<dependency>
<groupId>ch.qos.logback</groupId>
<artifactId>logback-core</artifactId>
<version>${logback.version}</version>
</dependency>
<dependency>
<groupId>ch.qos.logback</groupId>
<artifactId>logback-classic</artifactId>
<version>$logback.version}</version>
</dependency>
The Driver and DB Urls then look like:
database.driver.class=net.sf.log4jdbc.sql.jdbcapi.DriverSpy
database.url=jdbc:log4jdbc:hsqldb:mem:db_name #Hsql
#database.url=jdbc:log4jdbc:mysql://localhost:3306/db_name
My logback.xml configuration file looks like the below: this outputs all SQL statements with parameters plus the resultset tables for all queries.
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n
</pattern>
</encoder>
</appender>
<logger name="jdbc.audit" level="ERROR" />
<logger name="jdbc.connection" level="ERROR" />
<logger name="jdbc.sqltiming" level="ERROR" />
<logger name="jdbc.resultset" level="ERROR" />
<!-- UNCOMMENT THE BELOW TO HIDE THE RESULT SET TABLE OUTPUT -->
<!--<logger name="jdbc.resultsettable" level="ERROR" /> -->
<root level="debug">
<appender-ref ref="STDOUT" />
</root>
</configuration>
Finally, I had to create a file named log4jdbc.log4j2.properties at the root of the classpath e.g. src/test/resources or src/main/resources in a Mevn project. This file has one line which is the below:
log4jdbc.spylogdelegator.name=net.sf.log4jdbc.log.slf4j.Slf4jSpyLogDelegator
The above will depend on your logging library. See the docs at https://code.google.com/archive/p/log4jdbc-log4j2 for further info
Sample Output:
10:44:29.400 [main] DEBUG jdbc.sqlonly - org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:70)
5. select memberrole0_.member_id as member_i2_12_0_, memberrole0_.id as id1_12_0_, memberrole0_.id
as id1_12_1_, memberrole0_.member_id as member_i2_12_1_, memberrole0_.role_id as role_id3_12_1_,
role1_.id as id1_17_2_, role1_.name as name2_17_2_ from member_roles memberrole0_ left outer
join roles role1_ on memberrole0_.role_id=role1_.id where memberrole0_.member_id=104
10:44:29.402 [main] INFO jdbc.resultsettable -
|----------|---|---|----------|--------|---|-----|
|member_id |id |id |member_id |role_id |id |name |
|----------|---|---|----------|--------|---|-----|
|----------|---|---|----------|--------|---|-----|
You can do it using the datasource-proxy, as I described in this post.
Assuming your application expects a dataSource
bean (e.g. via @Resource
), this is how you can configure datasource-proxy
:
<bean id="actualDataSource" class="bitronix.tm.resource.jdbc.PoolingDataSource" init-method="init"
destroy-method="close">
<property name="className" value="bitronix.tm.resource.jdbc.lrc.LrcXADataSource"/>
<property name="uniqueName" value="actualDataSource"/>
<property name="minPoolSize" value="0"/>
<property name="maxPoolSize" value="5"/>
<property name="allowLocalTransactions" value="false" />
<property name="driverProperties">
<props>
<prop key="user">${jdbc.username}</prop>
<prop key="password">${jdbc.password}</prop>
<prop key="url">${jdbc.url}</prop>
<prop key="driverClassName">${jdbc.driverClassName}</prop>
</props>
</property>
</bean>
<bean id="proxyDataSource" class="net.ttddyy.dsproxy.support.ProxyDataSource">
<property name="dataSource" ref="testDataSource"/>
<property name="listener">
<bean class="net.ttddyy.dsproxy.listener.ChainListener">
<property name="listeners">
<list>
<bean class="net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener">
<property name="logLevel" value="INFO"/>
</bean>
<bean class="net.ttddyy.dsproxy.listener.DataSourceQueryCountListener"/>
</list>
</property>
</bean>
</property>
</bean>
<alias name="proxyDataSource" alias="dataSource"/>
Now the Hibernate output vs datasource-proxy:
INFO [main]: n.t.d.l.CommonsQueryLoggingListener - Name:, Time:1, Num:1, Query:{[select company0_.id as id1_6_, company0_.name as name2_6_ from Company company0_][]}
INFO [main]: n.t.d.l.CommonsQueryLoggingListener - Name:, Time:0, Num:1, Query:{[insert into WarehouseProductInfo (id, quantity) values (default, ?)][19]}
INFO [main]: n.t.d.l.CommonsQueryLoggingListener - Name:, Time:0, Num:1, Query:{[insert into Product (id, code, company_id, importer_id, name, version) values (default, ?, ?, ?, ?, ?)][phoneCode,1,-5,Phone,0]}
The datasource-proxy
queries contain parameter values and you can even add custom JDBC statement interceptors so that you can catch N+1 query issues right from your integration tests.
<!-- A time/date based rolling appender -->
<appender name="FILE" class="org.apache.log4j.RollingFileAppender">
<param name="File" value="logs/system.log" />
<param name="Append" value="true" />
<param name="ImmediateFlush" value="true" />
<param name="MaxFileSize" value="200MB" />
<param name="MaxBackupIndex" value="100" />
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d %d{Z} [%t] %-5p (%F:%L) - %m%n" />
</layout>
</appender>
<appender name="journaldev-hibernate" class="org.apache.log4j.RollingFileAppender">
<param name="File" value="logs/project.log" />
<param name="Append" value="true" />
<param name="ImmediateFlush" value="true" />
<param name="MaxFileSize" value="200MB" />
<param name="MaxBackupIndex" value="50" />
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d %d{Z} [%t] %-5p (%F:%L) - %m%n" />
</layout>
</appender>
<logger name="com.journaldev.hibernate" additivity="false">
<level value="DEBUG" />
<appender-ref ref="journaldev-hibernate" />
</logger>
<logger name="org.hibernate" additivity="false">
<level value="INFO" />
<appender-ref ref="FILE" />
</logger>
<logger name="org.hibernate.type" additivity="false">
<level value="TRACE" />
<appender-ref ref="FILE" />
</logger>
<root>
<priority value="INFO"></priority>
<appender-ref ref="FILE" />
</root>
The solution is correct but logs also all bindings for the result objects. To prevent this it's possibile to create a separate appender and enable filtering, for example:
<!-- A time/date based rolling appender -->
<appender name="FILE_HIBERNATE" class="org.jboss.logging.appender.DailyRollingFileAppender">
<errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
<param name="File" value="${jboss.server.log.dir}/hiber.log"/>
<param name="Append" value="false"/>
<param name="Threshold" value="TRACE"/>
<!-- Rollover at midnight each day -->
<param name="DatePattern" value="'.'yyyy-MM-dd"/>
<layout class="org.apache.log4j.PatternLayout">
<!-- The default pattern: Date Priority [Category] Message\n -->
<param name="ConversionPattern" value="%d %-5p [%c] %m%n"/>
</layout>
<filter class="org.apache.log4j.varia.StringMatchFilter">
<param name="StringToMatch" value="bind" />
<param name="AcceptOnMatch" value="true" />
</filter>
<filter class="org.apache.log4j.varia.StringMatchFilter">
<param name="StringToMatch" value="select" />
<param name="AcceptOnMatch" value="true" />
</filter>
<filter class="org.apache.log4j.varia.DenyAllFilter"/>
</appender>
<category name="org.hibernate.type">
<priority value="TRACE"/>
</category>
<logger name="org.hibernate.type">
<level value="TRACE"/>
<appender-ref ref="FILE_HIBERNATE"/>
</logger>
<logger name="org.hibernate.SQL">
<level value="TRACE"/>
<appender-ref ref="FILE_HIBERNATE"/>
</logger>
**If you want hibernate to print generated sql queries with real values instead of question marks.**
**add following entry in hibernate.cfg.xml/hibernate.properties:**
show_sql=true
format_sql=true
use_sql_comments=true
**And add following entry in log4j.properties :**
log4j.logger.org.hibernate=INFO, hb
log4j.logger.org.hibernate.SQL=DEBUG
log4j.logger.org.hibernate.type=TRACE
log4j.appender.hb=org.apache.log4j.ConsoleAppender
log4j.appender.hb.layout=org.apache.log4j.PatternLayout
This answer is a little variance for the question. Sometimes, we only need the sql only for debug purposes in runtime. In that case, there are a more easy way, using debug on editors.
This is for hibernate 3. I'm not sure that this work on other versions.
mysql jdbc driver has already provide a convenient to meet this requirement, you must at least the have the jar version >= mysql-connect-jar-5.1.6.jar
step 1: [configure your jdbc.url to add logger and custom logging]
jdbc.url=jdbc:mysql://host:port/your_db?logger=com.mysql.jdbc.log.Slf4JLogger&profileSQL=true&profilerEventHandler=com.xxx.CustomLoggingProfilerEventHandler
now, it is using slf4j logging, if your default logging is log4j, you must add slf4j-api, slf4j-log4j12 dependencies to use slf4j logging
step 2: [write your custom logging]
package com.xxx;
import java.sql.SQLException;
import java.util.Properties;
import com.mysql.jdbc.Connection;
import com.mysql.jdbc.log.Log;
public class CustomLoggingProfilerEventHandler implements ProfilerEventHandler {
private Log log;
public LoggingProfilerEventHandler() {
}
public void consumeEvent(ProfilerEvent evt) {
/**
* you can only print the sql as this.log.logInfo(evt.getMessage())
* you can adjust your sql print log level with: DEBUG,INFO
* you can also handle the message to meet your requirement
*/
this.log.logInfo(evt);
}
public void destroy() {
this.log = null;
}
public void init(Connection conn, Properties props) throws SQLException {
this.log = conn.getLog();
}
}
I like this for log4j:
log4j.logger.org.hibernate.SQL=trace
log4j.logger.org.hibernate.engine.query=trace
log4j.logger.org.hibernate.type=trace
log4j.logger.org.hibernate.jdbc=trace
log4j.logger.org.hibernate.type.descriptor.sql.BasicExtractor=error
log4j.logger.org.hibernate.type.CollectionType=error
Logging works but not exactly you want or i wanted some time ago, but P6Spy does work perfectly,
here is the simple tutorial to implement as well MKYONG tutorial for P6Spy.
for me it worked like charm.
Get the “p6spy-install.jar“
Extract the p6spy-install.jar
file, look for p6spy.jar
and spy.properties
Add p6spy.jar
into your project library dependency
Modify your database configuration file. You need to replace your existing JDBC driver with P6Spy JDBC driver – com.p6spy.engine.spy.P6SpyDriver
Original is MySQL JDBC driver – com.mysql.jdbc.Driver
<session-factory>
<property name="hibernate.bytecode.use_reflection_optimizer">false</property>
<property name="hibernate.connection.driver_class">com.mysql.jdbc.Driver</property>
<property name="hibernate.connection.password">password</property>
<property name="hibernate.connection.url">jdbc:mysql://localhost:3306/mkyong</property>
<property name="hibernate.connection.username">root</property>
<property name="hibernate.dialect">org.hibernate.dialect.MySQLDialect</property>
<property name="show_sql">true</property>
</session-factory>
Changed it to P6Spy JDBC driver – com.p6spy.engine.spy.P6SpyDriver
<session-factory>
<property name="hibernate.bytecode.use_reflection_optimizer">false</property>
<property name="hibernate.connection.driver_class">com.p6spy.engine.spy.P6SpyDriver
</property>
<property name="hibernate.connection.password">password</property>
<property name="hibernate.connection.url">jdbc:mysql://localhost:3306/mkyong</property>
<property name="hibernate.connection.username">root</property>
<property name="hibernate.dialect">org.hibernate.dialect.MySQLDialect</property>
<property name="show_sql">true</property>
</session-factory>
spy.properties
Replace the real driver
with your existing MySQL JDBC driver
realdriver=com.mysql.jdbc.Driver
#specifies another driver to use
realdriver2=
#specifies a third driver to use
realdriver3=
Change the Log file location Change the log file location in logfile property, all SQL statements will log into this file.
Windows
logfile = c:/spy.log
*nix
logfile = /srv/log/spy.log
“spy.properties”
to project classpathCopy “spy.properties”
to your project root folder, make sure your project can locate “spy.properties”, else it will prompt “spy.properties”
file not found exception.
<appender name="console" class="org.apache.log4j.ConsoleAppender">
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern"
value="%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n" />
</layout>
</appender>
<logger name="org.hibernate" additivity="false">
<level value="INFO" />
<appender-ref ref="console" />
</logger>
<logger name="org.hibernate.type" additivity="false">
<level value="TRACE" />
<appender-ref ref="console" />
</logger>
Using Hibernate 4 and slf4j/log4j2 , I tried adding the following in my log4j2.xml configuration :
<Logger name="org.hibernate.type.descriptor.sql.BasicBinder" level="trace" additivity="false">
<AppenderRef ref="Console"/>
</Logger>
<Logger name="org.hibernate.type.EnumType" level="trace" additivity="false">
<AppenderRef ref="Console"/>
</Logger>
But without success.
I found out through this thread that the jboss-logging framework used by hibernate needed to be configured in order to log through slf4j. I added the following argument to the VM arguments of the application:
-Dorg.jboss.logging.provider=slf4j
And it worked like a charm.
You can log this:
net.sf.hibernate.hql.QueryTranslator
Output example:
2013-10-31 14:56:19,029 DEBUG [net.sf.hibernate.hql.QueryTranslator] HQL: select noti.id, noti.idmicrosite, noti.fcaducidad, noti.fpublicacion, noti.tipo, noti.imagen, noti.visible, trad.titulo, trad.subtitulo, trad.laurl, trad.urlnom, trad.fuente, trad.texto from org.ibit.rol.sac.micromodel.Noticia noti join noti.traducciones trad where index(trad)='ca' and noti.visible='S' and noti.idmicrosite=985 and noti.tipo=3446
2013-10-31 14:56:19,029 DEBUG [net.sf.hibernate.hql.QueryTranslator] SQL: select noticia0_.NOT_CODI as x0_0_, noticia0_.NOT_MICCOD as x1_0_, noticia0_.NOT_CADUCA as x2_0_, noticia0_.NOT_PUBLIC as x3_0_, noticia0_.NOT_TIPO as x4_0_, noticia0_.NOT_IMAGEN as x5_0_, noticia0_.NOT_VISIB as x6_0_, traduccion1_.NID_TITULO as x7_0_, traduccion1_.NID_SUBTIT as x8_0_, traduccion1_.NID_URL as x9_0_, traduccion1_.NID_URLNOM as x10_0_, traduccion1_.NID_FUENTE as x11_0_, traduccion1_.NID_TEXTO as x12_0_ from GUS_NOTICS noticia0_ inner join GUS_NOTIDI traduccion1_ on noticia0_.NOT_CODI=traduccion1_.NID_NOTCOD where (traduccion1_.NID_CODIDI='ca' )and(noticia0_.NOT_VISIB='S' )and(noticia0_.NOT_MICCOD=985 )and(noticia0_.NOT_TIPO=3446 )
All of the answers here are helpful, but if you're using a Spring application context XML to setup your session factory, setting the log4j SQL level variable only gets you part of the way there, you also have to set the hibernate.show_sql variable in the app context itself to get Hibernate to start actually showing the values.
ApplicationContext.xml has:
<property name="hibernateProperties">
<value>
hibernate.jdbc.batch_size=25
... <!-- Other parameter values here -->
hibernate.show_sql=true
</value>
</property>
And your log4j file needs
log4j.logger.org.hibernate.SQL=DEBUG
Hibernate shows query and their parameter values in different lines.
If you are using application.properties in spring boot and you can use below highlighted parameter in application.properties.
org.hibernate.SQL will show queries
org.hibernate.type will show all parameter values, which will map with select , insert and update queries. logging.level.org.hibernate.type=TRACE
org.hibernate.type.EnumType will show enum type parameter value
example ::
2018-06-14 11:06:28,217 TRACE [main] [EnumType.java : 321] Binding [active] to parameter: [1]
sql.BasicBinder will show integer, varchar, boolean type parameter value
example ::
The simplest solution for me is implementing a regular stringReplace to replace parameter inputs with parameter values (treating all parameters as string, for simplicity):
String debugedSql = sql;
//then, for each named parameter
debugedSql = debugedSql.replaceAll(":"+key, "'"+value.toString()+"'");
//and finnaly
println(debugedSql);
or something similar for positional parameters (?).
Take care of null values and specific value types like date, if you want a run ready sql to be logged.
hibernate-types has a utility method to log jpql and criteria queries. More details can be found in the autors's blog post. Here is an example using jpql:
Query jpql = entityManager.createQuery("""
select
YEAR(p.createdOn) as year,
count(p) as postCount
from
Post p
group by
YEAR(p.createdOn)
""", Tuple.class
);
String sql = SQLExtractor.from(jpql);
sql
variable has the following value:
SELECT
extract(YEAR FROM sqlextract0_.created_on) AS col_0_0_,
count(sqlextract0_.id) AS col_1_0_
FROM
post p
GROUP BY
extract(YEAR FROM p.created_on)
It can be copy-pasted into the db console as is.