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.trcOracle9i Enterprise Edition Release 9.2.0.3.0 - 64bit ProductionJServer Release 9.2.0.3.0 - ProductionORACLE_HOME = /appl/oracle/product/9.2.0System name:    SunOSNode name:      sdsunn01Release:        5.9Version:        Generic_112233-08Machine:        sun4uInstance name: EI1TRedo thread mounted by this instance: 1Oracle process number: 17Unix 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.429APPNAME mod='SQL*Plus' mh=3669949024 act='' ah=4029777240

APPNAME:Application name which can be set with dbms_application_infomod:module namemh:module hashact:Actionah: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 = :b1END OF STMTPARSE #6:c=0,e=981,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=0,tim=1621758552403BINDS #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=1WAIT #6: nam='db file sequential read' ela= 8051 p1=14 p2=261084 p3=1WAIT #6: nam='db file sequential read' ela= 7165 p1=19 p2=147722 p3=1WAIT #6: nam='db file sequential read' ela= 9604 p1=19 p2=133999 p3=1WAIT #6: nam='db file sequential read' ela= 6381 p1=19 p2=133801 p3=1EXEC #6:c=10000,e=45750,p=5,cr=1,cu=10,mis=0,r=1,dep=1,og=4,tim=1621758598343FETCH #5:c=0,e=357,p=0,cr=5,cu=0,mis=0,r=0,dep=1,og=4,tim=1621758598896EXEC #1:c=30000,e=116691,p=36,cr=35,cu=10,mis=0,r=1,dep=0,og=4,tim=1621758599043WAIT #1: nam='SQL*Net message to client' ela= 5 p1=1413697536 p2=1 p3=0WAIT #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.depRecursive depth of the cursor.uidSchema user id of parsing user.octOracle command type.lidPrivilege user id.elaElapsed time. 8i: in 1/1000^th of a second, 9i: 1/1'000'000^th of a second timTimestamp. 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. hvHash id.adSQLTEXT 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 mismiss in cache (?) r rows processed deprecursive depth og optimizer goal timtime

 

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.paddrwhere  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 setmypidSQL> oradebug tracefile_name