Tracing and debugging Sitecore's application-side SQL activity

This post is about how to attempt to dig a bit deeper into the workings of the ADO.NET components found in the .NET Framework BCL, in order to diagnose any awkward SQL Server issues. Obviously this technique is not specific to Sitecore, but Sitecore's SQL Server data provider leverages these components for its data access, so it's definitely worth being aware of how to easily get at the extra trace information available inside the System.Data assembly.

I was trying to help a client diagnose automatic failover issues in a SQL Server mirroring setup - in short, when the DBA team manually failed over from the primary to mirror SQL instance, the application seemed not not be able to find the mirror SQL instance. From the log messages printed out by Sitecore, it looked like the application was at least *trying* to fail over (or at least was aware that it was connected to a mirrored SQL instance.) But annoyingly, after restarting the application the mirror host was being connecting to without any problems. This situation is not ideal when your client is trying to ensure a highly available website! I wanted to double check the name of the instance that the application was trying to connect to during failover - this information is received by the application when it makes its initial connection to the primary instance (some useful background here if you're having a similar issue), but is not added in any exception messages.

If you inspect the System.Data assembly in your favourite decompiler, and navigate to the relevant method, it looks like there are some juicy trace messages just waiting to be reached:

But how to get access to them? Here's how:

  • Add a registry key to HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\BidInterface\Loader and add a string value with key ":Path" (note the colon) and value "C:\Windows\Microsoft.NET\Framework64\v4.0.30319\AdoNetDiag.dll"
  • In a command window, navigate to C:\Windows\Microsoft.NET\Framework64\v4.0.30319\ and run the command mofcomp adonetdiag.mof - this registers the ADO.NET components with the WMI repository (more details about these technologies here)
  • You can run logman query providers {914ABDE2-171E-C600-3348-C514171DE148} to check that the previous step was a success - “System.Data.1” should be the result
  • Then run iisreset and spin up your application
  • Create a directory C:\BID

Now we're ready to trace - open a command window ...

  • cd C:\BID
  • logman start MyTrace -p {914ABDE2-171E-C600-3348-C514171DE148} 0xFFFFFFFF 5 -ct perf -ets
  • Now we're tracing, so e.g. make a request to your application
  • logman stop MyTrace -ets
  • tracerpt -of xml MyTrace.etl

Then take a look in dumpfile.xml to get the details you've been looking for:

BID tracing dumpfile

Be aware that these logs can get very big very quickly, so you may want to limit the time you are tracing, and make sure nothing else is making requests to the application! Alternatively you might want to get creative by filtering out unwanted events, but I didn't require this...

If you need to clean up after yourself then:

  • Remove the registry key HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\BidInterface\Loader
  • Create a file delete.mof containing

    #pragma namespace ("\\\\.\\Root\\WMI")

    #pragma deleteclass("Bid2Etw_System_Data_1", FAIL)

  • Run mofcomp delete.mof

This technique is great if you need quick answers without making any code changes, and you can't recreate the problem in a local development environment. If you wanted to break into System.Data locally with Visual Studio you could look into using DotPeek as a symbol server. I did also take a quick look into the possibility of extending the existing Sitecore SQL access libraries to add some extra tracing of the connection host, but it doesn't look like Sitecore's extension points let you achieve this without needing to rewrite half of Sitecore.Kernel!