In a previous post, we showed how you can extract the count of executions of a given SQL statement for a given bind variable.
We recently found a need to print each execution a given SQL statement with the bind variables used for that execution and how many I/O’s and seconds it required.
This awk script is shown below…
#!/bin/awk -f
#----------------------------------------------------------------------------------
#Author: Steve Howard
#Date: February 16, 2012
#Purpose: Extract bind variable values and execution times and I/O's from a 10046 trace file.
#----------------------------------------------------------------------------------
BEGIN {
if (ARGC != 3) {
print "Usage:",ARGV[0]," -f script_name tracefile_name \"query_for_which_to_search\""
exit(1)
}
start = systime()
SQL=ARGV[2]
BIND=ARGV[3]
ARGC=2
}
{
if ($0 ~ "^PARSING") {
B=$4;
sub("#","",B);
getline;
if ($0 ~ SQL) {
C=B;
}
else if (C == B && $0 !~ SQL) {
C=-1;
}
}
else if (length(C) > 0 && $0 ~ "BINDS #"C) {
looking = 1;
}
else if ($0 ~ "value=" && looking == 1) {
sub("value=","",$0)
tmp=tmp $0;
}
else if (length(C) > 0 && $0 ~ "FETCH #"C && length(tmp) > 0) {
split($0,t,",")
sub("e=","",t[2])
sub("cr=","",t[4])
printf("Variable value list (in order):%s Seconds for this execution: %'.2f Number of IO's %'.0f\n",tmp,t[2]/1000000,t[4])
tmp = ""
looking = 0
}
}
…and sample output is also shown below…
[FN9DMO]-CMHLDEVPSOFT01:/home/oracle >./allbinds.awk fn9dev_ora_17068.trc "SELECT JLN.JOURNAL_LINE, JLN.LINE_DESCR"
Variable value list (in order): "EXCAN" "0000000064" "09-FEB-2011" Seconds for this execution: 0.05 Number of IO's 1,602
Variable value list (in order): "EXCAN" "0000000089" "09-FEB-2011" Seconds for this execution: 0.04 Number of IO's 1,998
Variable value list (in order): "EXCAN" "0000000114" "09-FEB-2011" Seconds for this execution: 0.04 Number of IO's 2,196
Variable value list (in order): "EXCAN" "0000000139" "09-FEB-2011" Seconds for this execution: 0.05 Number of IO's 1,998
Variable value list (in order): "EXCAN" "0000000164" "09-FEB-2011" Seconds for this execution: 0.04 Number of IO's 2,431
Variable value list (in order): "EXCAN" "0000000046" "21-FEB-2012" Seconds for this execution: 1.91 Number of IO's 74,209
Variable value list (in order): "EXCAN" "0000000049" "24-FEB-2012" Seconds for this execution: 861.94 Number of IO's 27,389,474
Variable value list (in order): "EXCAN" "0000000054" "18-FEB-2012" Seconds for this execution: 0.05 Number of IO's 2,460
Variable value list (in order): "EXCAN" "0000000056" "16-FEB-2012" Seconds for this execution: 0.03 Number of IO's 1,106
Variable value list (in order): "EXCAN" "0000000059" "12-FEB-2012" Seconds for this execution: 0.05 Number of IO's 1,745
Variable value list (in order): "EXCAN" "0000000060" "11-FEB-2012" Seconds for this execution: 0.05 Number of IO's 1,908
Variable value list (in order): "EXCAN" "0000000066" "06-FEB-2012" Seconds for this execution: 0.50 Number of IO's 20,033
Variable value list (in order): "EXCAN" "0000000067" "05-FEB-2012" Seconds for this execution: 1.33 Number of IO's 46,878
Variable value list (in order): "EXCAN" "0000000068" "04-FEB-2012" Seconds for this execution: 0.40 Number of IO's 15,334
Variable value list (in order): "EXCAN" "0000000069" "20-FEB-2012" Seconds for this execution: 2,782.37 Number of IO's 90,354,396
Variable value list (in order): "EXCAN" "0000000071" "21-FEB-2012" Seconds for this execution: 1.98 Number of IO's 79,072
Variable value list (in order): "EXCAN" "0000000074" "24-FEB-2012" Seconds for this execution: 1,292.16 Number of IO's 28,825,091
Variable value list (in order): "EXCAN" "0000000079" "18-FEB-2012" Seconds for this execution: 0.21 Number of IO's 2,460
Variable value list (in order): "EXCAN" "0000000081" "16-FEB-2012" Seconds for this execution: 0.08 Number of IO's 1,378
Variable value list (in order): "EXCAN" "0000000084" "12-FEB-2012" Seconds for this execution: 0.13 Number of IO's 2,178
Variable value list (in order): "EXCAN" "0000000085" "11-FEB-2012" Seconds for this execution: 0.12 Number of IO's 2,118
Variable value list (in order): "EXCAN" "0000000091" "06-FEB-2012" Seconds for this execution: 0.69 Number of IO's 18,767
Variable value list (in order): "EXCAN" "0000000092" "05-FEB-2012" Seconds for this execution: 1.57 Number of IO's 50,783
Variable value list (in order): "EXCAN" "0000000093" "04-FEB-2012" Seconds for this execution: 0.44 Number of IO's 16,919
[FN9DMO]-CMHLDEVPSOFT01:/home/oracle >
As you can see above, three variables took 99% of the total execution time in the trace. This is a perfect example of the raw trace data being so much more usable than just tkprof alone. tkprof, while enormously useful, would average the results of each execution and hide the fact that most of them were OK.