Use Oracle client tracing and tkprof to review submitted SQL queries

Question

I would like to learn how to trace an Oracle client and view the SQL queries submitted.

I started by adding these lines to my client's sqlnet.ora file:

TRACE_LEVEL_CLIENT=16
TRACE_FILE_CLIENT=sqlnet.trc
TRACE_DIRECTORY_CLIENT=c:\temp
LOG_DIRECTORY_CLIENT=c:\temp
TRACE_UNIQUE_CLIENT=TRUE
TRACE_TIMESTAMP_CLIENT=TRUE
DIAG_ADR_ENABLED=OFF

Then I logged into the database on that same client using SQL*Plus. I submitted two queries:

select * from all_tables where table_name = 'ADDRESS';
select * from all_users where username like 'AB%';

Then I exited SQL*Plus. The trace file was created in c:\temp. The file is about 4000 lines long. I can definitely see my two SQL statements in there. The format is a pain to read though, as they are just hex dumps:

(10632) [29-AUG-2016 17:08:40:240] nsbasic_bsd: 00 00 31 73 65 6C 65 63  |..1selec|
(10632) [29-AUG-2016 17:08:40:240] nsbasic_bsd: 74 20 2A 20 66 72 6F 6D  |t.*.from|
(10632) [29-AUG-2016 17:08:40:240] nsbasic_bsd: 20 61 6C 6C 5F 75 73 65  |.all_use|
(10632) [29-AUG-2016 17:08:40:240] nsbasic_bsd: 72 73 20 77 68 65 72 65  |rs.where|
(10632) [29-AUG-2016 17:08:40:240] nsbasic_bsd: 20 75 73 65 72 6E 61 6D  |.usernam|
(10632) [29-AUG-2016 17:08:40:240] nsbasic_bsd: 65 20 6C 69 6B 65 20 27  |e.like.'|
(10632) [29-AUG-2016 17:08:40:240] nsbasic_bsd: 41 42 25 27 01 00 00 00  |AB%'....|

My research leads me to believe that tkprof is the way to get a readable report of my trace file. I tried the following:

tkprof c:\temp\sqlnet_10632.trc report.txt

But that gives me a pretty pointless file:

   0  session in tracefile
   0  user  SQL statements in trace file.
   0  internal SQL statements in trace file.
   0  SQL statements in trace file.
   0  unique SQL statements in trace file.
4361  lines in trace file.
   0  elapsed seconds in trace file.

Ideally, I'd like to see a report that for this situation shows me easy-to-read SQL text submitted by the client (including the two I manually typed in), in the order they were submitted. Am I on the right track? What am I missing? If I'm not on the right track, what should I do instead to trace the SQL submitted by the client?

Note: I am using a 12c client. I do not have access to the database server.

Answer 1

The tkprof utility is used to generate reports from 10046 trace files.

These trace files show database operations.

Here is a good article to get you started with those: sql trace 10046

tkprof would not be at all useful for sqlnet trace files.

For sqlnet trace files, you would want to use the trcasst utility.

While trcasst is useful, if you really want to find out what is going on, you will need to develop some understanding of the files themselves.

Here are some good references to get started with understanding sqlnet trace files:

Tracing Error Information for Oracle Net Services

If you have access to My Oracle Support, the following notes will be invaluable:

SQLNET PACKET STRUCTURE: NS PACKET HEADER (Doc ID 1007807.6) Examining Oracle Net, Net8, SQLNet Trace Files (Doc ID 156485.1)

That second article has a PDF attached that explains quite a bit.

Documentation from 11g - 19c will all state that you should set the following in sqlnet.ora:

diag_adr_enabled=off

If you want accurate timestamps, then do this instead:

diag_adr_enabled=on

That is a bug that I hope to see fixed by the time Oracle 20c is released.

Answer 2

Just for reference, Oracle provides the trcasst utility to perform this action:

$ORACLE_HOME/bin/trcasst client_Tract_file.trc > client_Tract_file.txt

Answer 3

This isn't the answer I was hoping for, but I needed to get-r-done and move on, so I wrote a quick and dirty Windows console application (C#):

    static void Main(string[] args)
    {
        using (var sr = new StreamReader(args[0]))
        {
            var line = string.Empty;
            var parsingSqlHex = false;
            var timestamp = string.Empty;
            var parsedSql = string.Empty;
            var patternStart = @"nsbasic_bsd\: packet dump";
            var patternTimeStamp = @"\[\d{2}-[A-Z]{3}-\d{4} (\d\d\:){3}\d{3}\]";
            var patternHex = @"nsbasic_bsd\: ([0-9A-F][0-9A-F] ){8}";
            var patternEnd = @"nsbasic_bsd\: exit \(0\)$";

            while (line != null)
            {
                if (Regex.IsMatch(line, patternStart))
                {
                    timestamp = Regex.Match(line, patternTimeStamp).Value;
                    parsingSqlHex = true;
                }
                else if (parsingSqlHex)
                {
                    if (Regex.IsMatch(line, patternEnd))
                    {
                        if (!string.IsNullOrEmpty(parsedSql))
                        {
                            Console.WriteLine(timestamp);
                            Console.WriteLine(parsedSql + "\r\n");
                        }
                        parsedSql = string.Empty;
                        parsingSqlHex = false;
                    }
                    else if (Regex.IsMatch(line, patternHex))
                    {
                        parsedSql += HexToString(line.Substring(line.Length - 35, 23));
                    }
                }

                line = sr.ReadLine();
            }
        }
    }


    static string HexToString(string hexValues)
    {
        var hexCodeArray = hexValues.Split(" ".ToCharArray());
        var n = 0;
        var s = string.Empty;

        for (var i = 0; i < hexCodeArray.Length; i++)
        {
            n = Convert.ToInt32(hexCodeArray[i], 16);
            if (n > 31 && n < 127) s += Convert.ToChar(Convert.ToUInt32(hexCodeArray[i], 16));
        }

        return s;
    }

I'm using it to parse my trace files like so:

OracleTraceParser.exe c:\temp\trace.txt > report.txt

Then my report.txt file has some odd characters here and there, but nonetheless gives me what I'm after:

[30-AUG-2016 13:50:51:534]
i^qx(SELECT DECODE('A','A','1','2') FROM DUAL

[30-AUG-2016 13:50:51:534]
i

[30-AUG-2016 13:51:05:003]
^a5select * from all_tables where table_name = 'ADDRESS'

[30-AUG-2016 13:51:21:081]
i^a1select * from all_users where username like 'AB%'