Oracle TKPROF & SQLTRACE Trace Plustrace

Oracle TKPROF & SQL_TRACE

Version 11.1

General Information

Note: Use "dbms_monitor.session_trace_enable()" instead of "alter session set events ..." and you will see the columns sys.gv_$session updated

TKPROF stands for Transient Kernel Profiler

Event Numbering Range

10000 - 10999

Event Definitions

Event #	Level	Description
8186	-	ALTER SESSION SET EVENTS '8186 trace name context OFF' - VERSIONS BETWEEN query
10013	1	Monitor Transaction Recovery
10015	1	Dump Undo Segment Headers
10015	3	Identify corrupt undo segments
10032	4	Dump Sort Statistics
10031		Sort Debug Events
10032	10	Dump Sort Statistics
10033	4	Dump Sort Large Run Statistics (blocks dumped to disk and read back) - poss. no levels.
10033	10	Dump Sort Intermediate Run Statistics
10045	1	Trace Free List Management Operations
10046	0	No statistics generated
10046	1	Standard trace output including parsing, executes and fetches plus more
10046	2	Same as Level 1
10046	4	Level 1 + Bind Variables
10046	8	Level 1 + Waits
10046	12	Level 1 + Bind Variables & Waits
10053	1	Dump Optimizer Statistics and Computations
10053	2	Dump Optimizer Computations only
10060	1	Dump Predicates
10065	1	Restrict Library Cache Output for State Object Dumps - Library Objects Only
10065	2	Restrict Library Cache Output for State Object Dumps + library object lock details
10065	3	Restrict Library Cache Output for State Object Dumps + library object handle and library object
10079	2	Dump SQL*Net Statistics
10081	1	Dump High Water Mark Changes
10104	10	Dump Hash Join Statistics
10128	1	Dump Partition Pruning Information
10128	2	Dump partition iterators
10128	4	Dump optimizer decisions about partition-wise joins
10128	8	Dump ROWID range scan pruning information
10132	12	Dumps SQL statements into UDUMP along with the actual execution plan
10200	1	Dump Consistent Reads
10201	1	Dump Consistent Read Undo Application
10210	10	Table Integrity Check
10211	10	Index Integrity Check
10220	1	Dump Changes to Undo Header
10221	7	Dump Undo Changes
10224	1	Dump Index Block Splits / Deletes
10225	1	Dump Changes to Dictionary Managed Extents
10231	10	Causes full table scans to skip corrupt blocks, rather than fail with an ORA-1578 error
10232	10	Causes corrupt blocks to be dumped to the process trace file
10233	10	Traces memory usage statistics
10235	1	Check memory manager internal structures (use with ORA-600/ORA-7445 errors)
10241	1	Dump Remote SQL Execution
10246	1	Trace PMON Process
10248	10	Trace Dispatcher Processes
10249	10	Trace Shared Server (MTS) Processes
10270	10	Debug Shared Cursors
10289	1	Dump a database block in hexadecimal
10299	1	Debug Prefetch
10357	1	Debug Direct Path
10359	1	Stops writes to the control file during NOLOGGING operations: May substantially improve performance
10390	0x0001	Dump Parallel Execution Slave Statistics - Slave-side execution messages
10390	0x0002	Dump Parallel Execution Slave Statistics - Coordinator-side execution messages
10390	0x0004	Dump Parallel Execution Slave Statistics - Slave context state changes
10390	0x0008	Dump Parallel Execution Slave Statistics - Slave ROWID range bind variables and xty
10390	0x0010	Dump Parallel Execution Slave Statistics - Slave fetched rows as enqueued to TQ
10390	0x0020	Dump Parallel Execution Slave Statistics - Coordinator wait reply handling
10390	0x0040	Dump Parallel Execution Slave Statistics - Coordinator wait message buffering
10390	0x0080	Dump Parallel Execution Slave Statistics - Slave dump timing
10390	0x0100	Dump Parallel Execution Slave Statistics - Coordinator dump timing
10390	0x0200	Dump Parallel Execution Slave Statistics - Slave dump allocation file number
10390	0x0400	Dump Parallel Execution Slave Statistics - Terse format for debug dumps
10390	0x0800	Dump Parallel Execution Slave Statistics - Trace CRI random sampling
10390	0x1000	Dump Parallel Execution Slave Statistics - Trace signals
10390	0x2000	Dump Parallel Execution Slave Statistics - Trace parallel execution granule operations
10390	0x4000	Dump Parallel Execution Slave Statistics - Force compilation by slave 0
10391	0x0001	Dump Parallel Execution Granule Allocation - Summary of each object scanned in parallel
10391	0x0002	Dump Parallel Execution Granule Allocation - Full dump of each object except extent map
10391	0x0004	Dump Parallel Execution Granule Allocation - Full dump of each object including extent map
10391	0x0010	Dump Parallel Execution Granule Allocation - Summary of each granule generators
10391	0x0020	Dump Parallel Execution Granule Allocation - Granule generators except granule instances
10391	0x0040	Dump Parallel Execution Granule Allocation - Granule generators including granule instances
10391	0x0080	Dump Parallel Execution Granule Allocation - System information
10391	0x0100	Dump Parallel Execution Granule Allocation - Reference object for the query
10391	0x0200	Dump Parallel Execution Granule Allocation - kxfralo timing
10391	0x0400	Dump Parallel Execution Granule Allocation - Affinity module
10391	0x0800	Dump Parallel Execution Granule Allocation - Granule allocation during query execution
10391	0x1000	Dump Parallel Execution Granule Allocation - Object flush
10393	1	Dump Parallel Execution Statistics
10401	1	KSXP tracing - event 10401 trace name context forever, level 1 (for RAC kernel)
10402	1	SKGXP tracing - event 10402 trace name context forever, level 1 (for RAC kernel) minimal tracing
10402	127	SKGXP tracing - event 10402 trace name context forever, level 1 (for RAC kernel) maximum tracing
10500	1	Trace SMON Process
10608	10	Trace Bitmap Index Creation
10704	1	Trace Enqueues
10706	1	Trace Global Enqueue Manipulation
10708	10	Trace RAC Buffer Cache
10710	1	Trace Bitmap Index Access
10711	1	Trace Bitmap Index Merge Operation
10712	1	Trace Bitmap Index OR Operation
10713	1	Trace Bitmap Index AND Operation
10714	1	Trace Bitmap Index MINUS Operation
10715	1	Trace Bitmap Index Conversion to ROWIDs
10716	1	Trace Bitmap Index Compress / Decompress
10717	1	Trace Bitmap Index Compaction
10719	1	10719 - Trace Bitmap Index DML
10730	1	Trace Fine Grained Access Predicates
10731	1	Trace CURSOR Statements
10731	2	Trace CURSOR Statements
10851	2	Disables error 24005 when attempting to manually drop a queue table
10852		Enable dumping of the AQ statistics hash table
10853		Event for AQ statistics latch cleanup testing
10856		Disable AQ propagator from using streaming
10857		Force AQ propagator to use two-phase commit
10858		Crash the AQ propagator at different stages of commit
10859		Disable updates of message retry count
10860		Event for AQ admin disable new name parser
10861		Disable storing extended message properties
10862	1	Resolve default queue owner to current user in enqueue/dequeue
10901		Disable extent trimming
10928	1	Trace PL/SQL Execution
10938	1	Trace PL/SQL Execution Statistics
29700		Enable the collection of DLM lock conversion statistics to query GV$DLM_CONVERT_LOCAL and GV$DLM_CONVERT_REMOTE
44410	0	xmlagg() with a GROUP BY can fail with ORA-22813 if the result is too large. No statistics
44410	1	Basic statistics CURSOR, PARSE, EXEC, FETCH ERROR, SORT UMAP, ERROR, UMAP, STATS and XCTEND. Same as setting sql_trace=true.
44410	2	Same as level 1
44410	4	Level 1 plus binds
44410	8	Level 1 plus wait events
44410	12	Combine levels 4 and 8

ShowDoc

10060 Event	10128 Event
CREATE TABLE kkoipt_table ( c1 INTEGER, c2 VARCHAR2(80);	CREATE TABLE kkpap_pruning ( partition_count NUMBER, iterator VARCHAR2(32), partition_level VARCHAR2(32), order_pt VARCHAR2(12), call_time VARCHAR2(12), part# NUMBER, subp# NUMBER, abs# NUMBER);

Trace File Locations

$ORACLE_BASE/admin/sid_name/

bdump ... alert logs and system generated trace files
cdump ... core dumps
udump ... user generated trace files

Grant public access to all views used by TKPROF with verbose=y option.

$ORACLE_HOME/rdbms/admin/utltkprf.sql

Add timed statistics to trace file

conn / as sysdba

set linesize 121
col name format a40
col value format a30

SELECT name, value
FROM gv$parameter
WHERE name LIKE 'timed%';

ALTER SYSTEM SET timed_statistics=TRUE;

System Privilege To Enable and Disable Tracing

GRANT alter session TO <user_name>;

GRANT alter session TO uwclass;

REVOKE alter session FROM uwclass;

PFile Entries vs. Alter Session

init.ora Parameter Example

event='1401 trace name errorstack, level 12';

ALTER SESSION Commands

Start and Stop Session Tracing

ALTER SESSION SET sql_trace = <TRUE | FALSE>;

ALTER SESSION SET sql_trace = TRUE;

ALTER SESSION SET sql_trace = FALSE;

Event Tracing Examples

Active Session History

alter session set events 'immediate trace name ashdump level 10';

Control File Dump

alter session set events 'immediate trace name CONTROLF level 10';

Error Stack (Exception) Trace

alter session set events '<error_number_without_leading_zeros> trace name errorstack level 10';

alter session set events '60 trace name errorstack level 10';

File Header Dump

alter session set events 'immediate trace name FILE_HDRS level 10';

Library Cache Dump

alter session set events 'immediate trace name LIBRARY_CACHE level 10';

Process State Dump

alter session set events 'immediate trace name PROCESSSTATE LEVEL 10';

Redo Log Headers Dump

alter session set events 'immediate trace name REDOHDR LEVEL 10';

System State Dump

alter session set events 'immediate trace name SYSTEMSTATE LEVEL 10';

Tracing Demo

Go through a 10053 output to find why Oracle ignores a hint or thinks it is smarter than you. One little trick is to grep for lines starting "Join order" and "Best so far." The join order lists tables by table name, so you can see when an order you expected did not survive (or did not reach) the CBO's processing. The "Best so far" appear only when the CBO has decided that the most recent join order has a plan better than the previous best, so you can quickly check the evolution of the plan.

ALTER SESSION SET tracefile_identifier = 'test_plan1';

ALTER SESSION SET EVENTS '10053 trace name context forever, level 1';

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

SELECT srvr_id
FROM servers
WHERE srvr_id IN (
   SELECT srvr_id
   FROM serv_inst);

SELECT srvr_id
FROM servers
WHERE srvr_id IN (
   SELECT i.srvr_id
   FROM serv_inst i, servers s
   WHERE i.srvr_id = s.srvr_id);

ALTER SESSION SET EVENTS '10053 trace name context OFF';
ALTER SESSION SET EVENTS '10046 trace name context OFF';
or
ALTER SESSION SET SQL_TRACE=FALSE;

review the trace file in $ORACLE_BASE/diag/orabase/orabase/trace

TKPROF

Generate TKPROF Output

TKPROF <trace_file_name> <output_file_name>
[explain=<user/password> [table=<schema.table_name>]]
[print=<integer>]    -- list only the first nth SQL statements
[aggregate=<yes|no>
[insert=<file_name>] -- list SQL statements and data inside INSERT statements
[sys=<no>]           -- TKPROF does not list SQL statements run as user SYS
[record=<file_name>] -- record non-recursive statements in the trace file
[waits=<yes|no>]     -- record summary of for wait events in the trace file
[sort=<sort_options_list>] -- zero or more of the listed sort options

Sort Option	Description
execnt	number of execute was called
execpu	cpu time spent executing
execu	number of buffers for current read during execute
exedsk	number of disk reads during execute
exeela	elapsed time executing
exemis	number of library cache misses during execute
exeqry	number of buffers for consistent read during execute
exerow	number of rows processed during execute
fchcnt	number of times fetch was called
fchcpu	cpu time spent fetching
fchcu	number of buffers for current read during fetch
fchdsk	number of disk reads during fetch
fchela	elapsed time fetching
fchqry	number of buffers for consistent read during fetch
fchrow	number of rows fetched
prscnt	number of times parse was called
prscpu	cpu time parsing
prscu	number of buffers for current read during parse
prsdsk	number of disk reads during parse
prsela	elapsed time parsing
prsmis	number of misses in library cache during parse
prsqry	number of buffers for consistent read during parse
userid	userid of user that parsed the cursor

TKPROF c:\temp\orabase_ora_1492.trc c:\temp\trace_out.txt

PLSHPROF

Generate PLSHPROF Output

PLSHPROF [<options>] -output <input_file1> [<input_file2>]

Note: "output" refers to the output from DBMS_HPROF not the output from PLSHPROF.

Options	Description	Default
-trace <symbol>	Specifies function name of tree root	N/A
-skip <count>	Skips first count calls. Use only with -trace symbol	0
-collect <count>	Collects information for count calls. Use only with -trace symbol	1
-output <filename>	Specifies name of output file	N/A
-summary	Prints only elapsed time	N/A

plshprof -trace -output hprof_trace.html hprof.trc

Related Topics