Until 11g ,tracing was synonymous with sessions. You could not trace anything other than sessions (Don’t take this literally)—
—
With 11g you have the option of tracing individual SQL’s by means a event/trigger. This is very useful if you are executing a long running process and interested in tracing only a particular SQL. You can trace the SQL either at session level or system level.
…
Syntax
- alter system set events ‘sql_trace [sql:sql_id] level 12’
- alter session set events ‘sql_trace [sql:sql_id] level 12’
Note: The SQL trace command can be executed for more than 1 SQL_ID too by separating the sql_id’s with pipe symbol
alter system set events ‘sql_trace [sql:sql_id|sql_id] level 12′;
=-
Steps to Trace the SQL
—
Step-1: Execute the following Query to get the SQL_ID.
.
SQL>select object_name from dba_objects where object_name=’DBA_TABLES’;
—
Step-2: Find the SQL_ID from v$sql
..
SQL> column sql_text format a80
SQL> set lines 120 pages 2000
SQL> set long 3000
SQL>
SQL> select sql_id , sql_text from v$sql where sql_text like
'%select object_name from dba_objects where object_name=%';
SQL_ID SQL_TEXT
------------- --------------------------------------------------------------------------------
gynhgrz60jayw select object_name from dba_objects where object_name='DBA_TABLES'
3n6v2xv2s5wm4 select sql_id , sql_text from v$sql where sql_text like '%select object_name fro
m dba_objects where object_name=%'
--
.
Step-3: Enable the trace for the SQL_ID
—
.
SQL> alter system set events ‘sql_trace [sql:gynhgrz60jayw] level 12’;
System altered
.
Step-4: Execute the SQL statement to generate trace
—
.
SQL> select object_name from dba_objects where object_name=’DBA_TABLES’;
OBJECT_NAME
————————————————————————————————————————
DBA_TABLES
DBA_TABLES
—
Step-5: Analyze the trace file. This is the fun part. Identifying problem SQL is often easy but fixing it …
—
Trace file /app/oracle/diag/rdbms/mydb/mydn/trace/mydb_ora_36897294.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 – 64bit Production
With the Partitioning option
ORACLE_HOME = /app/oracle/product/11.2.0.2/db
System name: AIX
Node name: mydb1
Release: 1
Version: 6
Machine: 00CF7$B54C00
Instance name: mydb
Redo thread mounted by this instance: 1
Oracle process number: 28
Unix process pid: 36897294, image: oracle@mydb1 (TNS V1-V3)
*** 2012-08-07 16:55:40.894
*** SESSION ID:(1012.117) 2012-08-07 16:55:40.894
*** CLIENT ID:() 2012-08-07 16:55:40.894
*** SERVICE NAME:(SYS$USERS) 2012-08-07 16:55:40.894
*** MODULE NAME:(SQL*Plus) 2012-08-07 16:55:40.894
*** ACTION NAME:() 2012-08-07 16:55:40.894
=====================
PARSING IN CURSOR #4575285296 len=37 dep=1 uid=0 oct=3 lid=0 tim=49002870757326
hv=1398610540 ad=’700000127d65258′ sqlid=’grwydz59pu6mc’
select text from view$ where rowid=:1
END OF STMT
PARSE #4575285296:c=0,e=683,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,plh=0,tim=49002870757324
BINDS #4575285296:
Bind#0
oacdty=11 mxl=16(16) mxlc=00 mal=00 scl=00 pre=00
oacflg=18 fl2=0001 frm=00 csi=00 siz=16 off=0
kxsbbbfp=110b54bf0 bln=16 avl=16 flg=05
value=000004D6.0000.0001
EXEC #4575285296:c=0,e=1314,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,plh=1028580536,tim=49002870772280
FETCH #4575285296:c=0,e=89,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,plh=1028580536,tim=49002870772402
STAT #4575285296 id=1 cnt=1 pid=0 pos=1 obj=59 op=’TABLE ACCESS BY USER ROWID VIEW$ (cr=2 pr=0 pw=0 time=69 us cost=1 size=15 card=1)’
CLOSE #4575285296:c=0,e=52,dep=1,type=0,tim=49002870772481
=====================
PARSING IN CURSOR #4575285296 len=37 dep=1 uid=0 oct=3 lid=0 tim=49002870773099 hv=1398610540 ad=’700000127d65258′ sqlid=’grwydz59pu6mc’
select text from view$ where rowid=:1
END OF STMT
PARSE #4575285296:c=0,e=23,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1028580536,tim=49002870773098
BINDS #4575285296:
Bind#0
oacdty=11 mxl=16(16) mxlc=00 mal=00 scl=00 pre=00
oacflg=18 fl2=0001 frm=00 csi=00 siz=16 off=0
kxsbbbfp=110b54bf0 bln=16 avl=16 flg=05
value=0000C0C4.0000.0001
EXEC #4575285296:c=0,e=77,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1028580536,tim=49002870773248
FETCH #4575285296:c=0,e=15,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=1028580536,tim=49002870773283
STAT #4575285296 id=1 cnt=1 pid=0 pos=1 obj=59 op=’TABLE ACCESS BY USER ROWID VIEW$ (cr=1 pr=0 pw=0 time=8 us cost=1 size=15 card=1)’
CLOSE #4575285296:c=0,e=29,dep=1,type=0,tim=49002870773333
=====================
PARSING IN CURSOR #4575286160 len=66 dep=0 uid=21 oct=3 lid=21 tim=49002870784095 hv=3423120348 ad=’7000001208cd1f8′ sqlid=’gynhgrz60jayw’
select object_name from dba_objects where object_name=’DBA_TABLES’
END OF STMT
EXEC #4575286160:c=0,e=38,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=2,plh=2998908629,tim=49002870784093
WAIT #4575286160: nam=’SQL*Net message to client’ ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=49002870784259
FETCH #4575286160:c=0,e=336,p=0,cr=17,cu=0,mis=0,r=1,dep=0,og=2,plh=2998908629,tim=49002870784629
WAIT #4575286160: nam=’SQL*Net message from client’ ela= 280 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=49002870784977
WAIT #4575286160: nam=’SQL*Net message to client’ ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=49002870785044
FETCH #4575286160:c=0,e=2993,p=0,cr=304,cu=0,mis=0,r=1,dep=0,og=2,plh=2998908629,tim=49002870787996
STAT #4575286160 id=1 cnt=2 pid=0 pos=1 obj=1195 op=’VIEW DBA_OBJECTS (cr=321 pr=0 pw=0 time=332 us cost=79 size=132 card=2)’
STAT #4575286160 id=2 cnt=2 pid=1 pos=1 obj=0 op=’UNION-ALL (cr=321 pr=0 pw=0 time=328 us)’
STAT #4575286160 id=3 cnt=2 pid=2 pos=1 obj=0 op=’FILTER (cr=317 pr=0 pw=0 time=321 us)’
STAT #4575286160 id=4 cnt=2 pid=3 pos=1 obj=0 op=’NESTED LOOPS (cr=317 pr=0 pw=0 time=315 us cost=78 size=65 card=1)’
STAT #4575286160 id=5 cnt=2 pid=4 pos=1 obj=0 op=’NESTED LOOPS (cr=314 pr=0 pw=0 time=323 us cost=77 size=61 card=1)’
STAT #4575286160 id=6 cnt=2 pid=5 pos=1 obj=507636 op=’TABLE ACCESS FULL OBJ$ (cr=311 pr=0 pw=0 time=263 us cost=76 size=39 card=1)’
STAT #4575286160 id=7 cnt=2 pid=5 pos=2 obj=507644 op=’INDEX RANGE SCAN I_USER2 (cr=3 pr=0 pw=0 time=57 us cost=1 size=22 card=1)’
STAT #4575286160 id=8 cnt=2 pid=4 pos=2 obj=507644 op=’INDEX RANGE SCAN I_USER2 (cr=3 pr=0 pw=0 time=10 us cost=1 size=4 card=1)’
STAT #4575286160 id=9 cnt=0 pid=3 pos=2 obj=19 op=’TABLE ACCESS BY INDEX ROWID IND$ (cr=0 pr=0 pw=0 time=0 us cost=2 size=8 card=1)’
STAT #4575286160 id=10 cnt=0 pid=9 pos=1 obj=36 op=’INDEX UNIQUE SCAN I_IND1 (cr=0 pr=0 pw=0 time=0 us cost=1 size=0 card=1)’
STAT #4575286160 id=11 cnt=0 pid=3 pos=3 obj=0 op=’NESTED LOOPS (cr=0 pr=0 pw=0 time=0 us cost=2 size=30 card=1)’
STAT #4575286160 id=12 cnt=0 pid=11 pos=1 obj=507644 op=’INDEX SKIP SCAN I_USER2 (cr=0 pr=0 pw=0 time=0 us cost=1 size=20 card=1)’
STAT #4575286160 id=13 cnt=0 pid=11 pos=2 obj=507640 op=’INDEX RANGE SCAN I_OBJ4 (cr=0 pr=0 pw=0 time=0 us cost=1 size=10 card=1)’
STAT #4575286160 id=14 cnt=0 pid=2 pos=2 obj=0 op=’NESTED LOOPS (cr=4 pr=0 pw=0 time=199 us cost=1 size=29 card=1)’
STAT #4575286160 id=15 cnt=89 pid=14 pos=1 obj=507644 op=’INDEX FULL SCAN I_USER2 (cr=1 pr=0 pw=0 time=98 us cost=1 size=352 card=88)’
STAT #4575286160 id=16 cnt=0 pid=14 pos=2 obj=105 op=’INDEX RANGE SCAN I_LINK1 (cr=3 pr=0 pw=0 time=133 us cost=0 size=25 card=1)’
*** 2012-08-07 16:55:44.200
CLOSE #4575286160:c=0,e=38,dep=0,type=0,tim=49002874076143
TwelveC 
Recent Comments