Seeing the underlying SQL in the Spring JdbcTemplate?

Question

I am learning about the wonders of JdbcTemplate and NamedParameterJdbcTemplate. I like what I see, but is there any easy way to see the underlying SQL that it ends up executing? I'd like to see this for debug purposes (in order to for example debug the resulting SQL in an outside tool).

Answer 1

The Spring documentation says they're logged at DEBUG level:

All SQL issued by this class is logged at the DEBUG level under the category corresponding to the fully qualified class name of the template instance (typically JdbcTemplate, but it may be different if you are using a custom subclass of the JdbcTemplate class).

In XML terms, you need to configure the logger something like:

<category name="org.springframework.jdbc.core.JdbcTemplate">
    <priority value="debug" />
</category>

This subject was however discussed here a month ago and it seems not as easy to get to work as in Hibernate and/or it didn't return the expected information: Spring JDBC is not logging SQL with log4j This topic under each suggests to use P6Spy which can also be integrated in Spring according this article.

Answer 2

This works for me with org.springframework.jdbc-3.0.6.RELEASE.jar. I could not find this anywhere in the Spring docs (maybe I'm just lazy) but I found (trial and error) that the TRACE level did the magic.

I'm using log4j-1.2.15 along with slf4j (1.6.4) and properties file to configure the log4j:

log4j.logger.org.springframework.jdbc.core = TRACE

This displays both the SQL statement and bound parameters like this:

Executing prepared SQL statement [select HEADLINE_TEXT, NEWS_DATE_TIME from MY_TABLE where PRODUCT_KEY = ? and NEWS_DATE_TIME between ? and ? order by NEWS_DATE_TIME]
Setting SQL statement parameter value: column index 1, parameter value [aaa], value class [java.lang.String], SQL type unknown
Setting SQL statement parameter value: column index 2, parameter value [Thu Oct 11 08:00:00 CEST 2012], value class [java.util.Date], SQL type unknown
Setting SQL statement parameter value: column index 3, parameter value [Thu Oct 11 08:00:10 CEST 2012], value class [java.util.Date], SQL type unknown

Not sure about the SQL type unknown but I guess we can ignore it here

For just an SQL (i.e. if you're not interested in bound parameter values) DEBUG should be enough.

Answer 3

Parameter values seem to be printed on TRACE level. This worked for me:

log4j.logger.org.springframework.jdbc.core.JdbcTem plate=DEBUG, file
log4j.logger.org.springframework.jdbc.core.StatementCreatorUtils=TRACE, file

Console output:

02:40:56,519 TRACE http-bio-8080-exec-13 core.StatementCreatorUtils:206 - Setting SQL statement parameter value: column index 1, parameter value [Tue May 31 14:00:00 CEST 2005], value class [java.util.Date], SQL type unknown
02:40:56,528 TRACE http-bio-8080-exec-13 core.StatementCreatorUtils:206 - Setting SQL statement parameter value: column index 2, parameter value [61], value class [java.lang.Integer], SQL type unknown
02:40:56,528 TRACE http-bio-8080-exec-13 core.StatementCreatorUtils:206 - Setting SQL statement parameter value: column index 3, parameter value [80], value class [java.lang.Integer], SQL type unknown

Answer 4

This worked for me with log4j2 and xml parameters:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="debug">
    <Properties>
        <Property name="log-path">/some_path/logs/</Property>
        <Property name="app-id">my_app</Property>
    </Properties>

    <Appenders>
        <RollingFile name="file-log" fileName="${log-path}/${app-id}.log"
            filePattern="${log-path}/${app-id}-%d{yyyy-MM-dd}.log">
            <PatternLayout>
                <pattern>[%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n
                </pattern>
            </PatternLayout>
            <Policies>
                <TimeBasedTriggeringPolicy interval="1"
                    modulate="true" />
            </Policies>
        </RollingFile>

        <Console name="console" target="SYSTEM_OUT">
            <PatternLayout
                pattern="[%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n" />
        </Console>
    </Appenders>
    <Loggers>

        <Logger name="org.springframework.jdbc.core" level="trace" additivity="false">
            <appender-ref ref="file-log" />
            <appender-ref ref="console" />
        </Logger>

        <Root level="info" additivity="false">
            <appender-ref ref="file-log" />
            <appender-ref ref="console" />
        </Root>
    </Loggers>

</Configuration>

Result console and file log was:

JdbcTemplate - Executing prepared SQL query
JdbcTemplate - Executing prepared SQL statement [select a, b from c where id = ? ]
StatementCreatorUtils - Setting SQL statement parameter value: column index 1, parameter value [my_id], value class [java.lang.String], SQL type unknown

Just copy/past

HTH

Answer 5

I use this line for Spring Boot applications:

logging.level.org.springframework.jdbc.core = TRACE

This approach pretty universal and I usually use it for any other classes inside my application.

Answer 6

I'm not 100% sure what you're getting at since usually you will pass in your SQL queries (parameterized or not) to the JdbcTemplate, in which case you would just log those. If you have PreparedStatements and you don't know which one is being executed, the toString method should work fine. But while we're on the subject, there's a nice Jdbc logger package here which will let you automatically log your queries as well as see the bound parameters each time. Very useful. The output looks something like this:

executing PreparedStatement: 'insert into ECAL_USER_APPT
(appt_id, user_id, accepted, scheduler, id) values (?, ?, ?, ?, null)'
     with bind parameters: {1=25, 2=49, 3=1, 4=1} 

Answer 7

Try adding in log4j.xml

<!--  enable query logging -->
<category name="org.springframework.jdbc.core.JdbcTemplate">
    <priority value="DEBUG" />
</category>

<!-- enable query logging for SQL statement parameter value -->
<category name="org.springframework.jdbc.core.StatementCreatorUtils">
    <priority value="TRACE" />
</category>

your logs looks like:

DEBUG JdbcTemplate:682 - Executing prepared SQL query
DEBUG JdbcTemplate:616 - Executing prepared SQL statement [your sql query]
TRACE StatementCreatorUtils:228 - Setting SQL statement parameter value: column index 1, parameter value [param], value class [java.lang.String], SQL type unknown