Reading ADO.NET Trace Files

When you connect to a Database using Connect for ADO.NET provider, you can set various Connection Options. If you set the connection options titled Enable Trace and Trace File, you will be able to see the trace files that contains event logs.

Enable Trace takes values 0 and 1. 0 is the default value, it indicates that the trace is disabled. 1 means tracing is enabled.

Trace file: if no value is given, it generates a text with DDTekTrace.txt

While setting the Trace connection options, you will have to specify the full qualified path of the Trace file. Once the ADO.NET Tracing option is enabled, the Trace files are auto-generated. The Trace File contains information that can help you diagnose and resolve operating problems.

The following information is contained in the trace file:

1. Assembly details
2. Connection log details - connection open and close
3. Get Schema
4. Database operation details

In the following section, you can see the example text for each information type.

Assembly Details

If you want to know which dll is being used, you need to check this section of the trace file.

Here, you can see the dll version number of the vanilla provider. If Entity framework dll is loaded, the details of the Entity assembly are also logged. If there is no corresponding Entity provider Assembly loaded, you get a message indicating that the Entity dll is not loaded. In the snippet below, the entity assembly is loaded. Hence you see the details of the Entity assembly.

Assembly Name: DDTek.Oracle, Version=4.3.0.0, Culture=neutral, PublicKeyToken=c84cd5c63851e072
Assembly File Version: 4.3.0.0
Entity Assembly Name: DDTek.Oracle.Entity, Version=4.3.0.0, Culture=neutral, PublicKeyToken=c84cd5c63851e072
Entity Assembly File Version: 4.3.0.0078

Connection Open

This section opens with the phrase Connection :: Open Enter and closes with the phrase Connection :: Open Exit. This section has information related to the following:

• Connection string
• Connection timeout
• Pooling

You will see information about the Connection string and Connection timeout. If the connection is not established within this specified time, it will time out.

If pooling is set to true, pooling-related information is displayed. Note that this is set to true by default.

00000001 15:00:35.269 T1 I30015890 Connection::Open ENTER
ConnectionString: Host=test.abcd.xyz.com;Port=5000;Database Name=sampleDB;User ID=sample1;Password=*****;
License Path=C:\\ABD\\XXX\\DDTEK.lIC;
Enable Trace=1;
Trace File=C:\\Tracefile.txt
ConnectionTimeout: 15
POOL: Found a pooled connection
POOL: Current status: 1 pools, 0 connections
01 7.307 T1 I30015890 Connection::Open EXIT

Get Schema

This section opens with the phrase Connection :: GetSchema ENTER and closes with the phrase Connection :: GetSchema EXIT. In this section, you can see the schema level details. In the following example, the schema contains tables, and you can see details like table name, table type, rows and columns, and details of rows and columns.

00000086 6:26:36.794 T1 I339559 Connection::GetSchema ENTER
Arg #1: "Tables"
Arg #2: null
00000086 6:26:38.4 T1 I339559 Connection::GetSchema EXIT
Return: Tables
 
TABLE_SCHEMA, TABLE_NAME, TABLE_TYPE, DATE_CREATED, DATE_MODIFIED
SAMPLEUSER, Categories, TABLE, 5/9/2017 6:26:37 AM, 5/9/2017 6:26:38 AM
SAMPLEUSER, Customers, TABLE, 5/9/2017 6:26:37 AM, 5/9/2017 6:26:38 AM
SAMPLEUSER, DBTypeNonUnicode, TABLE, 5/9/2017 6:26:37 AM, 5/9/2017 6:26:37 AM
SAMPLEUSER, DBTypeUnicode, TABLE, 5/9/2017 6:26:37 AM, 5/9/2017 6:26:37 AM
SAMPLEUSER, EmployeeTerritories, TABLE, 5/9/2017 6:26:37 AM, 5/9/2017 6:26:38 AM
SAMPLEUSER, Employees, TABLE, 5/9/2017 6:26:37 AM, 5/9/2017 6:26:38 AM
SAMPLEUSER, InternationalOrders, TABLE, 5/9/2017 6:26:38 AM, 5/9/2017 6:26:38 AM
SAMPLEUSER, OracleDataTypes, TABLE, 5/9/2017 6:26:37 AM, 5/9/2017 6:26:37 AM
SAMPLEUSER, OrderDetails, TABLE, 5/9/2017 6:26:38 AM, 5/9/2017 6:26:38 AM
SAMPLEUSER, Orders, TABLE, 5/9/2017 6:26:38 AM, 5/9/2017 6:26:38 AM
SAMPLEUSER, PreferedSuppliers, TABLE, 5/9/2017 6:26:38 AM, 5/9/2017 6:26:38 AM
SAMPLEUSER, PreviousEmployees, TABLE, 5/9/2017 6:26:38 AM, 5/9/2017 6:26:38 AM
SAMPLEUSER, Products, TABLE, 5/9/2017 6:26:38 AM, 5/9/2017 6:26:38 AM
SAMPLEUSER, Regions, TABLE, 5/9/2017 6:26:38 AM, 5/9/2017 6:26:38 AM
SAMPLEUSER, Store, TABLE, 5/9/2017 6:26:37 AM, 5/9/2017 6:26:37 AM
SAMPLEUSER, StressTable, TABLE, 5/9/2017 6:26:37 AM, 5/9/2017 6:26:37 AM
SAMPLEUSER, Suppliers, TABLE, 5/9/2017 6:26:38 AM, 5/9/2017 6:26:38 AM
SAMPLEUSER, Territories, TABLE, 5/9/2017 6:26:38 AM, 5/9/2017 6:26:38 AM
SAMPLEUSER, List_Of_Prod, VIEW, 5/9/2017 6:26:38 AM, 5/9/2017 6:26:38 AM

