An AWKward look at tkprof.

Reading trough a tkprof file can be a long, arduous process. How do you find the things you’re looking for, without having to dredge through endless lines of trace data?
Here are some awk one-liners that can help with that.
What do you really care about in a trace file? Usually you are looking for the SQL that either consumed the most time, or the most logical I/Os.
Here is a on-liner that will show you the top-5 SQL statements that took the most elapsed time: (in my examples the tkprof output file name is tk.txt)

awk '/^call/' tk.txt | head -n 1;  awk '/^total/' tk.txt | sort -k 4 -nr | head -n 5

The result looks something like this:

You can see right away, that the SQL statement that took the longest, took 332.15 seconds to execute.
Explanation: The first awk statements simply displays the column headings. The second looks at all the totals, sorts them numerically descending, and displays only the first five records.
Notice that it sorts the fourth column, which is the elapsed time. To sort on a different column simply change the integer after the –k argument. The following columns are available:

You can ingore the first column (call), which just tells you that we are looking at the totals for a particular SQL statement.
The meanings of the following columns are explained in the header of each tkprof output file:

To find which SQL statement caused the particular elapsed time, simply search the tkprof output for that value.

Another usefull one-liner condenses the tkprof file to where you only see the SQL statement and its execution totals. This keeps you from having to look a all the nitty gritty details:

awk 'tolower($1)~ /(^select)|(^insert)|(^update)|(^delete)|(^declare)|(^begin)/,/^$/ { print NR "\t" $0 } /^call/ { print NR "\t" $0 } /^total/ { print NR "\t" $0 "\n"}' tk.txt | less

The output looks something like this:

Explanation: This command looks for all the lines that begin with an SQL statement, then starts printing until it comes across an empty line. Then it looks for a line beginning with the word call and prints the column headings. Finally it skips down to the total line and prints the values, followed by a blank line. The output is then piped to less. You could also pipe it to another text file if you wish. The nice thing about less, however, is that you can search the output right there. So if you were looking for the SQL statement that caused the 332.15 seconds of elapsed time (see above), simple search the output with the forward slash:

The output will skip to the line with that occurance.
Conclusion: These two one-liners can help you quickly identify the SQL statements that take a long time to execute, or cause a lot of reads in your database. What they don’t do, is tell you why. To do that, you have to dive into the details of the tkprof output, or use a third party tool like the Hotsos Profiler. The Hotsos Profiler will actually tell you where the time went during the execution of an SQL statement, and will give you a definitive starting point for your performance optimization.

Leave a Reply

Your email address will not be published. Required fields are marked *