Mattias Lövström
Sep 3, 2010
  9428
(2 votes)

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

Comments

Svante Seleborg
Svante Seleborg Sep 21, 2010 10:33 AM

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!

Sep 21, 2010 10:33 AM

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.

Sep 21, 2010 10:33 AM

Wow! :-) This is great!

Marthin Freij
Marthin Freij Sep 21, 2010 10:33 AM

Awesome! Thank you Mattias!

Sep 21, 2010 10:33 AM

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
Svante Seleborg Sep 21, 2010 10:33 AM

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!

Sep 21, 2010 10:33 AM

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.

Sep 30, 2010 04:33 PM

This is a very useful tool, thanks!

Nikolaos Georgiou
Nikolaos Georgiou Nov 2, 2011 01:06 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

Apr 13, 2012 10:42 AM

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"/>



Nov 21, 2016 11:39 AM

Download link no longer works.

Please login to comment.
Latest blogs
Headless with Content Delivery API

Hello Everyone, This blog will help anyone who wants to start or build an architecture of headless using content delivery api. When we shifted to...

PuneetGarg | Oct 15, 2024

Introducing Optimizely Graph Source .NET SDK

Overview Of Optimizely Graph Optimizely Graph is a cutting-edge, headless content management solution designed to integrate seamlessly with any...

Jake Minard | Oct 15, 2024

SEO redirects in .NET + Optimizely

Nice and easy way to add necessary SEO redirects

Damian Smutek | Oct 14, 2024 | Syndicated blog

Multiple Anonymous Carts created from external Head front fetching custom Api

Scenario and Problem Working in a custom headless architecture where a NextJs application hosted in Vercel consumes a custom API built in a...

David Ortiz | Oct 11, 2024