ADO.NET Trace Logging

Introduction

Tracing allows you to keep track of various events happening in the system. Tracing allows you to track the sequence of code execution along with the time taken for each step. Together, tracing can throw light on how your code is being executed and the performance of every step. Many real world applications are database driven and call for performance optimization of your data access code. Luckily, ADO.NET 2.0 provides built-in support for trace logging. The ADO.NET trace logging is tuned for performance and uses Event Tracing for Windows (ETW) providers. This article explains how you can configure the ADO.NET trace logging feature.

Enabling ADO.NET Trace Logging

The ADO.NET trace logging is not enabled by default. To enable it, you need to follow these steps:

• Add certain Registry entries
• Configure ETW providers for ADO.NET
• Create a trace log using the Logman command line tool
• Start the tracing

Now, see each step in more detail.

Add Required Registry Entries

The trace logging feature of ADO.NET is dependent on a DLL named AdoNetDiag.dll. This DLL is located in the installation folder of .NET. The following figure shows this DLL in Windows Explorer.

The AdoNetDiag.dll is a component that makes any class library designed for trace logging appear as an ETW provider. In the example, it will make assemblies such as System.Data.dll appear as ETW providers.

Now, open the Windows Registry editor (regedit.exe) and locate the following key:

HKLMSoftwareMicrosoftBidInterface

By default, the BidInterface key will not have any sub-key. Add a sub-key to BidInterface named Loader. Then, add a string value under Loader with a name such as :Path and a value as the full path and name of AdoNetDiag.dll assembly (see below).

Configure ETW Providers for ADO.NET

Now, you need to configure AdoNetDiag.dll so that it is visible on a public ETW provider list as well as the WMI (Windows Management Instrumentation) provider list. This can be done with the help of the mofcomp.exe command line tool. The mofcomp.exe tool expects a .mof (Managed Object Format) file containing details about the objects to be added to the WMI repository. For AdoNetDiag.dll, the required .mof file is available in the same folder as the AdoNetDiag.dll itself (see below).

Open Command Prompt and issue the following command:

mofcomp.exe C:WindowsMicrosoft.NetFrameworkv2.0.50727
   AdoNetDiag.mof

The following figure shows a successful run of the above command. Make sure to replace the path of AdoNetDiag.mof file as per your installation.

To ensure that the ETW providers are enabled correctly, you can use the logman.exe command line tool. Issue the following command at the command prompt:

logman.exe list providers

The above command will display a list of ETW providers. The following figure shows a sample run of this command.

Out of the providers listed in the above figure, the following were registered because of the mofcomp.exe tool and AdoNetDiag.mof file.

Create a Trace Log by Using the Logman Tool

Now that you have published the required ETW providers, it’s time to create a trace log. You do that with the help of the Logman command line tool. Before you use this tool, however, you need to create a text file that supplies information about the providers to be used. In the example, the text file will look like this:

"ADONETDIAG.ETW"        0x2     0x0     ADONETDIAG.ETW
"System.Data.1"         0x2     0x0     System.Data.1
"System.Data.SNI.1"     0x2     0x0     System.Data.SNI.1

The four columns indicate Provider, control bit, logging level, and provider name. The provider can be specified as a string value enclosed in double quotes or a GUID. The control bit is used to filter the trace. 0x2 means basic trace information. The logging level indicates what will be logged. The value of 0x0 means normal. Finally, the provider name indicates the name of the provider as expected by ETW.

Create the tab-delimited file above and save it as ProviderInfo.txt in a local folder on your machine.

Now, start a trace log by using logman tool as shown below:

logman.exe start MyTrace -pf providerinfo.txt
   -o MyTraceLog.etl -ets

In the above command:

• start indicates that you want to start a new trace log named MyTrace
• The -pf switch supplies a file containing the list of providers to be used. Remember to use the correct path of ProviderInfo.txt file as per your setup
• The -o switch indicates the output file to store the log information. The log information is stored in binary format
• The -ets switch indicates that the trace collection definition will be persisted in the system

Running ADO.NET Code

Now that you have enabled ADO.NET trace logging, it’s time to test it. Create a new project of type “Console Application” using Visual Studio. In the Main() method, add the following code:

SqlConnection cnn;
SqlDataAdapter da;
SqlCommandBuilder builder;
DataSet ds;

string connstr = @"data source=.sqlexpress;
   initial catalog=northwind;
integrated security=true";
cnn = new SqlConnection(connstr);
da = new SqlDataAdapter("select * from customers", cnn);
builder = new SqlCommandBuilder(da);
ds = new DataSet();
da.Fill(ds, "customers");
foreach (DataRow row in ds.Tables[0].Rows)
{
row["companyname"] = row["companyname"];
}
da.Update(ds, "customers");

