Mohamed Houri’s Oracle Notes

May 25, 2012

Tuning a batch job using AWR

Filed under: Trouble shooting — hourim @ 10:16 am
Tags:

We received a complaint from a customer about a weekly scheduled overnight oracle job which took 14 hours to get at its normal end during its last execution.  The same job has been smoothly running in about 14 minutes for the past several months. So what went wrong this time?

A 30 minutes AWR snapshots report collected during the execution of the last job execution look like:

        Snap Id      Snap Time      Sessions Curs/Sess
           --------- ------------------- -------- ---------
Begin Snap:     16178 21-May-12 07:00:09       292       2.9
  End Snap:     16179 21-May-12 07:30:16       294       2.9
   Elapsed:               30.11 (mins)
   DB Time:               48.68 (mins)

Cache Sizes                       Begin        End
~~~~~~~~~~~                  ---------- ----------
               Buffer Cache:    10,752M    10,752M  Std Block Size:         8K
           Shared Pool Size:     7,744M     7,744M      Log Buffer:    53,972K

Load Profile              Per Second    Per Transaction   Per Exec   Per Call
~~~~~~~~~~~~         ---------------    --------------- ---------- ----------
      DB Time(s):                1.6                0.8       0.01       0.01
       DB CPU(s):                0.9                0.4       0.01       0.00
       Redo size:           36,781.3           18,374.5
   Logical reads:           86,607.6           43,265.8
   Block changes:              172.5               86.2
  Physical reads:            2,590.0            1,293.9
 Physical writes:               26.0               13.0
      User calls:              223.3              111.5
          Parses:               92.0               46.0
     Hard parses:                2.8                1.4
W/A MB processed:                1.6                0.8
          Logons:                0.2                0.1
        Executes:              108.3               54.1
       Rollbacks:                0.0                0.0
    Transactions:                2.0

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
            Buffer Nowait %:  100.00       Redo NoWait %:  100.00
            Buffer  Hit   %:   99.69    In-memory Sort %:  100.00
            Library Hit   %:   93.95        Soft Parse %:   96.91
         Execute to Parse %:   15.02         Latch Hit %:   97.14
Parse CPU to Parse Elapsd %:   82.80     % Non-Parse CPU:   97.99

 Shared Pool Statistics        Begin    End
                              ------  ------
             Memory Usage %:   76.47   75.97
    % SQL with executions>1:   98.62   97.70
  % Memory for SQL w/exec>1:   95.92   94.74

Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                           Avg
                                                          wait   % DB
Event                                 Waits     Time(s)   (ms)   time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
DB CPU                                            1,561          53.4
db file sequential read             275,799         691      3   23.7 User I/O
direct path read                     32,996         560     17   19.2 User I/O
db file parallel read                   720         124    173    4.3 User I/O
db file scattered read                8,488          20      2     .7 User I/O

So what to spot from that?

The direct path read wait event look suspect: 32,996 waits at a catastrophic 17 ms per wait. This represents about 9 minutes (32,996 * 17/1000)/60. The db file sequential read wait event may be here in this situation a necessary step for the smooth accomplishment of the desired work.  This is why I was quite confident that the direct path is the wait event on which effort should be concentrated in this particular situation.

Before embarking on this direct path read wait event, I would have to say few words about the CPU consumption. The AWR elapsed time is 30.11 minutes and the CPU time as reported in the Top 5 events is 1,561 seconds. Dividing these two metrics gives (1,806.6/1,561) 1.15 CPU at 100% utilisation. Since, this server was running under 32 CPU cores then the data base server was not CPU bound (1,15/32) = 3.6% CPU utilisation.

Since I have been confirmed that neither the PL/SQL code nor the data volume has changed, I have then asked to have the last week AWR report taken at the same time when the job was running.  The corresponding Top 5 Timed Foreground Events are shown below:


 Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                           Avg
                                                          wait   % DB
Event                                 Waits     Time(s)   (ms)   time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
DB CPU                                            1,082          54,01
db file sequential read               717,957       936      1   46.7  User I/O
direct path read                          371         6     15    0.28 User I/O
db file parallel read                   3,347         4    173    0.18 User I/O
db file scattered read                  2,852         3      2    0.14 User I/O

from where it can be easily pointed out that, in normal job execution, the direct path read wait contribution to the total execution time is ridiculous: 0,28% (0,09 minutes) while it contributed by 19% (9 minutes) to the total execution time during the last job execution.  So what makes the direct path wait event increase by this very high magnitude so that it altered the performance of the overnight job?

My suspicions were still good!!!

The part of the AWR report that has a correlation with the direct path read event and which is worth investigating is SQL ordered by reads, Segments by physical reads and (if in 11gR1 or higher),  Segments by direct physical reads.

 When I drill down up to the SQL ordered by reads I found this:

Physical Reads Executions  Reads per Exec  %Total Elapsed Time (s) %CPU %IO   QL Id         Module
-------------- ----------- --------------  ------ ---------------  ---- ----  ------------- ---------
  4,164,466     1           4,164,466.00    89.0   811.1           21.6 82.9 d6w4psbcwgt54  TOAD 9.7.2.5
 

Without mentioning the sql text behind this, what kind of overnight batch this job is as far as it has reported using a huge amount of physical read coming from TOAD ?  Is this sql issued from TOAD a part of the job? The answer was of course not.

So, clearly someone was issuing a huge query using TOAD which was doing a huge amount of direct path read consuming a lot of CPU resource that usually was only dedicated to the db file sequential read of that job.

Segments by direct physical read AWR part shows also correlated information :

