Tracing a Specific SQL Statement

posted Apr 22, 2012, 8:00 AM by Sachchida Ojha   [ updated Apr 22, 2012, 8:31 AM ]
You want to trace a specific SQL statement to find where the database is spending its time during the execution of the statement.
1. Setup the trace

SQL> alter session set events 'sql_trace level 12';

Session altered.
===============================================================================================
You can also choose to trace specific SQL statement by specifying the SQL ID.

SQL> select sql_text,sql_id from v$sql where sql_text ='select count(*) from dict';
SQL_TEXT
--------------------------------------------------------------------------------
SQL_ID
-------------
select count(*) from dict
7ugyh72gqtm58
SQL> alter session set events 'sql_trace [sql:7ugyh72gqtm58] level 12';

You can also trace multiple SQL statement
SQL> alter session set events 'sql_trace [sql:7ugyh72gqtm58|7ugyh72gqtm59|7ugyh72gqtm60] level 12';

You can trace a specific SQL statement running on a different session by issuing an alter system set events command.

SQL> alter system set events 'sql_trace [sql:7ugyh72gqtm58] level 12';

===============================================================================================


2. EXECUTE the SQL Statement

SQL> select count(*) from dict;   

  COUNT(*)
----------
      2553

3. Set tracing OFF

SQL> alter session set events 'sql_trace off';

Session altered.

===============================================================================================
SQL> alter session set events 'sql_trace [sql:7ugyh72gqtm58] off';

SQL> alter session set events 'sql_trace [sql:7ugyh72gqtm58|7ugyh72gqtm59|7ugyh72gqtm60] off';

SQL> alter system set events 'sql_trace [sql:7ugyh72gqtm58] off';
===============================================================================================
4. Finding the trace file

[oracle@usha ~]$ adrci

ADRCI: Release 11.2.0.1.0 - Production on Sun Apr 22 10:07:58 2012

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

ADR base = "/u01/app/oracle"
adrci> show tracefile -t
  
   22-APR-12 08:44:35  diag/rdbms/testdb/testdb/trace/testdb_vktm_19533.trc
   22-APR-12 08:44:43  diag/rdbms/testdb/testdb/trace/testdb_p000_19573.trc
   22-APR-12 08:44:43  diag/rdbms/testdb/testdb/trace/testdb_p001_19575.trc
   22-APR-12 08:44:46  diag/rdbms/testdb/testdb/trace/testdb_dbrm_19541.trc
   22-APR-12 08:45:04  diag/rdbms/testdb/testdb/trace/testdb_mmon_19559.trc
   22-APR-12 08:45:15  diag/rdbms/testdb/testdb/trace/testdb_j007_19615.trc
   22-APR-12 08:46:13  diag/rdbms/testdb/testdb/trace/testdb_j000_19623.trc
   22-APR-12 08:49:51  diag/rdbms/testdb/testdb/trace/alert_testdb.log
   22-APR-12 09:05:34  diag/rdbms/testdb/testdb/trace/testdb_ora_19571.trc
adrci>

===========================================================================================

NOTE: Issue the following statement to set an identifier for your trace file.
SQL> alter session set events 'sql_trace level 12';
Session altered.
SQL> alter session set tracefile_identifier='MyTune1';
Session altered.
SQL> select count(*) from dict;   

  COUNT(*)
----------
      2553

SQL> alter session set events 'sql_trace off';
Session altered.
SQL> quit
Disconnected from Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
[oracle@usha ~]$ adrci

ADRCI: Release 11.2.0.1.0 - Production on Sun Apr 22 10:21:03 2012

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

ADR base = "/u01/app/oracle"
adrci> show tracefile -t
  
   22-APR-12 08:45:15  diag/rdbms/testdb/testdb/trace/testdb_j007_19615.trc
   22-APR-12 08:46:13  diag/rdbms/testdb/testdb/trace/testdb_j000_19623.trc
   22-APR-12 09:05:34  diag/rdbms/testdb/testdb/trace/testdb_ora_19571.trc
   22-APR-12 09:15:46  diag/rdbms/testdb/testdb/trace/alert_testdb.log
   22-APR-12 09:20:10  diag/rdbms/testdb/testdb/trace/testdb_ora_19868.trc
   22-APR-12 09:20:57  diag/rdbms/testdb/testdb/trace/testdb_ora_19868_MyTune1.trc
