Data Access Tracing in SQL Server 2008
SQL Server Technical Article
Writers: Bob Beauchemin, Jennifer Perret; Acey Bunch, David Schwartz
Published: October 2009
Applies To:
Microsoft® ADO.NET 2.0
Microsoft® ADO.NET 4.0
Microsoft MDAC 2.8 SP2
Microsoft Windows Data Access Components
Microsoft SQL Server™ Native Client
Microsoft SQL Server 2005 JDBC Driver
Microsoft SQL Network Protocols
Microsoft SQL Server 2005
Microsoft SQL Server 2008
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.
Download Sample and MOF Files
To use BID tracing, you will need MOF and control files. You can download those files to your computer by clicking here.
Table of Contents
Introduction. 1
Tracing a Data Access Application. 2
Setting Up the Trace. 2
Creating the Trace DLL Registry Entry. 2
Registering the Trace Schema. 3
Configuring and Running the Trace. 5
Reviewing the Trace Results 6
Formatting the Trace Output 6
Reading the Trace Output 7
User Data and ADO.NET Tracing. 8
Configuring Which Applications Are Traced. 9
Data Tracing Example. 11
Using Tracing to Debug a Parameter Binding Problem.. 11
Two Key Diagnostic Scenarios 12
Inside Data Tracing. 13
What is ETW? 13
Special Considerations for Tracing on Windows 2000. 14
Special Considerations for Tracing the JDBC Driver 14
Conclusion. 15
Appendix. 15
A: MOF Files 15
B: Control GUID Files 16
C: Categories 16
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, Microsoft Windows Data Access Components, 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 written article (located at https://msdn.microsoft.com/en-us/library/aa964124.aspx) 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 Server Native Client OLE DB provider and ODBC driver, MDAC 2.82, Microsoft Windows Data Access Components, 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 Server 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 KB article How to back up, edit, and restore the registry in Windows found at https://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:
HKEY_LOCAL_MACHINE\Software\Microsoft\BidInterface\Loader
One exception is when tracing a 32-bit application on 64-bit platform (WOW). In this case, please use the registry key in Wow6432Node as follows:
HKEY_LOCAL_MACHINE\software\Wow6432Node\Microsoft\BidInterface\Loader
If you do not see the Loader key, right click the BidInterface key and select New, then Key. Name the key Loader.
3. 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.
4. 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.
5. 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 Server Native Client, JDBC driver, and MDAC 2.82 (no ADO.NET 2.0 on the system), and Microsoft Windows Data Access Components
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 (setup_trace.reg is one of the files that you can download with the link at the beginning of this article), using the command “regedit setup_trace.reg”. This will set the msdadiag.dll Built-in Diagnostics (BID) adapter into the registry location as listed above. When tracing a 32-bit application on a 64-bit operating system, you must use "C:\Windows\SystemWOW64\regedit.exe setup_trace.reg". Note, this procedure does not work for ADO.NET 2.0.
Finally, restart the process you want to trace (client application or SQL Server) to complete the process of enabling BID tracing.
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 Server 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}
*SQLSERVER.SNI10.1 {48D59D84-105B-00FA-6B49-03462F696737}
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}
*SQLNCLI10.1 {A9377239-477A-DD22-6E21-75912A95FD08}
*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}
BCP10.1 {ED303448-5479-CA3F-5686-E020BA4F47F9}
DBNETLIB.1 {BD568F20-FCCD-B948-054E-DB3421115D61}
*ADODB.1 {04C8A86F-3369-12F8-4769-24E484A9E725}
MSADCF.1 {101C0E21-EBBA-A60A-EC3D-58797788928A}
*ADOMD.1 {7EA56435-3F2F-3F63-A829-F0B35B5CAD41}
*MSADCO.1 {5C6CE734-1B3E-705E-C2AB-B272D99AAF8F}
*MSADOX.1 {6C770D53-0441-AFD4-DCAB-1D89155FECFC}
*MSDASQL.1 {B6501BA0-C61A-C4E6-6FA2-A4E7F8C8E7A0}
*ODBCBCP.1 {932B59F1-90C2-D8BA-0956-3975C344AE2B}
*System.Data.1 {914ABDE2-171E-C600-3348-C514171DE148}
Spooler Trace Control {94a984ef-f525-4bf1-be3c-ef374056a592}
System.Data.Entity.1 {A68D8BB7-4F92-9A7A-D50B-CEC0F44C4808}
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. You can download the WMI Administrative Tools at https://www.microsoft.com/downloads/details.aspx?displaylang=en&familyid=6430f853-1120-48db-8cc5-f2abdc3ed314. The WMI schemas for data tracing are pretty simple, and we'll talk about them in a later section.
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 using a Windows operating system other than Windows 2000, 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 not available on Windows XP. This option creates better time granularity within the trace captures.
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
{A68D8BB7-4F92-9A7A-D50B-CEC0F44C4808} 0xFFFFFFFF 0 System.Data.Entity.1
{C9996FA5-C06F-F20C-8A20-69B3BA392315} 0x00000000 0 System.Data.SNI.1
{DCD90923-4953-20C2-8708-01976FB15287} 0x00000000 0 System.Data.OracleClient.1
{8B98D3F2-3CC6-0B9C-6651-9649CCE5C752} 0x00000000 0 MSDADIAG.ETW
{04C8A86F-3369-12F8-4769-24E484A9E725} 0x00000007 0 ADODB.1
{7EA56435-3F2F-3F63-A829-F0B35B5CAD41} 0x00000007 0 ADOMD.1
{BD568F20-FCCD-B948-054E-DB3421115D61} 0x00000007 0 DBNETLIB.1
{F34765F6-A1BE-4B9D-1400-B8A12921F704} 0x00000007 0 ODBC.1
{932B59F1-90C2-D8BA-0956-3975C344AE2B} 0x00000007 0 ODBCBCP.1
{0DD082C4-66F2-271F-74BA-2BF1F9F65C66} 0x00000007 0 OLEDB.1
{C5BFFE2E-9D87-D568-A09E-08FC83D0C7C2} 0x00000007 0 SQLOLEDB.1
{4B647745-F438-0A42-F870-5DBD29949C99} 0x00000007 0 SQLSRV32.1
{76DBA919-5A36-FC80-2CAD-3185532B7CB1} 0x00000007 0 MSADCE.1
{101C0E21-EBBA-A60A-EC3D-58797788928A} 0x00000000 0 MSADCF.1
{5C6CE734-1B3E-705E-C2AB-B272D99AAF8F} 0x00000007 0 MSADCO.1
{13CD7F92-5BAA-8C7C-3D72-B69FAC139A46} 0x00000000 0 MSADDS.1
{6C770D53-0441-AFD4-DCAB-1D89155FECFC} 0x00000007 0 MSADOX.1
{64A552E0-6C60-B907-E59C-10F1DFF76B0D} 0x00000000 0 MSDAPRST.1
{564F1E24-FC86-28E1-74F8-5CA0D950BEE0} 0x00000000 0 MSDAREM.1
{B6501BA0-C61A-C4E6-6FA2-A4E7F8C8E7A0} 0x00000007 0 MSDASQL.1
{FC9F92E6-D521-9C9A-1D8C-D8980B9978A9} 0xFFFFFFFF 0 SQLBROWSER.1
{172E580D-9BEF-D154-EABB-83429A6F3718} 0x00000000 0 SQLJDBC_XA.1
{BA798F36-2325-EC5B-ECF8-76958A2AF9B5} 0xFFFFFFFF 0 SQLNCLI.1
{AB6D5EEB-0132-74AB-C5F5-B23E1644DADA} 0xFFFFFFFF 0 SQLSERVER.SNI.1
{24722B88-DF97-4FF6-E395-DB533AC42A1E} 0x00000000 0 BCP.1
{A9377239-477A-DD22-6E21-75912A95FD08} 0xFFFFFFFF 0 SQLNCLI10.1
{48D59D84-105B-00FA-6B49-03462F696737} 0xFFFFFFFF 0 SQLSERVER.SNI10.1
{ED303448-5479-CA3F-5686-E020BA4F47F9} 0xFFFFFFFF 0 BCP10.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 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 in binary format. 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. You can browse this file for now; later, you can do some further post-processing, such as loading the data into SQL Server and querying it with SQL. You now have your first trace.
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"
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. The next section will discuss the bracket format of the user data generated by the "mainstream" tracer, System.Data.1.
User Data and ADO.NET Tracing
The content and format of the user data field is determined by the user (or trace provider). Calls to System.Data.dll and System.OracleClient.dll have 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. Abbreviated namespaces minimize the size of the output. 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
Description |
Abbreviation |
Namespace |
SqlClient managed provider |
sc |
System.Data.SqlClient |
OleDb managed provider |
oledb |
System.Data.OleDb |
Odbc managed provider |
odbc |
System.Data.Odbc |
Oracle managed provider |
ora |
System.Data.OracleClient |
DataSet/DataTable/Data* |
ds |
System.Data |
Common code |
comn |
System.Data.Common |
Provider base implementation classes |
prov |
System.Data.ProviderBase |
Table 2. Categories used in .NET Trace Points
Keyword |
Category |
API |
Public API (method, property) is called |
OLEDB |
Code calls OLEDB component |
ODBC |
Code calls ODBC API |
SNI |
Code calls SNI |
ERR |
Error |
WARN |
Warning |
INFO |
Information |
RET |
Return value, usually in the form of API|RET |
THROW |
An new exception is being thrown (not applicable to exceptions being re-thrown) |
CATCH |
Code catches an exception |
CPOOL |
Connection pool activities |
ADV |
Advanced 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. Appendix C: Categories lists the categories used for SQL Server Native Client Providers, the JDBC driver, SNI (SQL Network Interfaces), and MDAC.
Tracing a Data Access Application (Alternative Procedure)
The procedure in the previous section requires you to edit the registry and to use MOF and control GUID files. The procedure described in this section may be suitable when tracing a single provider. However, it does require knowledge of the GUIDs.
1. Issue the following commands:
reg add HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\BidInterface\Loader /v ":Path" /t REG_SZ /d msdadiag.dll
logman start MyTrace -p <GUID for our BID provider> -ct perf -o Out.etl -ets
In the previous command, replace <GUID for our BID provider> with the GUID for the provider you want to trace. The file ctrl.guid.all has a list of GUIDs.
The -p option allows only one provider to be specified. To capture traces from multiple providers, use multiple logman commands, each specifying a separate trace name, *.etl file name, and provider GUID. You can then pass all the *.etl files into a single tracerpt command, which will merge them into a single dumpfile.csv.
Getting a full SNI trace requires a bit mask. For example:
logman start MyTrace -p {AB6D5EEB-0132-74AB-C5F5-B23E1644DADA} 0xFFFFFFFF -ct perf -o Out.etl -ets
On Windows XP, omit “-ct perf”.
2. Restart the application and run the scenario you want to trace.
3. Issue the following commands:
logman stop MyTrace -ets
reg delete HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\BidInterface\Loader /v ":Path" /f
To convert Out.etl into a .CSV file, issue the following commands:
mofcomp all.mof
tracerpt /y Out.etl
Configuring Which Applications Are Traced
The ":Path" string value of the Loader registry key. Manual configuration is protected by an ACL (security access control list) making it updateable only by the administrator; in future releases it may be read-only.
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 (and SQLNCLI10.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 hides a rich error message and generates a vague 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.
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 Server 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 Server Native Client data traces register five ETW event providers:
· System.Data.1—ADO.NET providers and classes in System.Data.dll
· System.Data.Entity.1—Entity Framework in System.Data.Entity.dll beginning with .NET Framework 4.0 beta 2
· System.Data.OracleClient.1—OracleClient provider in System.OracleClient.dll
· System.Data.SNI. B1—SNI from System.Data
· SQLNCLI.1—SQL Server Native Client providers and SNI from SQL Server 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 site, which you can find at https://msdn.microsoft.com/library/default.asp?url=/library/en-us/dnpag/html/scalenet-atglance.asp.
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 IIS 6.0 Resource Kit Tools found at https://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 at https://msdn2.microsoft.com/en-us/library/ms378517(SQL.90).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!
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 and Acey Bunch contibuted to this article.
Appendix
A: MOF Files
Table 3. MOF Files
File |
Details |
ADO_NET.mof |
ADO.NET only |
all.mof |
All of the MOF files in this list |
bcp.mof |
BCP only (SQL Server 2005) |
bcp10.mof |
BCP only (SQL Server 2008) |
MDAC_srv03.mof |
MDAC on Windows Server 2003 only |
MDAC_xpsp2.mof |
MDAC on XP SP2 only |
snac.mof |
SQL Server Native Client only (SQL Server 2005) |
snac10.mof |
SQL Server Native Client only (SQL Server 2008) |
sqlbrowser.mof |
SQLBrowser only |
sqljdbc_xa.mof |
JDBC driver only (XA transactions only) |
sqlserver_sni.mof |
SQL Server SNI only (SQL Server 2005) |
sqlserver_sni10.mof |
SQL Server SNI only (SQL Server 2008) |
wdac.mof |
Windows Data Access Components on Windows 7 only |
B: Control GUID Files
A control GUID file specifies which data access provider(s) to trace. ctrl.guid.contains GUIDs for Microsoft providers. The other files are for common trace scenarios. If a control file has a SQL Server 2005 GUID and there is no equivalent control file for SQL Server 2008, you can make a SQL Server 2008 control file by making a copy of the control file and replacing the SQL Server 2005 GUID with the equivalent GUID for SQL Server 2008 from ctrl.guid.all.
Table 4. Control GUID Files
File |
Details |
ctrl.guid.adonet |
ADO.NET only |
ctrl.guid.all |
All data access technologies: ADO.NET, MDAC, Microsoft Windows Data Access Components, SQL Server Native Client, JDBC driver, SQL Network Interfaces, and BCP This file contains GUIDs for SQL Server 2005 (SQLNCLI.1, SQLSERVER.SNI.1, and BCP.1) and SQL Server 2008 (SQLNCLI10.1, SQLSERVER.SNI10.1, and BCP10.1). |
ctrl.guid.all.No_SNI |
All data access technologies enabled except ADO.NET, SQL Network Interfaces: MDAC, Microsoft Windows Data Access Components, SQL Server Native Client, JDBC driver, and BCP |
ctrl.guid.all.srv03 |
All data access technologies for Windows Server 2003 (differences in MDAC versions) |
ctrl.guid.all.srv03.No_SNI |
All data access technologies for Windows Server 2003 enabled except ADO.NET, SQL Network Interfaces: MDAC, SQL Server Native Client, JDBC driver, and BCP |
ctrl.guid.all_asp_iis |
All data access technologies and ASP.NET and IIS ETW Provider GUIDs |
ctrl.guid.bcp |
BCP only (SQL Server 2005) |
ctrl.guid.bcp10 |
BCP only (SQL Server 2008) |
ctrl.guid.msdadiag |
MSDADIAG only |
ctrl.guid.snac |
SQL Server Native Client Providers only (SQL Server 2005) |
ctrl.guid.snac10 |
SQL Server Native Client Providers only (SQL Server 2008) |
ctrl.guid.sqlbrowser |
SQL Browser only |
ctrl.guid.sqljdbc_xa |
JDBC driver only |
ctrl.guid.sqlserver |
SQL Server SNI only (SQL Server 2005) |
ctrl.guid.sqlserver10 |
SQL Server SNI only (SQL Server 2008) |
ctrl.guid.mdac |
Windows Data Access Components (formerly Microsoft Data Access Components) on Windows 7 only |
ctrl.guid.wdac |
Windows Data Access Components on Windows 7 only |
C: Categories
Table 5. Categories used in .NET Trace Points
Keyword |
Categories |
API |
Public API (method, property) is called |
OLEDB |
Code calls OLEDB component |
ODBC |
Code calls ODBC API |
SNI |
Code calls SNI |
ERR |
Error |
WARN |
Warning |
INFO |
Information |
RET |
Return value, usually in the form of API|RET |
THROW |
An new exception is being thrown (not applicable to exceptions being re-thrown) |
CATCH |
Code catches an exception |
CPOOL |
Connection pool activities |
ADV |
Advanced trace points |
Table 6. Categories used in SQL Server Native Client Provider Trace Points
Keyword |
Categories |
API|OLEDB or API|ODBC |
Public API (method, property) is called in either OLEDB or ODBC Providers. |
ERR |
Error |
INFO |
Additional information exists. |
LIFETIME |
Lifetime-related activity, such as AddRef/Release for COM objects |
ODBC |
ODBC driver |
OLEDB |
OLE DB provider |
PERF |
Perf hooks for perf related tracing. |
RES |
Resources |
RES|MEM |
Memory allocation/free |
RET |
Return value, usually in the form of API|OLEDB|RET or API|RET|ODBC |
TDS |
TDS parser |
WARN |
Warning |
ADV |
Advanced trace points |
Table 7. Categories used in the JDBC driver
Keyword |
Categories |
ERR |
Exceptions and errors thrown from sqljdbc_xa.dll |
ADV |
Advanced trace points |
Table 8. Categories used in Windows Data Access Components
Keyword |
Categories |
API|OLEDB or API|ODBC |
Public API (method, property) is called in either OLEDB Core services, OLEDB providers or ODBC Drivers |
ERR |
Error |
INFO |
Additional information exists |
ADO |
ADO components |
ODBC|DRIVER |
ODBC driver (SQLSRV32) |
ODBC|DM |
ODBC driver manager |
OLEDB |
OLE DB core services or OLEDB provider (SQLOLEDB) |
RES |
Resources |
RES|MEM |
Memory allocation/free |
RET |
Return value, usually in the form of API|OLEDB|RET or API|RET|ODBC |
TDS |
TDS parser |
WARN |
Warning |
ADV |
Advanced trace points |
For more information:
https://msdn.microsoft.com/data/
https://msdn.microsoft.com/sqlserver/
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?