Hi Chris,

Here is one way to get timing info with some command line hacking.

The first step is to identify the SQL of interest in the trace file, as it may (probably) contain several SQL statements.

The following command will show us the cursor ID for the SQL statement we are interested in.

grep -B1 ‘select sql_id, sql_fulltext’ oravm1_ora_10917_JKSTILL-SLOW-SQL.trc
PARSING IN CURSOR #47722271586392 len=266 dep=0 uid=90 oct=3 lid=90 tim=1461168326148808 hv=2475747935 ad=’c12231a0′ sqlid=’4h7qfxa9t1ukz’
select sql_id, sql_fulltext

Note that method is not always 100% reliable, cursors can be closed new cursors opened with the same ID.
(if the formatting is too difficult to read, I will try again)

The following command will show if any cursor IDs are reused:

grep ‘^PARSING IN CURSOR’ oravm1_ora_10917_JKSTILL-SLOW-SQL.trc | awk ‘{ print $4 }’ | sort | uniq -c | sort -n
1 #47722266762664
1 #47722266769160
1 #47722266805040
1 #47722266828600
1 #47722266837320
1 #47722270882888
1 #47722271584600
1 #47722271586392
1 #47722271593192
1 #47722271598504
1 #47722271697480
1 #47722271709776
1 #47722271710944
1 #47722271712112
1 #47722271713352
1 #47722271717264
1 #47722271733496
1 #47722271734664
1 #47722272079784
1 #47722272166104
1 #47722272176160
1 #47722272181736
1 #47722272186728
1 #47722272195040
1 #47722272241000
1 #47722272249112
1 #47722272249688
1 #47722272255792
1 #47722272260992
1 #47722272266192
1 #47722272271824
1 #47722272277456
1 #47722272284136
1 #47722272289352
2 #47722266806248

Indeed, cursor ID #47722266806248 has been reused. The cursor we are interested in is #47722271586392, which was parsed only once in the trace file.

That command serves to illustrate the point, while the next command is more useful; it shows only the information we are interested in.

grep ‘^PARSING IN CURSOR’ oravm1_ora_10917_JKSTILL-SLOW-SQL.trc | awk ‘{ print $4 }’ | sort | uniq -c | sort -n | grep ‘#47722271586392’
1 #47722271586392

This clearly shows that cursor #47722271586392 usually always refers to the SQL of interest.

The reason to say ‘usually’ is that cursor ID may have already been open when the trace file started.
In this case that was true. The amount of prior waits on this cursor ID was miniscule, but for the sake of being more accurate, we can get the line number where the new PARSE occurs and consider only lines in the trace file following that (including the PARSE line).

grep -n ‘^PARSING IN CURSOR #47722271586392′ oravm1_ora_10917_JKSTILL-SLOW-SQL.trc
2435:PARSING IN CURSOR #47722271586392 len=266 dep=0 uid=90 oct=3 lid=90 tim=1461168326148808 hv=2475747935 ad=’c12231a0′ sqlid=’4h7qfxa9t1ukz’

And so lines prior to #2435 will be ignored.

There are some lines that affect the cursor, but do not include the cursor ID.
LOBREAD, LOBARRTMPFRE and probably a few others.
Here’s a sample:

WAIT #0: nam=’SQL*Net message to client’ ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1461168326163985
LOBREAD: c=0,e=11,p=0,cr=0,cu=0,tim=1461168326163991
WAIT #0: nam=’SQL*Net message from client’ ela= 188 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1461168326164187
LOBARRTMPFRE: c=0,e=3,p=0,cr=0,cu=0,tim=1461168326164203

As we are just trying to get a rough idea of the timing, and not a detailed analysis, we’re not going to worry about those for now.
So we will just get FETCH times and WAIT times, with WAITS broken down by name.

Now let’s get some timing information.

When I said ‘bash and awk’, I probably should have said ‘bash and perl’. This can be done with awk, but I am better with perl for this use case.

So here’s the simple perl script filter that will sum up the times:

my %times=();
my %waits=();

while() {
my $line=$_;
chomp $line;
my ($type) = split(/\s+/,$line);

next unless $type =~ /FETCH|WAIT/;

if ( ‘WAIT’ eq $type ) {
my @a = split(/\s+/,$line);
# names are delimited with single quotes
# get posisition of 2nd quote
my $qpos1 = index($line,q{‘});
my $qpos2 = index($line,q{‘},$qpos1+1);

my $waitName = substr($line,$qpos1+1, $qpos2 – $qpos1 -1 );
#print “waitName: $waitName\n”;

my ($dummy, $dummy, $elapsed) = split(/\s+/,substr($line,$qpos2));

$times{$type} += $elapsed;
$waits{$waitName} += $elapsed;
} elsif ( ‘FETCH’ eq $type ) {
my @a = split(/,/,$line);
my ($dummy,$elapsed) = split(/=/, $a[1]);
$times{$type} += $elapsed;
} else {
die “Something is wrong\n”;
}

}

END {
print “FETCH Total: $times{‘FETCH’}\n”;
print “WAIT Total: $times{‘WAIT’}\n”;

foreach my $waitName ( keys %waits ) {
print “$waitName: $waits{$waitName}\n”;
}
}

Now we run it:

tail –lines=2435 oravm1_ora_10917_JKSTILL-SLOW-SQL.trc | perl p2.pl
FETCH Total: 18258
WAIT Total: 22606
db file sequential read: 14027
SQL*Net message to client: 47
SQL*Net message from client: 8154
asynch descriptor resize: 3
log file sync: 375

As per this utility, about 0.04 seconds are contained in this trace file (this was the ‘fast’ SQL Trace)

There are some readily available Perl scripts for doing this as well.
“Optimizing Oracle Performance” by Cary Millsap and Jeff Holt contains one such script.
Others can be found via Google.

All told I spent about 75 minutes on this. The time would have been considerably less without the explanatory text.