# 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](../course-plan.md) · Appendix entry: [DBMS_HPROF](../appendix.md#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

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