Interpreting TKPROF Output
PARSE Translates the SQL statement into an execution plan, including checks for proper security authorization and checks for the existence of tables, columns, and other referenced objects.
EXECUTE Actual execution of the statement by Oracle. For INSERT, UPDATE, and DELETE statements, this modifies the data. For SELECT statements, this identifies the selected rows.
FETCH Retrieves rows returned by a query. Fetches are only performed for SELECT statements.
COUNT Number of times a statement was parsed, executed, or fetched.
CPU Total CPU time in seconds for all parse, execute, or fetch calls for the statement. This value is zero (0) if TIMED_STATISTICS is not turned on.
ELAPSED Total elapsed time in seconds for all parse, execute, or fetch calls for the statement. This value is zero (0) if TIMED_STATISTICS is not turned on.
DISK Total number of data blocks physically read from the datafiles on disk for all parse, execute, or fetch calls.
QUERY Total number of buffers retrieved in consistent mode for all parse, execute, or fetch calls. Usually, buffers are retrieved in consistent mode for queries.
CURRENT Total number of buffers retrieved in current mode. Buffers are retrieved in current mode for statements such as INSERT, UPDATE, and DELETE.
ROWS Total number of rows processed by the SQL statement. This total does not include rows processed by subqueries of the SQL statement.
Sample TKPROF Header
Copyright (c) Oracle Corporation 1979, 1999. All rights reserved.
Trace file: v80_ora_2758.trc
Sort options: default
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************
The following statement encountered a error during parse:
select deptno, avg(sal) from emp e group by deptno
having exists (select deptno from dept
where dept.deptno = e.deptno
and dept.budget > avg(e.sal)) order by 1
Error encountered: ORA-00904
********************************************************************************
Sample TKPROF Body
ALTER SESSION SET SQL_TRACE = true
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.00 0.10 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.00 0.10 0 0 0 0
Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer goal: CHOOSE
Parsing user id: 02 (USER02)
********************************************************************************
SELECT emp.ename, dept.dname
FROM emp, dept
WHERE emp.deptno = dept.deptno
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.11 0.13 2 0 1 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 2 2 4 14
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.11 0.13 4 2 5 14
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 02 (USER02)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
14 MERGE JOIN
4 SORT (JOIN)
4 TABLE ACCESS (FULL) OF 'DEPT'
14 SORT (JOIN)
14 TABLE ACCESS (FULL) OF 'EMP'
********************************************************************************
SELECT a.ename name, b.ename manager
FROM emp a, emp b
WHERE a.mgr = b.empno(+)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.01 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.01 0.01 1 50 2 14
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.02 0.02 1 50 2 14
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 01 (USER01)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
13 NESTED LOOPS (OUTER)
14 TABLE ACCESS (FULL) OF 'EMP'
13 TABLE ACCESS (BY ROWID) OF 'EMP'
26 INDEX (RANGE SCAN) OF 'EMP_IND' (NON-UNIQUE)
********************************************************************************
SELECT ename, job, sal
FROM emp
WHERE sal =
(SELECT max(sal)
FROM emp)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 12 4 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 12 4 1
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 01 (USER01)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
14 FILTER
14 TABLE ACCESS (FULL) OF 'EMP'
14 SORT (AGGREGATE)
14 TABLE ACCESS (FULL) OF 'EMP'
********************************************************************************
SELECT deptno
FROM emp
WHERE job = 'clerk'
GROUP BY deptno
HAVING COUNT(*) >= 2
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 1 1 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 1 1 0
Misses in library cache during parse: 13
Optimizer goal: CHOOSE
Parsing user id: 01 (USER01)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
0 FILTER
0 SORT (GROUP BY)
14 TABLE ACCESS (FULL) OF 'EMP'
********************************************************************************
SELECT dept.deptno, dname, job, ename
FROM dept,emp
WHERE dept.deptno = emp.deptno(+)
ORDER BY dept.deptno
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 3 3 10
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 3 3 10
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 01 (USER01)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
14 MERGE JOIN (OUTER)
4 SORT (JOIN)
4 TABLE ACCESS (FULL) OF 'DEPT'
14 SORT (JOIN)
14 TABLE ACCESS (FULL) OF 'EMP'
********************************************************************************
SELECT grade, job, ename, sal
FROM emp, salgrade
WHERE sal BETWEEN losal AND hisal
ORDER BY grade, job
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.04 0.06 2 16 1 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.01 0.01 1 10 12 10
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.05 0.07 3 26 13 10
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 02 (USER02)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
14 SORT (ORDER BY)
14 NESTED LOOPS
5 TABLE ACCESS (FULL) OF 'SALGRADE'
70 TABLE ACCESS (FULL) OF 'EMP'
********************************************************************************
SELECT LPAD(' ',level*2)||ename org_chart, level, empno, mgr, job, deptno
FROM emp
CONNECT BY prior empno = mgr
START WITH ename = 'clark'
OR ename = 'blake'
ORDER BY deptno
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.01 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.01 0.01 0 1 2 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.02 0.02 0 1 2 0
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 02 (USER02)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
0 SORT (ORDER BY)
0 CONNECT BY
14 TABLE ACCESS (FULL) OF 'EMP'
0 TABLE ACCESS (BY ROWID) OF 'EMP'
0 TABLE ACCESS (FULL) OF 'EMP'
********************************************************************************
CREATE TABLE TKOPTKP (a number, b number)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.01 0.01 1 0 1 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.01 0.01 1 0 1 0
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 02 (USER02)
Rows Execution Plan
------- ---------------------------------------------------
0 CREATE TABLE STATEMENT GOAL: CHOOSE
********************************************************************************
INSERT INTO TKOPTKP
VALUES (1,1)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.07 0.09 0 0 0 0
Execute 1 0.01 0.20 2 2 3 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.08 0.29 2 2 3 1
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 02 (USER02)
Rows Execution Plan
------- ---------------------------------------------------
0 INSERT STATEMENT GOAL: CHOOSE
********************************************************************************
INSERT INTO TKOPTKP SELECT * FROM TKOPTKP
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.02 0.02 0 2 3 11
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.02 0.02 0 2 3 11
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 02 (USER02)
Rows Execution Plan
------- ---------------------------------------------------
0 INSERT STATEMENT GOAL: CHOOSE
12 TABLE ACCESS (FULL) OF 'TKOPTKP'
********************************************************************************
SELECT *
FROM TKOPTKP
WHERE a > 2
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.01 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 1 2 10
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.01 0.01 0 1 2 10
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 02 (USER02)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
24 TABLE ACCESS (FULL) OF 'TKOPTKP'
********************************************************************************
Sample TKPROF Summary
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 18 0.40 0.53 30 182 3 0
Execute 19 0.05 0.41 3 7 10 16
Fetch 12 0.05 0.06 4 105 66 78
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 49 0.50 1.00 37 294 79 94
Misses in library cache during parse: 18
Misses in library cache during execute: 1
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 69 0.49 0.60 9 12 8 0
Execute 103 0.13 0.54 0 0 0 0
Fetch 213 0.12 0.27 40 435 0 162
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 385 0.74 1.41 49 447 8 162
Misses in library cache during parse: 13
19 user SQL statements in session.
69 internal SQL statements in session.
88 SQL statements in session.
17 statements EXPLAINed in this session.
********************************************************************************
Trace file: v80_ora_2758.trc
Trace file compatibility: 7.03.02
Sort options: default
1 session in tracefile.
19 user SQL statements in trace file.
69 internal SQL statements in trace file.
88 SQL statements in trace file.
41 unique SQL statements in trace file.
17 SQL statements EXPLAINed using schema:
SCOTT.prof$plan_table
Default table was used.
Table was created.
Table was dropped.
1017 lines in trace file.
