# Deep Dive — DBMS_UTILITY GET_TIME

> Two numbers — elapsed and CPU — taken before and after a step. Their difference tells you whether the step is *working* or *waiting*, which is the first fork in every performance investigation.

Used in: [Chapter 10 — Measure](../course-plan.md) · Appendix entry: [DBMS_UTILITY GET_TIME](../appendix.md#dbms_utility-get_time) · Related: [DBMS_APPLICATION_INFO](dbms_application_info.md), [DBMS_HPROF](dbms_hprof.md), [DBMS_XPLAN](dbms_xplan.md), [PRAGMA AUTONOMOUS_TRANSACTION](pragma-autonomous_transaction.md)

---

## 1. What It Is and When

| Function | Returns | Measures |
| --- | --- | --- |
| `DBMS_UTILITY.GET_TIME` | `NUMBER`, hundredths of a second | wall-clock elapsed, including every wait |
| `DBMS_UTILITY.GET_CPU_TIME` | `NUMBER`, hundredths of a second | CPU consumed by this session (10g+) |

Both return a counter whose absolute value means nothing — only differences do. `GET_TIME` wraps around (it is a signed 32-bit hundredths counter), so a difference can come out negative on the rare wrap; `GET_CPU_TIME` is a session total.

Use them to time **steps** of a job — not to profile functions (that is [DBMS_HPROF](dbms_hprof.md)) and not to explain a single SQL (that is [DBMS_XPLAN](dbms_xplan.md)). The first thing you learn from `elapsed` vs `cpu`:

| Observation | Meaning | Next tool |
| --- | --- | --- |
| elapsed ≈ cpu | the code is busy: PL/SQL logic, row-by-row overhead, sorting in memory | `DBMS_HPROF` |
| elapsed ≫ cpu | the session is waiting: I/O, locks, `log file sync`, network | `V$SESSION_EVENT`, ASH |

## 2. Syntax

```sql
DBMS_UTILITY.GET_TIME      RETURN NUMBER;
DBMS_UTILITY.GET_CPU_TIME  RETURN NUMBER;

-- alternatives with better resolution
SYSTIMESTAMP                                  -- microseconds; subtract for an INTERVAL DAY TO SECOND
DBMS_UTILITY.GET_ENDIANNESS                   -- (unrelated; listed to avoid confusion)
-- session statistics for the "why"
V$MYSTAT / V$STATNAME                         -- 'CPU used by this session', 'session logical reads', 'redo size', 'physical reads', 'user commits'
V$SESSION_EVENT                               -- wait events of this session, cumulative
```

## 3. Examples on the Course Schema

### 3a. Elapsed vs CPU around a step

```sql
DECLARE
  t0 PLS_INTEGER := DBMS_UTILITY.GET_TIME;
  c0 PLS_INTEGER := DBMS_UTILITY.GET_CPU_TIME;
BEGIN
  reprice_orders;
  DBMS_OUTPUT.PUT_LINE('reprice: elapsed ' || (DBMS_UTILITY.GET_TIME - t0) / 100 || 's, cpu ' ||
                       (DBMS_UTILITY.GET_CPU_TIME - c0) / 100 || 's');
END;
/
-- reprice: elapsed 4210.3s, cpu 3980.1s   → busy: row-by-row somewhere. HPROF.
-- reprice: elapsed 4210.3s, cpu  212.7s   → waiting: I/O or commits or locks. V$SESSION_EVENT.
```

### 3b. Wrap-safe elapsed helper

```sql
CREATE OR REPLACE FUNCTION elapsed_cs (p_start PLS_INTEGER) RETURN NUMBER IS
  l_now PLS_INTEGER := DBMS_UTILITY.GET_TIME;
BEGIN
  RETURN MOD(l_now - p_start + POWER(2, 32), POWER(2, 32));    -- hundredths, correct across a wrap
END;
/
```

A wrap during a nightly job is rare (the counter cycles every ~248 days of instance uptime) but produces a large negative or absurd number when it happens. Or use `SYSTIMESTAMP` differences, which never wrap.

### 3c. A stopwatch package with laps to a log table

```sql
CREATE OR REPLACE PACKAGE stopwatch AS
  PROCEDURE start_run (p_job VARCHAR2);
  PROCEDURE lap (p_step VARCHAR2);          -- logs the step ended now, since the previous lap
  PROCEDURE stop_run;
END;
/
CREATE OR REPLACE PACKAGE BODY stopwatch AS
  g_job   VARCHAR2(64);
  g_t     PLS_INTEGER;
  g_c     PLS_INTEGER;

  PROCEDURE write_lap (p_step VARCHAR2, p_elapsed NUMBER, p_cpu NUMBER) IS
    PRAGMA AUTONOMOUS_TRANSACTION;
  BEGIN
    INSERT INTO job_timing (job_name, step, logged_at, elapsed_sec, cpu_sec)
    VALUES (g_job, p_step, SYSTIMESTAMP, p_elapsed, p_cpu);
    COMMIT;
  END;

  PROCEDURE start_run (p_job VARCHAR2) IS
  BEGIN
    g_job := p_job; g_t := DBMS_UTILITY.GET_TIME; g_c := DBMS_UTILITY.GET_CPU_TIME;
    DBMS_APPLICATION_INFO.SET_MODULE(p_job, 'start');
  END;

  PROCEDURE lap (p_step VARCHAR2) IS
    l_t PLS_INTEGER := DBMS_UTILITY.GET_TIME;
    l_c PLS_INTEGER := DBMS_UTILITY.GET_CPU_TIME;
  BEGIN
    write_lap(p_step, (l_t - g_t) / 100, (l_c - g_c) / 100);
    g_t := l_t; g_c := l_c;
    DBMS_APPLICATION_INFO.SET_ACTION(p_step);
  END;

  PROCEDURE stop_run IS
  BEGIN
    lap('end');
    DBMS_APPLICATION_INFO.SET_MODULE(NULL, NULL);
  END;
END;
/
```

```sql
BEGIN
  stopwatch.start_run('nightly_batch');
  load_orders;      stopwatch.lap('load');
  reprice_orders;   stopwatch.lap('reprice');
  archive_orders;   stopwatch.lap('archive');
  stopwatch.stop_run;
END;
/
-- trend over the last 30 runs:
SELECT step, TRUNC(logged_at) AS run_day, elapsed_sec, cpu_sec
FROM   job_timing WHERE job_name = 'nightly_batch' AND logged_at > SYSDATE - 30
ORDER  BY logged_at, step;
```

The log table is the point: a step that took 40 minutes last month and 90 today is a regression you see *before* the job misses its window.

### 3d. Session statistics around a step — the "why" behind the seconds

```sql
CREATE OR REPLACE PROCEDURE snap_stats (p_label VARCHAR2) IS
BEGIN
  FOR r IN (SELECT n.name, s.value
            FROM   v$mystat s JOIN v$statname n ON n.statistic# = s.statistic#
            WHERE  n.name IN ('CPU used by this session', 'session logical reads',
                              'physical reads', 'redo size', 'user commits',
                              'execute count', 'parse count (hard)')) LOOP
    INSERT INTO stat_snap (label, stat_name, value, snapped_at) VALUES (p_label, r.name, r.value, SYSTIMESTAMP);
  END LOOP;
END;
/
snap_stats('before'); reprice_orders; snap_stats('after');

SELECT a.stat_name, a.value - b.value AS delta
FROM   stat_snap a JOIN stat_snap b ON b.stat_name = a.stat_name
WHERE  a.label = 'after' AND b.label = 'before';
```

Illustrative deltas that each tell a story:

| Statistic | Delta | Says |
| --- | --- | --- |
| `execute count` | 40,000,000 | one statement per row — Chapter 2 |
| `user commits` | 40,000,000 | commit per row — Chapter 5 |
| `parse count (hard)` | 40,000,000 | concatenated literals — Chapter 6 |
| `session logical reads` | 3,800,000,000 | a per-row lookup or a bad plan — Chapters 3, 4, XPLAN |
| `redo size` | 12 GB | conventional path where direct path was possible — Chapter 9 |

This is Tom Kyte's *runstats* idea reduced to its core: compare two implementations by what they *do*, not only by how long they take. Logical reads and redo do not change when the cache is warm; seconds do.

### 3e. Where the waiting went

```sql
-- when elapsed ≫ cpu: which waits, this session, cumulative since logon
SELECT event, total_waits, ROUND(time_waited_micro / 1e6, 1) AS sec
FROM   v$session_event
WHERE  sid = SYS_CONTEXT('USERENV', 'SID')
ORDER  BY time_waited_micro DESC FETCH FIRST 5 ROWS ONLY;
-- log file sync      → commits (Chapter 5)
-- db file sequential read → index probes per row (Chapters 3, 4)
-- enq: TX - row lock contention → locks (Chapter 8)
-- direct path write → good: direct-path load doing its job
```

Snapshot before and after the step and subtract, as in 3d.

### 3f. Microseconds with SYSTIMESTAMP

```sql
DECLARE
  t0 TIMESTAMP := SYSTIMESTAMP;
  d  INTERVAL DAY TO SECOND;
BEGIN
  small_step;
  d := SYSTIMESTAMP - t0;
  DBMS_OUTPUT.PUT_LINE('took ' || EXTRACT(SECOND FROM d) + 60 * EXTRACT(MINUTE FROM d) || ' s');
END;
```

For steps under a few hundredths of a second, `GET_TIME`'s resolution is too coarse; `SYSTIMESTAMP` gives microseconds (at the cost of an interval arithmetic that is annoying to print).

## 4. What Breaks at Scale

- Timing calls are cheap; **what you do with the result is not**. `DBMS_OUTPUT.PUT_LINE` inside a 500M-row loop fills the output buffer (`ORU-10027`) and costs more than the work. Time steps and batches, write to a table once per step ([PRAGMA AUTONOMOUS_TRANSACTION](pragma-autonomous_transaction.md) for the log — one commit per step is fine).
- **First run vs warm run.** The first execution pays hard parses, package initialization, and a cold cache. Measure the second run, or measure logical reads instead of seconds.
- **CPU time on a parallel statement** is the coordinator's CPU only; the PX slaves' CPU is elsewhere. For parallel steps, elapsed is honest, CPU is not — use `V$PQ_SESSTAT` / ASH.
- **Autonomous logging of timings** is a commit per lap — negligible at step granularity, harmful at row granularity.

## 5. Pitfalls

1. Reporting `GET_TIME` itself instead of a difference.
2. A negative elapsed after a counter wrap — 3b.
3. `GET_CPU_TIME` on a version < 10g — does not exist.
4. Timing inside the loop, per row — the measurement becomes the workload.
5. Comparing seconds across machines, or across a warm and a cold cache — compare logical reads and redo (3d).
6. Concluding "the SQL is slow" from elapsed alone — elapsed ≫ cpu with `log file sync` on top is a commit problem, not a SQL problem.
7. Leaving the timing log without a retention policy — a job with 20 steps × 365 days × years is a table nobody prunes. Partition by month, or purge.

## 6. Related

- [DBMS_APPLICATION_INFO](dbms_application_info.md) — tag the step you are timing.
- [DBMS_HPROF](dbms_hprof.md) — when elapsed ≈ cpu and you need the function.
- [DBMS_XPLAN](dbms_xplan.md) — when logical reads say the plan is wrong.
- [PRAGMA AUTONOMOUS_TRANSACTION](pragma-autonomous_transaction.md) — the timing log's commits.