Collect a SQL Driver BID Trace - microsoft/CSS_SQL_Networking_Tools GitHub Wiki

Collect a SQL Server Driver Built-In Diagnostic (BID) Trace

What is a BID Trace

The built-in diagnostic trace outputs the state of various driver APIs. This is a very detailed trace that can reveal information about issues that the driver may encounter. The trace records the process and thread ID to keep various activities separate, as well as a timestamp accurate to the system timer resolution (about 100ns).

On Windows systems, a BID Trace is based on LOGMAN Event Tracing for Windows (ETW) tracing and results in an ETL file that can be read by NETMON or converted into a CSV file that you can open in Excel.

On Linux and Mac systems, parameters in the ODBCINST.INI configuration enable the tracing and the driver writes directly to the log file.

BID Trace vs ODBC Trace

An ODBC trace is performed by the ODBC Driver Manager, a shim DLL between the application and the driver. This DLL acts as a proxy, and as such, intercepts all driver calls and can log the ODBC API state of any ODBC driver.

This trace has a number of major disadvantages over BID traces:

  1. It is very slow and can significantly impact application performance.
  2. It is very difficult to configure to trace server applications.
  3. It only traces the high-level API between the application and the driver and shows no internal driver state.

What Can Be Traced using BID Tracing

  • Almost all Windows-based data access components, including ADO, JDBC XA Transactions, and managed providers.
  • SQL Servers up through SQL 2014. SQL 2016 and later can be traced via XEvent SNI tracing.
  • SQL Server ODBC Drivers for Linux and Mac (special instructions apply).

What Cannot Be Traced using BID Tracing

When to Use BID Tracing

BID tracing is generally warranted if you need to see specifics of the driver actions. Two main scenarios present themselves:

  1. In a network trace, you see an unexpected behavior from the driver or server, such as:
    1.1. A long delay where there should be none, such as a delay in sending out the PreLogin packet after the TCP 3-way handshake. The BID trace may reveal an internal API taking a long time, such as a call to Active Directory or the DNS server.
    1.2. The client unexpectedly closes the connection, e.g. after the TCP 3-way handshake, or in the middle of SSL handshake. It can also reveal how much of the Connection Timeout was spent on preparing to put the first packet on the wire.

In the above cases, the client and server network trace should agree on the bad behavior. Take the BID trace of the server if it is the entity with the delay or closing the connection. Likewise, take it of the client driver if the delay or closure originates on the client.

  1. The client is making a local connection to the server and that is failing and you cannot reproduce it in a remote connection in order to take a network trace.

In this case, take a BID trace/Xevent SNI Trace of both the client and server.

Providers on Windows

The BID trace can record events from a variety of drivers. You should specify as few as necessary in order to take the trace. In order to do this, you should know which driver the application is using and what the SQL Server version is. There are also generic trace points for ODBC, OLE DB, and ADO, that can help even if not using a Microsoft driver. Since most applications use the SqlClient managed Provider, using System.Data and System.Data.SNI are common trace points.

From an Admin command prompt, use tasklist /m /fi "imagename eq myApp.exe" to list the DLLs in a specific process to identify the driver name in the table below. You can also run the SQL Connectivity Check (SQLCHECK) tool, which lists each process and what providers are currently loaded by them.

