Skip to Main Content
  • Questions
  • Performance monitoring for pl/sql procedures

Breadcrumb

May 4th

Question and Answer

Tom Kyte

Thanks for the question, nagavenugopal.

Asked: January 14, 2002 - 10:53 pm UTC

Last updated: January 20, 2006 - 10:33 am UTC

Version: 8.1.7

Viewed 1000+ times

You Asked

Hi tom,

Is there any mechanism to find the performance of each procedure.

1. How much CPU time it takes to execute?
2. How much Space it occupies in the database.
3. How tables/Procedures it refers.
4. How to develop a report on these activities.

Regards,
Venu


and Tom said...

do you have my book? you'll be interested in the chapter on dbms_profiler I have in there.

search for

dbms_profiler

on this site for other examples of using that.

That'll answer #1.

#2 is the view dba_object_size

#3 is dba_dependencies

#4 is writing sql ;)



Rating

  (5 ratings)

Is this answer out of date? If it is, please let us know via a Comment

Comments

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?

Tom Kyte
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
 

Tom Kyte
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


Tom Kyte
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

Tom Kyte
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.

Tom Kyte
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.

More to Explore

PL/SQL demos

Check out more PL/SQL tutorials on our LiveSQL tool.

PL/SQL docs

PL/SQL reference manual from the Oracle documentation library