dbi services: Database Infrastructure Services - Engineering, Implementation, Operation, Modernization

Blog - comments
Julien said,
  Unluckily there is a bug on this feature which causes the reversed eff  
youtube html5 player said,
  Wow, very comprehensive review. I'm thinking about learning HTML5. I'm  
youtube html5 player said,
  I have no words for this great post such a awe-some information i got  
SEO Services said,
  Thanks for the nice blog. It was very useful for me. Keep sharing such  
Jhon said,
  Me personally and my friends genuinely favored the post and i believe  
Blog Hervé Schweitzer A SQL statement is slow and suddenly fast? Have a look at "Cardinality Feedback"!

dbi services Blog

Welcome to the dbi services Blog! This blog focuses on database infrastructure and middleware topics. It covers technologies such as Oracle, Microsoft SQL Server, MySQL, Sybase, Linux, or Documentum (etc.). The dbi services blog represents the view of our consultants, not necessarily that of dbi services. Feel free to comment on the postings!

Hervé Schweitzer

A SQL statement is slow and suddenly fast? Have a look at "Cardinality Feedback"!

While discussing with some tuning gurus, I was made aware about this feature. It is not so far from the adaptive cursor sharing perfectly described in Chris Antognini's blog: http://antognini.ch/papers/BindVariablePeeking_20090718.pdf

This feature compares the real execution (number of returned/actual rows - "A-rows") with some expectations (number of expected rows - "E-rows") and chooses another plan for the next executions if the difference between the expectation and the actual result is too big. "Cardinality Feedback" is not well documented in the Oracle documentation.

The purpose of this post is not to dive into the technical details, but just to make you aware that this feature exists :-), it might explain some strange figures :-). The first execution time of some SQL statements might be poor/slow and afterwards they may be very fast. Not due to caching, not due to parsing, but due to a complete explain plan change - even if data and statistics are exactly the same.

Let's have a look. First of all, we deactivated this functionality with the parameter below :

 
SQL> alter session set "_optimizer_use_feedback"=false;
Session altered.

 

Then, we start an SQL statement several times - the result was always "slow" (>20s) as you can see below:


SQL> set timing on
SQL> select /* HERVE TEST ADVISOR */  all d.object_name, f.r_folder_path from dev_common_sp  d, loby_az.DM_TABLEB_R f, loby_az.DM_BIG_TABLE_R s where ((d.r_lock_owner='loby eh 3') and (s.r_object_id=d.r_object_id) and (s.i_folder_id=f.r_object_id) and f.r_folder_path != ' ' and d.object_name != ' ' and (d.i_is_reference=0)) and (d.i_has_folder = 1 and d.i_is_deleted = 0) and ( ( d.owner_name in ('loby eh 3','loby clinical reader')) or (exists (select 1 from dm_acl_s ACL_S0, dm_acl_r ACL_R where ACL_S0.r_object_id = ACL_R.r_object_id and d.acl_domain = ACL_S0.owner_name and d.acl_name = ACL_S0.object_name and ((ACL_R.r_accessor_name in ('loby eh 3','dm_world') or (ACL_R.r_is_group = 1 and (ACL_R.r_accessor_name in ('loby eh 3','loby clinical reader','dm_world','loby crd luda','loby cp contributor','loby luda','ploby reader','loby users','loby reader','rr reader','loby old products reader','loby users','loby contributor','enterprise reader','ploby users','test dz','loby enterprise reader','enterprise loby_az reader')))) and ((ACL_R.r_permit_type = 0 or ACL_R.r_permit_type is null) and (((ACL_R.r_accessor_permit >= 2))))))));


OBJECT_NAME                            
R_FOLDER_PATH
-----------------------------------     ----------------------------------------
1234test                                /loby Projects/X/WDBIOA/BLOG studies/CSP
00012abcd_2011-march-13 16:23:1510      /loby Projects/X/WDBIOA/BLOG studies/CSP


Elapsed: 00:00:27.23

SQL> /

OBJECT_NAME                             R_FOLDER_PATH
--------------------------              ----------------------------------------

1234test                                /loby Projects/X/WDBIOA/BLOG studies/CSP
00012abcd_2011-march-13 16:23:1510      /loby Projects/X/WDBIOA/BLOG studies/CSP

Elapsed: 00:00:23.97

 

If Cardinality Feedback is deactivated, the statement is always slow and it uses an identical execution plan - which is bad. Then, we activate the functionality again (true = default as of 11.2):


SQL> alter session set "_optimizer_use_feedback"=true;
Session altered.


In order to see how Oracle handles the Cardinality Feedback feature, we decided to collect the "plan statistics" to print out the estimations calculated by Oracle using the hint "/*+ gather_plan_statistics */"

 

