Views: 7520
Number of votes: 2
Average rating:

Troubleshooting database tool – SqlClientLogger

This tool logs every call to the database done by the application layer with a stack trace and a time it took to execute the query. The benefits of using this tool is that it prints out a stack trace so it’s easy to locate what code that generates the database call. The logs are written to log4net and should appear in the sites log file.

Download

Download SqlClientLogger

Requirements:

.Net 2.0

Log4Net

Installation

Drop the assembly “SqlClientLogger.dll” to your sites bin/folder

Replace the SqlClient database provider with the logging SqlClient database provider in web.config

<configuration>
  ...
  <system.data>
    <DbProviderFactories>
      <remove invariant="System.Data.SqlClient" />
      <add name="System.Data.SqlClient"
           invariant="System.Data.SqlClient"
           description=".Net Framework Data Provider for SqlServer with logging of executed commands"
           type="SqlClientLogger.DatabaseFactory, SqlClientLogger"/>
    </DbProviderFactories>
  </system.data> 
</configuration>
 

Usage

When the SqlClientLogger is installed on the site it is going to send log4net messages using the logger “SqlClientLogger”.

Log4Net logger levels

DEBUG – prints out database command, stack trace and execution time

INFO – prints out database command and execution time.

WARN – prints out database command, stack trace and execution time the execution time is over 500 ms

Sample of how to configure it in the file

EPiServerLog.config (or where your log4net configuration is)

<log4net>
  ...
  <logger name="SqlClientLogger">
    <level value="DEBUG" />
  </logger>

Duration Filter

Duration threshold can be set in the appSettings in the web.config file for the keys

SqlClientLoggerDurationFilterMs – a threshold for all logged database calls

SqlClientLoggerDurationWarnFilterMs - a threshold for trigger a warning message, the default is set to 500 ms

Example of setting duration threshold to 10 ms and warning threshold to 100 ms

<configuration>
  ...
  <appSettings>
    <add key="SqlClientLoggerDurationFilterMs" value="10"/>
    <add key="SqlClientLoggerDurationWarnFilterMs" value="100"/>
  </appSettings>

Remarks

SqlClientLogger are not going to work with LinqToSql sense it using the SqlClient database providers directly without looking at the configuration. To trace LinqToSql calls please use LinqToSqlLogger.zip

Example of output:

In this example we can see the stored procedure “netPropertyTree” is executed without any arguments are  executed by the user control in Templates/Public/Pages/DodumentList.aspx and its takes 685 milliseconds.

SqlClientLogger

Sep 03, 2010

Svante Seleborg
(By Svante Seleborg, 9/21/2010 12:33:34 PM)

That's a very nice addition to the toolbox!

Just so it's not forgotten, I'd like to point out how easy it is to use the SQL Profiler to start with. I've used it extensively recently, and it should give you a great head-start. Then, in really difficult cases where you can't determine the caller from the arguments displayed by the profiler, or other more dynamic cases, I'd surely try your client-side SQL logger out!

An advantage with the SQL Profiler is that it's really easy to filter out just the calls that for example take more than 100ms and are made to a specific stored procedure.

It would be nice if the client side logger had similar filtering ability, since it's easy to be totally swamped by the size and amount of logging performed. I believe log4net supports implementation of such filters, so you could have it filter on similar conditions as the SQL Profiler.

Still, nice work!

mattias.lovstrom
(By mattias.lovstrom, 9/21/2010 12:33:34 PM)

Thanks Svante,

I totally agree with you about the SQL profiler, but in a multithreaded production environment it can be very hard to see what code responsible for generating the actual database call.
Regarding you question about filter on execution time, I have added a constant filter on log4nets WARN level to 500ms. But what I can do is adding an appConfig setting to make this configurable – but it will come in the next release if the tool seams to be useful.

steve
(By steve, 9/21/2010 12:33:35 PM)

Wow! :-) This is great!

Marthin Freij
(By Marthin Freij, 9/21/2010 12:33:35 PM)

Awesome! Thank you Mattias!

mattias.lovstrom
(By mattias.lovstrom, 9/21/2010 12:33:35 PM)

And after so nice comments (and that I have to change it anyway for the LinToSql support) I have added a duration threshold that can be set in the appSettings in the web.config file for the keys
SqlClientLoggerDurationFilterMs – a threshold for all logged database calls
SqlClientLoggerDurationWarnFilterMs - a threshold for trigger a warning message, the default is set to 500 ms

Example:

...




Svante Seleborg
(By Svante Seleborg, 9/21/2010 12:33:35 PM)

That was a record response to blog comments I think! I wish I could be that responsive... I'll be sure to give your tool a try soon, I have a very specific 'victim' in mind... Thanks!

pb
(By pb, 9/21/2010 12:33:35 PM)

My poor mans version of this has been to add a throw statement into a stored procedure to get a call stack back on the site, this is much more useful and less intrusive ;-) Really like the threshold as well. Great work as always, will try it out the next time I get a chance.

klaswikstrom
(By klaswikstrom, 9/30/2010 6:33:34 PM)

This is a very useful tool, thanks!

Nikolaos Georgiou
(By Nikolaos Georgiou, 11/2/2011 2:06:57 PM)

Hello,

does this still work in .NET 4? I'm trying to set it up but it is ignored, nothing is logged in the log files.

Maybe DbProviderFactories don't behave the same anymore? I have this link that makes me think it doesn't work anymore:
http://social.msdn.microsoft.com/Forums/en-US/adodotnetentityframework/thread/02461dcf-23d2-4910-854a-bbdbfb2530b3/


Also I tried to just change the providerName to "SqlClientLoggerProvider" on both my connection strings and the DbProviderFactories section but that gives a weird exception: The license for this installation does not allow using Oracle as a database.

Looking into the EPiServer assembly with ILSpy I can see why I get the Oracle exception:

if (DataAccessBase.ConnectionSettings.ProviderName.EndsWith("SqlClient"))
{
DataAccessBase._databaseFactory = new SqlDatabaseFactory(DataAccessBase.ConnectionSettings);
}
else
{
DataAccessBase._databaseFactory = new OracleDatabaseFactory(DataAccessBase.ConnectionSettings);
}

So that's straight forward. If I rename now the provider name to LoggerSqlClient, I get a different exception:

Parameter discovery is not supported for connections using GenericDatabase. You must specify the parameters explicitly, or configure the connection to use a type deriving from Database that supports parameter discovery.

The interesting thing here is that at this point I do get log entries from SqlClientLogger but then the exception comes...

Has anyone had better luck with .NET 4 ?

Thanks

mattias.lovstrom
(By mattias.lovstrom, 4/13/2012 12:42:21 PM)

Sense in .NET 4 the machine configuration for this system data providers is immutable. We need to create own name for this.
In connectionstrings.config


...


In web.config



invariant="LoggingSqlClient"
description=".Net Framework Data Provider for SqlServer with logging of executed commands"
type="SqlClientLogger.DatabaseFactory, SqlClientLogger"/>



mgrzegorzak
(By mgrzegorzak, 11/21/2016 12:39:53 PM)

Download link no longer works.

Please login to comment.