The following extract from the BIDTrace.vbs script shows drivers that can be traced and their LOGMAN guids:

        "{8B98D3F2-3CC6-0B9C-6651-9649CCE5C752}","{8B98D3F3-3CC6-0B9C-6651-9649CCE5C752}","MSDADIAG","ETW", _
        "{04C8A86F-3369-12F8-4769-24E484A9E725}","{04C8A870-3369-12F8-4769-24E484A9E725}","ADODB","1",      _
        "{7EA56435-3F2F-3F63-A829-F0B35B5CAD41}","{7EA56436-3F2F-3F63-A829-F0B35B5CAD41}","ADOMD","1",      _
        "{24722B88-DF97-4FF6-E395-DB533AC42A1E}","{24722B89-DF97-4FF6-E395-DB533AC42A1E}","BCP","1",        _
        "{ED303448-5479-CA3F-5686-E020BA4F47F9}","{ED303449-5479-CA3F-5686-E020BA4F47F9}","BCP10","1",      _
        "{BD568F20-FCCD-B948-054E-DB3421115D61}","{BD568F21-FCCD-B948-054E-DB3421115D61}","DBNETLIB","1",   _
        "{76DBA919-5A36-FC80-2CAD-3185532B7CB1}","{76DBA91A-5A36-FC80-2CAD-3185532B7CB1}","MSADCE","1",     _
        "{101C0E21-EBBA-A60A-EC3D-58797788928A}","{101C0E22-EBBA-A60A-EC3D-58797788928A}","MSADCF","1",     _ 
        "{5C6CE734-1B3E-705E-C2AB-B272D99AAF8F}","{5C6CE735-1B3E-705E-C2AB-B272D99AAF8F}","MSADCO","1",     _
        "{13CD7F92-5BAA-8C7C-3D72-B69FAC139A46}","{13CD7F93-5BAA-8C7C-3D72-B69FAC139A46}","MSADDS","1",     _
        "{6C770D53-0441-AFD4-DCAB-1D89155FECFC}","{6C770D54-0441-AFD4-DCAB-1D89155FECFC}","MSADOX","1",     _
        "{F02A5DAC-6DB2-F77F-F6A8-6404FE697B7D}","{F02A5DAD-6DB2-F77F-F6A8-6404FE697B7D}","MSDAORA","1",    _
        "{64A552E0-6C60-B907-E59C-10F1DFF76B0D}","{64A552E1-6C60-B907-E59C-10F1DFF76B0D}","MSDAPRST","1",   _
        "{564F1E24-FC86-28E1-74F8-5CA0D950BEE0}","{564F1E25-FC86-28E1-74F8-5CA0D950BEE0}","MSDAREM","1",    _
        "{CEB7253C-BB96-9DFE-51D1-53D966D0CF8B}","{CEB7253D-BB96-9DFE-51D1-53D966D0CF8B}","MSDART","1",     _
        "{B6501BA0-C61A-C4E6-6FA2-A4E7F8C8E7A0}","{B6501BA1-C61A-C4E6-6FA2-A4E7F8C8E7A0}","MSDASQL","1",    _
        "{87B93A44-1F73-EC83-7261-2DFC972D9B1E}","{87B93A45-1F73-EC83-7261-2DFC972D9B1E}","MSDATL3","1",    _
        "{F34765F6-A1BE-4B9D-1400-B8A12921F704}","{F34765F7-A1BE-4B9D-1400-B8A12921F704}","ODBC","1",       _
        "{932B59F1-90C2-D8BA-0956-3975C344AE2B}","{932B59F2-90C2-D8BA-0956-3975C344AE2B}","ODBCBCP","1",    _
        "{0DD082C4-66F2-271F-74BA-2BF1F9F65C66}","{0DD082C5-66F2-271F-74BA-2BF1F9F65C66}","OLEDB","1",      _
        "{74A75B02-36D8-EDE6-D10E-95B691503408}","{74A75B03-36D8-EDE6-D10E-95B691503408}","RowsetHelper","1",   _
        "{FC9F92E6-D521-9C9A-1D8C-D8980B9978A9}","{FC9F92E7-D521-9C9A-1D8C-D8980B9978A9}","SQLBROWSER","1",     _
        "{C5BFFE2E-9D87-D568-A09E-08FC83D0C7C2}","{C5BFFE2F-9D87-D568-A09E-08FC83D0C7C2}","SQLOLEDB","1",   _
        "{BA798F36-2325-EC5B-ECF8-76958A2AF9B5}","{BA798F37-2325-EC5B-ECF8-76958A2AF9B5}","SQLNCLI","1",        _
        "{A9377239-477A-DD22-6E21-75912A95FD08}","{A937723A-477A-DD22-6E21-75912A95FD08}","SQLNCLI10","1",      _
        "{2DA81B52-908E-7DB6-EF81-76856BB47C4F}","{2DA81B53-908E-7DB6-EF81-76856BB47C4F}","SQLNCLI11","1",      _
        "{EE7FB59C-D3E8-9684-AEAC-B214EFD91B31}","{EE7FB59D-D3E8-9684-AEAC-B214EFD91B31}","MSOLEDBSQL","1",      _
        "{699773CA-18E7-57DF-5718-C244760A9F44}","{699773CB-18E7-57DF-5718-C244760A9F44}","MSOLEDBSQL19","1",      _
        "{AB6D5EEB-0132-74AB-C5F5-B23E1644DADA}","{AB6D5EEC-0132-74AB-C5F5-B23E1644DADA}","SQLSERVER.SNI", "1", _
        "{48D59D84-105B-00FA-6B49-03462F696737}","{48D59D85-105B-00FA-6B49-03462F696737}","SQLSERVER.SNI10","1",     _
        "{B2A28C42-A7C2-1563-97CC-3BE49FDA19F9}","{B2A28C43-A7C2-1563-97CC-3BE49FDA19F9}","SQLSERVER.SNI11","1",     _
        "{5BD84A98-C66F-1694-6E42-B18A6243602B}","{5BD84A99-C66F-1694-6E42-B18A6243602B}","SQLSERVER.SNI12","1",     _
        "{4B647745-F438-0A42-F870-5DBD29949C99}","{4B647746-F438-0A42-F870-5DBD29949C99}","SQLSRV32","1",       _
        "{7C360F7F-7102-250A-A233-F9BEBB9875C2}","{7C360F80-7102-250A-A233-F9BEBB9875C2}","MSODBCSQL11","1",       _
        "{85DC6E48-9394-F805-45C9-C8B2ACA2E7FE}","{85DC6E49-9394-F805-45C9-C8B2ACA2E7FE}","MSODBCSQL13","1",       _
        "{053A11C4-BC2B-F7CE-4A10-9D2602643DA0}","{053A11C5-BC2B-F7CE-4A10-9D2602643DA0}","MSODBCSQL17","1",       _
        "{1a1283ad-c65d-28ef-d729-39794ffdab32}","{1a1283ae-c65d-28ef-d729-39794ffdab32}","MSODBCSQL18","1",       _
        "{914ABDE2-171E-C600-3348-C514171DE148}","{914ABDE3-171E-C600-3348-C514171DE148}","System.Data","1",    _
        "{DCD90923-4953-20C2-8708-01976FB15287}","{DCD90924-4953-20C2-8708-01976FB15287}","System.Data.OracleClient","1", _
        "{C9996FA5-C06F-F20C-8A20-69B3BA392315}","{C9996FA6-C06F-F20C-8A20-69B3BA392315}","System.Data.SNI","1", _
        "{A68D8BB7-4F92-9A7A-D50B-CEC0F44C4808}","{A68D8BB8-4F92-9A7A-D50B-CEC0F44C4808}","System.Data.Entity","1", _
        "{172E580D-9BEF-D154-EABB-83429A6F3718}","{172E580E-9BEF-D154-EABB-83429A6F3718}","SQLJDBC_XA","1"

