Good way to time SQL queries when using Linq to SQL

Question

Is there a good way to time SQL queries when using Linq to SQL? I really like logging feature, but it would be great if you could somehow also time that query. Any ideas?

Answer 1

We use SQL Profiler to test our queries with LLBLGen Pro.

Answer 2

You could use a System.Diagnostics.Stopwatch it will allow you to track the time the query executes. Just remember that Linq->SQL queries aren't executed until you enumerate over them. Also note that if you are logging to Console.Out there will be a significant performance hit.

Answer 3

The best is to log the queries to a file and them use SQL Profiler to time them and tweak the indexes for the queries.

Answer 4

As two people already said, SQL Profiler is the out-of-the-box tool to use for that. I don't want to be an echo but I wanted to elaborate a bit more in detail: Not only does it provide the actual timings from SQL Server (as opposed to timing from the app-side where network i/o, connection and connection pool timings are added to the cake) but it also gives you the [often more important] I/O statistics figures, locking info (as needed) etc.

The reason I/O statistics are important is that a very expensive query may run fast while consuming excessive amounts of server resources. If for example a query that is executed often hits large tables and there are no matching indexes resulting table scans, the affected tables will be cached in memory by SQL Server (if it can). This can sometimes cause the same query to execute blazingly fast while in effect it is harming the rest of the system/app/db by eating up server resources.

Locking info is almost as important -> tiny queries doing PK lookups for a single record can have bad timings due to locking and blocking. I read somewhere that this very site was plagued by deadlocks in its' early beta days. SQL Profiler is your friend for identifying and resolving problems caused by locking too.

To summarize it; whether you use L2S, EF, plain ADO - if you want to make sure your app "behaves nice" towards the database always have SQL Profiler ready during development and testing. It pays off!

Edit: Since I wrote the answer above I have developed a new runtime profiling tool for L2S that bring the best of both worlds together; I/O stats and server-side timings from SQL Server, SQL Server execution plan, SQL Server's "missing index" alerts, combined with the managed call stack to make it easy to find what code generated a certain query, and some advanced filter options to log only queries that fulfill certain criteria. Additionally, the logging component can be distributed with apps to make runtime query profiling in live customer environments easier. The tool can be downloaded from:

http://www.huagati.com/L2SProfiler/ where you can also get a free 45-day trial license.

A longer background description and intro to the tool is also posted here:
http://huagati.blogspot.com/2009/06/profiling-linq-to-sql-applications.html

...and a sample/walkthrough of using some of the more advanced filter options is available here:
http://huagati.blogspot.com/2009/08/walkthrough-of-newest-filters-and.html

Answer 5

SQL Profiler to get the query and the time, and also Execution Path in Query analyzer to see where the bottlenecks are.

Answer 6

What you could do is add a custom TextWriter implementation to the DataContext.Log which will write the generated sql to a file or memory. Then loop through those queries, executing them with raw ADO.NET code, surrounding each with a stopwatch.

I've used a similar technique before because it seemed whenever I was developing some code I never had Profiler open, and it was really easy to output those results to a HTML page. Sure your executing them twice per website request, but its helpful to see execution times asap instead of waiting until you catch something in Profiler.

Also if your going to the SQL Tool route I would recommend googling "slowest query DMV" and getting a stored procedure that can give you stats on the slowest queries in your db. Its not always easy to scroll through profiler results to find the bad queries. Also with the right queries over sql 2005's dmv you can also do ordering by lets say cpu vs. time and so forth.