Deep Dive — DBMS_HPROF, the PL/SQL Hierarchical Profiler

Answers one question: where does the time go — per function, who called whom, and how much of it is SQL.

Used in: Chapter 10 — Measure
Appendix entry: DBMS_HPROF

1. What It Is and Why This One

Tool	What it measures	When
`DBMS_PROFILER`	Time per line (flat)	Legacy. High overhead, does not separate SQL from PL/SQL.
`DBMS_HPROF`	Time per function + call tree + SQL statements as separate nodes	The default since 11g.
`V$SQL` / `DBMS_XPLAN`	The SQL itself	After HPROF has shown which SQL is heavy.

HPROF intercepts entry/exit of every subprogram (not every line) — that is why the overhead is low, and why the output is a tree.

2. How It Works — Three Steps

START_PROFILING ──► code runs ──► STOP_PROFILING          (1) collect  → raw trace file
ANALYZE(trace)                                             (2) analyze  → 3 DBMSHP_* tables
SELECT ... FROM dbmshp_function_info  /  plshprof → HTML   (3) read

3. One-Time Setup

SQL

-- As DBA:
CREATE OR REPLACE DIRECTORY prof_dir AS '/u01/app/oracle/hprof';
GRANT READ, WRITE ON DIRECTORY prof_dir TO app_user;
GRANT EXECUTE ON DBMS_HPROF TO app_user;        -- usually already granted to PUBLIC

-- As app_user (the tables must live in the schema that runs ANALYZE):
--   11g / 12.1:
@?/rdbms/admin/dbmshptab.sql
--   12.2+:
EXEC DBMS_HPROF.CREATE_TABLES;                  -- force_it => TRUE drops and recreates

Tables created: DBMSHP_RUNS (one row per run), DBMSHP_FUNCTION_INFO (one row per function), DBMSHP_PARENT_CHILD_INFO (edges of the call tree), and from 12.2 DBMSHP_TRACE_DATA (raw trace stored in a table instead of a file).

4. Full Example on the Course Schema

"Suspicious" code — a lookup per row (the problem from Chapters 3–4):

SQL

CREATE OR REPLACE PACKAGE nightly AS
  PROCEDURE run;
END;
/
CREATE OR REPLACE PACKAGE BODY nightly AS
  FUNCTION customer_tier (p_id NUMBER) RETURN VARCHAR2 IS
    v customers.tier%TYPE;
  BEGIN
    SELECT tier INTO v FROM customers WHERE customer_id = p_id;         -- line 6
    RETURN v;
  END;

  PROCEDURE reprice IS
  BEGIN
    FOR r IN (SELECT order_id, customer_id, amount
              FROM orders WHERE status = 'NEW' AND ROWNUM <= 100000) LOOP  -- line 13
      IF customer_tier(r.customer_id) = 'VIP' THEN
        UPDATE orders SET amount = amount * 0.9 WHERE order_id = r.order_id;  -- line 15
      END IF;
    END LOOP;
  END;

  PROCEDURE archive IS
  BEGIN
    INSERT INTO orders_archive
    SELECT * FROM orders WHERE order_date < ADD_MONTHS(TRUNC(SYSDATE, 'MM'), -24); -- line 23
  END;

  PROCEDURE run IS
  BEGIN
    reprice;
    archive;
    COMMIT;
  END;
END;
/

Profile it:

SQL

DECLARE
  l_runid NUMBER;
BEGIN
  DBMS_HPROF.START_PROFILING(location => 'PROF_DIR', filename => 'nightly.trc');
  nightly.run;
  DBMS_HPROF.STOP_PROFILING;

  l_runid := DBMS_HPROF.ANALYZE(location    => 'PROF_DIR',
                                filename    => 'nightly.trc',
                                run_comment => 'nightly - before fix');
  DBMS_OUTPUT.PUT_LINE('runid = ' || l_runid);
END;
/

Query A — who burns the time (self time)

SQL

SELECT function, type, line#, calls,
       ROUND(function_elapsed_time / 1e6, 1) AS self_sec,
       ROUND(subtree_elapsed_time  / 1e6, 1) AS total_sec
FROM   dbmshp_function_info
WHERE  runid = :runid
ORDER  BY function_elapsed_time DESC
FETCH FIRST 8 ROWS ONLY;

Typical output (numbers are illustrative):

FUNCTION                        TYPE           LINE#   CALLS  SELF_SEC  TOTAL_SEC
------------------------------  ------------  ------  ------  --------  ---------
__static_sql_exec_line6         (SQL)              6  100000      41.2       41.2
__static_sql_exec_line23        (SQL)             23       1      18.7       18.7
__static_sql_exec_line15        (SQL)             15   12000       5.9        5.9
CUSTOMER_TIER                   PACKAGE BODY       3  100000       3.1       44.3
__sql_fetch_line13              (SQL)             13    1001       2.4        2.4
REPRICE                         PACKAGE BODY      10       1       1.8       55.5
ARCHIVE                         PACKAGE BODY      20       1       0.0       18.7
RUN                             PACKAGE BODY      26       1       0.0       74.2

Reading it: out of 74 seconds, 41 are 100,000 executions of the SELECT on line 6 — the per-row lookup. Not a guess. This is exactly what Chapter 4 fixes.

Query B — the call tree

SQL

SELECT LPAD(' ', 2 * (LEVEL - 1)) || c.function AS call_tree,
       pc.calls,
       ROUND(pc.function_elapsed_time / 1e6, 1) AS self_sec,
       ROUND(pc.subtree_elapsed_time  / 1e6, 1) AS total_sec
FROM   dbmshp_parent_child_info pc
JOIN   dbmshp_function_info    c  ON c.runid = pc.runid AND c.symbolid = pc.childsymid
WHERE  pc.runid = :runid
START WITH pc.parentsymid = (SELECT symbolid FROM dbmshp_function_info
                             WHERE  runid = :runid AND function = '__plsql_vm')
CONNECT BY NOCYCLE PRIOR pc.childsymid = pc.parentsymid AND pc.runid = :runid
ORDER SIBLINGS BY pc.subtree_elapsed_time DESC;

CALL_TREE                              CALLS  SELF_SEC  TOTAL_SEC
------------------------------------  ------  --------  ---------
__anonymous_block                          1       0.0       74.2
  RUN                                      1       0.0       74.2
    REPRICE                                1       1.8       55.5
      CUSTOMER_TIER                   100000       3.1       44.3
        __static_sql_exec_line6       100000      41.2       41.2
      __static_sql_exec_line15         12000       5.9        5.9
      __sql_fetch_line13                1001       2.4        2.4
      __static_sql_exec_line13            1       0.3        0.3
    ARCHIVE                                1       0.0       18.7
      __static_sql_exec_line23             1      18.7       18.7

PARENT_CHILD_INFO splits time per edge — if customer_tier is also called from somewhere else, you see what it cost from each caller separately.

5. Reading the Output

Column / name	Meaning
`function_elapsed_time`	self — time inside the function itself, excluding children (microseconds)
`subtree_elapsed_time`	inclusive — including everything it called
`calls`	number of calls
`namespace`	`PLSQL` or `SQL`
`__plsql_vm`	entry into the PL/SQL engine (from SQL or from the client)
`__anonymous_block`	the anonymous block
`__pkg_init`	package initialization (once per session)
`__static_sql_exec_lineN`	static SQL executed at line N (the execute)
`__sql_fetch_lineN`	the fetches of a cursor at line N
`__dyn_sql_exec_lineN`	`EXECUTE IMMEDIATE` / `OPEN FOR` at line N

Rule: start from high self time. High self on a SQL node → the problem is the SQL (continue to DBMS_XPLAN). High self on a PL/SQL function → the problem is the code itself. A huge calls count on a SQL node → row-by-row.

6. plshprof — HTML Report and Run Comparison

A command-line tool in $ORACLE_HOME/bin. Works on the trace file directly (no tables needed):

Bash

plshprof -output nightly nightly.trc            # nightly.html + one page per function
plshprof -output diff before.trc after.trc      # difference report between two runs

The report gives: time by function / module / namespace (how much is SQL vs PL/SQL), parents and children per function, and in diff mode — what improved and what got worse. The diff is how you answer "did my fix help?" with numbers.

7. Table Mode (12.2+) — No DIRECTORY

SQL

DECLARE
  l_trace NUMBER;
  l_runid NUMBER;
BEGIN
  l_trace := DBMS_HPROF.START_PROFILING(run_comment => 'nightly - after fix');  -- raw → DBMSHP_TRACE_DATA
  nightly.run;
  DBMS_HPROF.STOP_PROFILING;
  l_runid := DBMS_HPROF.ANALYZE(trace_id => l_trace, run_comment => 'nightly - after fix');
END;
/

Convenient when you have no access to the server file system. Verify the exact signature on your version with DESC DBMS_HPROF.

8. Parameters Worth Knowing

START_PROFILING

max_depth — maximum depth of the recorded tree; deeper calls are attributed to the last recorded function. Useful for deep recursion.
profile_uga / profile_pga (12.2+) — also collect memory deltas per function. Shows who inflates PGA (Chapter 4 — collections without LIMIT).
sqlmonitor (12.2+, default TRUE) — links SQL statements in the profile to SQL Monitor reports. Requires the Tuning Pack license.
run_comment — a name for the run. Always fill it in; a week later runid=17 means nothing.

ANALYZE

summary_mode => TRUE — per-function summary only, no tree. Fast on a huge trace.
trace => '"APP_USER"."NIGHTLY"."REPRICE"' + skip + collect — analyze only one function, e.g. only its 5th to 10th invocation. Zoom into a subtree without re-profiling everything.

9. Pitfalls

Profiling = the current session only. A Scheduler job — wrap its action in START/STOP; you cannot profile it from outside.
ANALYZE needs the tables in the caller's schema. If it runs and nothing is written — the tables are in another schema.
ORA-29283 invalid file operation — no READ/WRITE on the DIRECTORY, or the OS path does not exist.
Session ended without STOP_PROFILING — a truncated trace file; ANALYZE fails or gives partial results.
Low overhead — not zero. Run on a representative volume (100K rows, not 500M); do not leave it on in production.
The first run includes __pkg_init and hard parses. Run twice and look at the second.
Your backup is the trace. Keep before.trc next to after.trc — otherwise there is no diff, and no proof the fix helped.