Call now: 252-767-6166  
Oracle Training Oracle Support Development Oracle Apps

 
 Home
 E-mail Us
 Oracle Articles


 Oracle Training
 Oracle Tips

 Oracle Forum
 Class Catalog


 Remote DBA
 Oracle Tuning
 Emergency 911
 RAC Support
 Apps Support
 Analysis
 Design
 Implementation
 Oracle Support


 SQL Tuning
 Security

 Oracle UNIX
 Oracle Linux
 Monitoring
 Remote s
upport
 Remote plans
 Remote
services
 Application Server

 Applications
 Oracle Forms
 Oracle Portal
 App Upgrades
 SQL Server
 Oracle Concepts
 Software Support

 Remote S
upport  
 Development  

 Implementation


 Consulting Staff
 Consulting Prices
 Help Wanted!

 


 Oracle Posters
 Oracle Books

 Oracle Scripts
 Ion
 Excel-DB  

Don Burleson Blog 


 

 

 


 

 

 
 

Trace Example


Oracle Tips by Burleson Consulting

 

The following Tip is from the outstanding book "Oracle PL/SQL Tuning: Expert Secrets for High Performance Programming" by Dr. Tim Hall, Oracle ACE of the year, 2006:

The sql_trace_test.sql script creates a test table and the procedure that populates it.   This procedure is the subject of the example trace.

sql_trace_test.sql

CREATE TABLE sql_trace_test (
  id  NUMBER,
  description  VARCHAR2(50)
);

EXEC DBMS_STATS.gather_table_stats('test', 'sql_trace_test');

CREATE OR REPLACE PROCEDURE populate_sql_trace_test (p_loops  IN  NUMBER) AS
  l_number  NUMBER;
BEGIN
  FOR i IN 1 .. p_loops LOOP
    INSERT INTO sql_trace_test (id, description)
    VALUES (i, 'Description for ' || i);
  END LOOP; 

  SELECT COUNT(*)
  INTO   l_number
  FROM   sql_trace_test; 

  COMMIT; 

  DBMS_OUTPUT.put_line(l_number || ' rows inserted.');
END;
/
SHOW ERRORS

Gathering the statistics on the empty table may seem odd, but this prevents any dynamic sampling being added to the trace file contents, which would only serve to complicate the file.

Before the procedure is traced, the trace file that will be produced should be identified.  The name of the trace file is based on the current value of the user_dump_dest, the sessionís process id and the instance name.  The identify_trace_file.sql script combines these values to produce the expected trace file name.

identify_trace_file.sql

SET LINESIZE 100
COLUMN trace_file FORMAT A60

SELECT s.sid,
       s.serial#,
       pa.value || '/' || LOWER(SYS_CONTEXT('userenv','instance_name')) ||   
       '_ora_' || p.spid || '.trc' AS trace_file
FROM   v$session s,
       v$process p,
       v$parameter pa
WHERE  pa.name = 'user_dump_dest'
AND    s.paddr = p.addr
AND    s.audsid = SYS_CONTEXT('USERENV', 'SESSIONID');

If a windows environment is being used, the "/" will need to be altered to a "\" in the concatenated string.  The expected output from this script is displayed below.

SQL> @identify_trace_file.sql

       SID    SERIAL# TRACE_FILE
---------- ---------- ------------------------------------------------------------
       130      26739 /u01/app/oracle/admin/DEV/udump/dev1_ora_367660.trc

1 row selected.

Now that the name of the trace file is known, tracing can be enabled, the procedure executed and tracing disabled.

SQL> ALTER SESSION SET EVENTS '10046 trace name context forever, level 8';

Session altered.

SQL> SET SERVEROUTPUT ON
SQL> EXEC populate_sql_trace_test(p_loops => 5);
5 rows inserted.

PL/SQL procedure successfully completed.

SQL> ALTER SESSION SET EVENTS '10046 trace name context off';

Session altered.

SQL>

The contents of the file are listed below.  The output looks a little confusing, but the individual statements and their associated waits and statistics can be identified.

