log4jdbc를 활용하여 쿼리 로그 남기기

1. 필요한 라이브러리 다운 로드
 - log4jdbc3-1.1.jar(If you are using JDK 1.4 or 1.5, you should use the JDBC 3 version of log4jdbc.)
 - slf4j-api-1.5.0.jar(log4jdbc와 logging 서비스 연동을 위한 API 제공)
 - slf4j-log4j12-1.5.2.jar(log4jdbc와 Log4j 기반의 Logging 서비스 연동을 위한 구현 라이브러리 제공)

2. DataSource 서비스 속성 정의 파일 정의

<bean id="dataSource" class="org.apache.commons.dbcp.BasicDataSource"

 destroy-method="close">

	<property name="driverClassName" 

	value="net.sf.log4jdbc.DriverSpy"/>

	<property name="url" 

	value="jdbc:log4jdbc:mysql://localhost:3306/member?useUnicode=true

	&characterEncoding=utf8"/>

	<property name="username" value="member"/>

	<property name="password" value="member"/>

	<property name="maxActive" value="30"/>

	<property name="maxIdle" value="3"/>

	<property name="maxWait" value="-1"/>

</bean>

3. Logger 정의


 - jdbc.sqlonly : SQL문만을 로그로 남기며, PreparedStatement일 경우 관련된 argument 값으로 대체된 SQL문이 보여진다. 

 - jdbc.sqltiming : SQL문과 해당 SQL을 실행시키는데 수행된 시간 정보(milliseconds)를 포함한다. 

 - jdbc.audit : ResultSet을 제외한 모든 JDBC 호출 정보를 로그로 남긴다. 많은 양의 로그가 생성되므로 특별히 JDBC 문제를 추적해야 할 필요가 있는 경우를 제외하고는 사용을 권장하지 않는다. 

 - jdbc.resultset : ResultSet을 포함한 모든 JDBC 호출 정보를 로그로 남기므로 매우 방대한 양의 로그가 생성된다. 

 - 예) log4j.xml

<?xml version="1.0" encoding="UTF-8"?>

<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration 

    xmlns:log4j="http://jakarta.apache.org/log4j/" debug="false">

    

    <appender name="console" class="org.apache.log4j.ConsoleAppender">

        <layout class="org.apache.log4j.PatternLayout">

            <param name="ConversionPattern" value="%d %5p [%c] %m%n" />

        </layout>   

    </appender>

    

	<appender name="rollingFile" 

class="org.apache.log4j.RollingFileAppender">

		<param name="File" value="C:\\logs\\error\\error.log"/>

		<param name="Append" value="true"/> 

		<param name="MaxFileSize" value="100MB"/>    

		<param name="MaxBackupIndex" value="2"/>    

	    <layout class="org.apache.log4j.PatternLayout">

	        <param name="ConversionPattern" value="%d %p [%c]-%m%n" />

	    </layout>   

	</appender>  

    

    <logger name="org.springframework.jdbc">

        <level value="DEBUG"/>

        <appender-ref ref="console"/>

    </logger> 

        

    <logger name="com.mimul">

        <level value="DEBUG"/>

        <appender-ref ref="console"/>

        <appender-ref ref="rollingFile"/>

    </logger>     

    

    <logger name="org.apache.struts">

        <level value="DEBUG"/>

        <appender-ref ref="console"/>

        <appender-ref ref="rollingFile"/>

    </logger>  

    

    	<!-- log SQL (pre-execution) plus exceptions caused by SQL -->

	<logger name="jdbc.sqlonly" additivity="false">

		<level value="DEBUG" />

		<appender-ref ref="console" />

		<appender-ref ref="rollingFile"/>

	</logger>


	<!-- log SQL with timing information, post execution -->

	<logger name="jdbc.sqltiming" additivity="false">

		<level value="DEBUG" />

		<appender-ref ref="console" />

		<appender-ref ref="rollingFile"/>

	</logger>


	<!-- only use the two logs below to trace ALL JDBC information,

		NOTE:  This can be very voluminous!  -->

	<!-- log all jdbc calls except ResultSet calls -->

	<logger name="jdbc.audit" additivity="false">

		<level value="DEBUG" />

		<appender-ref ref="console" />

		<appender-ref ref="rollingFile"/>

	</logger>


	<!-- log the jdbc ResultSet calls -->

	<logger name="jdbc.resultset" additivity="false">

		<level value="DEBUG" />

		<appender-ref ref="console" />

		<appender-ref ref="rollingFile"/>

	</logger>


	<!-- this log is for internal debugging of log4jdbc, itself -->

	<!-- debug logging for log4jdbc itself -->

	<logger name="log4jdbc.debug" additivity="false">

		<level value="DEBUG" />

		<appender-ref ref="console" />

		<appender-ref ref="rollingFile"/>

	</logger>

	<root>

		<level value="DEBUG" />

		<appender-ref ref="console" />

		<appender-ref ref="rollingFile"/>

	</root> 

