Search notes:

Oracle: Trace file

Each process writes some messages to a tracefile.
The processes's trace file paths can be queried from v$process: 
select
   prc.tracefile
from
   v$process prc                         join
   v$session ses on prc.addr = ses.paddr
where
   ses.sid = sys_context('userenv', 'sid')
;
The content of the tracefile can be queried from v$diag_trace_file_contents. 
select
   trc.payload,
   trc.timestamp
from
   v$diag_info inf   join
   v$diag_trace_file_contents  trc on regexp_replace(inf.value, '.*[\\/]', '') = trc.trace_filename
where
   inf.name = 'Default Trace File'
order by
   trc.line_number
;
The directory into which trace files are written can be queried like so: 
select
   value trace_dir
from
   v$diag_info
where
   name = 'Diag Trace';

Enabling/disabling certain information that is written to trace files

alter system  set event = '…' /* set init-parameter named 'event'          */ ;
alter system  set events '…'  /* Note the plural and 'missing' equal sign  */ ;
alter session set events '…'                                                  ;

exec dbms_system.set_ev(…);

exec dbms_monitor.session_trace_enable
exec dbms_monitor.session_trace_disable

SQL>  oradebug event

Abbreviations

ad Address of cursor
c Elapsed time for call in μs (± 10,000 μs)
card STAT Number of records that a row source is expected to produce (cardinality). Compare with actual real produced number in cnt.
cr Number of blocks read from buffer cache using consistent read (aka consistent mode?)
cnt STAT Number of records produced by a row source. Compare with card.
cu number of blocks read using current mode
dep if > 0: child (dependent) SQL
e elapsed time in μs (± 1 μs)
ela WAIT elapsed time
hv hash-value of SQL statement
len
nam WAIT
mis (Number of?) Library cache misses. (Always either 0 or 1?)
oct Oracle command type (See v$sqlcommand)
og Optimizer goal; 1=all_rows, 2=first_rows, 3=rule, 4=choose
op Name of plan operation
p number of blocks read using OS call (p = physical reads)
pr STAT Physical reads
p1,p2,p3 WAIT
plh plan-hash
sqlid
tim an ever increasing point in time (μs)
uid User id

STAT

STAT lines show row source statistics. pid points to a row source's consumer (parent) that is identified by id. Thus, the STAT lines allow to re-assemble the execution plan and to find hot spots in it.

XCTEND

End of a transaction:
  • rlbk=0: commit, rlbk=1: rollback
  • rd_only=0: no transaction started, rd_only=1: a transaction had already begun
TODO:

TODO: Events that might be set

Set event 10235 to level 1. 
alter session set events '10235';
Reveal optimizer statistics after SQL statement parsing. 
alter session set events '10053 trace name context forever';
alter session set events 'trace[rdbms.SQL_Optimizer.*]';
alter session set events 'trace[rdbms.SQL_Optimizer.*][sql_id:012345689abc]';

alter session set events 'trace[sql_execution]';

alter session set events '10046 level 12';
alter session set events 'sql_trace level 12';
alter session set events 'sql_trace wait=true, plan_stat=never';
alter session set events 'sql_trace [sql_id:012345689abc] wait=true, plan_stat=never';
alter session set events 'sql_trace off';
See oradebug doc event name sql_trace for usage.
Compare with the init parameter sql_trace. 
alter session set events 'trace[SQL_COMPILER.*] disk=highest';
Disable invoking the action after 1234 events: 
alter session set events '10046 trace name context level 12, lifetime 1234';
Skip first 500 events: 
alter session set events '10046 trace name context level 12, lifetime 1234, after 500 occurrences';

alter session set events '60 trace name hanganalyze level 4';

alter session set events q'{60 trace           -
name hanganalyze_global level   4, forever;    -
name systemstate        level 266, lifetime 1; -
name processstate       level   2, forever}';

alter session set events 'deadlock trace name hanganalyze_global';

alter system  set events   'immediate trace name GWM_TRACE level 7';
alter system  set events   'immediate trace name krb_options level 1'; /* dumps current KRB flags set for session   Found in recover.bsq */
alter system  set event  = '10798 trace name context forever, level 7' scope=spfile;
alter system  set events   'trace[progint_appcont_rdbms]'
alter system  set events   'trace[sess_signature] disk highest';
alter session set events   'trace[rdbms.SQL_Optimizer.*]';
alter session set events   'trace[rdbms.SQL_Optimizer.*] [sql:6kdz5a5c427qd]' /* sql:6kdz5a5c427qd restricts event to SQL id */;
alter session set events   'trace[krb.*]';
Force a crash after a commit (Tanel Poder): 
create table xyz(a number);
alter session set events 'wait_event["log file sync"] crash()';
insert into xyz values (1);
commit;

alter session set events 'wait_event["db file sequential read"] trace("stack is: %\n", shortstack())';
Found here: 
alter session set events 'trace[RDBMS.SQL_Transform] [SQL: 32cqz71gd8wy3] disk=high RDBMS.query_block_dump(1) processstate(1) callstack(1)';