adrci>

SQL>alter session set tracefile_identifier='MyTune1';

5. Examining the RAW SQL Trace File

Open the file in a text editor. Here are few things you will see
[oracle@usha ~]$ vi /u01/app/oracle/diag/rdbms/testdb/testdb/trace/testdb_ora_19868_MyTune1.trc

*** 2012-04-22 10:20:57.614
WAIT #7: nam='SQL*Net message from client' ela= 24056253 driver id=1650815232 #bytes=1 p3=0 obj#=68 tim=1335104457614532
CLOSE #7:c=0,e=42,dep=0,type=0,tim=1335104457614724
=====================
PARSING IN CURSOR #4 len=40 dep=0 uid=0 oct=42 lid=0 tim=1335104457614858 hv=103992512 ad='0' sqlid='7226hs0335m60'
alter session set events 'sql_trace off'
END OF STMT
PARSE #4:c=0,e=48,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1335104457614856
EXEC #4:c=0,e=262,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1335104457615189
~                        

6. Formatting the TRACE Files using TKPROF

[oracle@usha ~]$ tkprof /u01/app/oracle/diag/rdbms/testdb/testdb/trace/testdb_ora_19868_MyTune1.trc mytune1.prf

TKPROF: Release 11.2.0.1.0 - Development on Sun Apr 22 10:27:15 2012

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.


[oracle@usha ~]$ ls mytune1.prf
mytune1.prf
[oracle@usha ~]$ vi mytune1.prf
[oracle@usha ~]$

7. Analyze the TKPROF Output

Header

TKPROF: Release 11.2.0.1.0 - Development on Sun Apr 22 10:27:15 2012
 
Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.
 
Trace file: /u01/app/oracle/diag/rdbms/testdb/testdb/trace/testdb_ora_19868_MyTune1.trc
Sort options: default
 
********************************************************************************
count    = number of times OCI procedure was executed
cpu      = cpu time in seconds executing 
elapsed  = elapsed time in seconds executing
disk     = number of physical reads of buffers from disk
query    = number of buffers gotten for consistent read
current  = number of buffers gotten in current mode (usually for update)
rows     = number of rows processed by the fetch or execute call
********************************************************************************
 
EXECUTION STATISTICS

SQL ID: 7ugyh72gqtm58
Plan Hash: 2690817011
select count(*) 
from
 dict


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.02       0.04          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.12       0.76        542       2019          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.14       0.81        542       2019          0           1

Misses in library cache during parse: 1
================================================================================================
count -> The no of times the database parsed,executed or fetched this statement.
cpu -> CPU time used for the parse/execute/fetch phases
elapsed ->Total elapsed time in SECONDS for the parse/execute/fetch phases
disk -> No of physical block reads for the  parse/execute/fetch phases
query -> No of data blocks read with logical reads from the buffer cache in consistent mode for the parse/execute/fetch phases (for a select statement)
current -> No of data blocks read and retrieved with logical reads from the buffer cache in current mode ( for insert, update, delete, and merge statements)
rows -> No of fetched rows for a select statement or the no of rows inserted, deleted or updated respectively for an insert, update, delete, and merge statements.

====================
============================================================================
Row Source Operation

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=2019 pr=542 pw=315 time=0 us)
   2553   VIEW  DICTIONARY (cr=2019 pr=542 pw=315 time=39938 us cost=514 size=0 card=2140)
   2553    UNION-ALL  (cr=2019 pr=542 pw=315 time=34069 us)
   1415     CONCATENATION  (cr=226 pr=64 pw=0 time=15907 us)
    698      FILTER  (cr=78 pr=64 pw=0 time=8131 us)
    698       FILTER  (cr=78 pr=64 pw=0 time=6737 us)
   5177        HASH JOIN OUTER (cr=78 pr=64 pw=0 time=8963 us cost=24 size=1845 card=41)
    726         INDEX RANGE SCAN I_OBJ2 (cr=10 pr=0 pw=0 time=1329 us cost=10 size=1591 card=43)(object id 37)
  15871         INDEX FAST FULL SCAN I_COM1 (cr=68 pr=64 pw=0 time=18813 us cost=13 size=94328 card=11791)(object id 138)
      1       FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us cost=0 size=26 card=1)
    372      FILTER  (cr=74 pr=0 pw=0 time=2968 us)
   3030       HASH JOIN OUTER (cr=74 pr=0 pw=0 time=4164 us cost=20 size=720 card=16)
    385        INDEX RANGE SCAN I_OBJ2 (cr=6 pr=0 pw=0 time=576 us cost=6 size=629 card=17)(object id 37)
      1         FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us cost=0 size=26 card=1)
  15871        INDEX FAST FULL SCAN I_COM1 (cr=68 pr=0 pw=0 time=18429 us cost=13 size=94328 card=11791)(object id 138)
    345      FILTER  (cr=74 pr=0 pw=0 time=3554 us)
   3327       HASH JOIN OUTER (cr=74 pr=0 pw=0 time=8954 us cost=20 size=1080 card=24)
    360        INDEX RANGE SCAN I_OBJ2 (cr=6 pr=0 pw=0 time=837 us cost=6 size=925 card=25)(object id 37)
      1         FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us cost=0 size=26 card=1)
  15871        INDEX FAST FULL SCAN I_COM1 (cr=68 pr=0 pw=0 time=17917 us cost=13 size=94328 card=11791)(object id 138)
     21     FILTER  (cr=112 pr=0 pw=0 time=80 us)
     99      HASH JOIN OUTER (cr=112 pr=0 pw=0 time=196 us cost=36 size=574 card=14)
     21       INLIST ITERATOR  (cr=44 pr=0 pw=0 time=820 us)
     21        INDEX RANGE SCAN I_OBJ2 (cr=44 pr=0 pw=0 time=0 us cost=22 size=462 card=14)(object id 37)
  15871       INDEX FAST FULL SCAN I_COM1 (cr=68 pr=0 pw=0 time=17917 us cost=13 size=94328 card=11791)(object id 138)
   1117     FILTER  (cr=1681 pr=478 pw=315 time=68820 us)
   1117      HASH JOIN  (cr=1681 pr=478 pw=315 time=65968 us cost=416 size=2390955 card=16265)
  27702       INDEX FAST FULL SCAN I_OBJ2 (cr=758 pr=0 pw=0 time=43402 us cost=204 size=408776 card=11048)(object id 37)
   2715       HASH JOIN  (cr=923 pr=163 pw=240 time=4911 us cost=211 size=1789920 card=16272)
   3751        INDEX FAST FULL SCAN I_OBJ2 (cr=758 pr=0 pw=0 time=12250 us cost=204 size=178533 card=2151)(object id 37)
  23789        TABLE ACCESS FULL SYN$ (cr=165 pr=163 pw=0 time=27880 us cost=6 size=642303 card=23789)
      0      NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us cost=2 size=21 card=1)
      0       INDEX RANGE SCAN I_OBJAUTH1 (cr=0 pr=0 pw=0 time=0 us cost=2 size=8 card=1)(object id 62)
      0       FIXED TABLE FULL X$KZSRO (cr=0 pr=0 pw=0 time=0 us cost=0 size=13 card=1)
      0      FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us cost=0 size=26 card=1)
================================================================================================
cr -> Blocks retrieved through a logical read in the consistent mode
pr -> no of blocks read through a physical disk read
pw -> No of blocks written with a physical write to a disk
time -> Total time in milliseconds spent processing the operation
cost ->Estimated cost of the operation
size -> Estimated amount of data (bytes) returned by the operation.
card -> Estimated no of rows returned by the operation
================================================================================================

WAIT EVENTS

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  db file sequential read                         2        0.01          0.03
  db file scattered read                          8        0.01          0.08
  Disk file operations I/O                        1        0.01          0.01
  direct path write temp                         21        0.03          0.25
  asynch descriptor resize                        4        0.00          0.00
  direct path read                               19        0.03          0.22
  direct path read temp                          21        0.00          0.00
  SQL*Net message from client                     2       24.05         24.05
********************************************************************************





Comments