6.

Tracing SQL statements

7/24/13 11:08 PM

Tracing SQL
statements

Janusz R. Getta

CSCI317/MCS9317 Database Performance Tuning, SCSSE, Spring 2013

6. Tracing SQL statements

7/24/13 11:08 PM

"EXPLAINING" SQL statements

EXPLAIN PLAN statement of SQL
EXPLAIN PLAN FOR
SELECT E#, ENAME
FROM EMPLOYEE
WHERE SALARY > 20000;
Query plan
-----------------------------------------------------SELECT STATEMENT
TABLE ACCESS FULL EMPLOYEE
TABLE ACCESS FULL EMPLOYEE means that system plans to read
entire table EMPLOYEE in a block by block mode

Janusz R. Getta

CSCI317/MCS9317 Database Performance Tuning, SCSSE, Spring 2013

6. Tracing SQL statements

7/24/13 11:08 PM

"EXPLAINING" SQL statements

EXPLAIN PLAN statement
EXPLAIN PLAN FOR
SELECT ENAME, SALARY
FROM EMPLOYEE
WHERE E# = 007;
Query plan
-----------------------------------------------------SELECT STATEMENT
TABLE ACCESS BY INDEX ROWID EMPLOYEE
INDEX UNIQUE SCAN EMPLOYEE_PKEY
INDEX UNIQUE SCAN EMPLOYEE_PKEY means that system plans to
access and index EMPLOYEE_PKEY and with ROWID found to access
a table EMPLOYEE (TABLE ACCESS BY INDEX ROWID EMPLOYEE)
Janusz R. Getta

CSCI317/MCS9317 Database Performance Tuning, SCSSE, Spring 2013

6. Tracing SQL statements

7/24/13 11:08 PM

"EXPLAINING" SQL statements

EXPLAIN PLAN statement
EXPLAIN PLAN FOR
SELECT ENAME, SALARY
FROM EMPLOYEE NATURAL JOIN DEPARTMENT
WHERE BUDGET > 100000;
Query plan
-------------------------------------------------------------------SELECT STATEMENT
NESTED LOOPS
TABLE ACCESS FULL EMPLOYEE
TABLE ACCESS BY INDEX ROWID DEPARTMENT
INDEX UNIQUE SCAN DEPARTMENT_PKEY
The system plans to use a nested loop implementation of join operator (NESTED
LOOPS). With each row selected from EMPLOYEE and each value of attribute DNAME the
system plans to access and index over primary key of DEPARTMENT (INDEX UNIQUE
SCAN DEPARTMENT_PKEY ) and later on with ROWID found to access a table
DEPARTMENT (TABLE ACCESS BY INDEX ROWID DEPARTMENT) in order to join the
rows from EMPLOYEE and DEPARTMENT
Janusz R. Getta

CSCI317/MCS9317 Database Performance Tuning, SCSSE, Spring 2013

6. Tracing SQL statements

7/24/13 11:08 PM

"EXPLAINING" SQL statements

EXPLAIN PLAN statement
EXPLAIN PLAN FOR
SELECT ENAME, SALARY /*+ USE_HASH */
FROM EMPLOYEE NATURAL JOIN DEPARTMENT
WHERE BUDGET > 100000;
Query plan
-------------------------------------------------------------------SELECT STATEMENT
FILTER
HASH JOIN
TABLE ACCESS FULL DEPARTMENT
TABLE ACCESS FULL EMPLOYEE
The system plans to use a hash implementation of join operator (HASH JOIN) dues to
a hint /*+ USE_HASH */. The results of join will be filtered over a condition BUDGET
> 100000.

Janusz R. Getta

CSCI317/MCS9317 Database Performance Tuning, SCSSE, Spring 2013

6. Tracing SQL statements

7/24/13 11:08 PM

Using AUTOTRACE in SQL*Plus

