Dump Trace File For Troubleshooting

Dumping trace file is a frequently used method for Oracle trouble shooting.

Error of current session
ALTER SESSION SET SQL_TRACE=ON;
 
-- execute the SQL which has problems
...
 
ALTER SESSION SET SQL_TRACE=OFF;
Current session, advanced trace(i.e. latch, wait etc.)
ALTER SESSION SET EVENTS '10046 trace name context forever, level 12';
 
-- execute the SQL which has problems
...
 
ALTER SESSION SET EVENTS '10046 trace name context off';

level:

Level Description
LEVEL 1 same as SQL_TRACE
LEVEL 4 LEVEL 1 plus bind vars
LEVEL 8 LEVEL 1 plus wait events
LEVEL 12 LEVEL 1 plus bind vars and wait events
Coding into application

In same case, it's hard to set trace manually, We can add trace code into application.

execute 'ALTER SESSION SET EVENTS ''10046 trace name context forever, level 12'' ';
 
-- execute the SQL which has problems
...
 
execute 'ALTER SESSION SET EVENTS ''10046 trace name context off'' ';
Catch trace file of other session
-- get SID and SERIAL#
SQL> SELECT sid,serial#,username,program,machine,status,last_call_et FROM v$session
  2  WHERE username='SCOTT';
 
  SID    SERIAL# USERNAME     PROGRAM                           MACHINE      STATUS   LAST_CALL_ET
----- ---------- ------------ --------------------------------- ------------ -------- ------------
   10          2 SCOTT        sqlplus@linuxtest (TNS V1-V3)     linux006     INACTIVE            2
 
-- set trace
EXECUTE DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(10,12,TRUE);
 
-- execute the SQL which has problems
...
 
EXECUTE DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(10,12,FALSE);
 
-- set level and trace
EXECUTE DBMS_SYSTEM.SET_EV(10,2,10046,12,'');
 
-- execute the SQL which has problems
...
 
EXECUTE DBMS_SYSTEM.SET_EV(10,2,10046,0,'');
find trace file(en)
find trace file

http://www.builder.com.cn/2007/0910/497699.shtml

-- under 11g
SELECT    a.VALUE || b.symbol || c.instance_name || '_ora_' || d.spid || '.trc' trace_file
  FROM (SELECT VALUE FROM v$parameter WHERE NAME = 'user_dump_dest') a,
       (SELECT SUBSTR (VALUE, -6, 1) symbol FROM v$parameter
         WHERE NAME = 'user_dump_dest') b,
       (SELECT instance_name FROM v$instance) c,
       (SELECT spid FROM v$session s, v$process p, v$mystat m
         WHERE s.paddr = p.addr AND s.SID = m.SID AND m.statistic# = 0) d
;
-- after 11g
SELECT VALUE FROM V$DIAG_INFO WHERE NAME = 'Default Trace File';

or sort file list of user_dump_dest on desc of time, the newest file is the trace file.

SQL> show parameter user_dump_dest
 
NAME                                 TYPE
------------------------------------ ---------------------------------
VALUE
------------------------------
user_dump_dest                       string
/u01/oracle/app/oracle/admin/sid/udump
 
host
 
[oracle@linuxtest ~]$ cd /u01/oracle/app/oracle/admin/sid/udump
[oracle@ linuxtest udump]$ ls -ltr
 
...
 
-rw-r-----  1 oracle oinstall      2541  8月 21 16:34 dbsid_ora_10101.trc
-rw-r-----  1 oracle oinstall       943  8月 21 16:43 dbsid_ora_14837.trc
-rw-r-----  1 oracle oinstall      1361  8月 21 16:43 dbsid_ora_10773.trc
Read the raw trade file

References:
http://www.itpub.net/forum.php?mod=viewthread&tid=1137992
1.Activating/deactivating trace http://www.gplivna.eu/papers/otrace.htm
2.Interpreting Raw SQL_TRACE and DBMS_SUPPORT.START_TRACE output, Metalink Note 39817.1
3.Trace Analyzer TRCANLZR - Interpreting Raw SQL Traces with Binds and/or Waits generated by EVENT 10046 Metalink Note 224270.1

See Also:
Abbreviation In Oracle Trace File

Here is a sample snippet from a trace file.

PARSING IN CURSOR #5 len=222 dep=1 uid=0 oct=3 lid=0 tim=1230889092568518 hv=3598296092 ad='402c848c' sqlid='1a8n1zgb7m90w'
select user#,password,datats#,tempts#,type#,defrole,resource$, ptime,exptime, ltime, astatus, lcount, decode(defschclass,NULL,'DEFAULT_CONSUMER_GROUP',defschclass),spare1,spare4,ext_username,spare2 from user$ where name=:1
END OF STMT
PARSE #5:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1457651150,tim=1230889092568518
EXEC #5:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1457651150,tim=1230889092568518
FETCH #5:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=1457651150,tim=1230889092568518
STAT #5 id=1 cnt=1 pid=0 pos=1 obj=22 op='TABLE ACCESS BY INDEX ROWID USER$ (cr=2 pr=0 pw=0 time=0 us)'
STAT #5 id=2 cnt=1 pid=1 pos=1 obj=46 op='INDEX UNIQUE SCAN I_USER1 (cr=1 pr=0 pw=0 time=0 us)'
CLOSE #5:c=0,e=0,dep=1,type=3,tim=1230889092568518

Parsing in cursor:

len =the length of the cursor.
dep =recursive depth of cursor(0-parent,>0-child)
uid =user id
oct =oracle command type no OCI
lid =user id owning the statement e.g. package(libary user id)
tim =the time the parse began
hv =hash valus
ad =sql address of cursor
sqlid=sql id of cursor
END OF STMT=indicate the end of sql STateMenT


c =cpu time
e =elapsed time
p =number of database blocks read (physical)
cr =number of consistent mode blocks read(logical)
cu =number of current mode blocks read(logical)
mis=number of library cache misses
r =number of rows returned
dep=recursive depth of cursor
og =optimizer goal (1=all_rows, 2=first_rows, 3=rule and 4=choose)
plh=plan hash value
tim=


cr =BG(Backgroud) Consistent Read mode
pr =OS Buffer Gets
pw =OS Write Calls

WAIT #5: nam='rdbms ipc reply' ela= 873 from_process=9 timeout=2147483647 p3=0 obj#=64143 tim=1230889212565389
WAIT #5: nam='rdbms ipc reply' ela= 820 from_process=5 timeout=2147483647 p3=0 obj#=64143 tim=1230889212566547
XCTEND rlbk=0, rd_only=1, tim=1230889212602618


nam =event name
ela =elapsed time

next three values after ela are indicate the P1, P2 and P3 variables for each specific event.

XCTEND =Transaction Commit END

rlbk True(1) if and only if the transaction was rolled back.
rd_only True(1) if and only if the transaction changed no data in the database