Server trace names:

Trace Name Component
SQLBROWSER SQL Browser
SQLSERVER.SNI SQL Server 2005 (unsupported)
SQLSERVER.SNI10 SQL Server 2008 and 2008 R2 (unsupported)
SQLSERVER.SNI11 SQL Server 2012 (unsupported)
SQLSERVER.SNI12 SQL Server 2014
Use XEvent SNI tracing SQL Server 2016 and later

Driver and client-side component trace names:

Trace Name Component
SYSTEM.DATA High-level API tracing for System.Data.SqlClient, System.Data.Odbc, etc.
SYSTEM.DATA.SNI Low-level tracing for System.Data.SqlClient. Use with SYSTEM.DATA.
SYSTEM.DATA.ORACLECLIENT Low-level tracing for System.Data.OracleClient. Use with SYSTEM.DATA.
SYSTEM.DATA.ENTITY Entity Framework trace points
SQLOLEDBSQLSRV32DBNETLIB SQL 2000 OLE DBSQL 2000 ODBCSQL 2000 driver common network layer. Use with one of the above.These components are deprecated legacy and should not be used for new development.
SQLNCLISQLNCLI10SQLNCLI11MSOLEDBSQLMSOLEDBSQL19 SQL Server Native Client 2005 OLE DB and ODBC (unsupported)SQL Server Native Client 2008 and 2008 R2 OLE DB and ODBC (unsupported)SQL Server Native Client 2012 OLE DB and ODBC (unsupported)Microsoft OLE DB Driver for SQL Server (18)Microsoft OLE DB Driver for SQL Server (19)
MSODBCSQL11MSODBCSQL13MSODBCSQL17MSODBCSQL18 ODBC Driver 11 for SQL ServerODBC Driver 13 for SQL ServerODBC Driver 17 for SQL ServerODBC Driver 18 for SQL Server
ODBCOLEDB ODBC Driver Manager tracing - similar to an ODBC traceOLE DB API tracing

