SQL Trace and TKPROF
SQL Trace and TKPROF, Accrately assess the efficiency of the SQL Stat. an application runs.
SQL Trace:
Trace facility provide performance information on individual SQL Stat... It’s generating the following stat. for each stat.
1. Parse, execute and fetch counts
2. CPI and Elapsed Times
3. Physical Reads and logical Reads
4. Number of rows processed
5. Misses on the library cache
6. Username under which each parse occurred
7. Each commit and rollback
8. Wait event for each SQL Statement and a summary for each trace file.
TKPROF :
If you run TKPROF program to format the contents of the trace file and place the output into a readable output file
1. Create a SQL Script that stores the statistics in the database.
2. Determine the execution plan of SQL Stat.
Initialization Parameter to check before enables SQL Trace:
1. TIMED_STATISTICS = TRUE
2. MAX_DUMP_FILE_SIZE = 500 (By default)
3. USER_DUMP_DEST
4. SQL_TRACE= TRUE
DBMS_SESSION.SET_SQL_TRACE Procedure or
ALTER SESSION SET SQL_TRACE=TRUE
Identify Trace file:
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');
Output :
SID SERIAL#
---------- ----------
TRACE_FILE
--------------------------------------------------------------------------------
159 3
F:\ORACLE\PRODUCT\10.2.0\ADMIN\KEYSTONE\UDUMP/keystone_ora_4788.trc
Execute TKPROF Tool:
F:\oracle\product\10.2.0\admin\KEYSTONE\udump>tkprof keystone_ora_4788.trc babu1.txt explain=babu/babu TABLE=babu.plan_table sys=no waits=yes
TKPROF: Release 10.2.0.1.0 - Production on Mon Jun 11 18:35:52 2007
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Babu1.txt file output:
TKPROF: Release 10.2.0.1.0 - Production on Mon Jun 11 18:49:51 2007
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Trace file: keystone_ora_4788.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 statements encountered a error during parse:
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')
Error encountered: ORA-00936
--------------------------------------------------------------------------------
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');
Error encountered: ORA-00911
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 10 0.20 0.32 0 0 0 0
Execute 11 0.00 0.04 0 0 0 0
Fetch 16 0.03 0.07 0 0 0 19
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 37 0.23 0.44 0 0 0 19
Misses in library cache during parse: 7
Misses in library cache during execute: 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 5 0.00 0.00
SQL*Net message from client 4 1208.32 1208.43
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 7 0.00 0.03 0 0 0 0
Execute 12 0.03 0.09 0 0 0 0
Fetch 12 0.00 0.01 1 29 0 5
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 31 0.03 0.14 1 29 0 5
Misses in library cache during parse: 5
Misses in library cache during execute: 3
11 user SQL statements in session.
14 internal SQL statements in session.
25 SQL statements in session.
0 statements EXPLAINed in this session.
********************************************************************************
Trace file: keystone_ora_4788.trc
Trace file compatibility: 10.01.00
Sort options: default
1 session in tracefile.
11 user SQL statements in trace file.
14 internal SQL statements in trace file.
25 SQL statements in trace file.
13 unique SQL statements in trace file.
435 lines in trace file.
3839 elapsed seconds in trace file.
Thanks & Regards
Babu B
