CODE
Oracle Code Library
JOBS
Find Or Post Oracle Jobs
FORUM
Oracle Discussion & Chat
PSOUG Home Code Snippets Oracle Reference Oracle Functions PSOUG Forum Oracle Blogs Bookmark and Share
 
 Search the Reference Library pages:  

Free
Oracle Magazine
Subscriptions
and Oracle White Papers

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
10046 16 Added in 11g to generate STAT line dumps for each execution. STAT dumping has been amended in 11g so that they are not aggregated across all executions but are dumped after execution.
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: emp\orabase_ora_1492.trc   c: emp race_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
ASH
DBMS_HPROF
DBMS_MONITOR
DBMS_PROFILER
DBMS_SUPPORT
DBMS_SYSTEM
DBMS_TRACE
Explain Plan
 
Home      :      Code Library      :      Sponsors      :      Privacy      :      Terms of Use      :      Contact Us [51 users online]    © 2010 psoug.org