Other trace points are for more specialty components, such as ADO, the client cursor engine, or JET ADOX APIs.

Note: In the commands below, the trace names can be used with or without a .1 suffix, e.g. ODBC vs ODBC.1.

Sample BID Trace Commands

BID tracing takes part in 4 distinct phases:

  1. Configuration.
  2. Starting the trace.
  3. Stopping the trace.
  4. Cleanup.

This is the same whether you follow the manual registry and LOGMAN procedures in the articles referenced at the end or use the provided script. This section uses the script. All commands must be run from the Admin command prompt.

  1. Configuration. Update the registry so applications will load the trace driver. Restart the application you wish to trace after completing this step. If you reboot the machine or run IISRESET, you may trace more processes than you wish, which can bloat the trace file. You can also optionally configure the trace to target [all instances of] a single executable using the -A switch. 32-bit applications (or 32-bit and 64-bit) can be configured using the -WOWMODE switch and the BOTH or ONLY settings.
CSCRIPT BIDTRACE.VBS CONFIG -SETUP -WOWMODE BOTH | ONLY -A c:\windows\system32\notepad.exe
Key Word What it does
CSCRIPT Runs the script in console mode so you do not get confirmation dialogs.
BIDTRACE.VBS The VBScript file where all the LOGMAN and registry commands are generated.
CONFIG This indicates a configuration option as opposed to a tracing option.
-SETUP Causes the registry to be changed so applications will load the trace driver.
-WOWMODE ONLY-WOWMODE BOTH Optional arguments to trace only 32-bit applicationsor both 32-bit and 64-bit applications. Default is 64-bit only.
-A path\executable.exe Optional arguments to trace a specific named executable only.

The most common usage is:

CSCRIPT BIDTRACE.VBS CONFIG -SETUP

1.1. Restart the application(s) or service(s) to be traced or reboot the machine.

  1. Start the trace.
CSCRIPT BIDTRACE.VBS START MYTRACE -m provider.1 -m provider.1 -c 0x6307f | 0x630ff -FILEMODE CIRCULAR | NEWFILE -MAXFILE 1024 -o c:\temp\output_folder -NETWORK

Use -NETWORK if you want the network traced at the same time as the BID trace.

Key Word What it does
CSCRIPT Runs the script in console mode so you do not get confirmation dialogs.
BIDTRACE.VBS The VBScript file where all the LOGMAN and registry commands are generated.
START tracename Sets up the LOGMAN session and names the trace. There should be no reason to change the default name.
-m provder.1 Specify one or more provider trace names with or without the .1 suffix, .e.g. -m SYSTEM.DATA.1 -m SYSTEM.DATA.SNI. Omit to trace all components.
-c tracelevel Specifies how verbose the trace is. In general, use -c 0x630ff for full verbosity, which may include network packet data. For slightly less verbose traces, use -c 0x6307f.
-FILEMODE NEWFILE-FILEMODE CIRCULAR Optional argument to determine whether to log into multiple filesor into a circular buffer. Circular is the default.
-MAXFILE size Optional argument to specify the maximum size for a single file or the circular buffer. Both Excel and NETMON have file size limitations, so multiple smaller files is generally better than a single multi-gigabyte file. If you know the timestamp of the issue, it will help in choosing the file to analyze.
-o folderpath Optional argument specifying the folder in which to put the output. We recommend you use this argument.
-NETWORK Collects an optional chained NETSH trace in addition to the BID trace. This is recommended. If you start the trace using -NETWORK, stop it with -NETWORK, as well.

