« Learn from the smaller one's : Native support for ENUM Types | Main | Oracle 11GR2 Upgrade Resources »
Tuesday
Dec182012

When a Query runs slower on second execution - a possible side effect of cardinality feedback

After a successful migration from Oracle 10gR2 to Oracle 11gR2, I observed a very odd behavior executing a query; On first execution the query run fast - means 0.3 s; On second not faster but with tremendous reduced speed - approximate 20 s;

Now this behavior is the opposite I experienced with complex queries (lot of joins, lot of predicates) , the first time of execution needs the extra cost of hard parsing and disk reads if the data is not in cache. the second time even the query run initial several seconds it run in a fraction of a second.

The interesting thing was - if I changed the form of the query to enforce a hard reparse - the first time it run fast then the same - it was much slower on the second execution.

After some time of Analysis I made following  observations :

V$SQL

The V$SQL view showed two instances of the same SQL_ID :

SELECT s.Sql_Id
      ,s.Child_Number
      ,s.Executions
      ,s.Last_Active_Time
      ,s.User_Io_Wait_Time
      ,s.Object_Status
      ,s.Plan_Hash_Value
FROM   V$sql s
WHERE  s.Sql_Text LIKE 'SELECT /*+ FIRST_ROWS XX */ T1.SYNC_TIMESTMP, T1.CUSTNO, T1.XAFID_ID_IFX, T1.XAFID_CLASSIFIED%';

 

SQL_ID        CHILD_NUMBER EXECUTIONS LAST_ACTIVE_TIME USER_IO_WAIT_TIME OBJECT_STATUS       PLAN_HASH_VALUE
------------- ------------ ---------- ---------------- ----------------- ------------------- ---------------
9yggyzcv0qmar            0          1 22.11.2012 16:22                 0 VALID                     320084874
9yggyzcv0qmar            1          2 22.11.2012 16:31           3750311 VALID                    3847301186
SQL>

 

The first execution (CHILD_NUMBER = 0) didn't cause any remarkable User I/O Waits, the second cursor for this SQL generated shows a different PLAN_HASH_VALUE and a high user I/O wait time due to physical reads occured in the second plan;

The question now why oracle did generate a second plan? What was the triggering event for that? V$SQL did not give the answer ...

 

DBMS_XPLAN

This Package is great; Simple interface - just read the formatted output from a table function. The package reads the execution plan and additional metadata dependent on SQL_ID/Cursor-Number. These two Outputs have been generated using dbms_xplan;

The initial good execution plan - a pipelined function retrieves a rowset of customer id's for the given parent of a tree. In a nested loop the customer id's are passed/pushed to a view which then retrieves some customer ratings using indexes to access the rows. - skipped the SQL Code :

 

Plan hash value: 320084874
-------------------------------------------------------------------------------------------------------------
| Id  | Operation                            | Name                 | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                     |                      |       |       |    31 (100)|          |
|   1 |  NESTED LOOPS                        |                      |     5 |   560 |    31   (4)| 00:00:01 |
|   2 |   VIEW                               | VW_NSO_1             |     4 |    48 |    30   (4)| 00:00:01 |
|   3 |    HASH UNIQUE                       |                      |     4 |     8 |    30   (4)| 00:00:01 |
|*  4 |     COLLECTION ITERATOR PICKLER FETCH| CUSTOMERSTRUCT_LOAD  |     4 |     8 |    29   (0)| 00:00:01 |
|   5 |   VIEW                               |                      |     1 |   122 |     1   (0)| 00:00:01 |
|   6 |    UNION-ALL PARTITION               |                      |       |       |            |          |
|*  7 |     TABLE ACCESS BY INDEX ROWID      | XAFID_CLASS_IFX      |     1 |   122 |     1   (0)| 00:00:01 |
|*  8 |      INDEX RANGE SCAN                | XAFID_CLASS_IFX_UK01 |     1 |       |     1   (0)| 00:00:01 |

|*  9 |       INDEX UNIQUE SCAN              | XAFID_CLASS_APP_UK01 |     1 |    28 |     1   (0)| 00:00:01 |
|  10 |     TABLE ACCESS BY INDEX ROWID      | XAFID_CLASS_APP      |     1 |   116 |     1   (0)| 00:00:01 |
|* 11 |      INDEX RANGE SCAN                | XAFID_CLASS_APP_UK01 |     1 |       |     1   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   4 - filter((VALUE(KOKBF$) IS NULL AND VALUE(KOKBF$)=2))
   7 - filter("MCI"."SRC"='IFX')
   8 - access("MCI"."CUSTNO"="CUSTNO")
       filter( IS NULL)
   9 - access("MCI2"."CUSTNO"=:B1 AND "MCI2"."XAFID_ID_IFX"=:B2)
  11 - access("MCA"."CUSTNO"="CUSTNO")

The plan after 2nd execution : 

 Plan hash value: 3847301186

-------------------------------------------------------------------------------------------------------------
| Id  | Operation                            | Name                 | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                     |                      |       |       |   141 (100)|          |
|*  1 |  HASH JOIN                           |                      |   560 | 62720 |   141   (2)| 00:00:02 |
|   2 |   VIEW                               | VW_NSO_1             |   560 |  6720 |    30   (4)| 00:00:01 |
|   3 |    HASH UNIQUE                       |                      |   560 |  1120 |    30   (4)| 00:00:01 |
|*  4 |     COLLECTION ITERATOR PICKLER FETCH| CUSTOMERSTRUCT_LOAD  |  1120 |  2240 |    29   (0)| 00:00:01 |
|   5 |   VIEW                               |                      | 22045 |  2626K|   111   (1)| 00:00:02 |
|   6 |    UNION-ALL                         |                      |       |       |            |          |
|*  7 |     FILTER                           |                      |       |       |            |          |
|*  8 |      TABLE ACCESS FULL               | XAFID_CLASS_IFX      |   538 | 65636 | 15564   (1)| 00:03:07 |
|*  9 |      INDEX UNIQUE SCAN               | XAFID_CLASS_APP_UK01 |     1 |    28 |     1   (0)| 00:00:01 |
|  10 |     TABLE ACCESS FULL                | XAFID_CLASS_APP      | 21507 |  2436K|   103   (1)| 00:00:02 |
-------------------------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("QU01"."CUSTNO"="CUSTNO")
   4 - filter((VALUE(KOKBF$) IS NULL AND VALUE(KOKBF$)=2))
   7 - filter( IS NULL)
   8 - filter("MCI"."SRC"='IFX')
   9 - access("MCI2"."CUSTNO"=:B1 AND "MCI2"."XAFID_ID_IFX"=:B2)
 
Note
-----
   - cardinality feedback used for this statement

The main difference to the first execution plan is the estimated cardinality showed by the rows column.

starting with the estimated rows for the pipelined function (operation id  = 4) which was indeed much nearer to the reality. Cadinality of the opeartion changed from 4 to 1120!!

1st call :

-------------------------------------------------------------------------------------------------------------
| Id  | Operation                            | Name                 | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------------------------
|*  4 |     COLLECTION ITERATOR PICKLER FETCH| CUSTOMERSTRUCT_LOAD  |     4 |     8 |    29   (0)| 00:00:01 |

2nd call :

-------------------------------------------------------------------------------------------------------------
| Id  | Operation                            | Name                 | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------------------------
|*  4 |     COLLECTION ITERATOR PICKLER FETCH| CUSTOMERSTRUCT_LOAD  |  1120 |  2240 |    29   (0)| 00:00:01 |

Due to this fix (who caused it?) the the plan turned dramatically - but not the good way ;). The indexed access steps turned to full table scan steps.  which caused very expensive I/O operations. The table XAFIC_CLASS_IFX contained more then 3M ows.

1st call :

-------------------------------------------------------------------------------------------------------------
| Id  | Operation                            | Name                 | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------------------------
|*  8 |      INDEX RANGE SCAN                | XAFID_CLASS_IFX_UK01 |     1 |       |     1   (0)|  

2nd call :

-------------------------------------------------------------------------------------------------------------
| Id  | Operation                            | Name                 | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------------------------
|*  8 |      TABLE ACCESS FULL               | XAFID_CLASS_IFX      |   538 | 65636 | 15564   (1)| 

 

Another difference of the second plan output was the Note-Section; And indeed it pointed out what the reason for the generation of teh second plan was. 

Note
-----
   - cardinality feedback used for this statement