-> Total Direct Physical Reads:       4,209,804
-> Captured Segments account for   51.7% of Total
            Tablespace                      Subobject  Obj.        Direct
Owner         Name    Object Name            Name     Type         Reads  %Total
---------- ---------- -------------------- ---------- ----- ------------ -------
MHOADM     MHOMH_2011 MH_TABLES            TABLES_SX5 TABLE      349,197    8.29
MHOADM     MHOMH_2010 MH_TABLES            TABLES_SX5 TABLE      345,069    8.20
MHOADM     MHOMH_2009 MH_TABLES            TABLES_SX1 TABLE      275,781    6.55
MHOADM     MHOMH_2010 MH_TABLES            TABLES_SX1 TABLE      272,709    6.48
MHOADM     MHOMH_2011 MH_TABLES            TABLES_SX1 TABLE      265,037    6.30
          -------------------------------------------------------------

Where TABLES_SX5 is the table used by the same sql_id d6w4psbcwgt54 issued from TOAD and reported above.
Finally it becomes clear that the job has been in CPU concurrency with an abnormal and unusual select issued from TOAD.  The ADDM report that goes with the corresponding AWR also presents the TOAD sql_id d6w4psbcwgt54 as a Top SQL Statements to be tuned:

 Recommendation 1: SQL Tuning
   Estimated benefit is .46 active sessions, 28.18% of total activity.
   -------------------------------------------------------------------
   Action
      Run SQL Tuning Advisor on the SELECT statement with SQL_ID
      "d6w4psbcwgt54".
      Related Object
         SQL statement with SQL_ID d6w4psbcwgt54.     
   Rationale
      The SQL spent 100% of its database time on CPU, I/O and Cluster waits.
      This part of database time may be improved by the SQL Tuning Advisor.
   Rationale
      Database time for this SQL was divided as follows: 100% for SQL
      execution, 0% for parsing, 0% for PL/SQL execution and 0% for Java
      execution.
   Rationale
      SQL statement with SQL_ID "d6w4psbcwgt54" was executed 1 times and had
      an average elapsed time of 811 seconds.
   Rationale
      At least one execution of the statement ran in parallel.

   Recommendation 2: SQL Tuning
   Estimated benefit is .19 active sessions, 11.68% of total activity.

Action
      Look at the "Top SQL Statements" finding for SQL statements consuming
      significant I/O on this segment. For example, the SELECT statement with
      SQL_ID "d6w4psbcwgt54" is responsible for 100% of "User I/O" and
      "Cluster" waits for this segment.

   Rationale
      The I/O usage statistics for the object are: 9 full object scans, 277587
      physical reads, 0 physical writes and 275781 direct reads.
 

The ADDM report gives an additional credit to my suspicion when it recommends to investigate process that do not belong to this instance running on the host and consuming significant amount of virtual memory.  ADDM has identified the TOAD query; hasn’t it?

 Recommendation 1: Host Configuration
   Estimated benefit is 1.62 active sessions, 100% of total activity.
   ------------------------------------------------------------------
   Action
      Host operating system was experiencing significant paging but no
      particular root cause could be detected. Investigate processes that do
      not belong to this instance running on the host that are consuming
      significant amount of virtual memory. Also consider adding more physical
      memory to the host.
About these ads

5 Comments »

  1. Excellent, I love these kind of story.
    Did you get the who/why this sql was ran by toad during the night and its purpose?

    Comment by françois — May 25, 2012 @ 8:02 pm | Reply

  2. Bonjour François,

    No I didn’t. I have just been confirmed that the immediate subsequent run of this job has been accomplished in it’s normal execution time (14 minutes)

    Best Regards

    Mohamed Houri

    Comment by hourim — May 26, 2012 @ 6:24 am | Reply

    • Ok thanks, as a toad user I was curious about it. By the way I enjoyed your translation about clustering factor

      Comment by Francois — May 26, 2012 @ 7:08 am | Reply

  3. I thoroughly enjoyed this because of your correlating the different segments of AWR with reasoning. Keep it up. Please also point out more test cases like these.

    Comment by Fahd Mirza — July 23, 2012 @ 11:23 pm | Reply

  4. Fahd Mirza,

    Thanks a lot for your encouraging words.

    Cheers

    Mohamed Houri

    Comment by Mohamed Houri — July 24, 2012 @ 11:03 am | Reply


RSS feed for comments on this post. TrackBack URI

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

The Rubric Theme. Blog at WordPress.com.

Mohamed Houri’s Oracle Notes

Qui se conçoit bien s’énonce clairement

Oracle Database 11g

Oracle Database

Raheel's Blog

Things I have learnt as Oracle DBA

Coskan's Approach to Oracle

What I learned about Oracle

So Many Oracle Manuals, So Little Time

“Books to the ceiling, Books to the sky, My pile of books is a mile high. How I love them! How I need them! I'll have a long beard by the time I read them”—Lobel, Arnold. Whiskers and Rhymes. William Morrow & Co, 1988.

EU Careers info

Your career in the European Union

Oracle SQL Tuning Tools and Tips

SQL Tuning, eAdam, eDB360, SQLT, SQLHC

Oracle Scratchpad

Just another Oracle weblog

Tanel Poder's blog: Responsible data management

Linux, Oracle, Exadata and Hadoop.

OraStory

Dominic Brooks on Oracle Performance, Tuning, Data Quality & Sensible Design ... (Now with added Sets Appeal)

Follow

Get every new post delivered to your Inbox.

Join 81 other followers

%d bloggers like this: