pl/sql Stored procedure... where does the execution time go?

Question

Hi everybody,

I am currently tracing a performance leak in a stored procedure. Having a timestamp put out right after the initial "begin" and one right before the final "end" (I am doing a commit before) says the procedure takes abt. 10 secs to finish. However, I have to wait 2mins+ for it to end.

Can anybody tell me where the rest of the times goes? I am using Oracle SQL dev but It doesn't seem to be idleing for the rest of the time, the procedure seems to hold a lock on the respective table :(

Thanks a lot in advance for enlightening....

EDIT: thanks again for your input :) here's the stripped code for the procedure, depending on the number of items to be processed, the 1st section currently takes abt. 10 to 40 seconds, the 2nd section a few millisecs. however the procedure takes 2 to 8 mins to run. also, the table containing the data to delete seem to be locked somewhat longer than needed, causing inserts to be deferred. starting it as scheduled job makes no difference btw, same behavior.

create or replace
procedure MY_PROCEDURE is
start_procedure number;
start_delete number;
end_procedure number;
begin

  start_procedure :=dbms_utility.get_time;

  begin
  -- stripped: doing some selects/updates here
  end;
  commit;

  start_delete :=dbms_utility.get_time ;

  begin
  -- stripped: cleanig up some other data here
  end;
  commit;
  end_procedure :=dbms_utility.get_time ;

  dbms_output.put_line('procedure took: '||to_char((end_procedure- start_procedure)/1000));
  dbms_output.put_line('updates took: '||to_char((start_delete- start_procedure)/1000));
  dbms_output.put_line('delete took: '||to_char((end_procedure-start_delete)/1000));

end;

Answer 1

I think you need to be dividing by 100, not 1000(dbms_utility.get_time gives time in centiseconds). That should give you 100 seconds, which is about 2 minutes.

However, if you're interested in finding out where the 2 minutes of execution time went, and depending on the complexity of the procedure, you may want to either:

