Tracing LINQ to SQL queries without using SQL Profiler

Been meaning to write this up all week however kept getting distracted.

After watching Anders Hejlsberg Mix07 session on Linq, he was using a feature of Linq to log all of the SQL queries being executed within code instead of using SQL Profiler.  This is great if your using SQL/C# Express as this doesn’t support running SQL profile and with this code you can see gain a level of understanding regarding the SQL queries.  Code has been taken from the session video so all credit goes to him.

This code executes two queries, one to select all the customers, with the CustomerID outputted to the console, while the second query returns the customer with the ID ‘ALFKI’ and outputs all of their orders.  The code has a TextWriter which is associated with the database context’s Log property and this stores all the queries executed in a file called log.SQL, in this case is saved to the debug directory. 

static void Main(string[] args)
{
  TextWriter log;
  log = File.AppendText(“log.sql”);

  DataClasses1DataContext db = new DataClasses1DataContext();
  //db.Log = Console.Out;
  db.Log = log;

  var query = from c in db.Customers
  select c;

  foreach (Customer cust in query)
  {
    Console.WriteLine(cust.ContactName);
  }
  log.Write(“End of getting all customers queryrnrn”);

  Customer alfki = db.Customers.Single(c => c.CustomerID == “ALFKI”);
  foreach (Order o in alfki.Orders)
  {
    Console.WriteLine(“{0}:{1}”, o.OrderDate, o.OrderID);
  }

  log.Write(“End of getting all orders for alfkirnrn”);
  log.Close();

  Console.ReadLine();
}

We could then change the query sightly, and instead of having the SQL query being stored in the file we could redirect it to Console.Out and for it to display on our command prompt.  Very cool. 

For this, we just point the DataContext.Log property to Console.Out

db.Log = Console.Out;

The output generated for this application is:

SELECT [t0].[CustomerID], [t0].[CompanyName], [t0].[ContactName], [t0].[ContactTitle], [t0].[Address], [t0].[City], [t0].[Region], [t0].[PostalCode], [t0].[Country], [t0].[Phone], [t0].[Fax]
FROM [dbo].[Customers] AS [t0]
SqlProviderAttributedMetaModel

End of getting all customers query

SELECT [t0].[OrderID], [t0].[CustomerID], [t0].[EmployeeID], [t0].[OrderDate], [t0].[RequiredDate], [t0].[ShippedDate], [t0].[ShipVia], [t0].[Freight], [t0].[ShipName], [t0].[ShipAddress], [t0].[ShipCity], [t0].[ShipRegion], [t0].[ShipPostalCode], [t0].[ShipCountry]
FROM [dbo].[Orders] AS [t0]
WHERE [t0].[CustomerID] = @p0
— @p0: Input NVarChar (Size = 5; Prec = 0; Scale = 0) NOT NULL [ALFKI]
SqlProviderAttributedMetaModel

End of getting all orders for alfki

This demonstrates how the queries are saved to the log, but also how it displays the parameter (@p0) being passed into the parameterised query when it is executed.  I really think this is a great feature, maybe not for production but definitely for development.

Download the code and SQL output here:

http://blog.benhall.me.uk/code/linq/TraceLinqToSQL/TraceLinqToSQL.cs.txt

http://blog.benhall.me.uk/code/linq/TraceLinqToSQL/TraceLinqToSQLLog.sql.txt