SQL> select /*+ gather_plan_statistics */ all d.object_name, f.r_folder_path from dev_common_sp  d, loby_az.DM_TABLEB_R f, loby_az.DM_BIG_TABLE_R s where ((d.r_lock_owner='loby eh 3') and (s.r_object_id=d.r_object_id) and (s.i_folder_id=f.r_object_id) and f.r_folder_path != ' ' and d.object_name != ' ' and (d.i_is_reference=0)) and (d.i_has_folder = 1 and d.i_is_deleted = 0) and ( ( d.owner_name in ('loby eh 3','loby clinical reader')) or (exists (select 1 from dm_acl_s ACL_S0, dm_acl_r ACL_R where ACL_S0.r_object_id = ACL_R.r_object_id and d.acl_domain = ACL_S0.owner_name and d.acl_name = ACL_S0.object_name and ((ACL_R.r_accessor_name in ('loby eh 3','dm_world') or (ACL_R.r_is_group = 1 and (ACL_R.r_accessor_name in ('loby eh 3','loby clinical reader','dm_world','loby crd luda','loby cp contributor','loby luda','ploby reader','loby users','loby reader','rr reader','loby old products reader','loby users','loby contributor','enterprise reader','ploby users','test dz','loby enterprise reader','enterprise loby_az reader')))) and ((ACL_R.r_permit_type = 0 or ACL_R.r_permit_type is null) and (((ACL_R.r_accessor_permit >= 2))))))));

 

OBJECT_NAME R_FOLDER_PATH
--------------------------              ----------------------------------------
1234test                                /loby Projects/X/WDBIOA/BLOG studies/CSP
00012abcd_2011-march-13 16:23:1510      /loby Projects/X/WDBIOA/BLOG studies/CSP

Elapsed: 00:00:35.04

SQL> select * from table (dbms_xplan.display_cursor (format=>'ALLSTATS LAST'));

------------------------------------------------------------------------------------
| Id  | Operation                  | Name               | Starts | E-Rows | A-Rows | |-----------------------------------------------------------------------------------
|   0 | SELECT STATEMENT           |                    |      1 |        |      1 |      
|*  1 |  FILTER                    |                    |      1 |        |      1 |      
|*  2 |   HASH JOIN                |                    |      1 |    945K|      1 |  
|*  3 |    TABLE ACCESS FULL       | DM_TABLEB_R        |      1 |   1379K|   1382K|      
|*  4 |    HASH JOIN               |                    |      1 |    626K|      1 |  
|*  5 |     HASH JOIN              |                    |      1 |    429K|      1 |  
|*  6 |      TABLE ACCESS BY INDEX | DM_BIGTABLE        |      1 |    429K|      1 |      
|*  7 |       INDEX RANGE SCAN     | D_1F0095AF8000002A |      1 |   3439K|      1 |     
|   8 |      INDEX FAST FULL SCAN  | D_1F0095AF80000500 |      1 |   4613K|   4633K| 
|*  9 |     INDEX FAST FULL SCAN   | D_1F0095AF80000010 |      1 |   6943K|   6961K|
|  10 |   NESTED LOOPS             |                    |      0 |        |      0 |    
|  11 |    NESTED LOOPS            |                    |      0 |      1 |      0 |     
|* 12 |     INDEX RANGE SCAN       | D_1F0095AF80002D01 |      0 |      1 |      0 | 
|* 13 |     INDEX RANGE SCAN       | D_1F0095AF80000102 |      0 |     12 |      0 |    
|* 14 |    TABLE ACCESS BY INDEX   | DM_ACL_R           |      0 |      1 |      0 |      
------------------------------------------------------------------------------------

 

As you can see, there is a huge difference between the E-rows and the A-rows in some lines of the plan. In particular this one:

 


|*  7 |       INDEX RANGE SCAN     | D_1F0095AF8000002A |      1 |   3439K|      1 |00:00:00.01 |       3 |

 

SQL> /

OBJECT_NAME R_FOLDER_PATH
--------------------------              ----------------------------------------

1234test                                /loby Projects/X/WDBIOA/BLOG studies/CSP
00012abcd_2011-march-13 16:23:1510      /loby Projects/X/WDBIOA/BLOG studies/CSP

Elapsed: 00:00:23.97

 

The second execution of this statement was fast. Once again, not due to caching or faster parsing, but due to "Cardinality Feedback". Oracle tried to take care of these large differences between E-Rows and A-Rows.

The second time, the explain plan is completely reconsidered:

 

OBJECT_NAME R_FOLDER_PATH
--------------------------              ---------------------------------------- 1234test                                /loby Projects/X/WDBIOA/BLOG studies/CSP
00012abcd_2011-march-13 16:23:1510      /loby Projects/X/WDBIOA/BLOG studies/CSP

Elapsed: 00:00:00.01