To trace SqlClient producing chained output with files of 512MB each:

CSCRIPT BIDTRACE.VBS START MYTRACE -m SYSTEM.DATA.1 -m SYSTEM.DATA.SNI.1 -c 0x630ff -FILEMODE NEWFILE -MAXFILE 250 -NETWORK

To Trace SQL Native Client 11 and SQL Server 2012 on the same machine with a circular buffer of 2GB:

CSCRIPT BIDTRACE.VBS START MYTRACE -m SQLNCLI11.1 -m SQLSERVER.SNI11.1 -c 0x630ff -FILEMODE CIRCULAR -MAXFILE 2048 -NETWORK

Note: You won't be able to open the converted trace file in Excel if it contains more than 1 million rows. Note: Using the BIDTRACE.VBS script with a circular buffer will still result in a chained network trace.

When starting a BID Trace, various other commands are run to flush buffers, such as:

IPCONFIG /flushdns
NBTSTAT -R
Flush Kerberos tickets for all processes:
Powershell -command "Get-WmiObject Win32_LogonSession | Where-Object {$_.AuthenticationPackage -ne 'NTLM'} | ForEach-Object {c:\windows\system32\klist.exe purge -li ([Convert]::ToString($_.LogonId, 16))}"
tasklist

2.1. We strongly recommend taking a NETSH network trace (see Collect a Network Trace) on the same machine the BID trace is taken on - assuming client and server are on different machines. If you do not want a network trace or want to use a different trace tool, omit the -NETWORK argument from the command-line.

Note: -NETWORK is preferred because both the NETSH and BID traces can be filtered by process ID got from the task list in the logmanstart.out file or from each other.

2.2. Wait until the issue reproduces.

  1. Stop the trace.
CSCRIPT BIDTRACE.VBS STOP MYTRACE -NETWORK

If you started the trace with -NETWORK, stop the trace with -NETWORK, too. Otherwise, the network trace will keep running.

3.1. Wait for the command to complete and return you back to the command prompt. It may take a couple of minutes if you specified the -NETWORK option.

Note: Closing the console window will not terminate the traces; they will continue to run in the background. However, you can open a new Admin command prompt and terminate them.

If you need to manually stop the network trace, use the following commands:

logman query -ets                     view what traces are running
logman stop mytracenetwork -ets       this name is the same name as for the BID Trace with "network" added to the end.
netsh trace show status               confirm whether the netsh trace is running
netsh trace stop                      terminate the netsh trace; do last as this takes a couple of minutes

Note: You can capture multiple traces (steps 2 and 3) after step 1 is completed and the application restarted the one time.

  1. Deregister the trace driver when all tracing is done.
CSCRIPT BIDTRACE.VBS CONFIG -CLEANUP

You can optionally specify the -WOWMODE BOTH and -WOWMODE ONLY to affect the 32-bit registry, as well.
You can optionally specify the -A path\executable.exe name to remove a specific executable.

Once done, restart the application(s), service(s), or the machine to clear the trace driver from running processes.

Note: Many people never perform step 4.

Note: You may get empty folders as a result of the CONFIG commands in addition to the trace folder. These can be ignored.

BID Trace Script Files and Command Summary

The BID trace script file can be copied from this link: BidTrace.vbs

Sample Commands:

CSCRIPT BIDTRACE.VBS CONFIG -SETUP
CSCRIPT BIDTRACE.VBS START MYTRACE -m SYSTEM.DATA.1 -m SYSTEM.DATA.SNI.1 -c 0x630ff -FILEMODE NEWFILE -MAXFILE 250 -NETWORK
CSCRIPT BIDTRACE.VBS STOP MYTRACE -NETWORK
CSCRIPT BIDTRACE.VBS CONFIG -CLEANUP
CSCRIPT BIDTRACE.VBS CONFIG -MOFCOMP

This script generates the following files:

  • Starting task list in logmanstart.out
  • Ending task list in logmanstop.out
  • BID trace files are bidtrace*.etl
  • NETSH trace files are netsh*.etl
  • CAB file network_settings.cab

Converting the ETL file to CSV.

ETL files use MOF files to define their format. You must use the MOFCOMP command from the Admin command prompt to process the MOF files and let the trace files be interpreted properly. This is a one-time operation unless new drivers get added in the future.

The following script command generates the MOF files for the drivers listed above and compiles them for you.

CSCRIPT BIDTRACE.VBS CONFIG -MOFCOMP

Once the MOF files have been compiled, use the TRACERPT command to convert the ETL file into a CSV file. If you have multiple ETL files, you will have to run the TRACERPT command on each file separately. Pasting the commands into a .BAT or .CMD file helps automate the process.

TRACERPT bidtrace1.etl /of csv /o bidtrace1.csv
TRACERPT bidtrace2.etl /of csv /o bidtrace2.csv
...

Or use PowerShell in the folder where the traces are:

foreach($file in Get-ChildItem bidtrace*.etl) { tracerpt "$file" /of csv /o "$($file.basename).csv" }

You can open the CSV file in Excel if it contains fewer than 1 million rows.
You can also open the ETL file in NETMON if it is less than 4GB in size.

Issues with the trace

If the file is very small (8MB or less), then something likely went wrong with the trace. If you open the ETL file in NETMON, you may only see fewer than a dozen events recorded. Even tracing a UDL file connection typically results in 60-70MB of trace for the connection alone.

Here are some common scenarios and how to correct them.

  • Make sure the application was restarted after the initial configuration and before starting a trace. This is particularly true of service-based applications, such as IIS or SQL Server. For SSIS jobs, DTEXEC.EXE or ISSERVEREXEC.EXE are run every time the job runs and do not need to be restarted.
  • If tracing a driver via a clustered SQL Server linked server, make sure to run the setup command on all nodes in case of a failover or restarting causes another node to become the primary node. At the time of tracing, use the Cluster Manager or run "Select ServerProperty('ComputerNamePhysicalNetBIOS')" in SSMS to validate the node you are tracing on is still the primary instance.
  • If tracing on a web farm, make sure you run the setup command on all web servers and then run IISRESET on them. Trace on all web servers. To minimize the number of servers to trace on, you might want to temporarily take some web servers off-line.
  • Validate whether the application is 32-bit or 64-bit. You can see this in Task Manager. If in doubt, use the -WOWMODE BOTH option in the initial configuration step. You can run this step any number of times prior to tracing or between tracing. Restart the application after making the change.
  • Validate which driver the application is using. PROCMON or Process Explorer from www.sysinternals.com can help with this. You should be able to locate the DLL name in the trace or the list of handles the application has open. If you cannot determine this with any certainty, omit all the -m arguments when starting the trace.
  • Clear any -A named executables using the -CLEANUP command and -A command together. Restart the application.
  • Make sure the application is not a .NET Core application. BID tracing does not work in this scenario.
  • There may be a pending installation. Reboot the machine.
  • Install the latest driver version. Restart the application or service you are tracing.

Linux and Mac ODBC Driver BID Tracing

BID tracing on Linux and Mac systems is enabled via the driver properties in the odbcinst.ini file. This file is normally located at /etc/odbcinst.ini. If it is not located there, run the odbcinst -j command. It should list the folder containing the file.

Edit the file and add entries as the example shows below:

["ODBC Driver 17 for SQL Server"]
BIDTrace=yes
BIDTraceFile=/tmp/bidtrace.log
BIDTraceFileSize=10240000

Note: this is a different location than where you would enable ODBC tracing, which goes in the [ODBC] section. Make sure ODBC tracing is turned off.

The output file is a text file rather than an ETL file. The BIDTRaceFileSize is in bytes (10MB).

Remove the trace settings from the odbcinst.ini file when you are finished tracing. Restart your application

BID Trace Analysis

Analysis of BID traces is beyond the scope of this wiki. A Microsoft engineer from the SQL Networking team can help interpret the results.

References

Most of these articles cover the manual steps for Windows tracing that the BIDTRACE.VBS performs for you.