</log4j:configuration>

4. 로그 처리 결과 

 
2008-10-24 10:23:02 [jdbc.audit] - <2. Connection.setAutoCommit(true)

2008-10-24 10:23:02 [java.sql.Connection] - <{conn-100003} Connection>

2008-10-24 10:23:02 [java.sql.Connection] - <{conn-100003} 

Preparing Statement:      

select count(userid) as total from MEMBER   where userid = ? 

and password = ?  >

2008-10-24 10:23:02 [jdbc.audit] - 

<2. Connection.prepareStatement(

select count(userid) as total from MEMBER where

 userid = ? and password = ? ) 

2008-10-24 10:23:02 [jdbc.audit] - 

<2. PreparedStatement.setQueryTimeout(0)

2008-10-24 10:23:02 [jdbc.audit] - 

<2. PreparedStatement.setString(1, "pepsi") 

2008-10-24 10:23:02 [jdbc.audit] - 

<2. PreparedStatement.setString(2, "1234") 

2008-10-24 10:23:02 [java.sql.PreparedStatement] - 

<{pstm-100004} 

Executing Statement: 

select count(userid) as total from MEMBER where userid = ? and password = ?  >

2008-10-24 10:23:02 [java.sql.PreparedStatement]

 - <{pstm-100004} 

Parameters: [pepsi, 1234]>

2008-10-24 10:23:02,281 DEBUG [java.sql.PreparedStatement] - 

<{pstm-100004} Types: [java.lang.String, java.lang.String]>

2008-10-24 10:23:02,281 DEBUG [jdbc.sqlonly] - 

<2. select count(userid) as total from MEMBER where userid = 'pepsi' 

and password = '1234' >

2008-10-24 10:23:02,281 DEBUG [jdbc.sqltiming] -

<2. select count(userid) as total from MEMBER where userid = 'pepsi' 

and password = '1234'  

{executed in 0 msec}>

2008-10-24 10:23:02 [jdbc.audit] - <2. PreparedStatement.execute()  

2008-10-24 10:23:02 [jdbc.audit] - <2. PreparedStatement.getResultSet()

2008-10-24 10:23:02 [java.sql.ResultSet] - <{rset-100005} ResultSet>

2008-10-24 10:23:02 [jdbc.resultset] - <2. ResultSet.getType()

2008-10-24 10:23:02 [jdbc.resultset] - <2. ResultSet.next() returned true

2008-10-24 10:23:02 [jdbc.resultset] - <2. ResultSet.getMetaData() returned

2008-10-24 10:23:02 [jdbc.resultset] - <2. ResultSet.getInt(TOTAL) returned 1

2008-10-24 10:23:02 [jdbc.resultset] - <2. ResultSet.wasNull() returned false

2008-10-24 10:23:02 [jdbc.resultset] - <2. ResultSet.next() returned false

2008-10-24 10:23:02, [java.sql.ResultSet] - <{rset-100005} Header: [TOTAL]>

2008-10-24 10:23:02 [java.sql.ResultSet] - <{rset-100005} Result: [1]>

2008-10-24 10:23:02 [jdbc.audit] - <2. Connection.getMetaData()

2008-10-24 10:23:02 [jdbc.resultset] - <2. ResultSet.close()

2008-10-24 10:23:02 [jdbc.audit] - <2. PreparedStatement.close()

2008-10-24 10:23:02 [jdbc.audit] - <2. Connection.isClosed()

2008-10-24 10:23:02 [jdbc.audit] - <2. Connection.getAutoCommit()

2008-10-24 10:23:02 [jdbc.audit] - <2. Connection.clearWarnings() 

2008-10-24 10:23:02 [jdbc.audit] - <2. Connection.setAutoCommit(true)



jdbc.sqltiming 로그에 보면 실행된 FULL Query가 보일 것입니다.

[출처] : http://mimul.com/pebble/default/2008/10.html