/u01/app/oracle/admin/DEV/udump/dev1_ora_367660.trc
Oracle Database 10g Enterprise Edition Release 10.1.0.3.0 - Production
With the Partitioning, Oracle Label Security, OLAP and Data Mining options
ORACLE_HOME = /u01/app/oracle/product/10.1.0/db_1
System name:      OSF1
Node name:  odba05.lynx.co.uk
Release:    V5.1
Version:    2650
Machine:    alpha
Instance name: DEV1
Redo thread mounted by this instance: 1
Oracle process number: 16
Unix process pid: 367660, image: oracleDEV1@odba05.lynx.co.uk

*** 2005-04-05 09:46:51.499
*** ACTION NAME:() 2005-04-05 09:46:51.499
*** MODULE NAME:(SQL*Plus) 2005-04-05 09:46:51.499
*** SERVICE NAME:(SYS$USERS) 2005-04-05 09:46:51.499
*** SESSION ID:(130.26739) 2005-04-05 09:46:51.499
=====================
PARSING IN CURSOR #29 len=68 dep=0 uid=180 oct=42 lid=180 tim=11746409761792 hv=3847243385 ad='2bb57798'
ALTER SESSION SET EVENTS '10046 trace name context forever, level 8'
END OF STMT
EXEC #29:c=0,e=1024,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=11746409761792
WAIT #29: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #29: nam='SQL*Net message from client' ela= 7358464 p1=1413697536 p2=1 p3=0
=====================
PARSING IN CURSOR #4 len=36 dep=0 uid=180 oct=47 lid=180 tim=11746417122304 hv=3425213768 ad='2c631cd8'
BEGIN DBMS_OUTPUT.ENABLE(2000); END;
END OF STMT
PARSE #4:c=0,e=1024,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=11746417122304
EXEC #4:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=11746417122304
WAIT #4: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #4: nam='SQL*Net message from client' ela= 6924288 p1=1413697536 p2=1 p3=0
=====================
PARSING IN CURSOR #18 len=51 dep=0 uid=180 oct=47 lid=180 tim=11746424051712 hv=2083693016 ad='27ecb338'
BEGIN populate_sql_trace_test(p_loops => 5); END;
END OF STMT
PARSE #18:c=0,e=3072,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=11746424051712
=====================
PARSING IN CURSOR #19 len=86 dep=1 uid=180 oct=2 lid=180 tim=11746424052736 hv=3247833140 ad='28fa57f8'
INSERT INTO SQL_TRACE_TEST (ID, DESCRIPTION) VALUES (:B1 , 'Description for ' || :B1 )
END OF STMT
PARSE #19:c=0,e=1024,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=11746424052736
=====================
PARSING IN CURSOR #23 len=69 dep=2 uid=0 oct=3 lid=0 tim=11746424053760 hv=1471956217 ad='2e7591f0'
select con#,obj#,rcon#,enabled,nvl(defer,0) from cdef$ where robj#=:1
END OF STMT
PARSE #23:c=0,e=1024,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=4,tim=11746424053760
EXEC #23:c=0,e=5120,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=4,tim=11746424059904
FETCH #23:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424059904
=====================
PARSING IN CURSOR #25 len=146 dep=2 uid=0 oct=3 lid=0 tim=11746424065024 hv=2107929772 ad='2e7b4b08'
select
con#,type#,condlength,intcols,robj#,rcon#,match#,refact,nvl(enabled,0),rowid,cols,nvl(defer,0),mtime,nvl(spare1,0)
from cdef$ where obj#=:1
END OF STMT
PARSE #25:c=0,e=5120,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=4,tim=11746424065024
=====================
PARSING IN CURSOR #27 len=210 dep=3 uid=0 oct=3 lid=0 tim=11746424102912 hv=864012087 ad='2e351f08'
select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#, sample_size, minimum, maximum, distcnt,
lowval, hival, density, col#, spare1, spare2, avgcln from hist_head$ where obj#=:1 and intcol#=:2
END OF STMT
PARSE #27:c=50000,e=36864,p=0,cr=0,cu=0,mis=1,r=0,dep=3,og=3,tim=11746424102912
EXEC #27:c=16667,e=4096,p=0,cr=0,cu=0,mis=1,r=0,dep=3,og=3,tim=11746424108032
FETCH #27:c=0,e=1024,p=0,cr=3,cu=0,mis=0,r=1,dep=3,og=3,tim=11746424109056
EXEC #27:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=3,tim=11746424109056
FETCH #27:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=3,og=3,tim=11746424109056
EXEC #27:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=3,tim=11746424110080
FETCH #27:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=3,og=3,tim=11746424110080
=====================
PARSING IN CURSOR #28 len=121 dep=3 uid=0 oct=3 lid=0 tim=11746424119296 hv=3150898423 ad='2e347db8'
select /*+ rule */ bucket, endpoint, col#, epvalue from histgrm$ where obj#=:1 and intcol#=:2 and row#=:3 order by
bucket
END OF STMT
PARSE #28:c=0,e=9216,p=0,cr=0,cu=0,mis=1,r=0,dep=3,og=3,tim=11746424119296
EXEC #28:c=0,e=1024,p=0,cr=0,cu=0,mis=1,r=0,dep=3,og=3,tim=11746424121344
FETCH #28:c=0,e=1024,p=0,cr=3,cu=0,mis=0,r=3,dep=3,og=3,tim=11746424122368
EXEC #27:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=3,tim=11746424122368
FETCH #27:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=3,og=3,tim=11746424122368
EXEC #27:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=3,tim=11746424123392
FETCH #27:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=3,og=3,tim=11746424123392
EXEC #25:c=83334,e=61440,p=0,cr=18,cu=0,mis=1,r=0,dep=2,og=4,tim=11746424126464
FETCH #25:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424126464
=====================
PARSING IN CURSOR #12 len=169 dep=2 uid=0 oct=3 lid=0 tim=11746424128512 hv=1173719687 ad='2e7c2c50'
select col#, grantee#, privilege#,max(mod(nvl(option$,0),2)) from objauth$ where obj#=:1 and col# is not null
group by privilege#, col#, grantee# order by col#, grantee#
END OF STMT
PARSE #12:c=0,e=1024,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=4,tim=11746424128512
EXEC #12:c=0,e=3072,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=4,tim=11746424131584
FETCH #12:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424131584
=====================
PARSING IN CURSOR #26 len=151 dep=2 uid=0 oct=3 lid=0 tim=11746424131584 hv=4139184264 ad='2e7cc608'
select grantee#,privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 group by
grantee#,privilege#,nvl(col#,0) order by grantee#
END OF STMT
PARSE #26:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424131584
EXEC #26:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424131584
FETCH #26:c=0,e=1024,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424132608
=====================
PARSING IN CURSOR #7 len=175 dep=2 uid=0 oct=3 lid=0 tim=11746424132608 hv=1729330152 ad='2f3597a8'
select u.name,o.name, t.update$, t.insert$, t.delete$, t.enabled  from obj$ o,user$ u,trigger$ t  where
t.baseobject=:1 and t.obj#=o.obj# and o.owner#=u.user#  order by o.obj#
END OF STMT
PARSE #7:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424132608
EXEC #7:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424132608
FETCH #7:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424132608
STAT #7 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=2 pr=0 pw=0 time=0 us)'
STAT #7 id=2 cnt=0 pid=1 pos=1 obj=0 op='NESTED LOOPS  (cr=2 pr=0 pw=0 time=0 us)'
STAT #7 id=3 cnt=0 pid=2 pos=1 obj=0 op='NESTED LOOPS  (cr=2 pr=0 pw=0 time=0 us)'
STAT #7 id=4 cnt=0 pid=3 pos=1 obj=84 op='TABLE ACCESS BY INDEX ROWID TRIGGER$ (cr=2 pr=0 pw=0 time=0 us)'
STAT #7 id=5 cnt=0 pid=4 pos=1 obj=128 op='INDEX RANGE SCAN I_TRIGGER1 (cr=2 pr=0 pw=0 time=0 us)'
STAT #7 id=6 cnt=0 pid=3 pos=2 obj=18 op='TABLE ACCESS BY INDEX ROWID OBJ$ (cr=0 pr=0 pw=0 time=0 us)'
STAT #7 id=7 cnt=0 pid=6 pos=1 obj=36 op='INDEX UNIQUE SCAN I_OBJ1 (cr=0 pr=0 pw=0 time=0 us)'
STAT #7 id=8 cnt=0 pid=2 pos=2 obj=22 op='TABLE ACCESS CLUSTER USER$ (cr=0 pr=0 pw=0 time=0 us)'
STAT #7 id=9 cnt=0 pid=8 pos=1 obj=11 op='INDEX UNIQUE SCAN I_USER# (cr=0 pr=0 pw=0 time=0 us)'
EXEC #19:c=83334,e=86016,p=0,cr=29,cu=21,mis=1,r=1,dep=1,og=1,tim=11746424138752
EXEC #19:c=0,e=0,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=11746424138752
EXEC #19:c=0,e=0,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=11746424138752
EXEC #19:c=0,e=0,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=11746424139776
EXEC #19:c=0,e=0,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=11746424139776
=====================
PARSING IN CURSOR #29 len=35 dep=1 uid=180 oct=3 lid=180 tim=11746424140800 hv=3788777626 ad='2c84eb58'
SELECT COUNT(*) FROM SQL_TRACE_TEST
END OF STMT
PARSE #29:c=0,e=1024,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=11746424140800
EXEC #29:c=0,e=1024,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=11746424141824
FETCH #29:c=0,e=0,p=0,cr=7,cu=0,mis=0,r=1,dep=1,og=1,tim=11746424141824
=====================
PARSING IN CURSOR #4 len=6 dep=1 uid=180 oct=44 lid=180 tim=11746424141824 hv=255718823 ad='2e5363f0'
COMMIT
END OF STMT
PARSE #4:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=11746424141824
XCTEND rlbk=0, rd_only=0
EXEC #4:c=0,e=0,p=0,cr=0,cu=1,mis=0,r=0,dep=1,og=1,tim=11746424141824
EXEC #18:c=83334,e=91136,p=0,cr=36,cu=26,mis=0,r=1,dep=0,og=1,tim=11746424142848
WAIT #18: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #18: nam='SQL*Net message from client' ela= 1024 p1=1413697536 p2=1 p3=0
=====================
PARSING IN CURSOR #7 len=52 dep=0 uid=180 oct=47 lid=180 tim=11746424143872 hv=1029988163 ad='2c2ec1b8'
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
END OF STMT
PARSE #7:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=11746424143872
WAIT #7: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
EXEC #7:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=11746424144896
WAIT #7: nam='SQL*Net message from client' ela= 8560640 p1=1413697536 p2=1 p3=0
=====================
PARSING IN CURSOR #12 len=55 dep=0 uid=180 oct=42 lid=180 tim=11746432706560 hv=2655499671 ad='2a24eab8'
ALTER SESSION SET EVENTS '10046 trace name context off'
END OF STMT
PARSE #12:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=11746432705536
EXEC #12:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=11746432706560

The following command uses the tkprof utility to translate the trace file, placing the translated output in the translated.txt file.  The explain and table parameters have been set to allow execution plans to be displayed, and the sys parameter prevents recursive SQL being displayed.

$ cd /u01/app/oracle/admin/DEV/udump/
$ tkprof dev1_ora_367660.trc translated.txt explain=test/test table=sys.plan_table sys=no waits=yes

TKPROF: Release 10.1.0.3.0 - Production on Tue Apr 5 09:22:43 2005

Copyright (c) 1982, 2004, Oracle.  All rights reserved.
$

The contents of the translated file are displayed below.

TKPROF: Release 10.1.0.3.0 - Production on Tue Apr 5 09:53:50 2005

Copyright (c) 1982, 2004, Oracle.  All rights reserved.

Trace file: dev1_ora_367660.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
********************************************************************************

ALTER SESSION SET EVENTS '10046 trace name context forever, level 8'

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        1      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 180  (TEST)

Elapsed times include waiting on following events:

  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        7.35          7.35
********************************************************************************

BEGIN DBMS_OUTPUT.ENABLE(2000); END;

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           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 180  (TEST)

Elapsed times include waiting on following events:

  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        6.92          6.92
********************************************************************************

BEGIN populate_sql_trace_test(p_loops => 5); END;

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           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 180  (TEST)

Elapsed times include waiting on following events:

  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        0.00          0.00
********************************************************************************

INSERT INTO SQL_TRACE_TEST (ID, DESCRIPTION)
VALUES
 (:B1 , 'Description for ' || :B1 )

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      5      0.00       0.00          0          1         25           5
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        6      0.00       0.00          0          1         25           5

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 180  (TEST)   (recursive depth: 1)

Rows     Execution Plan
-------  ---------------------------------------------------
      0  INSERT STATEMENT   MODE: ALL_ROWS

********************************************************************************

SELECT COUNT(*)
FROM
 SQL_TRACE_TEST

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          7          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.00          0          7          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 180  (TEST)   (recursive depth: 1)

Rows     Execution Plan
-------  --------------------------------------------
-------
      0  SELECT STATEMENT   MODE: ALL_ROWS
      0   SORT (AGGREGATE)
      0    TABLE ACCESS   MODE: ANALYZED (FULL) OF 'SQL_TRACE_TEST'
               (TABLE)

********************************************************************************

COMMIT

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          1           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          1           0

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 180  (TEST)   (recursive depth: 1)
********************************************************************************


BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;

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           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 180  (TEST)

Elapsed times include waiting on following events:

  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        8.56          8.56
********************************************************************************

ALTER SESSION SET EVENTS '10046 trace name context off'

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        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 180  (TEST)

********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        4      0.00       0.00          0          0          0           0
Execute      5      0.00       0.00          0          0          0           3
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        9      0.00       0.00          0          0          0           3

Misses in library cache during parse: 1

Elapsed times include waiting on following events:

  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       4        0.00          0.00
  SQL*Net message from client                     4        8.56         22.84

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       10      0.05       0.05          0          0          0           0
Execute     18      0.03       0.03          0          1         26           5
Fetch       12      0.00       0.00          0         35          0           9
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       40      0.08       0.08          0         36         26          14

Misses in library cache during parse: 7
Misses in library cache during execute: 6

    8  user  SQL statements in session.
    7  internal SQL statements in session.
   15  SQL statements in session.
    2  statements EXPLAINed in this session.
********************************************************************************

Trace file: dev1_ora_367660.trc
Trace file compatibility: 10.01.00
Sort options: default

       1  session in tracefile.
       8  user  SQL statements in trace file.
       7  internal SQL statements in trace file.
      15  SQL statements in trace file.
      15  unique SQL statements in trace file.
       2  SQL statements EXPLAINed using schema:
           sys.plan_table
             Schema was specified.
             Existing table was used.
     146  lines in trace file.
      22  elapsed seconds in trace file.

For each statement executed by the session, the file contains a record of the parse, execute and fetch statistics, an execution plan where necessary and a list of session waits.

The next section presents alternate methods for checking the execution plans of SQL statements.

 

This is an excerpt from the bestselling book "Oracle PL/SQL Tuning: Expert Secrets for High Performance Programming" by Dr. Tim Hall, Oracle ACE of the year, 2006.

You can buy the book for only $23.95 (30%-off) when you buy directly from the publisher, and you also get instant access to the code depot of PL/SQL tuning scripts:


 

 
��  
 
 

 
 
 
 
oracle dba poster
 

 
 
Oracle performance tuning software 
 
Oracle Linux poster
 
 
 

 

Burleson is the American Team

Note: This Oracle documentation was created as a support and Oracle training reference for use by our DBA performance tuning consulting professionals.  Feel free to ask questions on our Oracle forum.

Verify experience! Anyone considering using the services of an Oracle support expert should independently investigate their credentials and experience, and not rely on advertisements and self-proclaimed expertise. All legitimate Oracle experts publish their Oracle qualifications.

Errata?  Oracle technology is changing and we strive to update our BC Oracle support information.  If you find an error or have a suggestion for improving our content, we would appreciate your feedback.  Just  e-mail:  and include the URL for the page.


                    









Burleson Consulting

The Oracle of Database Support

Oracle Performance Tuning

Remote DBA Services


 

Copyright © 1996 -  2014

All rights reserved by Burleson

Oracle © is the registered trademark of Oracle Corporation.