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
Appendix entry: DBMS_UTILITY GET_TIME
Related: DBMS_APPLICATION_INFO DBMS_HPROF DBMS_XPLAN PRAGMA AUTONOMOUS_TRANSACTION

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) and not to explain a single SQL (that is DBMS_XPLAN). 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 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

Reporting GET_TIME itself instead of a difference.
A negative elapsed after a counter wrap — 3b.
GET_CPU_TIME on a version < 10g — does not exist.
Timing inside the loop, per row — the measurement becomes the workload.
Comparing seconds across machines, or across a warm and a cold cache — compare logical reads and redo (3d).
Concluding "the SQL is slow" from elapsed alone — elapsed ≫ cpu with log file sync on top is a commit problem, not a SQL problem.
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.