• collect a statspack report by taking snapshots before and after the procedure runs
• use the PL/SQL Hierarchical Profiler(http://download.oracle.com/docs/cd/B28359_01/appdev.111/b28424/adfns_profiler.htm#CHDCIGIB).

The profiler may be better if you have a lot of chained PL/SQL procedure calls. The statspack report will be better if you have mostly sql statements inside the stored procedure.

Here's what the Profiler output looks like:

Sample Report

Function Elapsed Time (microsecs) Data sorted by Total Subtree Elapsed Time (microsecs)

2831 microsecs (elapsed time) & 12 function calls
Subtree     Ind%  Function  Descendant  Ind%  Calls  Ind%  Function Name
2831    100%  93  2738  96.7%  2  16.7%  __plsq_vm
2738    96.7%  310  2428  85.8%  2  16.7%  __anonymous_block
2428    85.8%  15  2413  85.2%  1  8.3%  HR.TEST.TEST (Line 1)
2413    85.2%  435  1978  69.9%  3  25.0%  HR.TEST.TEST.FOO (Line 3)
1978    69.9%  1978  0  0.0%  3  25.0%  HR.TEST.__static_sql_exec_line5 (Line 5)
0   0.0%  0  0  0.0%  1  8.3%  SYS.DBMS_HPROF.STOP_PROFILING (Line 53)

Answer 2

Your time is probably due to a large number of context switches between java and the database as SQL developer refreshes your screen. to test this, run your test again in SQLPlus. To fix, go into tools > preferences > database > advanced Parameters and up your SQL Array Fetch Size to a value somewhere between 150 and 500, and (if you have appropriate drivers) check off the Use OCI/Thick driver box.

Answer 3

if you have the appropriate perms (and if not, ask your dba for help) perhaps you could query the following views:

V$SESSION_WAIT
V$SYSTEM_EVENT

you can then check the results

here (http://www.remote-dba.net/oracle_10g_tuning/t_oracle_v$session_wait.htm)* is a description on how to read the output, and here is some more info on the events inside.

* you will have to copy the url as the $ is messing up the link.

Answer 4

So something like this?

CREATE PROCEDURE ...
AS
DECLARE some stuff
BEGIN
    print time
    do stuff
    COMMIT
    print time
END

I don't know that much about Oracle's transaction paradigm, but I wonder if the commit inside the procedure doesn't really have any effect until the procedure is complete, and the procedure isn't complete until the END is reached. At that point, the actual process of committing the transaction begins, and can take a long time if there are triggers and referential integrity constraints involved.

That kind of behavior would be similar to how DEFERRABLE INITALLY DEFERRED referential integrity constraints act.

I suspect the suggested system table queries would tell you, or you could try stepping through the "do stuff" steps in an interactive session and see what happens.

Answer 5

There might be something in the declaration section that is taking long to execute. Could you include the code of your stored procedure ?

Answer 6

I'm not familiar with pl/sql, but is there a way to pause or interrupt it while it's running?

The chance that you will hit it while it's being wasteful is equal to the percent of time it's wasting, so you may need to stop it several times to catch it in the act. Often the problem is somewhere in the middle of the call stack. Anything that appears on more than one stack sample will, if you can replace it, save you significant time.

In general, the method is this.

Answer 7

What does the procedure do ? One possible explanation may be DBMS_OUTPUT. If, on SQL*Plus, you do a SET SERVEROUTPUT ON, after a statement has executed, the client does a 'behind-the-scenes' fetch of any information that has been buffered using DBMS_OUTPUT.PUT_LINE. I'd guess SQL Developer does the same.

So if a lot of stuff has been pushed to DBMS_OUTPUT, then the execution of the procedure could be quick, but the behind-the-scenes collection of that could be taking up the time (especially if it is a slow network).

Another trick in SQL*Plus is you can SET TIMING ON (which will automatically show the elapsed time of the statement) and SET TIME ON (which shows the time in the SQL prompt).

So try

SET SERVEROUTPUT OFF
SET TIMING ON
SET TIME ON
DBMS_MONITOR.DATABASE_TRACE_ENABLE(TRUE);
exec stored_proc;
disconn

And see the results. I wouldn't expect to see any time unaccounted for. That is, the client should report the full two minutes. Assuming it does, I'd be using the trace (the DBMS_MONITOR command) and run a tkprof on the result to see what accounts for those 2 minutes.

Answer 8

If you replace those calls to dbms_utility.get_time by messages like:

dbms_output.put_line ('start procedure: ' || to_char(sysdate, HH24:MI:SS'));

and then call the procedure like this:

dbms_output.put_line ('before procedure: ' || to_char(sysdate, HH24:MI:SS'));
exec my_procedure;
dbms_output.put_line ('after procedure: ' || to_char(sysdate, HH24:MI:SS'));

then the place where the missing time occurs will show up.

Answer 9

Problem solved, but I still do not understand...

The leak was caused by a bad select statement buried in another procedure which is called by the other procedure. I optimized it, now it runs like charm.

I found out the hard way, commenting line by line... trying and trying.

However, I'd still like to know why the timestamps were absolutely inaccurate. This was very misleading and cost me quite some time... So, is there anything wrong with the way I create the timestamps?

If anyone has info on this, I'd be glad to hear it.

Thanks to all of you for your help with this issue.

Answer 10

In your DBMS_OUTPUT statements you are dividing your result by 1000. According to all the Oracle documenation I can find on the dbms_utility.get_time function measure time in 100ths of seconds, not 1000ths.

So while you are displaying 10 to 40 seconds, it is actually 100 (1 minute 40 seconds) to 400 (6 minutes 40 seconds) seconds. This is more inline with the 2 to 8 minutes you are observing.

Check out http://download-west.oracle.com/docs/cd/B19306_01/appdev.102/b14258/d_util.htm for more information on the function.

Answer 11

Oracle contains a profiler that will tell you the amount of time spent on each executable statement. dbms_profiler for 10g and earlier, and there's a fancier version (the hierarchical profiler) available in 11g.

Much simpler than using sets of dbms_utility and dbms_output statements, and it gives you much more complete information -- including drilldown into the called routines if you have rights to see their source code.

I'm glad you solved your problem. Next time, though, using the profiler will make it easier.