Helpful, but I have a question on sum of run times vs total run time
Jon, January 18, 2002 - 2:45 pm UTC
I have your book and read the DBMS_PROFILER section but I have a question.
Why is there such a discrepancy between summing the time on plsql_profiler_units and the value in plsql_profiler_runs?
14:13:25 ==> column secs format 999.99
14:32:05 ==> select runid,
14:32:10 2 substr(run_comment,1, 30) as run_comment,
14:32:10 3 run_total_time/1000000000 as secs
14:32:10 4 from (select a.runid, sum(a.total_time) run_total_time, b.run_comment
14:32:10 5 from plsql_profiler_units a, plsql_profiler_runs b
14:32:10 6 where a.runid = b.runid group by a.runid, b.run_comment )
14:32:10 7 where run_total_time > 0
14:32:10 8 order by runid asc;
RUNID RUN_COMMENT SECS
----- ----------- -------
26 batch 80.51
14:33:30 ==> select runid,run_total_time/1000000000 secs from plsql_profiler_runs;
RUNID SECS
----- -------
26 395.74
Where was the other 315 secs spent? Does it indicate a problem?
January 19, 2002 - 10:46 am UTC
The timings are collected using some unit of time, typically only granular to the HSECS.
That means that many discrete events that take less then 1/100th of a second, appear to take ZERO seconds.
Many discrete events that take less then 1/100ths of a second may appear to take 1/100th of a second.
Add up lots and lots of discrete events that take less then 1/100 of a second and you can introduce a lot of errors.
The total run time from the plsql_profile_runs however is only off by an aggregate of +- 1/100th of a second.
This is the difference between "analog" and "digital" -- think of the plsql_profile_runs as more of an analog thing, the other table is more "digital". To get the aggregate run time -- we looked at the clock, saved that time, ran the procedure, then looked at the clock again -- we got 395.74 seconds.
To get the individual line times -- we looked at the clock before each line, execute the line, look at the clock again -- each observation can add +- 1/100th of a second or so of error to the total value when summed later (don't forget, included in the aggregate runtime is the time in the profile code itself, time spent not in YOUR code but in Oracle's code -- thats not in the details either, not all of it anyway).
So, what you are seeing is the aggregate error introduced by executing many 10's or 100's (or even millions in your case, 395 seconds is a long time). lines of code and having each one be potentially off by as much as 1/100th of a second.
So, it indicates a "problem" -- one that cannot be solved since we are measuring discrete events with a clock that has a certain resolution. You just need to be aware of it.
This is the reason why in a TKPROF report you can sometimes have CPU time larger then ELAPSED time -- it is the same issue.
Elapsed Time vs Run Time -or- Is Run Time Really Nanoseconds
Kyle, July 14, 2005 - 10:05 am UTC
Hi Tom.
Referencing the following code...
SQL> select * from v$version;
BANNER
----------------------------------------------------------------
Oracle9i Enterprise Edition Release 9.2.0.4.0 - Production
PL/SQL Release 9.2.0.4.0 - Production
CORE 9.2.0.3.0 Production
TNS for 32-bit Windows: Version 9.2.0.4.0 - Production
NLSRTL Version 9.2.0.4.0 - Production
SQL> create or replace procedure timer_test as
2 cursor curAO is
3 select owner, object_name from all_objects;
4 rowAO curAO%rowtype;
5 begin
6 dbms_profiler.start_profiler('timer_test');
7 for rowAO in curAO loop
8 if rowAO.owner = rowAO.object_name then
9 dbms_output.put_line('whatever');
10 end if;
11 end loop;
12 dbms_profiler.stop_profiler;
13 end timer_test;
14 /
Procedure created.
SQL> set timing on
SQL> execute timer_test
PL/SQL procedure successfully completed.
Elapsed: 00:00:01.08
SQL> set timing off
SQL> column run_comment format a12
SQL> select run_comment, run_total_time / 1000000000 sec from plsql_profiler_runs;
RUN_COMMENT SEC
------------ ----------
timer_test 1027.15303
SQL>
... why doesn't the run_total_time more closely match the elapsed time? If plsql_profile_runs contains the aggregate run time in nanoseconds, shouldn't it be closer to the elapsed time? Is it possible that the run_total_time and other times in the profiler are measured in picoseconds instead of nanoseconds, which would calculate to 1.027 seconds?
Thanks,
Kyle
July 14, 2005 - 11:16 am UTC
sqlplus's elapsed time includes
o the time to ask the os what time it is
o the time it took whatever OS you are using to push pixels on the screen (scroll),
o to send data over network
o to get database to recognize that data was pushed,
o then to parse your statement,
and then to execute it (THIS is where plsql started timing and stopped timing)
o then to return the data
o to push pixels on your screen again
o to ask the OS again "what time is is"
sqlplus times alot more than the plsql block.
RE: Elapsed Time vs Run Time -or- Is Run Time Really Nanoseconds
Kyle, July 14, 2005 - 12:00 pm UTC
Tom,
Thanks for your reply. Maybe I wasn't very clear in describing my observations. I understand that the run_total_time will be less than the elapsed time, as you have described. What I don't understand is this:
Elapsed: 00:00:01.08
That's 1.08 seconds, right?
The query...
select run_comment, run_total_time / 1000000000 sec from
plsql_profiler_runs;
..results in...
RUN_COMMENT SEC
------------ ----------
timer_test 1027.15303
That's 1027.15303 seconds!!! Not even close!
The Oracle documentation states that run_total_time is in nanoseconds, but I propose that run_total_time may be in picoseconds, such that...
select run_comment, run_total_time / 1000000000000 sec from
plsql_profiler_runs;
...would result in a more accurate measurement of approximately 1.027 seconds. (Note the divide by 1000000000000 instead of 1000000000.)
It seems that either run_total_time is in picoseconds and the documentation is wrong, or run_total_time is not an aggregate of the total run and may be a summation of the fractions of time to run each line, causing inaccuracies in the value (or something like that)? What are your thoughts?
I hope my observations and questions are more clear this time.
Thanks again,
Kyle
July 14, 2005 - 1:02 pm UTC
platform? could be a platform issue, on linux,
ops$tkyte@ORA9IR2> select run_comment, run_total_time/1000000000 from plsql_profiler_runs;
RUN_COMMENT RUN_TOTAL_TIME/1000000000
----------- -------------------------
factorial .833089
iterative
factorial 1.372296
recursive
yes, indeed. you must be on windows, same thing on windows with 9.2:
tkyte@ORA9IR2W> select run_comment, run_total_time/1000000000 from plsql_profiler_runs;
RUN_COMMENT
-------------------------------------------------------------------------------
RUN_TOTAL_TIME/1000000000
-------------------------
factorial recursive
1915.48024
factorial iterative
1019.49072
Definitely, divide by 1,000 more.
problem while trying to create dbms_profiler
Sreenath, July 19, 2005 - 7:11 am UTC
Hi Tom,
I've an issue with this dbms_profiler..I've oracle 9i release 2 running on winXp system .As the dbms_profiler was not created I tried to do that by running the "profload.sql" from the sql command prompt.Any time I try doing this it is creating a package(dbms_profiler) with compilation errors .
Error is:"ORA-00900: invalid SQL statement
Warning: Package body created with compilation errors"
Can you please me to resolve this issue.
Regards,
sreenath
July 19, 2005 - 7:48 am UTC
I've not encountered that, please utilize support.
Yeah but No but Yeah...
Mike, January 20, 2006 - 8:12 am UTC
I'm hitting a similar rounding issue on 9.2.0.6 on HP-UX. For clarity I'm seeing a lack of time reported...
select run_time.time total_rum_time, sum_unit_time.time sum_of_unit_times,
run_time.time - sum_unit_time.time unaccounted_for_time
from
( select run_total_time / 1000000000 time
from PLSQL_PROFILER_RUNS
where runid = 18
) run_time,
( select sum(total_time) / 1000000000 time
from PLSQL_PROFILER_UNITS
where runid = 18
) sum_unit_time
/
TOTAL_RUM_TIME SUM_OF_UNIT_TIMES UNACCOUNTED_FOR_TIME
-------------- ----------------- --------------------
22.412604 14.798711 7.613893
While I fully appreciate what your saying and agree, This does somewhat stump my Performance analysis. Should I trust the percentages as reported by DBMS_PROFILER as accurate enough? I'm from the Millsap school of "work out where you spend your time first" and I'm not convinced I have.
I'd welcome your thoughts on next steps in my situation, I have traced the SQL in the process and it accounts for less that 1 second. I clearly have a PL/SQL issue.
Thanks in advance,
Mike.
January 20, 2006 - 10:33 am UTC
don't know what to say beyond what I've said though. You are comparing timings taken at two different levels. You'll have to draw your own conclusions from that.
time1 = get_time
elapsed_2 = 0;
loop lots of times
time2 = get_time
do something
time3 = get_time
elapsed_2 = elapsed_2 + (time3-time2);
end loop
time4 = get_time
elapsed_1 = time4-time1;
I would expect to see elapsed_1 and elapsed_2 to be "not the same", that is sort of what you are looking at here.