We saw how to enable trace in an earlier post. The trace files obtained from the method is in raw form which can be converted into a more readable format using the tkprof utility in Oracle (Transient Kernel PROFile utility)
tkprof utility in Oracle
- TKPROF is a tool for producing formatted reports from SQL Trace files (also known as event 10046 trace files).
- Each SQL (and PL/SQL) statement appearing in the trace file has its information summarized and collected in one place in the TKPROF report.
- This information includes: the number of parse, execution & fetch operations, total CPU & elapsed times, buffers read in consistent (query) and current mode, blocks read from disk and row counts, Row Source operations, execution plans, library cache misses, parsing user id & optimizer mode
- The most important part of tkprof is the sort option. This helps us identify the most resource-intensive SQL statements and helps target efficiently the SQL tuning process
The syntax is given below
tkprof Usage: tkprof tracefile outputfile [explain= ] [table= ] [print= ] [insert= ] [sys= ] [sort= ] table=schema.tablename Use 'schema.tablename' with 'explain=' option. explain=user/password Connect to ORACLE and issue EXPLAIN PLAN. print=integer List only the first 'integer' SQL statements. aggregate=yes|no insert=filename List SQL statements and data inside INSERT statements. sys=no TKPROF does not list SQL statements run as user SYS. record=filename Record non-recursive statements found in the trace file. waits=yes|no Record summary for any wait events found in the trace file. sort=option Set of zero or more of the following sort options: prscnt number of times parse was called prscpu CPU time parsing prsela elapsed time parsing prsdsk number of disk reads during parse prsqry number of buffers for consistent read during parseprscu number of buffers for current read during parseprsmis number of misses in library cache during parseexecnt number of execute was called execpu CPU time spent executing exeela elapsed time executing exedsk number of disk reads during execute exeqry number of buffers for consistent read during execute execu number of buffers for current read during execute exerow number of rows processed during execute exemis number of library cache misses during execute fchcnt number of times fetch was called fchcpu cpu time spent fetching fchela elapsed time fetching fchdsk number of disk reads during fetch fchqry number of buffers for consistent read during fetch fchcu number of buffers for current read during fetch fchrow number of rows fetched userid userid of user that parsed the cursor
Since we are usually interested in tuning statements that take more time to run as time is the most important property in the tuning, so most commonly used sort options are the ones ordering according to elapsed times consumed for the parse, execute, and fetch phases
sort=prsela,exeela,fchela
tkprof examples
tkprof file.trc file.txt sys=no explain=userid/password sort=prsela,exeela,fchela tkprof file.trc file.txt sys=no explain=userid/password sort=prsela,exeela,fchela tkprof file.trc file.txt sys=no tkprof file.trc file.txt sys=no explain=userid/password sort=prsela,exeela,fchela This print 10 sql only tkprof .trc elaps.prf sys=no explain=apps/ sort=(prsela,exeela,fchela) print=10 This print all the sql tkprof .trc elaps.prf sys=no explain=apps/apps sort=prsela,exeela,fchela
Example content of tkprof file
TKPROF: Release 11.2.0.4.0 - Production on Tue Jan 17 14:12:41 2013 Copyright (c) 1982, 2007, Oracle. All rights reserved. Trace file: TEST_ora_15941.trc Sort options: execpu fchcpu ******************************************************************************** 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 ******************************************************************************** SQL ID: 6w82ggrtysx Plan Hash: 2325776775 SELECT FUNCTION_NAME FROM FND_USER_DESKTOP_OBJECTS WHERE USER_ID = :b1 AND APPLICATION_ID = :b2 AND RESPONSIBILITY_ID = :b3 AND TYPE = 'FUNCTION' AND ROWNUM <= 10 ORDER BY SEQUENCE 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 2 0.00 0.00 0 4 0 1 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 4 0.00 0.00 0 4 0 1 Misses in library cache during parse: 0 Optimizer mode: ALL_ROWS Parsing user id: 173 (APPS) Number of plan statistics captured: 1 Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 SORT ORDER BY (cr=4 pr=0 pw=0 time=0 us cost=6 size=41 card=1) 1 1 1 COUNT STOPKEY (cr=4 pr=0 pw=0 time=0 us) 1 1 1 TABLE ACCESS BY INDEX ROWID FND_USER_DESKTOP_OBJECTS (cr=4 pr=0 pw=0 time=0 us cost=5 size=41 card=1) 1 1 1 INDEX RANGE SCAN FND_USER_DESKTOP_OBJECTS_N1 (cr=3 pr=0 pw=0 time=0 us cost=3 size=0 card=3)(object id 33596) Rows Execution Plan ------- --------------------------------------------------- 0 SELECT STATEMENT MODE: ALL_ROWS 1 SORT (ORDER BY) 1 COUNT (STOPKEY) 1 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF 'FND_USER_DESKTOP_OBJECTS' (TABLE) 1 INDEX MODE: ANALYZED (RANGE SCAN) OF 'FND_USER_DESKTOP_OBJECTS_N1' (INDEX) 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 5 0.00 0.00******************************************************************************** SQL ID: 276ut2ywqux Plan Hash: 3856112528 select object_name, icon_name from fnd_desktop_objects 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 3 0.00 0.00 0 6 0 47 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 5 0.00 0.00 0 6 0 47 Misses in library cache during parse: 0 Optimizer mode: ALL_ROWS Parsing user id: 173 (APPS) Number of plan statistics captured: 1 Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 47 47 47 TABLE ACCESS FULL FND_DESKTOP_OBJECTS (cr=6 pr=0 pw=0 time=0 us cost=2 size=1175 card=47) Rows Execution Plan ------- --------------------------------------------------- 0 SELECT STATEMENT MODE: ALL_ROWS 47 TABLE ACCESS MODE: ANALYZED (FULL) OF 'FND_DESKTOP_OBJECTS' (TABLE)
Oracle trcsess utility
- When using shared server sessions, many processes are involved. The trace pertaining to the user session is scattered across different trace files belonging to different processes. This makes it difficult to get a complete picture of the life cycle of a session.
- The trcsess utility consolidates trace output from selected trace files based on several criteria
trcsess [output=output_file_name] [session=session_id] [clientid=client_id] [service=service_name] [action=action_name] [module=module_name] [trace_files] trcsess output=main.trc service=TEST *trc
After the consolidated trace file has been generated you can execute tkprof on it.
Related Articles
SQL trace : SQL trace or 10046 event is being used to trace the session activity in Oracle.
Autotrace in oracle : Autotrace in Oracle, What is autotrace, how to set up it, Understanding Autotrace Output, Autotrace options, statistics displayed by autotrace
sql tuning advisor: How to run sql tuning advisor for SQL_ID in the Cursor cache, how is the sql tuning task created and executed to get the recommendation
Hanganalyze: check out how to take system state dump in Oracle, hanganalyze in Oracle, what is v$wait_chains, and how it can help find the blocking
How to generate FRD trace in Oracle Apps: How to generate Forms runtime diagnostics trace in Oracle apps 11i/R12
How to generate tkprof in EBS in 19c