Database Operations

This section opens with a phrase signifying the operation. For example, it may start with Command :: ExecuteNonQuery ENTER or Command :: ExecuteScalar ENTER. And it ends with phrases like Command :: ExecuteNonQuery EXIT or Command :: ExecuteScalar EXIT.

In this section, you can see the CRUD operations that you have performed against the database.

For example, you can see Parameterized queries that are used for data insert or retrieve operations. Parameterized queries can fail if the parameter value is incorrect (for instance, if you have entered a string in place of an integer parameter) or if corresponding records do not exist in the database. In the example below, you can see the Execute Reader, the details of the command Object and the number and details of parameters. The entries Par #1, Par #2 and Par #3 are the parameters that are passed with the query.

00000017 16:44:42.378 T1 I19176316 Command::ExecuteNonQuery ENTER
 
CommandText: insert into DB2_DEPT values(?, ?, ?)
CommandType: Text
CommandTimeout: 30
UpdatedRowSource: Both
Par #1: deptno, Input, Int16, 0, System.Int16, 1
Par #2: dname, Input, AnsiString, 3, System.String, "one"
Par #3: loc, Input, AnsiString, 6, System.String, "locone"
 
00000017 16:44:42.707 T1 I19176316 Command::ExecuteNonQuery EXIT
Return: 1

When you need to read data from a database, you use DataReader. The following example shows an example of DataReader Processing. Here you can see information about DataReader API calls and the Data returned. Command::ExecuteReader, DataReader::Read, DataReader::GetValue and DataReader::Close are examples of DataReader APIs. You can see the data returned after the 'Return' keyword at various places in the following log. The trace file also indicates the number of rows read in response to the DataReader::Read statements.

00000021 16:44:43.455 T1 I9711805 Command::ExecuteReader ENTER
Arg #1: "CommandBehavior.Default"
 
CommandText: SELECT * FROM DB2_DEPT
CommandType: Text
CommandTimeout: 30
UpdatedRowSource: Both
 
00000021 16:44:43.728 T1 I9711805 Command::ExecuteReader EXIT
Return: DDTek.DB2.DB2DataReader
RecordsAffected: -1
00000023 16:44:43.729 T1 I34262603 DataReader::Read ENTER
00000023 16:44:43.730 T1 I34262603 DataReader::Read EXIT
Out #1: "NumRowsRead = 1"
Return: True
00000026 16:44:43.731 T1 I34262603 DataReader::GetValue ENTER
Arg #1: 0
00000026 16:44:43.731 T1 I34262603 DataReader::GetValue EXIT
Return: 1
00000027 16:44:43.733 T1 I34262603 DataReader::GetValue ENTER
Arg #1: 1
00000027 16:44:43.734 T1 I34262603 DataReader::GetValue EXIT
Return: "one"
00000028 16:44:43.734 T1 I34262603 DataReader::GetValue ENTER
Arg #1: 2
00000028 16:44:43.734 T1 I34262603 DataReader::GetValue EXIT
Return: "locone"
00000029 16:44:43.734 T1 I34262603 DataReader::Read ENTER
00000029 16:44:43.734 T1 I34262603 DataReader::Read EXIT
Out #1: "NumRowsRead = 2"
Return: True
00000030 16:44:43.734 T1 I34262603 DataReader::GetValue ENTER
Arg #1: 0
00000030 16:44:43.734 T1 I34262603 DataReader::GetValue EXIT
Return: 2
00000031 16:44:43.734 T1 I34262603 DataReader::GetValue ENTER
Arg #1: 1
00000031 16:44:43.734 T1 I34262603 DataReader::GetValue EXIT
Return: "two"
00000032 16:44:43.734 T1 I34262603 DataReader::GetValue ENTER
Arg #1: 2
00000032 16:44:43.734 T1 I34262603 DataReader::GetValue EXIT
Return: "loctwo"
00000041 16:44:43.734 T1 I34262603 DataReader::Read EXIT
Out #1: "NumRowsRead = 2"
Return: False
00000042 16:44:43.736 T1 I34262603 DataReader::Close ENTER
00000042 16:44:43.974 T1 I34262603 DataReader::Close EXIT

Connection Close

This section opens with the phrase Connection :: Close Enter and closes with the phrase Connection :: Close Exit. In this section, you can see the trace file track the closing of the connection to the Database.

00000119 14:47:18.114 T1 I339559 Connection::Close ENTER00000119 14:47:18.114 T1 I339559 Connection::Close EXIT