Sunday, July 3, 2011

AWR Analysis : Case Study -1


AWR Analysis : Case Study -1


WORKLOAD REPOSITORY report for


DB Name         DB Id    Instance     Inst Num Release     Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
MDAIRY        1781870750 XXInstance              1 10.1.0.2.0  NO      XXInstanceHost


              Snap Id      Snap Time      Sessions Curs/Sess
            --------- ------------------- -------- ---------
Begin Snap:     48641 25-Apr-11 11:30:48       218   1,359.6
  End Snap:     48642 25-Apr-11 12:30:08       221   1,347.4
   Elapsed:               59.33 (mins)
   DB Time:               31.25 (mins)
 =======================================================================================================  
   Comments(saptarshi) : If "DB Time"  is much higher than the elapsed time, then it indicates that
the sessions are waiting for something.
But here it's not the case. So session is running fine.
=========================================================================================================
Cache Sizes (end)
~~~~~~~~~~~~~~~~~
               Buffer Cache:       156M      Std Block Size:         8K
           Shared Pool Size:       252M          Log Buffer:       512K


Load Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:              3,216.33              3,580.20
              Logical reads:             21,037.27             23,417.28
              Block changes:                 20.19                 22.48
             Physical reads:              1,178.14              1,311.42
            Physical writes:                 40.83                 45.45
                 User calls:                136.41                151.84
                     Parses:                 34.05                 37.91
                Hard parses:                  2.44                  2.71
                      Sorts:                  8.95                  9.96
                     Logons:                  0.06                  0.06
                   Executes:                 33.45                 37.23
               Transactions:                  0.90


  % Blocks changed per Read:    0.10    Recursive Call %:    50.04
 Rollback per transaction %:   10.54       Rows per Sort:  1654.72


Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
            Buffer Nowait %:   99.99       Redo NoWait %:   99.99
            Buffer  Hit   %:   94.59    In-memory Sort %:   99.95
            Library Hit   %:   96.09        Soft Parse %:   92.84
         Execute to Parse %:   -1.82         Latch Hit %:   99.96
Parse CPU to Parse Elapsd %:   88.85     % Non-Parse CPU:   92.51


=================================================================================================================
Comments(saptarshi) : (1) As per the thumb rule, Instance Efficieny Percentages should be ideally above 90%.
                          Here it's satisfying the rule. So no CPU bottleneck.
                       (2) Execute to Parse %:   -1.82: 
                       Cause
Low values for execute to parse can frequently be attributed to application design.
      That means the PARSES are greater than or equal to the EXECUTES.  The formula used it:


      ,'         Execute to Parse %:'                  dscr
      , round(100*(1-:prse/:exe),2)                    pctval


As prse = exe, the execute/parse % goes to ZERO.  As prse starts to exceed executes, the 
% goes NEGATIVE.


This happens when an application parses a query but never executes it.  Some applications 
(generic apps typically) parse a "select * from T" to describe a table, never execute the 
cursor -- their parses exceed their executes.  


The soft parse ratio is good cause they parse "select * from t" hundreds of times -- and 
each parse is in fact a soft parse.  They just parse way too much.


A soft parse happens during the PARSE.  You never need execute the query to increase the 
soft parse count.  So the two are not really related in any way.  You can have a low 
execute to parse with a high soft parse ratio, you can have a high execute to parse with 
ah low soft parse ratio as well.  They are two indicators that you look at independent of 
each other.
========
Solution
========


1) examines the CURSOR_SHARING parameter, SESSION_CACHED_CURSORS, and CURSOR_SPACE_FOR_TIME.


It looks at four application scenarios in the context of the above parameters :-


1) Not using bind variables at all
2) Cursor open, parse with bind variables, execute (fetch) and close for each SQL statement
3) Cursor open once, repeating parse with bind variables, execute (fetch) for each SQL statement
4) Cursor open and parse with bind variables once, repeated executes (fetch)


See Oracle Metalink Note: ID 307825.1


============================================================================================
 Shared Pool Statistics        Begin    End
                              ------  ------
             Memory Usage %:   89.68   88.14
    % SQL with executions>1:   38.70   40.54
  % Memory for SQL w/exec>1:   39.77   38.64
  
 =================================================================================================================== 
 Comments(saptarshi) Idealy this should be lesser. If it is very high like beyond 90, this shows the contention