SET AUTOTRACE statement of SQL*Plus
SET AUTOTRACE TRACEONLY; /* TRACEONLY skips the results of SELECT */
SELECT ENAME, SALARY
FROM EMPLOYEE
WHERE E# = 007;
Execution Plan
---------------------------------------------------------0
SELECT STATEMENT Optimizer=CHOOSE (Cost=1 Card=1 Bytes=12)
1
0
TABLE ACCESS (BY INDEX ROWID) OF 'EMPLOYEE' (Cost=1
Card=1 Bytes=12)
2

INDEX (UNIQUE SCAN) OF 'EMPLOYEE_PKEY' (UNIQUE)

Execution plan is the same as reported by EXPLAIN PLAN statement

Cost means the costs calculated by a cost-based optimizer
Card means the estimated number of rows accessed by the operation
Card means the estimated number of bytes accessed by the operation
Janusz R. Getta

CSCI317/MCS9317 Database Performance Tuning, SCSSE, Spring 2013

6. Tracing SQL statements

7/24/13 11:08 PM

Using AUTOTRACE in SQL*Plus

The results of tracing
Statistics
---------------------------------------------------------0 recursive calls
0 db block gets
1 consistent gets
0 physical reads
0 redo size
155 bytes sent via SQL*Net to client
270 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
0 rows processed

The number of recursive calls means the number of SQL statements

executed by the system in order to process a given SQL statements
The number of db block gets means the number of times a data block
was requested and read either from disk or data buffer cache without
checking transactional consistency
Janusz R. Getta

CSCI317/MCS9317 Database Performance Tuning, SCSSE, Spring 2013

6. Tracing SQL statements

7/24/13 11:08 PM

Using AUTOTRACE in SQL*Plus

The results of tracing
Statistics
---------------------------------------------------------0 recursive calls
0 db block gets
1 consistent gets
0 physical reads
0 redo size
155 bytes sent via SQL*Net to client
270 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
0 rows processed

The number of consistent gets means the number of times a consistent

read (with checking transactional consistency) either from disk or data
buffer cache was requested
The number of physical reads means the total number of data blocks
read from disk storage
Janusz R. Getta

CSCI317/MCS9317 Database Performance Tuning, SCSSE, Spring 2013

6. Tracing SQL statements

7/24/13 11:08 PM

Using AUTOTRACE in SQL*Plus

The results of tracing
Statistics
---------------------------------------------------------0 recursive calls
0 db block gets
1 consistent gets
0 physical reads
0 redo size
155 bytes sent via SQL*Net to client
270 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
0 rows processed

Redo size denotes the total amount of redo data generated in bytes by the
traced statement
The total number of SQL*Net roundtrips to/from client means the
total number of messages sent to and received from the client
The total number of rows processed means the number of rows
processed during the execution of the traced statement
Janusz R. Getta

CSCI317/MCS9317 Database Performance Tuning, SCSSE, Spring 2013

6. Tracing SQL statements

7/24/13 11:08 PM

Using SQL_TRACE in SQL

ALTER SESSION SET SQL_TRACE=TRUE statement
ALTER SESSION SET SQL_TRACE=TRUE;
SELECT ENAME, SALARY
FROM EMPLOYEE
WHERE E# = 007;
=====================
PARSING IN CURSOR #1 len=49 dep=0 uid=59 oct=3 lid=59 tim=619698093112
hv=595394454 ad='66ef9850'
SELECT ENAME, SALARY
FROM EMPLOYEE
WHERE E# = 007
END OF STMT
PARSE #1:c=15625,e=36140,p=4,cr=66,cu=0,mis=1,r=0,dep=0,og=4,tim=619698093107
EXEC #1:c=0,e=24,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=619698093207
FETCH #1:c=0,e=8740,p=1,cr=1,cu=0,mis=0,r=0,dep=0,og=4,tim=619698101989
*** 2004-07-12 13:43:13.000
A pretty cryptic trace is stored in a location determined by USER_DUMP_DEST in *.trc file

ALTER SESSION SET SQL_TRACE=FALSE;

Janusz R. Getta

CSCI317/MCS9317 Database Performance Tuning, SCSSE, Spring 2013

10

6. Tracing SQL statements

7/24/13 11:08 PM

Using SQL_TRACE in SQL

Using tkprof
SELECT ENAME, SALARY
FROM EMPLOYEE
WHERE E# = 007
call
count
------- -----Parse
1
Execute
1
Fetch
1
------- -----total
3

cpu
elapsed
disk
query
current
-------- ---------- ---------- ---------- ---------0.00
0.03
4
66
0
0.00
0.00
0
0
0
0.00
0.00
1
1
0
-------- ---------- ---------- ---------- ---------0.00
0.04
5
67
0

rows
---------0
0
0
---------0

Misses in library cache during parse: 1

Optimizer goal: CHOOSE
Parsing user id: 59

The execution statistics contain information about number of times Parse, Execute,
and Fetch occurred (column count), total CPU time spent, (column cpu), elapsed
time required (column elapsed), number of disk physical reads required (column
disk), number of reads in consistent (column query) or current (column current)
mode, and number of rows processed (column rows)
Janusz R. Getta

CSCI317/MCS9317 Database Performance Tuning, SCSSE, Spring 2013

11

6. Tracing SQL statements

7/24/13 11:08 PM

Using extended SQL trace

ALTER SESSION SET EVENTS'10046 trace name
context forever, level 8' statement
ALTER SESSION SET EVENTS '10046 trace name context forever, level 8'
SELECT ENAME, SALARY
FROM EMPLOYEE
WHERE E# = 007;
=====================
PARSING IN CURSOR #1 len=49 dep=0 uid=59 oct=3 lid=59 tim=818623840137 hv=595394454
ad='66ef7aa0'
SELECT ENAME, SALARY
FROM EMPLOYEE
WHERE E# = 007
END OF STMT
PARSE #1:c=0,e=31767,p=4,cr=66,cu=0,mis=1,r=0,dep=0,og=4,tim=818623840131
EXEC #1:c=0,e=24,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=818623840231
WAIT #1: nam='SQL*Net message to client' ela= 5 p1=1297371904 p2=1 p3=0
WAIT #1: nam='db file sequential read' ela= 8036 p1=11 p2=54093 p3=1
FETCH #1:c=0,e=8562,p=1,cr=1,cu=0,mis=0,r=0,dep=0,og=4,tim=818623848841
*** 2004-07-14 20:58:49.000
WAIT #1: nam='SQL*Net message from client' ela= 3 p1=1297371904 p2=1 p3=0

A pretty cryptic trace is stored in a location determined by USER_DUMP_DEST in *.trc file

ALTER SESSION SET EVENTS'10046 trace name context off'
Janusz R. Getta

CSCI317/MCS9317 Database Performance Tuning, SCSSE, Spring 2013

12

6. Tracing SQL statements

7/24/13 11:08 PM

Using extended SQL trace

The elements of extended trace
=====================
PARSING IN CURSOR #1 len=49 dep=0 uid=59 oct=3 lid=59 tim=818623840137 hv=595394454
ad='66ef7aa0'
SELECT ENAME, SALARY
FROM EMPLOYEE
WHERE E# = 007
END OF STMT
PARSE #1:c=0,e=31767,p=4,cr=66,cu=0,mis=1,r=0,dep=0,og=4,tim=818623840131
EXEC #1:c=0,e=24,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=818623840231
WAIT #1: nam='SQL*Net message to client' ela= 5 p1=1297371904 p2=1 p3=0
WAIT #1: nam='db file sequential read' ela= 8036 p1=11 p2=54093 p3=1
FETCH #1:c=0,e=8562,p=1,cr=1,cu=0,mis=0,r=0,dep=0,og=4,tim=818623848841
*** 2004-07-14 20:58:49.000
WAIT #1: nam='SQL*Net message from client' ela= 3 p1=1297371904 p2=1 p3=0

