How to profile end to end performance of Oracle stored procedure

Question

I want to know how long my stored procedure is taking to execute from the time an external process hits the database and says execute this to the time the database returns back to the process and says here ya go.

Is there a simple easy way to do this very basic task?

Of course a report of what is happening during the stored procedure execution and how much of the stored procedure's time is spent doing each task (inserts, plsql string manipulation etc.) would be a bonus, but I really just want something simple and easy to use. (And free)

Answer 1

If you're using Oracle 11g you should have a look at the hierarchical profiler, DBMS_HPROF. This is a tool which will give you elapsed timings for all the nodes in a PL/SQL program. As the name suggests, it is especially useful for investigating programs which call programs which call programs. It also identifies timing for SQL statements distinct from function calls. Find out more.

It is part of the standard 11g deployment, and hence is free. Well, once you've paid for your license it's free :)

By default rights on the DBMS_HPROF package are not granted to any one. So, you'll need to get somebody with SYSDBA access to see you right. The analysis also requires the creation of some tables. Neither of these things should be an issue but I know sometimes they are.

---

Alas, you're on an earlier version. So that leaves you with just DBMS_PROFILER, which has been around since 9i. This basically works well for a single program. Its main drawback is that we can only use it on programs for which we have the CREATE privilege (i.e. just programs in our schema unless we have the CREATE ANY PROCEDURE privilge, which usually means being a DBA). Also, for profiling embedded SQL statements we need to use the DBMS_TRACE package. Find out more.

Answer 2

SIMPLEST,CHEAPEST OPTION You could log events to a "debug" table and check the duration between the logs, like for ex. Log event before insert into table a with time stamp a into debug table. Log event after insert into table a with timestamp b into debug table.

It's a bit time consuming if you're stored procedure is anything more than 5 lines, but it will help you none the less. Also implement a debug flag, so when you need to log time stamps, set the flag at the top of the procedure to true, and then re-compile it. When executing the stored procedure, it will then go and log all your events, when done with debugging, set the flag to false and re-compile.

Answer 3

If you are looking to write your own time lapse into your PL/SQL programs the below is my template code for doing this. Also, this requires no assistance from your DBA. My DBA's are often reluctant to give me more access to more things. That, and I hate waiting for them to actually give me access.

/* This procedure is simply an example of parsing out an Elapsed time into their individual time parts */
/*   In other words it provides to the user the elapsed time in hours : minutes : seconds . milliseconds */

DECLARE

  G_START_TIME1     NUMBER        := DBMS_UTILITY.GET_TIME;
  G_START_TIME2     NUMBER        := DBMS_UTILITY.GET_TIME;
  vG_ELAPSED_TIME   VARCHAR2(200);

  /* Variables below are used for storing Elapsed time. */
  RETVAL           NUMBER;
  hourss            NUMBER;
  minutess          NUMBER;
  secondss          NUMBER;
  millisecondss     NUMBER;
    n_hrs         NUMBER := 360000;
    n_mins        NUMBER := 6000;
    n_secs        NUMBER := 100;
    n_sixty       NUMBER := 60;
    n_thirty      NUMBER := 30;
    n_ten         NUMBER := 10;

  v_PrintTime     VARCHAR2(200);


  /* The procedure below is simply used to simulate the passage of time */
  PROCEDURE waste_time(pn_Seconds NUMBER) IS

  n_CentiSeconds  NUMBER  :=  pn_Seconds * 100;
  n_ProgramStart  NUMBER  := DBMS_UTILITY.GET_TIME; /* dbms_utility_get_time returns times in hundreds of a second */

  BEGIN
    WHILE DBMS_UTILITY.GET_TIME < n_ProgramStart + n_CentiSeconds
    LOOP
      null;
    END LOOP;
  END waste_time;

BEGIN

  G_START_TIME1   :=    -2019618227; --dbms_utility.get_time;

  --waste_time(1);
  --dbms_output.put_line('1 Second Wasted'|| chr(10));

  G_START_TIME2   :=    G_START_TIME1 + 366110; ---2019619227; --dbms_utility.get_time;

  dbms_output.put_line('Start_time: '||G_START_TIME1);
  dbms_output.put_line('End_time:   '||G_START_TIME2||chr(10));

  vG_ELAPSED_TIME :=  G_START_TIME2 - G_START_TIME1;
  millisecondss   :=  vG_ELAPSED_TIME * n_ten;
  secondss        :=  vG_ELAPSED_TIME / n_secs;
  minutess        :=  vG_ELAPSED_TIME / n_mins;
  hourss          :=  vG_ELAPSED_TIME / n_hrs;

  dbms_output.put_line('Total Time: '||millisecondss ||' Milliseconds');
  dbms_output.put_line('Total Time: '||vG_ELAPSED_TIME ||' Centiseconds');
  dbms_output.put_line('Total Time: '||secondss ||' Seconds');
  dbms_output.put_line('Total Time: '||minutess ||' Minutes');
  dbms_output.put_line('Total Time: '||hourss ||' Hours');

  millisecondss   :=  mod(vG_ELAPSED_TIME * n_ten, 1000);            /* Milliseconds into Seconds.  Returns left over millisedonds */
  secondss        :=  trunc(mod(vG_ELAPSED_TIME / n_secs, n_sixty)); /* Seconds into hours.  Returns how many seconds are left over */
  minutess        :=  trunc(mod(vG_ELAPSED_TIME / n_mins, n_sixty)); /* Seconds into hours.  Returns how many seconds are left over */
  hourss          :=  trunc(vG_ELAPSED_TIME / n_hrs);                /* Spit out hours only using just trunc here.  Since we don't need to build up Days we can leave this as is */

  v_PrintTime     :=  hourss ||':'|| minutess ||':'|| secondss ||'.'|| millisecondss;

  dbms_output.put_line(chr(10) ||'Elapsed Time: '|| v_PrintTime);


END;