in the shared pool.That way this is OK. Still may be little increase in shared pool size could be tried.
=====================================================================================================================


Top 5 Timed Events
~~~~~~~~~~~~~~~~~~                                        % Total
Event                                 Waits    Time (s)   DB Time     Wait Class
------------------------------ ------------ ----------- --------- --------------
CPU time                                          1,022     54.51
db file sequential read             447,526         562     29.96       User I/O
db file scattered read              481,008         254     13.56       User I/O
direct path read temp                18,432          36      1.94       User I/O
read by other session                 8,090          14       .76       User I/O
          -------------------------------------------------------------
^LWait Events  DB/Inst: MDAIRY/XXInstance  Snaps: 48641-48642
-> s  - second
-> cs - centisecond -     100th of a second
-> ms - millisecond -    1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)


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


Comments(Saptarshi) :


The Streams capture process is observed to be running extremely slowly in 10.1 and 10.2 Streams.  
This  AWR report reveals that the top wait event for the instance is 'CPU time'.  
Please investigate the SQLs.
If that says that the biggest contributor to the CPU time, is execution of a procedure called SYS.LOGMNR_GTLO3 
then This behavior is caused by the following unpublished bug:


Bug 5135907 "STREAMS CAPTURE SLOW WHEN OBJECT DEFINITION IS NOT IN DICTIONARY".




After application of this patch, performance of the capture process in systems affected by the bug has been observed to increase many orders of magnitude.
Solution


This bug can occur in 10.1 and 10.2, and is fixed in 10.2.0.3 and higher.  
It is also fixed in version 11.0.  
If on 10.1 and a one-off patch cannot be found on Metalink for the necessary patchset level and platform, 
a one-off patch can be requested via Oracle Support Services.  
If on 10.2, the 10.2.0.3 patchset should be applied to resolve the problem.


                                                                   Avg
                                                    Total Wait    wait     Waits
Event                              Waits   Timeouts   Time (s)    (ms)      /txn
--------------------------- ------------ ---------- ---------- ------- ---------
db file sequential read          447,526          0        562       1     139.9
db file scattered read           481,008          0        254       1     150.4
direct path read temp             18,432          0         36       2       5.8
read by other session              8,090          0         14       2       2.5
direct path write temp             7,605          0         11       1       2.4
log file parallel write            3,900          0          7       2       1.2
control file parallel write        1,173          0          7       6       0.4
Queue Monitor Task Wait                1          1          5    5000       0.0
class slave wait                       1          1          5    5000       0.0
log file sync                      2,662          0          4       2       0.8
SQL*Net more data to client      152,830          0          3       0      47.8
db file parallel write               357          0          3       9       0.1
control file sequential rea          521          0          1       3       0.2
latch: cache buffers chains          290        262          1       3       0.1
SQL*Net message to client        485,752          0          0       0     151.9
log file sequential read              14          0          0      10       0.0
process startup                        3          0          0      22       0.0
latch: cache buffers lru ch          329          0          0       0       0.1
log file switch completion             1          0          0      40       0.0
latch free                            14          0          0       3       0.0
SQL*Net more data from clie          466          0          0       0       0.1
latch: shared pool                    20          0          0       1       0.0
direct path write                     63          0          0       0       0.0
log file single write                  2          0          0       4       0.0
direct path read                      48          0          0       0       0.0
db file parallel read                  1          0          0       6       0.0
log buffer space                       3          0          0       2       0.0
LGWR wait for redo copy               86          0          0       0       0.0
latch: library cache                  18          0          0       0       0.0
ksfd: async disk IO                    1          0          0       4       0.0
control file single write              4          0          0       1       0.0
SQL*Net break/reset to clie            2          0          0       0       0.0
rdbms ipc reply                        1          0          0       0       0.0
buffer busy waits                      3          0          0       0       0.0
enq: CF - contention                   1          0          0       0       0.0
latch: session allocation              1          0          0       0       0.0
SQL*Net message from client      485,749          0     62,850     129     151.9
Queue Monitor Slave Wait           1,349          0      8,019    5944       0.4
jobq slave wait                    2,359      2,300      6,941    2942       0.7
Queue Monitor Wait                 1,158        605      3,473    3000       0.4
virtual circuit status               119        119      3,459   29068       0.0
wakeup time manager                   16          4      3,458  216126       0.0
          -------------------------------------------------------------
                                                    Total Wait    wait     Waits