len=49 length of SQL statement

uid=59 user identifier
lid=59 privilege user id
hv=5 statement id

Janusz R. Getta

dep=0 so called "recursive depth"

oct=3 Oracle command type
tim=8 on some systems gettimeofday
ad='6 library cache address of the cursor

CSCI317/MCS9317 Database Performance Tuning, SCSSE, Spring 2013

13

6. Tracing SQL statements

7/24/13 11:08 PM

Using extended SQL trace

The elements of extended trace
=====================
PARSING IN CURSOR #1 len=49 dep=0 uid=59 oct=3 lid=59 tim=818623840137 hv=595394454
ad='66ef7aa0'
SELECT ENAME, SALARY
FROM EMPLOYEE
WHERE E# = 007
END OF STMT
PARSE #1:c=0,e=31767,p=4,cr=66,cu=0,mis=1,r=0,dep=0,og=4,tim=818623840131
EXEC #1:c=0,e=24,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=818623840231
WAIT #1: nam='SQL*Net message to client' ela= 5 p1=1297371904 p2=1 p3=0
WAIT #1: nam='db file sequential read' ela= 8036 p1=11 p2=54093 p3=1
FETCH #1:c=0,e=8562,p=1,cr=1,cu=0,mis=0,r=0,dep=0,og=4,tim=818623848841
*** 2004-07-14 20:58:49.000
WAIT #1: nam='SQL*Net message from client' ela= 3 p1=1297371904 p2=1 p3=0

c=0 total CPU time consumed

e=31767 amount of elapsed time
p=4 number of blocks from reads
cu=0 number of blocks read in consistent mode
mis=1 number of library cache misses r=0 number of rows returned
dep=0 so called "recursive depth" og=4 optimizer goal (4 means CHOOSE)
tim=8 on some systems gettimeofday

Janusz R. Getta

CSCI317/MCS9317 Database Performance Tuning, SCSSE, Spring 2013

14

6. Tracing SQL statements

7/24/13 11:08 PM

Using extended SQL trace

The elements of extended trace
=====================
PARSING IN CURSOR #1 len=49 dep=0 uid=59 oct=3 lid=59 tim=818623840137 hv=595394454
ad='66ef7aa0'
SELECT ENAME, SALARY
FROM EMPLOYEE
WHERE E# = 007
END OF STMT
PARSE #1:c=0,e=31767,p=4,cr=66,cu=0,mis=1,r=0,dep=0,og=4,tim=818623840131
EXEC #1:c=0,e=24,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=818623840231
WAIT #1: nam='SQL*Net message to client' ela= 5 p1=1297371904 p2=1 p3=0
WAIT #1: nam='db file sequential read' ela= 8036 p1=11 p2=54093 p3=1
FETCH #1:c=0,e=8562,p=1,cr=1,cu=0,mis=0,r=0,dep=0,og=4,tim=818623848841
*** 2004-07-14 20:58:49.000
WAIT #1: nam='SQL*Net message from client' ela= 3 p1=1297371904 p2=1 p3=0

nam='S name of "wait" event

ela= 5 elapsed time (in microseconds)
p1=1 , p2=1, p3=0 the names of parameters obtained from:
SELECT NAME, PARAMETER1, PARAMETER2, PARAMETER3
FROM V$EVENT_NAME
ORDER BY NAME;

Janusz R. Getta

CSCI317/MCS9317 Database Performance Tuning, SCSSE, Spring 2013

15

6. Tracing SQL statements

7/24/13 11:08 PM

References
G. Harrison Oracle Performance Survival Guide, Prentice
Hall, 2010
C. Millsap, Optimizing Oracle Performance, O'Reilly and Assoc., 2003,
chapters 5, 6 (UoW Library)
C. Antognini,Troubleshooting Oracle Performance, Apress, 2008

Janusz R. Getta

CSCI317/MCS9317 Database Performance Tuning, SCSSE, Spring 2013

16