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
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.
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!
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.
Wow! :-) This is great!
Awesome! Thank you Mattias!
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:
...
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!
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.
This is a very useful tool, thanks!
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
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"/>
Download link no longer works.