This second start was fast because of the recalculation of the plan. The estimated rows (E-rows) and the real output rows (A-rows) had too much differences in the first run, therefore Oracle recalculated the plan.

If you generate the SQL plan for this statement, you will see in the "Note" at the end if "Cardinality Feedback" was used :


SQL> select * from table (dbms_xplan.display_cursor (format=>'ALLSTATS LAST'));

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
SQL_ID  5w3td7kauxkkh, child number 1
-------------------------------------
select /*+ gather_plan_statistics */  all d.object_name, f.r_folder_path from
dev_common_sp  d, loby_az.DM_TABLEB_R f, loby_az.DM_BIG_TABLE_R s
where ((d.r_lock_owner='loby eh 3') and (s.r_object_id=d.r_object_id)
and (s.i_folder_id=f.r_object_id) and f.r_folder_path != ' ' and
d.object_name != ' ' and (d.i_is_reference=0)) and (d.i_has_folder = 1
and d.i_is_deleted = 0) and ( ( d.owner_name in ('loby eh 3','credi
clinical reader')) or (exists (select 1 from dm_acl_s
ACL_S0, dm_acl_r ACL_R where ACL_S0.r_object_id = ACL_R.r_object_id and
d.acl_domain = ACL_S0.owner_name and d.acl_name = ACL_S0.object_name
and ((ACL_R.r_accessor_name in ('loby eh 3','dm_world') or
(ACL_R.r_is_group = 1 and (ACL_R.r_accessor_name in ('loby eh 3','cr

Plan hash value: 683492381

------------------------------------------------------------------------------------------
| Id  | Operation                        | Name               | Starts | E-Rows | A-Rows |
------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                 |                    |      1 |        |      1 |
|*  1 |  FILTER                          |                    |      1 |        |      1 |
|   2 |   NESTED LOOPS                   |                    |      1 |        |      1 |
|   3 |    NESTED LOOPS                  |                    |      1 |      2 |      6 |
|   4 |     NESTED LOOPS                 |                    |      1 |      1 |      1 |
|   5 |      NESTED LOOPS                |                    |      1 |      1 |      1 |
|*  6 |       TABLE ACCESS BY INDEX ROWID| DM_BIG_TABLE       |      1 |      1 |      1 |
|*  7 |        INDEX RANGE SCAN          | D_1F0095AF8000002A |      1 |      1 |      1 |
|*  8 |       INDEX UNIQUE SCAN          | D_1F0095AF80000500 |      1 |      1 |      1 |
|*  9 |      TABLE ACCESS BY INDEX ROWID | DM_BIG_TABLE_R     |      1 |      1 |      1 |
|* 10 |       INDEX RANGE SCAN           | D_1F0095AF80000109 |      1 |      4 |      4 |
|* 11 |     INDEX RANGE SCAN             | D_1F0095AF80000132 |      1 |      7 |      6 |
|* 12 |    TABLE ACCESS BY INDEX ROWID   | DM_TABLEB_R        |      6 |      2 |      1 |
|  13 |   NESTED LOOPS                   |                    |      0 |        |      0 |
|  14 |    NESTED LOOPS                  |                    |      0 |      1 |      0 |
|* 15 |     INDEX RANGE SCAN             | D_1F0095AF80002D01 |      0 |      1 |      0 |
|* 16 |     INDEX RANGE SCAN             | D_1F0095AF80000102 |      0 |     12 |      0 |
|* 17 |    TABLE ACCESS BY INDEX ROWID   | DM_ACL_R           |      0 |      1 |      0 |
------------------------------------------------------------------------------------------

Here, the E-rows and A-rows are quite similar, Oracle will not re-evaluate the plan in the future.


Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - SEL$F5BB74E1

PLAN_TABLE_OUTPUT
-----------------------------
6 - SEL$F5BB74E1 / YG_@SEL$2
7 - SEL$F5BB74E1 / YG_@SEL$2
8 - SEL$F5BB74E1 / OTC_@SEL$2
9 - SEL$F5BB74E1 / S@SEL$1
10 - SEL$F5BB74E1 / S@SEL$1
11 - SEL$F5BB74E1 / F@SEL$1
12 - SEL$F5BB74E1 / F@SEL$1
13 - SEL$3
15 - SEL$3        / ACL_S0@SEL$3
16 - SEL$3        / ACL_R@SEL$3
17 - SEL$3        / ACL_R@SEL$3

Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter((INTERNAL_FUNCTION("YG_"."OWNER_NAME") OR  IS NOT NULL))
6 - filter(("YG_"."I_HAS_FOLDER"=1 AND "YG_"."I_IS_DELETED"=0 AND "YG_"."I_IS_REFERENCE"=0
AND "YG_"."OBJECT_NAME"<>' '))
7 - access("YG_"."R_LOCK_OWNER"='loby eh 3')
8 - access("YG_"."R_OBJECT_ID"="OTC_"."R_OBJECT_ID")
9 - filter("S"."I_FOLDER_ID" IS NOT NULL)
10 - access("S"."R_OBJECT_ID"="YG_"."R_OBJECT_ID")
11 - access("S"."I_FOLDER_ID"="F"."R_OBJECT_ID")
12 - filter("F"."R_FOLDER_PATH"<>' ')
15 - access("ACL_S0"."OWNER_NAME"=:B1 AND "ACL_S0"."OBJECT_NAME"=:B2)
16 - access("ACL_S0"."R_OBJECT_ID"="ACL_R"."R_OBJECT_ID")
17 - filter(((INTERNAL_FUNCTION("ACL_R"."R_ACCESSOR_NAME") OR ("ACL_R"."R_IS_GROUP"=1 AND
INTERNAL_FUNCTION("ACL_R"."R_ACCESSOR_NAME"))) AND "ACL_R"."R_ACCESSOR_PERMIT">=2 AND
("ACL_R"."R_PERMIT_TYPE"=0 OR "ACL_R"."R_PERMIT_TYPE" IS NULL)))

Column Projection Information (identified by operation id):
-----------------------------------------------------------
1 - "YG_"."OBJECT_NAME"[VARCHAR2,255], "F"."R_FOLDER_PATH"[VARCHAR2,740]
2 - "YG_"."OBJECT_NAME"[VARCHAR2,255], "YG_"."OWNER_NAME"[VARCHAR2,32],"YG_"."ACL_DOMAIN"[VARCHAR2,32], "YG_"."ACL_NAME"[VARCHAR2,32],"F"."R_FOLDER_PATH"[VARCHAR2,740]
3 - "YG_"."OBJECT_NAME"[VARCHAR2,255], "YG_"."OWNER_NAME"[VARCHAR2,32],"YG_"."ACL_DOMAIN"[VARCHAR2,32], "YG_"."ACL_NAME"[VARCHAR2,32], "F".ROWID[ROWID,10]
4 - "YG_"."OBJECT_NAME"[VARCHAR2,255], "YG_"."OWNER_NAME"[VARCHAR2,32],"YG_"."ACL_DOMAIN"[VARCHAR2,32], "YG_"."ACL_NAME"[VARCHAR2,32], "S"."I_FOLDER_ID"[VARCHAR2,16]
5 - "YG_"."R_OBJECT_ID"[VARCHAR2,16], "YG_"."OBJECT_NAME"[VARCHAR2,255],"YG_"."OWNER_NAME"[VARCHAR2,32], "YG_"."ACL_DOMAIN"[VARCHAR2,32], "YG_"."ACL_NAME"[VARCHAR2,32]
6 - "YG_"."R_OBJECT_ID"[VARCHAR2,16], "YG_"."OBJECT_NAME"[VARCHAR2,255],"YG_"."OWNER_NAME"[VARCHAR2,32], "YG_"."ACL_DOMAIN"[VARCHAR2,32], "YG_"."ACL_NAME"[VARCHAR2,32]
7 - "SYS_ALIAS_2".ROWID[ROWID,10]
9 - "S"."I_FOLDER_ID"[VARCHAR2,16]

PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------------------------
10 - "S".ROWID[ROWID,10]
11 - "F".ROWID[ROWID,10]
12 - "F"."R_FOLDER_PATH"[VARCHAR2,740]
14 - "ACL_R".ROWID[ROWID,10]
15 - "ACL_S0"."R_OBJECT_ID"[VARCHAR2,16]
16 - "ACL_R".ROWID[ROWID,10]

Note
-----
- cardinality feedback used for this statement <===== !!! Cardinality Feedback has been used !!!

105 rows selected.

 

However in this particular case, we have not solved anything, since the first execution was important.

I will tell you in the next posts how I have solved the problem and identified the real problem :-)

in this particular

About the author

Hervé Schweitzer
Hervé Schweitzer
Hervé Schweitzer is Principal Consultant and responsible of High Availability solutions at dbi services.

He has more than ten years of experience in database and infrastructure management, engineering, and optimization.

He is specialized in Oracle technologies such as standardisation, Backup and Recovery, Tuning, and in High Availability solutions such as Oracle Data Guard, Oracle Grid Infrastructure, Oracle Real Application Clusters RAC, Oracle GoldenGate and Oracle Failsafe.

Comments

Unluckily there is a bug on this feature which causes the reversed effect: The first run of the SQl is fast, but seconf and so on runs deadly slow. The bug is 13454409 - Wrong Cost estimation of Nested Loop probe after Cardinality feeback.

Friday, 18 May 2012
Leave your comment
Guest