alter session set events 'wait_event[all] trace(''event="%" ela=% p1=% p2=% p3=%\n'', evargs(5), evargn(1), evargn(2), evargn(3), evargn(4))';
(Invalid) components. 
alter session set events 'trace [invalid_component]';
ORA-49100: Failed to process event statement [trace [invalid_component]]
ORA-48904: String [INVALID_COMPONENT] is not a valid component name
Valid components can be found using oradebug doc component.
Remove (global) events: 
alter session set event = '…' scope spfile;
shutdown immediate
startup
show parameter event
…
alter system reset event scope = spfile sid='*';  
shutdown immediate
startup
Specify level in hexadecimal notation: 
alter system set events = '39089 trace name context forever, level 0x300' 
SCOPE = spfile;
Trace plan management: 
exec dbms_spm.configure('spm_tracing', 1);
select parameter_name, parameter_value from sys.smb$config;
Terminating the current session: 
alter session set events 'immediate crash';
ORA-03113: end-of-file on communication channel
Process ID: 9312
Session ID: 63 Serial number: 25232
Other immediate actions: 
alter session set events 'immediate eventdump(session)';
alter session set events 'immediate eventdump(system)' ;
Dump control file 
alter session set events 'immediate trace name controlf level 10';
Dump file headers: 
alter session set events 'immediate trace name file_hdrs level 10'
Dump redo log headers 
alter session set events 'immediate trace name redohdr level 10';
Dump system state: 
alter session set events 'immediate trace name systemstate level 10';

alter session set events 'immediate trace(10046)';
Specify parameters for events (for example: trace in memory and use high resolution timer): 
alter session set events 'trace[sql_mon.*] memory=high, get_time=highres';
Use | to set a combination of events: 
alter system set events 'trace[
  sql_mon |
  sql_optimizer.*
] {
  process: pname = p000 |
  process: pname=p005
}';

alter session set events 'parse_sql_statement trace("stack is: %\n", shortstack())';
Wrong syntax: 
alter session set events '10046 leve 12';
ORA-49100: Failed to process event statement [10046 leve 12]
ORA-49104: [LEVE] is not a valid argument for event [kg_event]
?? 
alter system set events 'sql_trace {process : pname = dw | pname = dm} level=12'
alter system set event ='sql_trace [sql:6kdz5a5c427qd] level=12' scope=spfile;
alter system set event ='sql_trace [sql:6kdz5a5c427qd] off';
List events that were set in the current session or systemwide: 
alter session set events 'immediate eventdump(session)';
alter session set events 'immediate eventdump(system )';
Remove all events: 
alter system reset event scope=spfile sid='*';

heapdump

alter session set events 'immediate trace name heapdump level n';
level:
Summary Detail Heap
1 1025 PGA
2 2050 SGA
4 4100 UGA
8 8200 CGA - Current call
16 16400 CGA - User call
32 32800 Large Pool

immediate vs number

With immediate, the desired event is executed immediately: 
alter session set events 'immediate trace name buffers level 10';
However, when using an (error) number, the event is triggered when the specified error is encountered in a session: 
alter session set events  '600 trace name buffers level 10'; 
alter session set events '1476 trace name errorstack';

Using oradebug

oradebug setmypid
oradebug event 942
Show events that are traced in «my» session: 
oradebug eventdump session

oradebug doc event

Other TODOs

begin
  dbms_sqldiag.dump_trace('6kdz5a5c427qd');
end;

expdp userid=rene schemas=rene trace=480300
Trace = xxx specifies a hexadecimal value which is a combination of the following flags:
10300 SHDW: To trace the Shadow process (API) (expdp/impdp)
20300 KUPV: To trace Fixed table
40300 'div' To trace Process services
80300 KUPM: To trace Master Control Process (MCP,DM)
100300 KUPF: To trace File Manager
200300 KUPC: To trace Queue services
400300 KUPW: To trace Worker process(DW)
800300 KUPD: To trace Data Package
1000300 META: To trace Metadata Package
1FF0300 'all' To trace all components(full tracing)

See also

Trace files are written to the Automatic Diagnostic Repository (ADR).
Trace files that are currently available in the ADR are listed in v$diag_trace_file. Their content can be queried from v$diag_trace_file_contents.
dbms_sqltune.select_sql_trace reads a trace file and returns the found SQL statements as an sqlset_row.
trace file analyzer
Tracing SQL statement execution
The two sql scripts tracefile.sql and find-trace-file.sql
Oracle SQL Developer allows to format a trace file with the menu File -> Open
The init parameters tracefile_identifier and sql_trace.
dba_enabled_traces
Using event 1722 to find an offending SQL statement that causes an ORA-01722: invalid number error.
oradebug tracefile_name and oradebug unlimit
x$dbgtfview
The function dbms_system.ksdwrt writes messages into trace files or into the alert log.
On reading trace files with PL/SQL
Setting trace file purge policy with ADRCI.
ORA-00600: internal error code…, ORA-03113: end-of-file on communication channel

Index