At the end of the plan output it could be slightly overseen. The fixed cardinality in operation ID 4 was caused by cardinality feedback (reparsing of the SQL with adoption of the cardinality with the effective cardinality of that execution step of the first execution of that SQL). The Note-Section is not simply a Note which may be read - it is realy an important hint what was going on behind the scenes.

 

How to fix

Cardinality feedback can be switched of in general or at session or at specific SQL level; I used a hint to disable it in the specific SQL :

/*+ OPT_PARAM('_OPTIMIZER_USE_FEEDBACK' 'FALSE') */

With Oracle 11g SQL Patches it would be possible to add a hint to the SQL without changing the software which generated the SQL; In our prod-environment I used this approach successfully.

 

Conclusion

Misleading cardinality estimation is one of the top reason for weak execution plans; Oracle introduced the feature Cardinality feedback with Oracle 11g - to be able to correct the optimizers cardinality estimations; A side effect of a corrected  cardinality could be that the second execution plan must not always the better one; So Cardinality feedback is not the healing method for wrong estimated cardinality but will help in many cases to repair weak execution plans.

for the DBA/Developer it must be in mind that a second execution of the same SQL may generate a new execution plan with different response time behavior - not to be get confused when you start your tuning task.

Hope you enjoyed -

/Karl

 

Reader Comments (4)

Karl,

I want to thank you for taking the time to write this article. The explanation is very clear, complete, and useful to me. It helped a colleague and me a great deal as we dealt with a query that ran in 7 seconds the first time, then 190 seconds subsequent times. Using the /*+ OPT_PARAM('_OPTIMIZER_USE_FEEDBACK' 'FALSE') */ hint worked perfectly, and every run is now 7 seconds.

It does leave me with some questions I'd like to test/find out, namely:

1. Is there a time-out such that, after a certain amount of time, the Cardinality Feedback "feature" isn't triggered for the same query, or does it continue to be triggered for that query for the entire session?

2. Are there specific, known conditions that cause these bad cardinality estimates?

3. Is the Cardinality Feedback mechanism employed after all queries, and is only sometimes wrong , or is it employed after only some queries, and is always wrong?

I'll update this comment when I find out the answer to any or all of these questions.

Thank you again for this article, as well as your article on Query Block Hints. I plan to read your other articles as well.

Sincerely,

Michael Milligan
West Layton, Utah, USA
ocp advanced pl/sql developer
oce sql • ocp dba • oca solaris

Data Modeler/Application DBA
Virtual Application DBA Team
Hewlett-Packard Corporation

May 8, 2013 | Unregistered CommenterMichael Milligan

Hello Micheal, you are welcome!

Now to your questions ...

1) No there is no time out - dependend on the paramters setting Cardinality feedback seems always be active. With Release 11g Oracle is able to track a specific SQL Execution to get the real cardinalities every exceution step caused. Then it compares it with the estimated cardinality calculated on
base of the Objects statistics ... ; If the estimated cardinality is similar to the real one the SQL is not reparsed. But if not then reparsing is done and an execution plan is completely re-drwan using 'real' cardinality instead, resulting in another - very often successfully improved plan.

But the model of calculating (a model is near to the reality but still an abstraction of it) an execution plan is not perfect - so a tuned cardinality could cause a weaker execution plan. And here it seems Oracle could add another check : if the new plan really needs less resources (I/O logical and physical, CPU) then the first one - and if not to switch back to the old one - this I think is missing.

So I hope this answers also the questions 2) and 3)

With Oracle 12c Oracle will be even able to change the excution plan during the first execution - which adds again a new level of dynamic plan adoption but also could add another level of confusion ...

/
Karl

May 8, 2013 | Registered CommenterKarl Reitschuster

Thanks -- nice clarification on something that was driving me nuts -- Sadly AUTOTRACE does not show the second plan is different. Nor did the TKPROF explain, you could 'see' from the trace it was doing something different but I had not played with the xplan display cursor, love it!

August 1, 2013 | Unregistered CommenterApril

yep and with Oracle 12c it will be even more confusing - a CBO which changes the Execution plan during an execution of an SQL; A stealth CBO ;)
u r welcome
/Karl

August 3, 2013 | Registered CommenterKarl Reitschuster

PostPost a New Comment

Enter your information below to add a new comment.

My response is on my own website »
Author Email (optional):
Author URL (optional):
Post:
 
Some HTML allowed: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <code> <em> <i> <strike> <strong>