[IBATISNET-80] Store additional <statement> debug information in the MDC

• Type: Sub-task
• Status: Closed
• Priority: Trivial
• Resolution: Won't Fix
• Fix Version/s: DataMapper 1.3
• Component/s: DataAccess
• Assignee: Gilles Bayon
• Reporter: liu ron
• Created: 14/Jun/05 06:57
• Updated: 11/Jul/05 00:59
• Resolved: 11/Jul/05 00:59

Description

I was trying to debug some strange entires in my log files today (I added the ... part):

PreparedStatement : [SELECT ...]
Parameters: [@param0=[value,1]]
Types: [@param0=[Int32, System.Int32]]
PreparedStatement : [SELECT ...]
Parameters: [@param0=[value,1]]
Types: [@param0=[Int32, System.Int32]]
PreparedStatement : [SELECT ...]
Parameters: [@param0=[value,1]]
Types: [@param0=[Int32, System.Int32]]
PreparedStatement : [SELECT ...]
Parameters: [@param0=[value,1]]

I realized that I had 100 <statement>s spread across 15 sql map files. It had been a while since I last looked at this project so I had no clue were those statements were being called from and why there were so many of them. It took me a while to finally track down what was going on. It would have been very helpful to see something like this in the log files:

Statement: [User.GetOne] PreparedStatement : [SELECT ...]
Statement: [User.GetOne] Parameters: [@param0=[value,1]]
Statement: [User.GetOne] Types: [@param0=[Int32, System.Int32]]
Statement: [User.GetOne] PreparedStatement : [SELECT ...]
Statement: [User.GetOne] Parameters: [@param0=[value,1]]
Statement: [User.GetOne] Types: [@param0=[Int32, System.Int32]]
Statement: [User.GetOne] PreparedStatement : [SELECT ...]
Statement: [User.GetOne] Parameters: [@param0=[value,1]]
Statement: [User.GetOne] Types: [@param0=[Int32, System.Int32]]
Statement: [User.GetOne] PreparedStatement : [SELECT ...]
Statement: [User.GetOne] Parameters: [@param0=[value,1]]

I'm sure not everyone wants that much information; some of us want more even more! A flexible solution may be to add this information to the log4net's MDC scope. The line that creates the initial sql log:

if (_logger.IsDebugEnabled)

{ _logger.Debug("PreparedStatement : [" + command.CommandText + "]"); }

could be changed to this:

if (_logger.IsDebugEnabled)

{ log4net.MDC.Set(LOG4NET_MDC_PREFIX + "StatementCacheModelName", statement.CacheModelName); log4net.MDC.Set(LOG4NET_MDC_PREFIX + "StatementId", statement.Id); log4net.MDC.Set(LOG4NET_MDC_PREFIX + "StatementResultMapId", statement.ResultMap.Id); _logger.Debug("PreparedStatement : [" + command.CommandText + "]"); }

In my case, I would have used this pattern in my Appender:

"%p %d (%c:%L) - Statement: %X

{ibatisnet:StatementId}

%m%n"

Maybe this additional information could be used as a way to dispaly execution time statistics:

http://issues.apache.org/jira/browse/IBATIS-151

"%p %d (%c:%L) - Statement: %X

{ibatisnet:StatementId}

%X

{ibatisnet:ExecutionTime}

%m%n"