Yaffle -<br>
Thanks for catching the obvious oversight in the SELECT statements. I can't believe I missed that!<br>
<br>
According to Oracle, the number returned by setting timing on (in your example, real: 5398) does not correspond to an actual unit of time. It is a derived value that takes into account many factors based on resource usage. It is useful for benchmarking, but will not give you an actual time value. Also, Oracle does not track time beyond hundredths of a second.<br>
<br>
For timing purposes, probably your best bet is to use sql_trace.<br>
You might want to use a script file that turns trace and timed_statistics on and off. This will minimize the impact on your system:<br>
<br>
ALTER SESSION SET TIMED_STATISTICS=TRUE;<br>
ALTER SESSION SET SQL_TRACE=TRUE;<br>
EXECUTE sort_procedure;<br>
ALTER SESSION SET SQL_TRACE=FALSE;<br>
ALTER SESSION SET TIMED_STATISTICS=FALSE;<br>
<br>
After running this script, you will use tkprof to reformat your trace file.<br>
<br>
Here is a copy of such a session (in this case, the procedure name is 'quack'):<br>
<br>
<br>
SQL> set timing off<br>
SQL> alter session set timed_statistics=true;<br>
SQL> alter session set sql_trace=true;<br>
SQL> execute quack;<br>
SQL> alter session set sql_trace=false;<br>
SQL> alter session set timed_statistics=false;<br>
<br>
This generated a trace file called ora00283.trc.<br>
<br>
Running tkprof:<br>
<br>
C:\>tkprof ora00283.trc c:\output.txt sys=NO<br>
<br>
This will read the trace file and put formatted information into an output file called output.txt.<br>
<br>
Looking at this file:<br>
<br>
Trace file: ora00283.trc<br>
Sort options: default<br>
<br>
********************************************************************************<br>
count = number of times OCI procedure was executed<br>
cpu = cpu time in seconds executing<br>
elapsed = elapsed time in seconds executing<br>
disk = number of physical reads of buffers from disk<br>
query = number of buffers gotten for consistent read<br>
current = number of buffers gotten in current mode (usually for update)<br>
rows = number of rows processed by the fetch or execute call<br>
********************************************************************************<br>
.<br>
.<br>
.<br>
BEGIN quack; END;<br>
<br>
<br>
call count cpu elapsed disk query current rows<br>
------- ------ ------- - ---------- ---------- ---------- ---------- ----------<br>
Parse 2 0.04 0.04 0 0 0 0<br>
Execute 2 0.05 0.05 0 0 0 2<br>
Fetch 0 0.00 0.00 0 0 0 0<br>
------- ------ -------- ---------- ---------- ---------- ---------- ----------<br>
total 4 0.09 0.09 0 0 0 2<br>
<br>
Misses in library cache during parse: 0<br>
Optimizer goal: CHOOSE<br>
Parsing user id: 25<br>
********************************************************************************<br>
<br>
We see this procedure took .09 seconds to complete. However, notice that almost half of this time (.04 seconds) was spent parsing. A second run would probably show a lower overall time, since the code would now be in the library cache and parsing would not be necessary. It's not a bad idea to run several executions and then take the average time. This helps minimize the effects of fluctuations in resource usage, data location, etc.<br>
<br>
I think this is about as good as it gets for timing purposes.<br>
<br>