PLSQL: Which code is taking longer?

So you have a slow process calling several PLSQL Codes, including Procedures, Functions and etc, but don’t know what is taking longer?

Your problems has ended… 

In Oracle 11gR1 was introduced the PL/SQL Hierarchical Profiler to help developers by providing hierarchical profiler data analysis for PL/SQL programs.

From Oracle base:
“The hierarchical profiler consists of the DBMS_HPROF package, which feels similar to the DBMS_PROFILER and DBMS_TRACE packages, and the plshprof command line utility to converts the profile information into HTML format.”

For example, we can set a profiler for procedure proc_example_1 and check in all calls and related statistics:

BEGIN
  DBMS_HPROF.start_profiling (
    location => 'ORACLE_DIR',
    filename => 'prof.txt');

  proc_example_1(p_number => 10);

  DBMS_HPROF.stop_profiling;
END;
/

And to see results, a simple output is:

COLUMN owner FORMAT A20
COLUMN module FORMAT A20
COLUMN type FORMAT A20
COLUMN function FORMAT A25
SELECT symbolid,
       owner,
       module,
       type,
       function
FROM   dbmshp_function_info
WHERE  runid = 1
ORDER BY symbolid;

  SYMBOLID OWNER                MODULE               TYPE                 FUNCTION
---------- -------------------- -------------------- -------------------- -------------------------
         1 TEST                 proc_example_1       PROCEDURE            proc_example_1
         2 TEST                 proc_example_2       PROCEDURE            proc_example_2
         3 TEST                 proc_example_3       PROCEDURE            proc_example_3
         4 SYS                  DBMS_HPROF           PACKAGE BODY         STOP_PROFILING
    5 TEST                 proc_example_3       PROCEDURE            __static_sql_exec_line5

5 rows selected.

Which can also be seen with this nice SQL from Oracle Base (Tim Hall):

SET LINESIZE 500 PAGESIZE 1000
COLUMN name FORMAT A100
SELECT RPAD(' ', (level-1)*2, ' ') || a.name AS name,
       a.subtree_elapsed_time,
       a.function_elapsed_time,
       a.calls
FROM   (SELECT fi.symbolid,
               pci.parentsymid,
               RTRIM(fi.owner || '.' || fi.module || '.' || NULLIF(fi.function,fi.module), '.') AS name,
               NVL(pci.subtree_elapsed_time, fi.subtree_elapsed_time) AS subtree_elapsed_time,
               NVL(pci.function_elapsed_time, fi.function_elapsed_time) AS function_elapsed_time,
               NVL(pci.calls, fi.calls) AS calls
        FROM   dbmshp_function_info fi
               LEFT JOIN dbmshp_parent_child_info pci ON fi.runid = pci.runid AND fi.symbolid = pci.childsymid
        WHERE  fi.runid = 1
        AND    fi.module != 'DBMS_HPROF') a
CONNECT BY a.parentsymid = PRIOR a.symbolid
START WITH a.parentsymid IS NULL;


NAME                                                SUBTREE_ELAPSED_TIME FUNCTION_ELAPSED_TIME      CALLS
--------------------------------------------------- -------------------- --------------------- ----------
TEST.proc_example_1                                                31262                    31          1
  TEST.proc_example_2                                              31231                   133         10
    TEST.proc_example_3                                            31098                  3241        100
      TEST.proc_example_3.__static_sql_exec_line5                  27857                 27857       1000

Cheers!