Tracing specific SQL’s (Tracing Series-2)

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

Advertisements

Tagged: , , , ,

%d bloggers like this: