By Franck Pachot

.
This follows the comments on Clemens Bleile post about SQL Plan Directives in Oracle 12.2 where he discovered a new behavior that is not documented. The feature is good: bypass the cardinality feedback overhead when the query is fast anyway.

Feature

In Clemens Bleile post about SQL Plan Directives changes in 12cR2 he determined than the new feature coming in bug 23596611 was responsible for the bypass of automatic reoptimization (the 12c cardinality feedback) in some cases.

The description gives the idea that the reason for the bypass of cardinality feedback is ‘small queries’:

SQL> select BUGNO,SQL_FEATURE,DESCRIPTION,OPTIMIZER_FEATURE_ENABLE from v$system_fix_control where bugno=23596611;
 
     BUGNO SQL_FEATURE                    DESCRIPTION                            OPTIMIZER_FEATURE_ENABLE
---------- ------------------------------ -------------------------------------- -------------------------
  23596611 QKSFM_STATS_FEEDBACK_23596611   No feedback for small queries         12.2.0.1

This is a new concept and in the traces we know there is nothing about ‘small queries’. Here is how to get more information.

Function

First, I’m looking for the ‘small queries’ text in the oracle executable:

$ strings $ORACLE_HOME/bin/oracle | grep "small query"
kkocfbCheckCardEst: No feedback for small query (BG %f, CPU %f (ms)
kkocfbCompareExecStats: skipping cost comparision forsmall query (BG %f, CPU %f (ms)

Good. This looks like there is a way to trace some information about that bypass decision, and there’s a clue that ‘small queries’ are evaluated on number of buffer gets (BG) and CPU time threshold. More than that, we have the name of the C function that traces this: kkocfbCheckCardEst

kkocfb probably means:

and then I’m looking for a way to get this trace. I didn’t know which event can trace that, but others know:

However there is another way to get an idea of the events that are checked by a function.
The idea is described here: http://yong321.freeshell.org/computer/OracleFuncCalls.html

Event

We are not allowed to disassemble oracle code (this is in the licensing rules that you accept when you download oracle) so I’ll not do it here.
If you think you have a special permission to do it, just run:

gdb oracle <<<"disas kkocfbCheckCardEst"

I can’t show the dissassembled code, so here is how to get the list of the events that are checked by the kkocfbCheckCardEst function:

$ gdb oracle <<<"disas kkocfbCheckCardEst" | awk --non-decimal-data '/mov .*,%edi$/{gsub(/[$,]/," ");a=$4}/EventRdbmsErr/{printf "%dn", a}' | sort -u
10507

The information we have about this event does not describe all what can be traced:

$ oerr ora 10507
10507, 00000, "Trace bind equivalence logic"
// *Cause:
// *Action:

From that, I don’t know which level to set the event, but in case of doubt and because levels are often bit flags, you can set it to the maximum 0xFFFFFFFF:


alter session set events '10507 trace name context forever, level 4294967295';

trace when cardinality feedback is bypassed

When I run the query where execution is doing less than 100 buffer gets I get the following trace with event 10507 level 512:


****** Begin CFB Hints (APA) [sql_id=a71qw8t17qpqq] xsc=0x7fca901f0e30 ctx=0x9415d4f8 ******
Dumping Hints
=============
*********** End CFB Hints (APA) ***********
kkocfbInitCardFdbkCompCtx [sql_id=a71qw8t17qpqq] monitor=y
kkocfbCheckCardEst: No feedback for small query (BG 0.000000, CPU 0.000000 (ms)

The message is clear: no feedback for small query. The Buffer Get and CPU show 0 but on my test case, increasing the size of the table, I have seen that 100 buffer gets is the threshold:


bq4fc1rdx97av is_reoptimizable: N                buffer_gets:          95 cpu_time:          0
bq4fc1rdx97av is_reoptimizable: N                buffer_gets:          95 cpu_time:       1000
bq4fc1rdx97av is_reoptimizable: N                buffer_gets:          96 cpu_time:       1000
bq4fc1rdx97av is_reoptimizable: N                buffer_gets:          96 cpu_time:       1000
bq4fc1rdx97av is_reoptimizable: N                buffer_gets:          97 cpu_time:          0
bq4fc1rdx97av is_reoptimizable: N                buffer_gets:          97 cpu_time:          0
bq4fc1rdx97av is_reoptimizable: N                buffer_gets:          98 cpu_time:       1000
bq4fc1rdx97av is_reoptimizable: N                buffer_gets:          98 cpu_time:          0
bq4fc1rdx97av is_reoptimizable: N                buffer_gets:          99 cpu_time:       1000
bq4fc1rdx97av is_reoptimizable: N                buffer_gets:          99 cpu_time:          0
bq4fc1rdx97av is_reoptimizable: Y                buffer_gets:         100 cpu_time:       1000
bq4fc1rdx97av is_reoptimizable: Y                buffer_gets:         100 cpu_time:       1000
bq4fc1rdx97av is_reoptimizable: Y                buffer_gets:         101 cpu_time:       1000
bq4fc1rdx97av is_reoptimizable: Y                buffer_gets:         101 cpu_time:          0
bq4fc1rdx97av is_reoptimizable: Y                buffer_gets:         102 cpu_time:          0
bq4fc1rdx97av is_reoptimizable: Y                buffer_gets:         102 cpu_time:       1000

trace when query becomes reoptimizable

When the query reads more than 100 buffer gets, the cursor is marked as reoptimizable and here is the trace:


****** Begin CFB Hints (APA) [sql_id=a71qw8t17qpqq] xsc=0x7fed7dc2ca40 ctx=0x9418f4f8 ******
Dumping Hints
=============
*********** End CFB Hints (APA) ***********
kkocfbInitCardFdbkCompCtx [sql_id=a71qw8t17qpqq] monitor=y
Reparsing due to card est...
 @=0x95426550 type=1 nodeid=1 monitor=Y halias="DEMO_TABLE" loc="SEL$1" act=500 min=0 est=63 next=(nil)
kkocfbCheckCardEst [sql_id=a71qw8t17qpqq] reparse=y ecs=n efb=n ost=n fbs=n
 *********** Begin Dump Context (kkocfbCheckCardEst) [sql_id=a71qw8t17qpqq cpcnt=0] ***********
 @=0x95426550 type=1 nodeid=1 monitor=Y halias="DEMO_TABLE" loc="SEL$1" act=500 min=0 est=63 next=(nil)
 *********** End Dump Context ***********

act=500 is the actual number of rows (A-Rows) and est=63 is the estimated one (A-Rows) and this is how misestimate is detected.

trace when reoptimized query is run again

At that point we can see the feedback as OPT_ESTIMATE hints in v$sql_reoptimization_hints.

When we run the same query another time, it is parsed again with those hits, fixing cardinality tho the A-Rows of previous execution.

Here is the trace for this second execution.


kkoarCopyCtx: [sql_id=a71qw8t17qpqq] origin=CFB old=0x63904140 new=0x7fcda3716d40 copyCnt=1 copyClient=y
**************************************************************
kkocfbCopyBestEst: Best Stats
  Exec count:         1
  CR gets:            279
  CU gets:            4
  Disk Reads:         0
  Disk Writes:        0
  IO Read Requests:   0
  IO Write Requests:  0
  Bytes Read:         0
  Bytes Written:      0
  Bytes Exchanged with Storage:  0
  Bytes Exchanged with Disk:  0
  Bytes Simulated Read:  0
  Bytes Simulated Returned:  0
  Elapsed Time: 6998 (us)
  CPU Time: 2000 (us)
  User I/O Time: 0 (us)
 *********** Begin Dump Context (kkocfbCopyBestEst) **********
 *********** End Dump Context ***********
kkocfbCopyCardCtx: oldCtx Dumping string mapping
----------------------
kkocfbCopyCardCtx: newCtx Dumping string mapping
----------------------
**************************************************************
kkocfbCopyCardCtx: Best stats
  Exec count:         1
  CR gets:            279
  CU gets:            4
  Disk Reads:         0
  Disk Writes:        0
  IO Read Requests:   0
  IO Write Requests:  0
  Bytes Read:         0
  Bytes Written:      0
  Bytes Exchanged with Storage:  0
  Bytes Exchanged with Disk:  0
  Bytes Simulated Read:  0
  Bytes Simulated Returned:  0
  Elapsed Time: 6998 (us)
  CPU Time: 2000 (us)
  User I/O Time: 0 (us)
 **** Begin Dump Context (kkocfbCopyCardCtx - best est) ****
 ********************* End Dump Context ********************
   *********** Begin Dump Context (Copy:old) [sql_id=a71qw8t17qpqq cpcnt=0] ***********
   @=0x6446dc58 type=1 nodeid=1 monitor=Y halias="DEMO_TABLE" loc="SEL$1" act=500 min=0 est=63 next=(nil)
   *********** End Dump Context ***********
   *********** Begin Dump Context (Copy:new) [sql_id=a71qw8t17qpqq cpcnt=0] ***********
   @=0x7fcda3716a78 type=1 nodeid=1 monitor=Y halias="DEMO_TABLE" loc="SEL$1" act=500 min=0 est=63 next=(nil)
   *********** End Dump Context ***********
kkoarReparse: xsc=0x7fcda3672b98 kxsAutoReoptCtx=0x7fcda3716d40
kkocfbAddCardHints: Dumping string mapping
----------------------
******** Begin CFB Hints [sql_id=a71qw8t17qpqq]  xsc=0x7fcda3672b98 ********
Dumping Hints
=============
  atom_hint=(@=0x7fcda37831e8 err=0 resol=0 used=0 token=1018 org=6 lvl=3 txt=OPT_ESTIMATE (@"SEL$1" TABLE "DEMO_TABLE"@"SEL$1" ROWS=500.000000 ) )
********** End CFB Hints **********

You can see the OPT_ESTIMATE hints here.


****** Begin CFB Hints (APA) [sql_id=a71qw8t17qpqq] xsc=0x7fcda3672b98 ctx=0x8a274118 ******
Dumping Hints
=============
  atom_hint=(@=0x7fcda37831e8 err=0 resol=1 used=0 token=1018 org=6 lvl=3 txt=OPT_ESTIMATE (@"SEL$1" TABLE "DEMO_TABLE"@"SEL$1" ROWS=500.000000 ) )
  atom_hint=(@=0x7fcda3782d10 err=0 resol=1 used=0 token=1018 org=6 lvl=3 txt=OPT_ESTIMATE (@"SEL$1" TABLE "DEMO_TABLE"@"SEL$1" ROWS=500.000000 ) )
*********** End CFB Hints (APA) ***********
kkocfbInitCardFdbkCompCtx [sql_id=a71qw8t17qpqq] monitor=y
**************************************************************
kkocfbCopyBestEst: Best Stats
  Exec count:         1
  CR gets:            279
  CU gets:            4
  Disk Reads:         0
  Disk Writes:        0
  IO Read Requests:   0
  IO Write Requests:  0
  Bytes Read:         0
  Bytes Written:      0
  Bytes Exchanged with Storage:  0
  Bytes Exchanged with Disk:  0
  Bytes Simulated Read:  0
  Bytes Simulated Returned:  0
  Elapsed Time: 6998 (us)
  CPU Time: 2000 (us)
  User I/O Time: 0 (us)
 *********** Begin Dump Context (kkocfbCopyBestEst) **********
 *********** End Dump Context ***********
kkocfbCheckCardEst [sql_id=a71qw8t17qpqq] reparse=n ecs=n efb=y ost=n fbs=n

So what?

With those adaptive feature it is good to be able to trace the decisions in order to understand and reproduce the problems we encounter. Event 10507 is very useful. It’s the execution time counterpart for the event 10053 which explains compile time decision. And in latest versions, the optimizer is more and more present at execution time.

We have always seen problems coming from cardinality feedback. Most of them are coming from bad statistics or a data model where there is not one optimal access plan. Then the CBO is always trying to find better and sometimes the best is the enemy of the good.
Now in 12.2 you have a very good way to avoid the cardinality feedback side effect: tune your queries and your data model so that the critical queries read less than 100 logical reads.