Bob Beauchemin, Jennifer Perret, Acey Bunch
Microsoft Corporation

June 2006

Applies to:
   Microsoft ADO.NET 2.0
   Microsoft MDAC 2.8 SP2
   Microsoft SQL Server Native Client
   Microsoft SQL Server 2005 JDBC Driver
   Microsoft SQL Network Protocols
   Microsoft SQL Server 2005 SP1

Summary: Learn how to apply the new tracing functionality in Microsoft data access technologies such as ADO.NET 2.0, MDAC 2.82, SQL Server Native Client, and the JDBC driver; and in the SQL Server network protocols and the Microsoft SQL Server 2005 database engine. (20 printed pages)

Download the associated Data_Access_Tracing.exe sample code [ http://download.microsoft.com/download/4/f/8/4f8f2dc9-a9a7-4b68-98cb-163482c95e0b/data_access_tracing.exe ] .

Download a copy of this article in Microsoft Word, Data_Access_Tracing.doc [ http://download.microsoft.com/download/f/1/c/f1cf7b8d-7fb9-4b71-a658-e748e67f9eba/data_access_tracing.doc ] .

Download the associated Data_Access_Tracing.exe sample code

Download a copy of this article in Microsoft Word, Data_Access_Tracing.doc

Contents

Introduction
Tracing a Data Access Application
   Setting Up the Trace
   Configuring and Running the Trace
   Reviewing the Trace Results
Configuring Which Applications Are Traced
Data Tracing Example
   Using Tracing to Debug a Parameter Binding Problem
   Two Key Diagnostic Scenarios
Inside Data Tracing
   What Is ETW?
   Special Considerations for Tracing on Windows 2000
   Special Considerations for Tracing the JDBC Driver
Conclusion
Appendix
   A: MOF Files
   B: Control GUID Files
   C: Categories

Introduction

One of the goals of this article is to point out that data access tracing is available not only in ADO.NET 2.0, but also in MDAC 2.8 SP2, SQL Server Native Client, the Microsoft SQL Server 2005 JDBC Driver, and within the SQL Server Network Interface (SNI) layer. Another goal is to discuss how you can use data tracing to track down bugs and bottlenecks in your applications.

Note   This article leverages a previously published MSDN article, Tracing Data Access, by Bob Beauchemin of Sysolutions Inc., with his permission of course.

There hasn't been a good built-in trace facility for data access since the days of ODBC Trace. OLE DB had many of different types of tracing; two that come to mind are the Visual Studio Analyzer-compatible instrumentation and ATLTRACE (a trace macro for ATL OLE DB templates). The issue with OLE DB and MDAC was not that there was no trace, but that there were too many separate kinds of tracing, each tied to a different evaluation mechanism. It was difficult if not impossible to trace down into various layers of the data access stack and get one trace output. All of that has changed. Microsoft has now created consistent tracing functionality that will allow you to debug your applications throughout the entire data access stack.

Microsoft has instrumented data tracing capabilities for all four of its .NET data providers (SqlClient, OracleClient, OleDbClient, and ODBCClient), the ADO.NET DataSet and friends, SQL Native Client OLE DB provider and ODBC driver, MDAC 2.82, the SQL Server 2005 JDBC driver, and the SQL Server 2005 network libraries. There are also an initial set of trace points that have been added to the SQL Server 2005 database engine.

Note   The only component of the JDBC driver that supports the tracing methodology outlined in this article is sqljdbc_xa.dll, which is the DLL that is used for distributed transactions. See Special Considerations for Tracing the JDBC Driver for more information.

This data tracing instrumentation enables you to trace your applications through all data access layers, including applications that leverage both managed and native code with the same tracing technologies. For example, an application that uses the managed OleDbClient provider to talk to a native OLE DB provider from MDAC, or the new SQL Native Client OLE DB provider, can now be traced from end to end with one command. The output generated will show the application flow from managed to native code. The ability to trace your data access applications from end to end, leveraging the same tracing technologies and analyzing one set of consistent tracing output, is a huge leap forward for diagnosing problems that are hard to solve.

The information in this article will help you get up and tracing quickly, show you how to do some cursory trace file analysis, and look at simple trace use cases. Please note that the examples within this article demonstrate how to set up a tracing scenario. If you are only trying to trace one assembly or one particular part of your application, you can easily modify the files that you use to register trace events so that you only receive trace events for the assemblies that you care about. We'll point out how you can customize your tracing output throughout this article. In addition, we'll talk about how the tracing layer is architected to be extendible to different trace technologies, and suggest more ways in which to use it.

Tracing a Data Access Application

To trace your data access application, there are a few basic steps that you'll need to follow:

1. Set up the trace.
2. Configure and run the trace.
3. Review the trace results.

In the following sections, we'll go over each of these steps in detail, starting with setting up your system to perform a trace.

Setting Up the Trace

When configuring your system to perform a data trace, there are a few small hoops that you'll need to jump through, including setting up the data tracing DLL registry entry, Event Tracing for Windows (ETW) providers, and Windows Management Instrumentation (WMI) schemas.

Don't worry if some of the tools like ETW and WMI are unfamiliar to you for now. Let's go over the steps one-by-one and then go back to a discussion of what these tools are and how they work.

Note   If you just can't wait to understand how data tracing works before you begin setting it up, read the Inside Data Tracing section that appears near the end of this article.

Creating the Trace DLL Registry Entry

This step consists of running a registry script or manually editing the registry to hook up data tracing to its ETW provider. We'll have more to say about customizing your trace output by using this registry key later; for now let's just enable tracing for every data-related process on the machine.

Warning   This article contains information about modifying the registry. Before you modify the registry, make sure to back it up and make sure that you understand how to restore the registry if a problem occurs. For information about how to back up, restore, and edit the registry, consult the Knowledge Base article How to back up, edit, and restore the registry in Windows XP and Windows Server 2003 [ http://support.microsoft.com/kb/322756 ] .

1. Open Registry Editor by typing regedit in the Run dialog box, which you can open from the Start menu.
2. In the tree view in the left pane of Registry Editor, expand My Computer, and then expand the registry hive named HKEY_LOCAL_MACHINE. Keep expanding nodes within this hive until you locate the following registry key:
3. HKEY_LOCAL_MACHINE\Software\Microsoft\BidInterface\Loader
4. Right click the Loader key and in the context menu that appears, select New, then String. Name the value ":Path". Note that the colon before "Path" is significant.
5. Right-click the new registry value that you just added, and in the context menu that appears, select Modify. This will bring up the Edit String dialog box.
6. In the Edit String dialog box, enter one of the following values in the Value data field, based on the data access technology that you are working with:

ADO.NET 2.0

Value="%SYSTEMROOT%\Microsoft.NET\Framework\v2.0.50727\ADONETDiag.dll"

SQL Native Client, JDBC driver, and MDAC 2.82 (no ADO.NET 2.0 on the system)

Value="%SYSTEMROOT%\SYSTEM32\msdaDiag.dll"

Note   ADONETDiag.dll and msdadiag.dll are nearly identical implementations. However, ADONETDiag.dll is installed only with .NET Framework 2.0. If you are not using ADO.NET, you may not have this assembly installed on your machine. You can use either implementation when tracing from managed or native code paths.

As an alternative to these steps, you can run the setup_trace.reg file that is included with this article. This will set the msdadiag.dll Built-in Diagnostics (BID) adapter into the registry location as listed above.

Registering the Trace Schema

The BID adapter you have just registered is a pluggable component that makes any product code that is instrumented for data tracing look like an ETW provider. You can use the providers now, but for them to appear in public provider lists and in WMI tools, you need to register the ETW providers and their WMI schemas for the events that the BID adapter exposes. You do this with a special format schema file called a Managed Object Format (MOF) file and a utility named mofcomp.exe. ADO.NET 2.0 provides a MOF file in the %SYSTEMROOT%\Microsoft.NET\Framework\v2.0.50727 directory. However, for the SQL Native Client, JDBC driver, and MDAC providers, you will need to leverage the MOF files provided with this article. To see a list of MOF files provided with this article as well as on the Windows operating system, please see Appendix A: MOF Files later in this article.

To register the tracing schema, issue the command manually from the command line as follows:

mofcomp <filename>.mof 

You can also run the _registerSchema.cmd file included with this article. This will register the schemas for all of the data access technologies.

Note   The MOF and ctrl.guid files for registering IIS and ASP.NET providers are also included in this article. IIS and ASP.NET do not use the same data access tracing mechanisms. However, their tracing mechanisms also tie into ETW. Therefore, by registering their ETW providers and schemas, you can capture a complete end to end tracing experience.

You can check that the providers are correctly registered by using the Log Manager (logman) tool to list the ETW providers. To do this, issue the following at the command prompt:

logman query providers

You should see the providers that you have registered, as well as other providers that come with the operating system or other products. Note that each provider is identified by a Globally Unique Identification (GUID) number. Your provider list should look something like this:

Provider                            GUID
--------------------------------------------------------------------------
*SQLOLEDB.1                         {C5BFFE2E-9D87-D568-A09E-08FC83D0C7C2}
MSDAPRST.1                          {64A552E0-6C60-B907-E59C-10F1DFF76B0D}
*SQLSERVER.SNI.1                    {AB6D5EEB-0132-74AB-C5F5-B23E1644DADA}
MSADDS.1                            {13CD7F92-5BAA-8C7C-3D72-B69FAC139A46}
HTTP Service Trace                  {dd5ef90a-6398-47a4-ad34-4dcecdef795f}
SQLSRV32.1                          {4B647745-F438-0A42-F870-5DBD29949C99}
MSADCE.1                            {76DBA919-5A36-FC80-2CAD-3185532B7CB1}
*SQLJDBC_XA.1                       {172E580D-9BEF-D154-EABB-83429A6F3718}
ASP.NET Events                      {AFF081FE-0247-4275-9C4E-021F3DC1DA35}
NTLM Security Protocol              {C92CF544-91B3-4dc0-8E11-C580339A0BF8}
IIS: WWW Isapi Extension            {a1c2040e-8840-4c31-ba11-9871031a19ea}
SQLBROWSER.1                        {FC9F92E6-D521-9C9A-1D8C-D8980B9978A9}
*ADONETDIAG.ETW                     {7ACDCAC8-8947-F88A-E51A-24018F5129EF}
*System.Data.OracleClient.1         {DCD90923-4953-20C2-8708-01976FB15287}
Windows Kernel Trace                {9e814aad-3204-11d2-9a82-006008a86939}
MSDAREM.1                           {564F1E24-FC86-28E1-74F8-5CA0D950BEE0}
Processor Trace Information         {08213901-B301-4a4c-B1DD-177238110F9F}
*SQLNCLI.1                          {BA798F36-2325-EC5B-ECF8-76958A2AF9B5}
*System.Data.SNI.1                  {C9996FA5-C06F-F20C-8A20-69B3BA392315}
*MSDADIAG.ETW                       {8B98D3F2-3CC6-0B9C-6651-9649CCE5C752}
*ODBC.1                             {F34765F6-A1BE-4B9D-1400-B8A12921F704}
MSSQLSERVER Trace                   {2373A92B-1C1C-4E71-B494-5CA97F96AA19}
Local Security Authority (LSA)      {cc85922f-db41-11d2-9244-006008269001}
ACPI Driver Trace Provider          {dab01d4d-2d48-477d-b1c3-daad0ce6f06b}
Active Directory: Kerberos          {bba3add2-c229-4cdb-ae2b-57eb6966b0c4}
IIS: SSL Filter                     {1fbecc45-c060-4e7c-8a0e-0dbd6116181b}
IIS: WWW Server                     {3a2a4e84-4c21-4981-ae10-3fda0d9b0f83}
IIS: Active Server Pages (ASP)      {06b94d9a-b15e-456e-a4ef-37c984a2cb4b}
*OLEDB.1                            {0DD082C4-66F2-271F-74BA-2BF1F9F65C66}
.NET Common Language Runtime        {e13c0d23-ccbc-4e12-931b-d9cc2eee27e4}
BCP.1                               {24722B88-DF97-4FF6-E395-DB533AC42A1E}
DBNETLIB.1                          {BD568F20-FCCD-B948-054E-DB3421115D61}
*ADODB.1                            {04C8A86F-3369-12F8-4769-24E484A9E725}
MSADCF.1                            {101C0E21-EBBA-A60A-EC3D-58797788928A}
*System.Data.1                      {914ABDE2-171E-C600-3348-C514171DE148}
Spooler Trace Control               {94a984ef-f525-4bf1-be3c-ef374056a592}

We've changed the output a bit, adding an asterisk next to the providers that are specific to the data access stack and to the example of end to end tracing that we demonstrate in this article. You can also check out the WMI schemas that were registered by using the WMI CIM Studio tool. Follow this link to download the WMI Administrative Tools [ http://www.microsoft.com/downloads/details.aspx?displaylang=en&familyid=6430f853-1120-48db-8cc5-f2abdc3ed314 ] .

Configuring and Running the Trace

Running the trace consists of defining named traces and issuing ETW commands to use them with the logman utility. Start the trace by running the script _startTrace.cmd included with this article.

Note   If you are trying to trace on Windows 2000, please see the Special Considerations for Tracing on Windows 2000 section of this article.

Assuming that you are running Windows Server 2003 or Windows XP, the command in the file looks like this:

@Logman start MyTrace -pf ctrl.guid.all -ct perf -o Out.etl -ets

Note   The –ct perf option is only available on Windows Server 2003 and not on Windows XP. This option creates better time granularity within the trace captures and you should use it if you are on Windows Server 2003.

This command file defines a single named trace instance (MyTrace) specifying all of the providers that we just registered. The list of providers and options for the providers are specified in a separate file, ctrl.guid.all. The contents of this file are:

{7ACDCAC8-8947-F88A-E51A-24018F5129EF}  0x00000000  0   ADONETDIAG.ETW
{914ABDE2-171E-C600-3348-C514171DE148}  0x00000000  0   System.Data.1
{C9996FA5-C06F-F20C-8A20-69B3BA392315}  0xFFFFFFFF  0   System.Data.SNI.1
{DCD90923-4953-20C2-8708-01976FB15287}  0x00000000  0   
System.Data.OracleClient.1
{BA798F36-2325-EC5B-ECF8-76958A2AF9B5}  0x00000000  0   SQLNCLI.1
{8B98D3F2-3CC6-0B9C-6651-9649CCE5C752}  0x00000000  0   MSDADIAG.ETW
{04C8A86F-3369-12F8-4769-24E484A9E725}  0x00000000  0   ADODB.1
{BD568F20-FCCD-B948-054E-DB3421115D61}  0x00000000  0   DBNETLIB.1
{F34765F6-A1BE-4B9D-1400-B8A12921F704}  0x00000000  0   ODBC.1
{0DD082C4-66F2-271F-74BA-2BF1F9F65C66}  0x00000000  0   OLEDB.1
{C5BFFE2E-9D87-D568-A09E-08FC83D0C7C2}  0x00000000  0   SQLOLEDB.1
{4B647745-F438-0A42-F870-5DBD29949C99}  0x00000000  0   SQLSRV32.1
{76DBA919-5A36-FC80-2CAD-3185532B7CB1}  0x00000000  0   MSADCE.1
{101C0E21-EBBA-A60A-EC3D-58797788928A}  0x00000000  0   MSADCF.1
{13CD7F92-5BAA-8C7C-3D72-B69FAC139A46}  0x00000000  0   MSADDS.1
{64A552E0-6C60-B907-E59C-10F1DFF76B0D}  0x00000000  0   MSDAPRST.1
{564F1E24-FC86-28E1-74F8-5CA0D950BEE0}  0x00000000  0   MSDAREM.1
{AB6D5EEB-0132-74AB-C5F5-B23E1644DADA}  0xFFFFFFFF  0   SQLSERVER.SNI.1
{FC9F92E6-D521-9C9A-1D8C-D8980B9978A9}  0xFFFFFFFF  0   SQLBROWSER.1
{24722B88-DF97-4FF6-E395-DB533AC42A1E}  0xFFFFFFFF  0   BCP.1
{172E580D-9BEF-D154-EABB-83429A6F3718}  0x00000000  0   SQLJDBC_XA.1

The lines include a GUID for each provider, provider options, and the provider's name (watch for line wrap). We'll say more about the provider options later. Please note that the download for this article includes a set of pre-configured ctrl.guid files to get you up and tracing your particular configurations faster, and these files are listed in Appendix B: Control GUID Files.

Invoking logman in this manner writes all of the events in a concise binary format to an event trace log file. These files have the suffix .etl by convention. Once you've turned it on, run the sample program, TracingExample_FillDataset.exe, which is included with the download for this article. Turn off the trace by running _stopTrace.cmd. This script just issues the command:

@Logman stop MyTrace -ets

You should see an approximately 150KB file named "out.etl" in the directory from which you issued the command. Because we've turned the trace providers on at each level of detail (ADO.NET providers, network calls, and responses from SQL Server if it's running on the same machine), there will be a large amount of output. We'll look at ways to filter the output later. Note that bringing up Visual Studio® 2005 to run the test program may generate extra trace events when, for example, Server Explorer runs data access code.

Reviewing the Trace Results

Of course going through the effort of creating a trace isn't much use if you don't review the results that it produces. In the following sections, we will discuss how to do just that.

Formatting the Trace Output

The out.etl file is not in a human readable format, unless you're one of those rare humans who likes to read binary. ETW utilities include a basic formatter named tracerpt.exe to convert it to a comma-separated value file. To get the CSV file, run _report.cmd, which issues the following command:

@TraceRPT /y Out.etl

This utility produces two files: summary.txt, which is a summary of the trace events captured in the session; and dumpfile.csv. These are the default file names output by tracerpt, and you can change them through command-line options. Dumpfile.csv is the file containing the information that you want. This file can be browsed with Excel® for now; later, you can do some further post-processing, such as loading the data into SQL Server and querying it with SQL. That's all there is to it! You now have your first trace. Let's have a look at the output.

Reading the Trace Output

The data tracing providers expose three major types of information: trace point information and provider identity, event type, and thread and timing information. Specifically, the columns of information consist of:

• Event Name—the name of the data tracing event provider
• Event Type—TextW or TextA
• TID—thread ID
• Clock-Time—Timestamp of the event
• Kernel (ms)—number of milliseconds in kernel mode (CPU time)
• User (ms)—number of milliseconds in user mode (CPU time)
• User Data—detailed information about the trace point

Although WMI providers are permitted to expose complex schemas, the data tracing providers only expose two simple event types: TextW and TextA. TextW is for Unicode character messages and TextA is for ANSI character messages. Note that many of the data tracing events are bracketed "begin" and "end" pairs that make it easy to follow the nested API calls. For example, in a sample ADO.NET trace, the User Data field looks somewhat like this:

"enter_01 <comm.DbDataAdapter.Fill|API> 1#  dataSet"
"enter_02 <comm.DbDataAdapter.Fill|API> 1#  dataSet  startRecord  
maxRecords  srcTable  command  behavior=16{ds.CommandBehavior}"
"<sc.SqlCommand.get_Connection|API> 1#"
"<sc.SqlCommand.get_Connection|API> 1#"
"enter_03 <sc.SqlConnection.Open|API> 1#"
"enter_04 <prov.DbConnectionBase.Open|API> 1#"
"enter_05 <SNIInitialize|API|SNI> pmo: 00000000{void}"
... many events deleted
"leave_05"
 "<sc.TdsParser.CreateSession|ADV> 1# created session 2"
 "<prov.DbConnectionFactory.CreatePooledConnection|RES|CPOOL> 1#  Pooled 
database connection created."
 "leave_04"
 "leave_03"

It's fairly straightforward to see that the program called the DataAdapter.Fill(DataSet) method, which is an overload of the DataAdapter.Fill method, which in turn called into the SqlConnection.Open method, and so on. Each enter_nn event has a corresponding leave_nn event. In this example, you're tracing the call into the underlying SNI (SQL Server networking interface) low-level protocol events. But what is that funny bracket format of the user data generated by the "mainstream" tracer, System.Data.1?

User Data and ADO.NET Tracing

As the name implies, the content and format of the user data field is entirely up to the user's (in this case the trace provider's) discretion. Calls to System.Data.dll and System.OracleClient.dll go by a special format that can be easily decoded. Take for example the entry from the previous trace record sequence:

"enter_04 <prov.DbConnectionBase.Open|API> 1#"
This can be decoded to:
<namespace_ abbreviation.classname.methodname|keyword> parms

So this example means that there is an API call to the Open method of System.Data.ProviderBase.DbConnectionBase class. The reason for using abbreviated namespaces is to keep the size of the output smaller. The number followed by a pound sign (1#) after the parameter number serves to identify the specific instance of the DbConnectionBase object; this is helpful when you are working with a complex trace and watching many instances. The following charts can help you decode the user data.

Table 1. Namespace abbreviations used in .NET Trace Points

Table 2. Categories used in .NET Trace Points

You can use the information in the tables above to post-process the trace output and look at only DataSet-related events, or choose between OleDb managed events and OLE DB native events. Or you can keep the information together for event correlation. A simple query using the LIKE operator is all you need. Appendix C: Categories lists the categories used for SQL Native Client Providers, the JDBC driver, SNI (SQL Network Interfaces), and MDAC.

Configuring Which Applications Are Traced

At the beginning of the article, we mentioned configuring the ":Path" string value of the Loader registry key. Manual configuration is only needed because data access tracing is still in its infancy. Specifically, programmers who use data tracing should not depend on this key being manually configurable in future releases. It is already protected by an ACL (security access control list) making it updateable only by the administrator; in future releases it may be read-only.

With that warning out of the way, configuring only the ":Path" value makes tracing available on all applications running on a given machine. For example, if a programmer is running a SQL Server 2005 instance and a data access client on his or her machine, turning on SNI tracing will trace SNI calls from both sides. That can generate some large output, although in certain use cases this can be exactly the type of output that you want. You can configure applications to be traced if there is no ":Path" value or to be excluded from tracing if there is a ":Path" value.

If there is no ":Path" value, only applications that are specifically configured will be traced. You can configure applications to be "traceable" by specifying a REG_SZ entry with the full path to the program's main executable file as the value name and the full path to AdoNetDiag.dll as the value. You can also configure an entire directory to be traceable by using the path name and the * wildcard.

If there is a ":Path" value, you can restrict applications or applications in a specific directory from being traced by adding a REG_SZ entry and the value of ":" (single colon). Wildcards in the directory name are allowed. For example, the name field containing the directory name (C:\Program Files\Microsoft SQL Server\MSSQL.1\MSSQL\Binn\*) along with a ":" value would keep all programs in the SQL Server Binn directory (such as SQL Server, SQL Trace, etc.) from showing up in a trace. This is what we want most often when SQL Server is running on the same machine as our application. Remember that configuring the registry entries just names the data tracing provider DLL—it does not turn on the trace. This is a particularly useful feature, as you can configure and set up data tracing before a long-running program (like a Web server or Windows service) executes without turning it on. You can then turn the trace on and off using logman, while the program is running, without disturbing it. There's no performance hit from the trace when you're not using it. If you're tracing a network problem, you don't have to run SQL Server with any special trace flags to get detailed information.

You can also configure which provider information is traced to which files and control what is traced to a certain extent. You can trace the output from all four providers to a single file as we did with the _startTrace.cmd file, or separate them into one file per provider. You do this by using the logman utility to make up named traces. Here's an example that creates four traces:

logman create trace test1 -p System.Data.1

logman create trace test2 -p System.Data.OracleClient.1

logman create trace test3 -p SQLNCLI.1

logman create trace test4 -p System.Data.SNI.1

Note   In addition to using logman from the command line, you can also use the Snap-in for Performance Logs And Alerts to configure, run, and stop the trace.

You have some control over what is traced by manipulating the bits in the logman control.guid file. You do not need to have a control.guid file if you use a single provider per trace and take defaults, as the previous examples show, but _startTrace.cmd used one. To refresh your memory, here's a single line from control.guid:

{914ABDE2-171E-C600-3348-C514171DE148} 0x00000000 0 System.Data.1

The information in this line consists of:

• Provider GuidUIDe—which ETW provider
• Control Bits—0x00000000, in this case
• Control Value—0, in this case
• Provider Name—Required by ETW, but ignored by the logman utility

By setting bits in the Control Bits and Control Value fields, you have a macro-level mechanism for pre-filtering the events. The valid values are:

0x00000002 Regular tracepoints
0x00000004 Execution flow (function enter/leave)
0x00000080 Advanced Output

There are also bits that have special meaning for System.Data.1 and SQLNCLI.1:

0x00001000 Connection Pooling specific trace (System.Data.1 only)
0x00020000 SNI Detailed Trace

The bits can be "OR'd" together, of course. If 0x00000000 is specified, then 0x00000006 is assumed.

There are two possible non-default values that can be set in the control value:

128 - Convert Unicode text to ASCII text (reduces etl file size)
64 - Disable tracing in this component

Although the control bits are a bitmask, the control value must be set as a number. Note that setting these control bits does not provide a granular mechanism for configuring individual components, but instead makes it easy to filter types of events without post-processing the CSV file yourself.

Data Tracing Example

Now that we've discussed the mechanics of performing a trace, let's see it in action with an actual example, and then we'll discuss some key diagnostic scenarios.

Using Tracing to Debug a Parameter Binding Problem

We often use a trace to do problem determination when an application "eats" a rich error message and produces a polite but fairly "information-free" message. Such application code would look something like this:

string s = GetConnectionStringFromConfigFile();
using (SqlConnection conn = new SqlConnection(s))
using (SqlCommand cmd = new SqlCommand(
   "select * from authors where au_id = @auid", conn))
{
   // The error is hardcoded here but could have come from suboptimal 
   // editing in a graphic user interface.
   cmd.Parameters.Add("@auid", SqlDbType.Int);
   cmd.Parameters[0].Value = 123456789;
   SqlDataReader rdr = null;
   try {
     // Some code that could fail goes here.
     conn.Open();
     rdr = cmd.ExecuteReader();
     while (rdr.Read())
        Console.WriteLine(rdr[0]);
     rdr.Close();
   }
   catch (Exception e) {
     MessageBox.Show("polite error message");
   }
}

In this case, the error was caused by a parameter type mismatch, and the person diagnosing the error might not have access to the source code of the program. Turning on the trace, we'll see output like this:

"enter_01 <sc.SqlCommand.ExecuteReader|API> 1#"
 "<sc.SqlCommand.get_Connection|API> 1#"
 "<sc.SqlCommand.get_Connection|API> 1#"
 "<sc.TdsParser.CreateSession|ADV> 1# created session 3"
 "<sc.TdsParserSessionPool.CreateSession|ADV> 1# adding session 3 to pool"
 "<sc.TdsParserSessionPool.GetSession|ADV> 1# using session 3"
 "<sc.TdsParser.GetSession|ADV> 1# getting session 3 from pool"
 "<sc.SqlCommand.ExecuteReader|INFO> 1#  Command executed as RPC."
 "<sc.SqlCommand.get_Connection|API> 1#"
 "leave_01"
 "enter_01 <sc.SqlDataReader.Read|API> 1#"
 "<sc.SqlError.SqlError|ERR> infoNumber=245  errorState=1  errorClass=16  
errorMessage='Syntax error converting the varchar value '172-32-1176' to a 
column of data type int.'  procedure=''  lineNumber=1"
 "leave_01"

This shows us directly that there is a parameter value mismatch. Note that the trace file is much more compact in this case because we're only tracing with the System.Data.1 provider.

Two Key Diagnostic Scenarios

Sometimes data tracing can be used to illuminate a problem that might have taken days or weeks to find otherwise. One example is diagnosing a problem with reclamation of resources. On occasion a program logic error might result in the program eventually running out of connections or overloading the connection pool. For example, beginning a transaction and having a logic path where COMMIT or ROLLBACK procedures are never called would result in the connection remaining in the transacted connection pool until the transaction times out. This can produce some strange connection pool behavior that baffles the application programmer (and the diagnostician). A related scenario could be simply failing to close connections, leaving the pooler and timeouts to do that work—this is a "sub-optimal" way to close connections, to put it mildly. Watching the connection pool activity and correlating this with transaction activity by running SELECT statements against a post-processed trace can be a great help in troubleshooting these knotty problems. The "enter-leave" pairs are particularly enlightening in the case, as are the transaction timeout trace entries.

Another scenario is when an application seems to have abnormally long connection times. Because of the way the network libraries can be configured, it's possible that SQL Server can attempt to connect through TCP/IP, for example, and then use named pipes or other protocols on the client protocol list when TCP/IP fails. If the first protocol in the list fails because of a timeout, this could look like slow connection or slow response time. You can use data tracing to watch this in graphic detail, because the trace of the SqlClient and other managed .NET data providers is integrated with the trace from the unmanaged stack and the network. The whole progression of events will even be bracketed in "enter-leave" blocks for you, with timestamps to enable you to see where the Open() method call is spending its time.

We've barely scratched the surface of uses for this complex and powerful feature. Some possibilities for further experimentation include:

• Integrating tracing into unit testing.
• Performing comparative analyses of DataSet and DataReader calls to determine where DataSet is spending its time.
• Using data tracing in conjunction with the ASP.NET and other ETW providers.
• Doing a combined data trace and SQL Server trace using the SQL Server ETW provider.
• Diagnosing other network protocol problems.

Inside Data Tracing

You now have a cookbook way to set up, run, and interpret traces in the Microsoft data access stacks. But, aside from issuing command line scripts, what exactly is going on?

Data tracing is based on a provider model itself. ADO.NET data providers or other data access code use standard APIs (which themselves use standard trace hooks) to feed trace information into the model. In the future, multiple data trace providers may be built. Currently only AdoNetDiag is available. However, it's easy to imagine data tracing consumers that provide a pre-filtering of events at a granular level, or use a different trace output system such as OutputDebugString, or output into SQL Server directly for ease in searching and querying. You could even hook data tracing up to the .NET System.Diagnostics.Trace.

ADO.NET 2.0 and SQL Native Client both come with an adapter to the Event Tracing for Windows (ETW) system. You can trace from the managed stack into the unmanaged stack and back without a hitch. ETW is a high-performance tracing system that was originally introduced to implement kernel-level tracing for device driver writers. Here's a high-level explanation of ETW that uses data tracing as an example.

What Is ETW?

Event Tracing for Windows is meant to provide low overhead tracing as compared with Windows Performance Monitor. ETW usually takes up no more than 5 percent of the CPU and can log up to 20,000 events per second. It's fast enough to enable tracing in real time. ETW uses a provider-based model; in this case a provider is a system or application component that sends events to the event system. Some examples of event providers are Active Directory, IIS, and ASP.NET. The ADO.NET and SQL Native Client data traces register five ETW event providers:

• System.Data.1—ADO.NET providers and classes in System.Data.dll
• System.Data.OracleClient.1—OracleClient provider in System.OracleClient.dll
• System.Data.SNI. B1—SNI from System.Data
• SQLNCLI.1—SQL Native Client providers and SNI from SQL Native Client
• ADONETDIAG.ETW—provides events from the ETW adapter itself

The ETW provider logs yield a timestamp with each event. When you start the trace, you can specify a high-resolution timestamp or low-resolution timestamp. In our _startTrace.cmd file, we've used the -ct perf option to choose a high-resolution timestamp. In the "single-file" scripts above, we've chosen the default (low-resolution) timestamp. ETW chooses high performance over ease of use. Formatting ETW traces with tracerpt.exe produces a cursory decoding. The format of the ETL file is documented and the schemas for individual trace providers is recorded in WMI, so programmers are welcome to build their own specialized formatter. A nice feature of using ETW is that the trace that you produce can be used in conjunction with an ASP.NET trace, or, for that matter, a low-level operating system kernel trace. All of the events can be logged on a per-provider basis to a single file for correlation or to separate files. Information on Event Tracing For Windows is available on the Performances Best Practices at a Glance page of the patterns & practices Web site.

ETW output can be consumed by a variety of tools, and if none of the tools suit your specific needs, you can build your own. One example of such a consumer tool is logparser. Logparser can consume output not only from ETW, but from other outputs like IIS log files and Windows Event Logs. Logparser then lets you use SQL-like syntax to query your events. Logparser is available as part of the Internet Information Services (IIS) 6.0 Resource Kit Tools [ http://www.microsoft.com/downloads/details.aspx?familyid=56fc92ee-a71a-4c73-b628-ade629c89499&displaylang=en ] .

Special Considerations for Tracing on Windows 2000

Unfortunately, Windows 2000 does not include ETW TraceRPT functionality. As a result, your steps for capturing a trace on a Windows 2000 computer need to be a bit different. To capture a trace on a Windows 2000 computer, copy the contents of the directory WIN2K_Only that accompanies this article to a directory on your machine. For this example, please create a directory named "C:\Trace" and copy the WIN2K_Only directory to it. The only differences from tracing in Windows XP and Windows Server 2003 are outlined in the following three steps.

Running Trace Command

@tracelog -start Trace -UsePerfCounter -guid ctrl.guid -flag 0x00000000 -
level 0 -f Out.etl

Stopping the Trace

@tracelog -stop Trace

Format the results as a .txt file

@tracefmt out.etl -p .\TMF_DataAccess -o dumpfile.txt

Special Considerations for Tracing the JDBC Driver

The only component of the JDBC driver that supports the tracing methodology outlined in this article is sqljdbc_xa.dll, which is the DLL that is used for distributed transactions. For all other JDBC driver components, tracing (or logging) is accomplished by using the logging APIs in java.util.logging, which provides a set of classes for creating Logger and LogRecord objects.

For more information about the JDBC driver's support for data tracing and logging, see Tracing Driver Operation [ http://msdn2.microsoft.com/en-us/library/ms378517.aspx ] .

Note that the user data of trace output from the JDBC driver does not follow the traces of other components, such as ADO.NET. Some information that is not present includes the namespace abbreviation. Additionally, the class name and method name are merged together by a "_". The JDBC driver only uses the keyword ERR, as in the following example. Besides these few deviations, the user data produced by a JDBC driver trace follows the ADO.NET user data syntax as in the following example:

"enter_01 <xp_sqljdbc_xa_init> pSrvProc=073523C0"
 "leave_01"
 "enter_01 <xp_sqljdbc_xa_start> pSrvProc=073523C8"
 "<xp_sqljdbc_xa_start|ERR> nStatus=-8  state=5"
 "leave_01"

Conclusion

Tracing has been added at the provider level, network protocol level, and to all of the data access technologies coming from Microsoft. You now have the ability to trace your data applications from end to end, and the model's flexibility will accommodate different trace engines in the future. Additionally, the API is straightforward so that provider writers and user application writers can add tracing to their products. The integration of data tracing with current trace-gathering facilities, as well as the extensibility to future trace-gathering facilities, makes for a useful and long-lived tool in the troubleshooter's and administrator's toolbox. Happy tracing!

 

About the authors

Bob Beauchemin is an instructor, course author, and database curriculum course liaison for DevelopMentor. He has over twenty-five years of experience as an architect, programmer, and administrator for data-centric distributed systems. He's written articles on ADO.NET, OLE DB, and SQL Server for Microsoft Systems Journal, SQL Server Magazine, and others.

Jennifer Perret is a Program Manager for the Data Programmability team at Microsoft, which builds the Data Access Technologies for Microsoft. The Data Programmability team is responsible for MDAC, SQL Native Client, SQL Network Interfaces, and ADO.NET.

Acey Bunch is a Programmer Writer for the SQL Server User Education team at Microsoft. He helps to document multiple data access technologies such as MDAC, ADO.NET, SQL Native Client, and the Microsoft SQL Server 2005 JDBC Driver.

Appendix

A: MOF Files

Table 3. MOF Files

B: Control GUID Files

Table 4. Control GUID Files

C: Categories

Table 5. Categories used in .NET Trace Points

Table 6. Categories used in SQL Native Client Provider Trace Points

Table 7. Categories used in the JDBC driver

For more information:

• http://msdn.microsoft.com/data/ [ http://msdn.microsoft.com/data/ ]
• http://msdn.microsoft.com/sql/ [ http://msdn.microsoft.com/sql/ ]

Did this paper help you? Please give us your feedback. On a scale of 1 (poor) to 5 (excellent), how would you rate this paper?

 

Copyright

The information contained in this document represents the current view of Microsoft Corporation on the issues discussed as of the date of publication. Because Microsoft must respond to changing market conditions, it should not be interpreted to be a commitment on the part of Microsoft, and Microsoft cannot guarantee the accuracy of any information presented after the date of publication.

This White Paper is for informational purposes only. MICROSOFT MAKES NO WARRANTIES, EXPRESS, IMPLIED OR STATUTORY, AS TO THE INFORMATION IN THIS DOCUMENT.

Complying with all applicable copyright laws is the responsibility of the user. Without limiting the rights under copyright, no part of this document may be reproduced, stored in or introduced into a retrieval system, or transmitted in any form or by any means (electronic, mechanical, photocopying, recording, or otherwise), or for any purpose, without the express written permission of Microsoft Corporation.

Microsoft may have patents, patent applications, trademarks, copyrights, or other intellectual property rights covering subject matter in this document. Except as expressly provided in any written license agreement from Microsoft, the furnishing of this document does not give you any license to these patents, trademarks, copyrights, or other intellectual property.

Unless otherwise noted, the example companies, organizations, products, domain names, e-mail addresses, logos, people, places and events depicted herein are fictitious, and no association with any real company, organization, product, domain name, e-mail address, logo, person, place or event is intended or should be inferred.

© 2006 Microsoft Corporation. All rights reserved.

Microsoft, Active Directory, Excel, Visual Studio, and Windows are either registered trademarks or trademarks of Microsoft Corporation in the United States and/or other countries.

The names of actual companies and products mentioned herein may be the trademarks of their respective owners.