Event                              Waits   Timeouts   Time (s)    (ms)      /txn
--------------------------- ------------ ---------- ---------- ------- ---------
log file parallel write            3,900          0          7       2       1.2
control file parallel write        1,173          0          7       6       0.4
Queue Monitor Task Wait                1          1          5    5000       0.0
db file sequential read            3,544          0          5       1       1.1
db file parallel write               357          0          3       9       0.1
control file sequential rea          474          0          1       3       0.1
db file scattered read               240          0          1       3       0.1
log file sequential read              14          0          0      10       0.0
process startup                        3          0          0      22       0.0
direct path write                     30          0          0       1       0.0
log file single write                  2          0          0       4       0.0
direct path read                      33          0          0       0       0.0
LGWR wait for redo copy               86          0          0       0       0.0
ksfd: async disk IO                    1          0          0       4       0.0
control file single write              4          0          0       1       0.0
latch: shared pool                     1          0          0       2       0.0
rdbms ipc reply                        1          0          0       0       0.0
latch: library cache                   1          0          0       0       0.0
enq: CF - contention                   1          0          0       0       0.0
latch: cache buffers lru ch            2          0          0       0       0.0
latch free                             1          0          0       0       0.0
rdbms ipc message                 13,518     10,026     34,606    2560       4.2
Queue Monitor Wait                 1,158        605      3,473    3000       0.4
wakeup time manager                   16          4      3,458  216126       0.0
smon timer                            12         11      3,288  273993       0.0
Queue Monitor Slave Wait             264          0      1,616    6120       0.1
          -------------------------------------------------------------
==========================================================================================================


Comments ( Saptarshi) (a) db file sequential read: on the higher side:
Starting in Oracle 10g release2, Oracle recommends not setting the db_file_multiblock_read_count 
parameter, allowing Oracle to empirically determine the optimal setting. 
Check your db setting.




(b) db file scattered read : on the higher side


Here we see that reads and a write constitute the majority of the total database time. 
In this case, we would want to increase the RAM size of the db_cache_size to reduce disk I/O, 
tune the SQL to reduce disk I/O, or invest in a faster disk I/O subsystem.


Tablespace
------------------------------
                 Av      Av     Av                       Av     Buffer Av Buf
         Reads Reads/s Rd(ms) Blks/Rd       Writes Writes/s      Waits Wt(ms)
-------------- ------- ------ ------- ------------ -------- ---------- ------
IDIS
       516,276     145    0.9     5.0          698        0      7,227    1.7
FAS
       262,356      74    0.6     3.3          238        0          0    0.0
USERS
        89,830      25    1.1     5.9           29        0        863    2.6
SYSTEM
        57,675      16    1.3     1.1          389        0          0    0.0
NEWTEMP
        17,867       5   11.9     8.0        7,333        2          0    0.0
SYSAUX
         1,896       1    3.9     1.6          550        0          0    0.0
UNDOTBS1
           222       0    3.8     1.0          236        0          3    0.0
HRMS
           168       0    8.0     2.4            2        0          0    0.0
HRMS_IND
            22       0    6.4     4.2            1        0          0    0.0
FAS_LIVE_IND
            20       0   12.0     1.0            1        0          0    0.0
HRMS_LIVE
            19       0    8.9     1.0            1        0          0    0.0
DIST
             1       0  100.0     1.0            1        0          0    0.0
PROD_OLD
             1       0  100.0     1.0            1        0          0    0.0
STATSPACK
             1       0  100.0     1.0            1        0          0    0.0
TEST
             1       0  100.0     1.0            1        0          0    0.0
RMAN_D
             1       0  100.0     1.0            1        0          0    0.0
PROD
             1       0  100.0     1.0            1        0          0    0.0


IDIS_DEVELOPMENT
             1       0  100.0     1.0            1        0          0    0.0
MATL_OLD
             1       0  100.0     1.0            1        0          0    0.0
PAY
             1       0  100.0     1.0            1        0          0    0.0
MDPAY_OLD
             1       0  100.0     1.0            1        0          0    0.0
FAS_OLD
             1       0  100.0     1.0            1        0          0    0.0
          -------------------------------------------------------------

No comments:

Post a Comment