Diagnostic event 10046

from:

http://www.adp-gmbh.ch/ora/tuning/diagnostic_events/10046.html

 

Event 10046 can be used to trace SQL statements. Arguably, this is the most important event that can be set.

It is functionally equivalent to setting sql_trace = true. However, it allows to output extra details by setting the level to 4, 8 or 12.

Levels

This event can be set with any of the four following levels:

• 1: Standard SQL tracing
• 4: Level 1 + tracing bind variables
• 8: Level 1 + tracing wait events
• 12: Level 4 + Level 8 (SQL tracing, bind vars and wait events)

The following command shows bind variables in the trace file:

	alter session set events '10046 trace name context forever, level 4';

After issuing this command, a trace file will be created.

Because event 10046 is somewhat special, there is a dedicated package procedure that allows to set that event:

 

dbms_support.start_trace.

 

 

Faster tracing with 10g: Oracle 10g has a new view (v$sql_bind_capture) that captures bind variables faster than tracing them.

Format of the trace file

The header

/appl/oracle/admin/EI1T/udump/ei1t_ora_14246.trc
Oracle9i Enterprise Edition Release 9.2.0.3.0 - 64bit Production
JServer Release 9.2.0.3.0 - Production
ORACLE_HOME = /appl/oracle/product/9.2.0
System name:    SunOS
Node name:      sdsunn01
Release:        5.9
Version:        Generic_112233-08
Machine:        sun4u
Instance name: EI1T
Redo thread mounted by this instance: 1
Oracle process number: 17
Unix process pid: 14246, image: oracle@sdsunn01?(TNS V1-V3)

*** 2003-10-13 16:13:59.450
*** SESSION ID:(45.30) 2003-10-13 16:13:59.429
APPNAME mod='SQL*Plus' mh=3669949024 act='' ah=4029777240

APPNAME:	Application name which can be set with dbms_application_info
mod:	module name
mh:	module hash
act:	Action
ah:	Action hash value

The content

=====================
PARSING IN CURSOR #6 len=107 dep=1 uid=44 oct=6 lid=44 tim=1621758552415 hv=3988607735 ad='902c07a8'
UPDATE rn_lu_lastname_loca set entr_loca_id_plz14 = translate(entr_loca_id_plz14,'_','-') where rowid = :b1
END OF STMT
PARSE #6:c=0,e=981,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=0,tim=1621758552403
BINDS #6:
 bind 0: dty=1 mxl=32(18) mal=00 scl=00 pre=00 oacflg=13 oacfl2=1 size=32 offset=0
   bfp=10331d748 bln=32 avl=18 flg=09
   value="AAAHINAATAAAwTTABV"
WAIT #6: nam='db file sequential read' ela= 12170 p1=6 p2=197843 p3=1
WAIT #6: nam='db file sequential read' ela= 8051 p1=14 p2=261084 p3=1
WAIT #6: nam='db file sequential read' ela= 7165 p1=19 p2=147722 p3=1
WAIT #6: nam='db file sequential read' ela= 9604 p1=19 p2=133999 p3=1
WAIT #6: nam='db file sequential read' ela= 6381 p1=19 p2=133801 p3=1
EXEC #6:c=10000,e=45750,p=5,cr=1,cu=10,mis=0,r=1,dep=1,og=4,tim=1621758598343
FETCH #5:c=0,e=357,p=0,cr=5,cu=0,mis=0,r=0,dep=1,og=4,tim=1621758598896
EXEC #1:c=30000,e=116691,p=36,cr=35,cu=10,mis=0,r=1,dep=0,og=4,tim=1621758599043
WAIT #1: nam='SQL*Net message to client' ela= 5 p1=1413697536 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 2283 p1=1413697536 p2=1 p3=0

Lines that start with WAIT

len	Length of SQL statement.
dep	Recursive depth of the cursor.
uid	Schema user id of parsing user.
oct	Oracle command type.
lid	Privilege user id.
ela	Elapsed time. 8i: in 1/1000th of a second, 9i: 1/1'000'000th of a second
tim	Timestamp. Pre-Oracle9i, the times recorded by Oracle only have a resolution of 1/100th of a second (10mS). As of Oracle9i some times are available to microsecond accuracy (1/1,000,000th of a second). The timestamp can be used to determine times between points in the trace file. The value is the value in v$timer when the line was written. If there are TIMESTAMPS in the file you can use the difference between 'tim' values to determine an absolute time.
hv	Hash id.
ad	SQLTEXT address (see v$sqlarea and v$sqltext).

Lines that start with PARSE, EXEC or FETCH

#n	n = number of cursor
c	cpu time
e	elapsed time
p	physical reads
cr	consistant reads
cu	current mode reads
mis	miss in cache (?)
r	rows processed
dep	recursive depth
og	optimizer goal
tim	time

 

Find trace file in Oracle

The following script returns the path to the trace file that the current session writes. It returns the path whether or not tracing is enabled.

select 
  u_dump.value   || '/'     || 
  db_name.value  || '_ora_' || 
  v$process.spid || 
  nvl2(v$process.traceid,  '_' || v$process.traceid, null ) 
  || '.trc'  "Trace File"
from 
             v$parameter u_dump 
  cross join v$parameter db_name
  cross join v$process 
        join v$session 
          on v$process.addr = v$session.paddr
where 
 u_dump.name   = 'user_dump_dest' and 
 db_name.name  = 'db_name'        and
 v$session.audsid=sys_context('userenv','sessionid');

In order to make a more informative trace file name, the following command can be used:

alter session set tracefile_identifier = here_is_my_session;

A trace file will then have this identifier (here: here_is_my_session) in it's filename.

 

 

The trace file's name can also be found with oradebug:

SQL> oradebug setmypid
SQL> oradebug tracefile_name