The above code uses the Customers table of the Northwind database. It creates objects of the SqlCommection, SqlCommand, SqlDataAdapter, SqlCommandBuilder, and DataSet classes. It then fills up the DataSet with the help of SqlDataAdapter. The SqlCommandBuilder configures the SqlDataAdapter for INSERT, UPDATE, and DELETE operations. A for loop simply changes the CompanyName column of DataRow objects. Finally, the Update() method of SqlDataAdapter saves the changes back to the database.

After writing this code, run the application. This will cause some ADO.NET “activity” and thus some trace information will be logged.

Reading the Trace

Now that you have logged some trace information, see what is actually logged. Open the command prompt and issue the following command:

logman.exe stop MyTrace -ets

This command simply stops the trace logging for the MyTrace log you started earlier. The MyTraceLog.etl file is a binary file and cannot be read directly. To extract information from MyTraceLog.etl file, you need to use the TraceRpt.exe (Trace Report) command line tool.

tracerpt MyTraceLog.etl

The above command creates two files, Summary.txt and Dumpfile.csv. The Summary.txt file contains information as shown below:

Files Processed:
MyTraceLog.etl
Total Buffers Processed 29
Total Events Processed 709
Total Events Lost 0
Start Time 4 Dec 2007 10:27:42.592
End Time 4 Dec 2007 10:31:52.231
Elapsed Time 249 sec
+------------------------------------------------------------+
|Event Count Event Name Event Type Guid |
+------------------------------------------------------------+
| 1 EventTrace Header {68fdd900-4a3e-11d1-84f4-0000f80464e3}|
| 6 AdoNetDiag TextW {7acdcac9-8947-f88a-e51a-24018f5129ef}|
| 702 System.Data TextW {914abde3-171e-c600-3348-c514171de148
| }|
+------------------------------------------------------------+

As you can see this file simply contains a summary of the trace log. The Dumpfile.txt file on the other hand contains detailed information about various events.

System.Data, TextW, 0x0EEC, 128412180408588592, 40, 100, 2,
"<sc.SqlCommand.set_Connection|API> 1# 1#", 0, 0
System.Data, TextW, 0x0EEC, 128412180408588592, 40, 100, 2,
   "<ds.DataSet.DataSet|API> 1#", 0, 0
System.Data, TextW, 0x0EEC, 128412180408588592, 40, 100, 2,
   "<ds.DataTableCollection.DataTableCollection|INFO>
   1# dataSet=1", 0, 0
System.Data, TextW, 0x0EEC, 128412180413195216, 60, 120, 2,
   "<sc.TdsParser.Connect|SEC> SSPI authentication", 0, 0
System.Data, TextW, 0x0EEC, 128412180454154112, 70, 170, 2,
   "<prov.DbConnectionFactory.CreatePooledConnection|RES|CPOOL>
   1# Pooled database connection created.", 0, 0
System.Data, TextW, 0x0EEC, 128412180454354400, 70, 170, 2,
   "<sc.SqlCommand.ExecuteReader|INFO> 1#
   Command executed as SQLBATCH.", 0, 0
System.Data, TextW, 0x0EEC, 128412180463467504, 70, 170, 2,
   "<ds.DataTable.DataTable|API> 1#", 0, 0
System.Data, TextW, 0x0EEC, 128412180463667792, 70, 170, 2,
   "<ds.DataColumn.DataColumn|API> 1# columnName='CustomerID'
   expr='(null)' type=1{ds.MappingType}", 0, 0
...

The Dumpfile.txt provides the following pieces of information:

• EventName: Name of the event provider
• EventType: Type of the event. For data providers, TextW indicates Unicode data and TextA indicates ASCII data.
• TID: Thread identifier
• Clock Time: A 64-bit integer that represents the timestamp at which the event took place
• Kernel (ms): Processor time in milliseconds for which the event was in kernel mode
• User (ms): Processor time in milliseconds for which the event was in user mode
• User Data: Data about the event

If you observe the above trace carefully, you easily can identify various events happening in the system, such as theexecution of data reader, creation of DataTable, and so forth. Also, notice how the trace uses abbreviations of the namespace names. For example, comm refers to System.Data.Common namespace, ds refers to System.Data, screfers to System.Data.SqlClient, prov refers to System.Data.ProviderBase, and so on.

For better readability, you may open this file in MS Excel or the LogParser utility (from the IIS resource kit).

Summary

The ADO.NET trace logging feature allows you to trace information that can reveal important information about your data access code. The ADO.NET ETW providers are tuned for performance and can be turned on or off at runtime. This way, you can enable or disable tracing without affecting your application. The AdoNetDiag.dll plays a vital role in providing trace logging. The main command line tools used in ADO.NET trace logging are Mofcomp.exe, Logman.exe and TraceRpt.exe.

Download the Code

You can download the code that accompanies this article here.