Mohamed Houri’s Oracle Notes

April 22, 2014

Trouble shooting a performance issue

Filed under: Trouble shooting — hourim @ 2:34 pm

Here it is a case of Trouble shooting a performance issue taken from a real life production system that I wanted to share with you. There is an Oracle stored procedure continuously activated via a scheduled job. Its goal is to parse incoming XML messages before accepting them into or rejecting them from a production application. 80% of the XML messages are treated in an acceptable execution time. But 20% of those messages when injected into the queue are hanging and slowing down the database with a side effect on the execution time of the normal messages. My strategy was to ask for one of those problematic XML messages from PRODUCTION instance and execute it in the TEST data base with a 10046 trace file. So I did, and among many observations, I stopped at the following select I wanted to share with you the method I followed to trouble shoot it:

SELECT *
FROM
 ( SELECT WD.WAGD_ID,WH.WAGH_ID,WD.WAG_ID,WH.ARRIVAL_DATE,WH.DEPARTURE_DATE,
  WD.CHECK_REPERAGE ,ROW_NUMBER() OVER (PARTITION BY WH.WAGD_ID ORDER BY
  WH.ARRIVAL_DATE) RN FROM SRI_ORDER_DETAILS WD ,SRI_ORDER_HISTORIC WH
  WHERE WD.FROM_COM_ID = :B1 AND WD.WAGD_ID = WH.WAGD_ID AND WH.PDES_ID IS
  NULL ) WHERE RN = 1 

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute   3124      0.28       0.27          0          0          0           0
Fetch     3124     31.79      32.05          0   10212356          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     6250     32.07      32.33          0   10212356          0           0

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 151     (recursive depth: 1)
Number of plan statistics captured: 2

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  VIEW  (cr=3269 pr=0 pw=0 time=14483 us cost=709 size=1245 card=15)
         0          0          0   WINDOW SORT PUSHED RANK (cr=3269 pr=0 pw=0 time=14480 us cost=709 size=660 card=15)
         0          0          0    MERGE JOIN  (cr=3269 pr=0 pw=0 time=14466 us cost=708 size=660 card=15)
         0          0          0     TABLE ACCESS BY INDEX ROWID SRI_ORDER_DETAILS (cr=3269 pr=0 pw=0 time=14464 us cost=532
     15139      15139      15139       INDEX FULL SCAN SRI_WAGD_PK (cr=2822 pr=0 pw=0 time=2305 us cost=80 size=0
         0          0          0     SORT JOIN (cr=0 pr=0 pw=0 time=0 us cost=176 size=320528 card=12328)
         0          0          0      TABLE ACCESS FULL SRI_ORDER_HISTORIC (cr=0 pr=0 pw=0 time=0 us cost=67 size=320528
********************************************************************************

Notice that the above select undergone 3,124 executions which have necessitated more than one million of logical reads to end up finally by producing 0 records. There is for sure a way to reduce this enormous waste of time and energy in manipulating non necessary millions of logical I/O. My experience in trouble shooting performance issues shows me that this kind of excessive logical I/O can be very often linked to two situations:

  •  Use of a not very precise index to access a table via an index rowid and throwing away the majority of rows
  •  The first operation of the plan is the one that manipulated the big number of rows in the entire row source execution plan

Coincidently, the first operation in my row source plan is an INDEX FULL SCAN and it is the operation generating the maximum number of rows (15,139). Well, now I can say that in order to tune this select I need first to have a more precise access to the SRI_ORDER_DETAILS table. Here how I managed to solve this issue:

1. Get a real time execution plan from memory

The desired execution plan confirming the row source stats from the Tkprof file is given here below:

----------------------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name                | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |                     |      1 |        |      1 |00:00:00.03 |    3469 |
|*  1 |  VIEW                          |                     |      1 |     13 |      1 |00:00:00.03 |    3469 |
|*  2 |   WINDOW SORT PUSHED RANK      |                     |      1 |     13 |      1 |00:00:00.03 |    3469 |
|   3 |    MERGE JOIN                  |                     |      1 |     13 |      1 |00:00:00.03 |    3469 |
|*  4 |     TABLE ACCESS BY INDEX ROWID| SRI_ORDER_DETAILS   |      1 |     13 |      1 |00:00:00.02 |    3269 |
|   5 |      INDEX FULL SCAN           | SRI_WAGD_PK         |      1 |  15139 |  15139 |00:00:00.01 |    2822 |
|*  6 |     SORT JOIN                  |                     |      1 |  13410 |      1 |00:00:00.01 |     200 |
|*  7 |      TABLE ACCESS FULL         | SRI_ORDER_HISTORIC  |      1 |  13410 |  13410 |00:00:00.01 |     200 |
----------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("RN"=1)
   2 - filter(ROW_NUMBER() OVER ( PARTITION BY "WH"."WAGD_ID" ORDER BY "WH"."ARRIVAL_DATE")<=1)
   4 - filter("WD"."FROM_COM_ID"=3813574)
   6 - access("WD"."WAGD_ID"="WH"."WAGD_ID")
       filter("WD"."WAGD_ID"="WH"."WAGD_ID")
   7 - filter("WH"."PDES_ID" IS NULL)

We identify a lot of data (15,139) by FULL SCANNING the primary key index SRI_WAGD_PK . The identified rows via the single PK column (wagd_id) index (operation n°5) are sent back to their parent operation (n°4) which wasted a lot of effort throwing away the entire set of generated rows (except one row for the bind variable I used during my test) by applying filter n°4 (FROM_COM_ID). Notice also how the CBO has made a complete mess of the cardinality estimate for the SORT JOIN operation n°6.

Now that the symptoms have been clearly identified next will be presented the solution

2. Create a new precise index

The solution that immediately came to my mind is to create an index with the FROM_COM_ID column. I was just wondering on how best is to design it?

  •  Using a single column index
  • Or a composite index
  •  And  in case of a composite index will the FROM_COM_ID be put at the beginning of the index or not?

As far as the single PK index contains the WAGD_ID column I was tended to create a composite index starting by the FROM_COM_ID. Something which resembles to this:

SQL> create index mho_test on SRI_ORDER_DETAILS(FROM_COM_ID, wagd_id);

Index created.

SQL> exec dbms_stats.gather_table_stats(user, 'SRI_ORDER_DETAILS', cascade => true, no_invalidate=> false);

PL/SQL procedure successfully completed.

When I re-queried again, the new row source execution plan looked like:

-----------------------------------------------------------------------------------------------------------------------
| Id  | Operation                       | Name                      | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-----------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                |                           |      1 |        |      1 |00:00:00.01 |       7 |
|*  1 |  VIEW                           |                           |      1 |     13 |      1 |00:00:00.01 |       7 |
|*  2 |   WINDOW SORT PUSHED RANK       |                           |      1 |     13 |      1 |00:00:00.01 |       7 |
|   3 |    NESTED LOOPS                 |                           |      1 |        |      1 |00:00:00.01 |       7 |
|   4 |     NESTED LOOPS                |                           |      1 |     13 |      1 |00:00:00.01 |       6 |
|   5 |      TABLE ACCESS BY INDEX ROWID| SRI_ORDER_DETAILS         |      1 |     13 |      1 |00:00:00.01 |       3 |
|*  6 |       INDEX RANGE SCAN          | MHO_TEST                  |      1 |     13 |      1 |00:00:00.01 |       2 |
|*  7 |      INDEX RANGE SCAN           | SRI_WAGH_ARRIVAL_DATE_UK  |      1 |      1 |      1 |00:00:00.01 |       3 |
|*  8 |     TABLE ACCESS BY INDEX ROWID | SRI_ORDER_HISTORIC        |      1 |      1 |      1 |00:00:00.01 |       1 |
-----------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("RN"=1)
   2 - filter(ROW_NUMBER() OVER ( PARTITION BY "WH"."WAGD_ID" ORDER BY "WH"."ARRIVAL_DATE")<=1)
   6 - access("WD"."FROM_COM_ID"=3813574)
   7 - access("WD"."WAGD_ID"="WH"."WAGD_ID")
   8 - filter("WH"."PDES_ID" IS NULL)

Thanks to this new precise index(MHO_TEST ) we have drastically reduced the total number of logical reads (from 3,469 to 7) and the estimations done by the CBO are almost acceptable which made the CBO prefering a more convenient NESTED LOOPS instead of the previous inadequately estimated SORT JOIN operation.

3. Conclusion

When trouble shooting performance issue in real life production system, look carefully at INDEX access operations that generate a lot of rows and for which the parent table access operation is discarding the majority of those corresponding rows. In such case there is certainly a way to create a precise index which not only will avoid that waste of effort but might conduct the CBO to have better estimations and hence an optimal plan

About these ads

3 Comments »

  1. Hi Hourim,

    Can you please explain why you have chosen a composite index over a normal index and in what cases a simple index be preferred over a composite index. Also is there any specific reason for choosing the column order in your composite index.

    Thanks and Regards,
    Vishith

    Comment by vishith — April 24, 2014 @ 1:58 am | Reply

  2. Vishith,

    Good question.

    Trouble shooting is a process that might pass through several steps. First, I have identified a problematic index full scan doing 2822 Buffers reads that needs to be re-engineered as shown below:

    ---------------------------------------------------------------------------------------------------
    | Id  | Operation                      | Name                | Starts | E-Rows | A-Rows | Buffers |
    ---------------------------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT               |                     |      1 |        |      1 |    3469 |
    |*  1 |  VIEW                          |                     |      1 |     13 |      1 |    3469 |
    |*  2 |   WINDOW SORT PUSHED RANK      |                     |      1 |     13 |      1 |    3469 |
    |   3 |    MERGE JOIN                  |                     |      1 |     13 |      1 |    3469 |
    |*  4 |     TABLE ACCESS BY INDEX ROWID| SRI_ORDER_DETAILS   |      1 |     13 |      1 |    3269 |
    |   5 |      INDEX FULL SCAN           | SRI_WAGD_PK         |      1 |  15139 |  15139 |    2822 |
    |*  6 |     SORT JOIN                  |                     |      1 |  13410 |      1 |     200 |
    |*  7 |      TABLE ACCESS FULL         | SRI_ORDER_HISTORIC  |      1 |  13410 |  13410 |     200 |
    ---------------------------------------------------------------------------------------------------
    
    Predicate Information (identified by operation id):
    ---------------------------------------------------
       1 - filter("RN"=1)
       2 - filter(ROW_NUMBER() OVER ( PARTITION BY "WH"."WAGD_ID" ORDER BY "WH"."ARRIVAL_DATE")<=1)
       4 - filter("WD"."FROM_COM_ID"=3813574)
       6 - access("WD"."WAGD_ID"="WH"."WAGD_ID")
           filter("WD"."WAGD_ID"="WH"."WAGD_ID")
       7 - filter("WH"."PDES_ID" IS NULL) 
    

    As far as I prefer keeping the PK index intact, I then have opted for a composite index that includes the primary key column plus the FROM_COM_ID

    SQL> create index MHO_TESTon SRI_ORDER_details (wagd_id,from_com_id);
    
    ----------------------------------------------------------------------------------------------------------
    | Id  | Operation                       | Name                      | Starts | E-Rows | A-Rows | Buffers |
    ----------------------------------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT                |                           |      1 |        |      1 |      52 |
    |*  1 |  VIEW                           |                           |      1 |     13 |      1 |      52 |
    |*  2 |   WINDOW SORT PUSHED RANK       |                           |      1 |     13 |      1 |      52 |
    |   3 |    NESTED LOOPS                 |                           |      1 |        |      1 |      52 |
    |   4 |     NESTED LOOPS                |                           |      1 |     13 |      1 |      51 |
    |   5 |      TABLE ACCESS BY INDEX ROWID| SRI_ORDER_DETAILS         |      1 |     13 |      1 |      48 |
    |*  6 |       INDEX SKIP SCAN           | MHO_TEST                  |      1 |     13 |      1 |      47 |
    |*  7 |      INDEX RANGE SCAN           | SRI_WAGH_ARRIVAL_DATE_UK  |      1 |      1 |      1 |       3 |
    |*  8 |     TABLE ACCESS BY INDEX ROWID | SRI_ORDER_HISTORIC        |      1 |      1 |      1 |       1 |
    ----------------------------------------------------------------------------------------------------------
    
    Predicate Information (identified by operation id):
    ---------------------------------------------------
       1 - filter("RN"=1)
       2 - filter(ROW_NUMBER() OVER ( PARTITION BY "WH"."WAGD_ID" ORDER BY "WH"."ARRIVAL_DATE")<=1)
       6 - access("WD"."FROM_COM_ID"=3813574)
           filter("WD"."FROM_COM_ID"=3813574)
       7 - access("WD"."WAGD_ID"="WH"."WAGD_ID")
       8 - filter("WH"."PDES_ID" IS NULL)
    

    Which makes the CBO doing good estimation and consuming less Buffers reads(47). But skiping an index is always an indication that a better index can be created. This is why I have opted for a new index by reversing the columns order of the preceding one

    
    SQL> create index MHO_TEST on SRI_ORDER_details (from_com_id, wagd_id);
    
    ----------------------------------------------------------------------------------------------------------
    | Id  | Operation                       | Name                      | Starts | E-Rows | A-Rows | Buffers |
    ----------------------------------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT                |                           |      1 |        |      0 |       2 |
    |*  1 |  VIEW                           |                           |      1 |      1 |      0 |       2 |
    |*  2 |   WINDOW SORT PUSHED RANK       |                           |      1 |      1 |      0 |       2 |
    |   3 |    NESTED LOOPS                 |                           |      1 |        |      0 |       2 |
    |   4 |     NESTED LOOPS                |                           |      1 |      1 |      0 |       2 |
    |   5 |      TABLE ACCESS BY INDEX ROWID| SRI_ORDER_DETAILS         |      1 |      1 |      0 |       2 |
    |*  6 |       INDEX RANGE SCAN          | MHO_TEST                  |      1 |      1 |      0 |       2 |
    |*  7 |      INDEX RANGE SCAN           | SRI_WAGH_ARRIVAL_DATE_UK  |      0 |      1 |      0 |       0 |
    |*  8 |     TABLE ACCESS BY INDEX ROWID | SRI_ORDER_HISTORIC        |      0 |      1 |      0 |       0 |
    ----------------------------------------------------------------------------------------------------------
    
    Predicate Information (identified by operation id):
    ---------------------------------------------------
    
       1 - filter("RN"=1)
       2 - filter(ROW_NUMBER() OVER ( PARTITION BY "WH"."WAGD_ID" ORDER BY "WH"."ARRIVAL_DATE")<=1)
       6 - access("WD"."FROM_COM_ID"=73076178)
       7 - access("WD"."WAGD_ID"="WH"."WAGD_ID")
       8 - filter("WH"."PDES_ID" IS NULL)
    

    With this final index I reached my desire.

    I have also tried a single column (from_com_id ) index with satisfactory results. But I have preferred a composite index because there are many other queries that could benefit from that composite index.

    I can continue exposing for you all questions that I have asked myself during this simple ‘’index re-design’’ but I prefer leaving that for another article in next future I hope.

    Best regards

    Comment by hourim — April 24, 2014 @ 7:32 am | Reply

    • Thank you so much sir for the detailed explanation. Looking forward for more such fantastic articles.

      Regards,
      Vishith

      Comment by vishith — April 25, 2014 @ 6:41 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

Theme: Rubric. Get a free 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

Carlos Sierra's Tools and Tips

Tools and Tips for Oracle Performance and SQL Tuning

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 100 other followers

%d bloggers like this: