Tracing Performance issues in oracle

Tracing session activity is the most SQL performance tuning exercise. Oracle provides various tools to trace SQL activity. Oracle SQL trace utility is most commonly used utility. We also use OEM Grid Control, Toad and other Oracle/ Third party tools to trace the SQL activity.

Oracle Provides numerous "events" that help you perform various types of traces. Although there are several tracing methods available, Oracle now recommends DBMS_MONITOR package for most types of tracing.

Oracle also provides the TKPROF utility and Oracle Trace Analyzer to analyze the raw trace files.

You need to set/prepare your environment before starting any trace activity.

1. Enable times statistics collection (set the timed_statistics parameter to TRUE)
SQL> show parameter statistics

NAME                     TYPE    VALUE
------------------------------------ ----------- ------------------------------
optimizer_use_pending_statistics     boolean    FALSE
statistics_level             string    TYPICAL
timed_os_statistics             integer    0
timed_statistics             boolean    TRUE
IF timed_statistics parameter is set to false then,

SQL> alter system set timed_statistics =TRUE;

2. Specify destination of the trace file.

SQL> select name,value from v$diag_info where name='Diag Trace';

NAME
----------------------------------------------------------------
VALUE
--------------------------------------------------------------------------------
Diag Trace
/u01/app/oracle/diag/rdbms/testdb/testdb/trace

3. Adjust the trace dump file size

SQL> show parameter dump

NAME                     TYPE    VALUE
------------------------------------ ----------- ------------------------------
background_core_dump             string    partial
background_dump_dest             string    /u01/app/oracle/diag/rdbms/tes
                        tdb/testdb/trace
core_dump_dest                 string    /u01/app/oracle/diag/rdbms/tes
                        tdb/testdb/cdump
max_dump_file_size             string    unlimited
shadow_core_dump             string    partial
user_dump_dest                 string    /u01/app/oracle/diag/rdbms/tes
                        tdb/testdb/trace
SQL>

Subscribe to posts

Tracing a Parallel Query

posted Apr 22, 2012, 12:32 PM by Sachchida Ojha [ updated Apr 22, 2012, 12:37 PM ]

You can get an event 10046 trace for a parallel query in the same way as you would for any other query.The only difference is that the 10046 event will generate as many trace file as the number of parallel query servers.

SQL> alter session set tracefile_identifier='MyPxTune1';

SQL> alter session set events '10046 trace name context forever, level 12';

SQL> select /*+ parallel (dtc, 16) */ count(1) from dba_tab_columns dtc;

COUNT(1)
----------
88069

================================================================================================
if you want to trace a specific parallel query processes then

SQL> alter system set event 'sql_trace {process: pname = p0002 | p003}';

SQL> alter system set event 'sql_trace {process: pname = p0002 | p003} off';

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

SQL> alter session set events '10046 trace name context off';

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
********************************************************************************

1-2 of 2