Profiling Linq-to-SQL applications

Profiling - why?

When developing database driven applications - especially apps with many users and different usage patterns - database performance is key to application performance and the database is often the 'resource bottleneck' when it comes to scaling applications to cope with a larger number of users.

If a certain operation spends a bit more time, CPU, and other resources client side it is often not as big of a matter scalability-wise as if it spends time or resources database-side/server-side. As the number of users in a large system grow, the impact of query costs - and savings of reducing it - is often the single most important factor to look at to improve performance and scalability, and the cheapest way to improve scalability.

Additionally, a production environment will often differ from test/development in ways that can affect how queries behave:

• Applications are often used different in a production environment than what developers and designers envisioned; users may refresh 'screen x' twice as often as was envisioned during design and development, or use search filters in search screen differently than anyone thought.
• SQL Server will often execute queries differently on different systems; depending on data volumes, available resources, system load, system and db configuration, and many other factors.

Because of this, runtime profiling live production systems can sometimes reveal bottlenecks and/or room for improvements/optimization that would not show up during development/test/QA, or on dev/test systems.

Profiling tools

There are many great tools available for investigating database performance at runtime / in production environments. The Microsoft tool stack offer some nice stuff for Linq-to-SQL and SQL Server based apps:

• SQL Server Profiler is a really great tool that comes with the management tools for SQL Server (Standard edition and up, unfortunately it not available in Express edition).
• Linq-to-SQL has a built in logging feature that allows executed queries to be written to log files by simply attaching a textwriter to the datacontext object.

To take this a step further, I have decided to throw a new tool onto the stack for L2S developers: a brand new profiler specifically targeting Linq-to-SQL applications.

But before we take a look at the L2S Profiler, a brief look at what comes out-of-the-box with SQL Server and Linq-to-SQL, and then what the L2S Profiler brings to the table compared to the existing tool stack.

SQL Server Profiler

Although SQL Server Profiler goes a long way when it comes to pinpointing what queries are causing the most stress db-side, it provides information from the SQL Server side of things only. It is built as a generic tool for all kinds of SQL Server profiling - not only queries but targeting other kinds of database activity as well. But a missing part is the application side of it: where did that query come from, what [user actions/calls] led to it being executed etc. In a large application with many developers involved this can make it time consuming to determine another important aspect who's code is responsible for hitting the database too frequently, or with too heavy queries, etc.

Add to that that SQL Server Profiler is made for DBAs, sys-admins, developers, and must be manually set up in a production environment. It can't be controlled from within applications, and it requires the person using it to know what they're looking for. It requires access to and privileges on the database server which is not always available in hosted environments, or in locked-down customer environments. It won't record execution plans so if you're reviewing a profiler log from a customer's system on your own system there is no way of determining what execution plan SQL Server used when it was executed.

Don't get me wrong: SQL Server profiler is an invaluable tool that I use on almost a daily basis, but there are some things it won't do that I would want it to.

Linq-to-SQL's DataContext.Log

So what about the built-in logging in Linq-to-SQL? It is a great feature as it stands, with a few lines of code you can get all SQL statements and queries generated by Linq-to-SQL written to a log file. Unfortunately you will then need to sort through them and manually determine which ones are a cause for concern and which ones are not. Time consuming to say the least as soon as query volumes creep up, and finding what queries can/need to be optimized quickly becomes a forest vs trees situation. Great for debugging locally, but beyond that at least I need more data and more filtering options.

Getting more into details

What if we are just interested in the where/what/who aspects of say...

• Queries that hit a specific table?
• Queries that do more than n I/O operations / page reads?
• Queries that take longer than n milliseconds to execute?
• Queries that generate specific SQL Server warning messages?
• Queries that result in scans?

Finding those queries by hand in a large text file isn't going to be easy. Spotting them in SQL Server Profiler is easier provided that all the requirements for using it in the first place are satisfied. On the other hand, SQL Server Profiler won't give us the where/what/who; where in the application it came from, what caused it to run, or who'se code generated it.

Add to that that we may want to control the profiling/logging from within the application by for example app settings. If we want to profile just a specific part of an application in a runtime environment, and filter out only queries that are costly then the combination of SQL Server Profiler, SQL Server Management Studio and the out-of-the-box logging capabilities of Linq-to-SQL can add quite a bit of manual work to map the logs together.

Introducting the Huagati Linq-to-SQL Profiler

So, to bring the .net application side together with the database performance side of things, I put together the Linq-to-SQL Profiler. It consists of two main components:

• A runtime component that is referenced from within an application and that can be distributed with your applications. It hooks into a combination of the Linq-to-SQL built in logging, the underlying database connections, and SQL Server's own features for retrieving I/O information, timings, execution plans etc, and combines that information into log files. It also has some advanced (and customizable) filtering options so you can instruct it to log only queries that fulfill certain criteria.
• A log viewer that read the log files generated by the runtime component, provides additional filtering, sorting (which is not available in SQL Server Profiler), and shows not only what query was executed by also the managed call stack that caused to to run, SQL Server I/O and timings etc. If execution plan logging was enabled in the runtime component it also provides quick links to bring up the execution plan as it stood on the machine where the query was executed, from when it was executed.

The runtime component

The runtime component is a small DLL that you add as a reference in your Linq-to-SQL application. It won't do anything just by being referenced, but it adds some new capabilities to the Linq-to-SQL DataContext. It can be distributed freely together with your app, provided that you have a license for the profiler.

Using it is very simple; it has two methods (with a couple of overloads) that can be used to instruct it to start profiler logging (datacontext.BeginProfiling), and to end profiler logging (datacontext.EndProfiling). Depending on your usage scenario you can either call those methods inline from your app code or you can extend the partial DataContext class generated by the Linq-to-SQL designer to call the profiler logging methods whenever a datacontext is created/used.

The following code samples shows a couple of usage scenarios which can be used to use for example app settings to determine if logging should be enabled or not, and what logging options to use.

Example 1: A profiler enabled datacontext partial class in C#

Example 2: Inline profiling with C# as an alternative to profiling-enabled DCs

Example 3: A profiling enabled datacontext in VB.NET

Example 4: Inline profiling in VB.NET as an alternative to profiling-enabled DataContexts

If you want to read more about the profiler runtime component API, check out the online help over at http://www.huagati.com/L2SProfiler/runtimehelp

The profiler viewer

The profiler viewer is a windows application that read the log files generated by the Linq-to-SQL Profiler runtime component. It has filter options and sorting to make it easier to find the 'worst offenders' or log entries that match more specific criteria than was used during the runtime logging.

The profiler's screen is divided into two parts; the upper part shows all queries from the log (minus those filtered out by any filters set in the viewer) and the lower part shows the details; the query itself, the managed call stack, I/O and timings etc. The I/O and timing data is accompanied by visual indicators showing the relative impact of a query. The thresholds used by the visual indicators can be configured in the application settings.

The lower part of the screen can also be customized; the log files contain a lot more information than what is shown in the default view and the rendering of the lower part is done using XSLT style sheets that can be switched in the application settings dialog. This allows developers to create their own detail views focusing on the specific information they're interested in.

The profiler settings dialog

Additional details such as the execution plan diagram, the source code involved, parameterized and 'sp_execute'-wrapped versions of the queries etc are available as hyperlinks in the detail view, but the same information can of course be visualized directly in a customized detail view template.

Taking it for a test spin

If you would like to take the profiler for a test spin, head over to the product page over at http://www.huagati.com/L2SProfiler/ , where you can download it and get a free 45-day trial license. After the trial expires I hope you're happy with it and want to continue using it. If so, please support continued development by purchasing a license (or a pile of licenses for your team :) ).

If you have any questions or concerns about the profiler, feel free to send an email to support@huagati.com, ask a question in the support forum (http://forum.huagati.com/forum4-huagati-linqtosql-profiler-support.aspx ), or drop a comment here on my blog.

Future features

There are of course new features are planned for the profiler, these will be made available as they're completed:

• A centralized logging server that you can run to write logs to a database. It will have a web-based frontend very similar to the windows version of the profiler logger but is better suited for team environments where many people may want to access and work with the same logs.
• More templates for the detail view in the profiler viewer
• Additional filters; both runtime- and design time filters to help keep the log files focused on the interesting bits only.
• Additional logging providers; if there is enough interest I may extend the runtime logging component to also support Entity Framework, plain ADO.NET, or other data access technologies such as 3rd party OR/Ms.

Fin.