>Oracle 11g has Adaptive Bind Peeking, right?
Adaptive Cursor Sharing, right :)

>Well no, adaptive bind variable peeking is a reactive technique – it only kicks in after the problem has happened!
Right, I’m sure you’ve read Kerry’s post on this matter.

The dynamics behind this situation have been a bit challenging for me to explain to developers and managers when it’s occurred in my own environments. Luckily for me, it occurs consistently enough and I can “force” a fix that they realize I’m not making it up! Excellent article and indepth research into this challenging complication with the bind variable peek feature!

the solution: alter system flush shared_pool :)

So, how to avoid bad execution time firs time ? Can someone post a link to an article itself? Sorry, i am new to this blog.

I actually spent some time to run sql scripts to demonstrate this issue. What I found is that the only reason optimizer does not change a plan for second execution , when performance is bad was that “ALTER SESSION SET OPTIMIZER_INDEX_COST_ADJ=10;” was issued earlier. If prior to executing script with ‘SYS’ value of a bind variable you would change it back : “ALTER SESSION SET OPTIMIZER_INDEX_COST_ADJ=100′ which is a default btw, optimizer would change its plan to hash join from nested loops. So, what is an issue? Adaptive cursor does work

SQL> DROP TABLE t1;
DROP TABLE t2;
DROP TABLE t3;

CREATE TABLE t1 AS SELECT * FROM dba_objects;
CREATE TABLE t2 AS SELECT * FROM dba_objects;
CREATE TABLE t3 AS SELECT * FROM dba_objects;

CREATE INDEX i1 ON t1(owner);
CREATE INDEX i2 ON t2(owner);
CREATE INDEX i3 ON t3(owner);

EXEC DBMS_STATS.GATHER_TABLE_STATS(user,’T1′,cascade=>TRUE, method_opt=>’FOR ALL INDEXED COLUMNS SIZE 254′);
EXEC DBMS_STATS.GATHER_TABLE_STATS(user,’T2′,cascade=>TRUE, method_opt=>’FOR ALL INDEXED COLUMNS SIZE 254′);
EXEC DBMS_STATS.GATHER_TABLE_STATS(user,’T3′,cascade=>TRUE, method_opt=>’FOR ALL INDEXED COLUMNS SIZE 254′);

Table dropped.

Elapsed: 00:00:00.12
SQL>
Table dropped.

Elapsed: 00:00:00.14
SQL>
Table dropped.

Elapsed: 00:00:00.12
SQL> SQL>
Table created.

Elapsed: 00:00:01.00
SQL>
Table created.

Elapsed: 00:00:00.93
SQL>
Table created.

Elapsed: 00:00:01.32
SQL> SQL>
Index created.

Elapsed: 00:00:00.56
SQL>
Index created.

Elapsed: 00:00:00.60
SQL>
Index created.

Elapsed: 00:00:00.54
SQL> SQL>
PL/SQL procedure successfully completed.

Elapsed: 00:00:00.45
SQL>
PL/SQL procedure successfully completed.

Elapsed: 00:00:00.46
SQL>
PL/SQL procedure successfully completed.

Elapsed: 00:00:00.46
SQL>

SQL> ALTER SESSION SET OPTIMIZER_INDEX_COST_ADJ=10;

Session altered.

SQL>
SQL> VAR v VARCHAR2(100)

SQL> SQL> EXEC :v:=’SCOTT’

SET TIMING ON

PL/SQL procedure successfully completed.

SQL> SQL> SQL>
SQL> PROMPT Running query first time, this should be fast (and should use nested loops execution plan)
Running query first time, this should be fast (and should use nested loops execution plan)
SQL>
SQL> SELECT
2 MIN(t1.created), MAX(t1.created)
3 FROM
4 t1
5 , t2
6 , t3
7 WHERE
8 t1.object_id = t2.object_id
9 AND t2.object_id = t3.object_id
10 AND t1.owner = :v
11 AND t2.owner = :v
12 AND t3.owner = :v
13 /

SET TIMING OFF

–SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(null,null,’ALLSTATS LAST ADVANCED’));
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(null,null));

MIN(T1.CR MAX(T1.CR
——— ———

Elapsed: 00:00:00.01
SQL> SQL> SQL> SQL> SQL>
PLAN_TABLE_OUTPUT
————————————————————————————————————————————————————————————
SQL_ID 5vy5qjd3fsn5c, child number 0
————————————-
SELECT MIN(t1.created), MAX(t1.created) FROM t1 , t2 , t3
WHERE t1.object_id = t2.object_id AND t2.object_id = t3.object_id
AND t1.owner = :v AND t2.owner = :v AND t3.owner = :v

Plan hash value: 4162198323

—————————————————————————————-
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
—————————————————————————————-

PLAN_TABLE_OUTPUT
————————————————————————————————————————————————————————————
| 0 | SELECT STATEMENT | | | | 3 (100)| |
| 1 | SORT AGGREGATE | | 1 | 66 | | |
| 2 | NESTED LOOPS | | | | | |
| 3 | NESTED LOOPS | | 6 | 396 | 3 (0)| 00:00:01 |
| 4 | NESTED LOOPS | | 6 | 282 | 2 (0)| 00:00:01 |
| 5 | TABLE ACCESS BY INDEX ROWID| T1 | 6 | 168 | 1 (0)| 00:00:01 |
|* 6 | INDEX RANGE SCAN | I1 | 6 | | 1 (0)| 00:00:01 |
|* 7 | TABLE ACCESS BY INDEX ROWID| T2 | 1 | 19 | 1 (0)| 00:00:01 |
|* 8 | INDEX RANGE SCAN | I2 | 6 | | 1 (0)| 00:00:01 |
|* 9 | INDEX RANGE SCAN | I3 | 6 | | 1 (0)| 00:00:01 |
|* 10 | TABLE ACCESS BY INDEX ROWID | T3 | 1 | 19 | 1 (0)| 00:00:01 |

PLAN_TABLE_OUTPUT
————————————————————————————————————————————————————————————
—————————————————————————————-

Predicate Information (identified by operation id):
—————————————————

6 – access(“T1″.”OWNER”=:V)
7 – filter(“T1″.”OBJECT_ID”=”T2″.”OBJECT_ID”)
8 – access(“T2″.”OWNER”=:V)
9 – access(“T3″.”OWNER”=:V)
10 – filter(“T2″.”OBJECT_ID”=”T3″.”OBJECT_ID”)

33 rows selected.

SQL> EXEC :v:=’SYS’

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00
SQL> SQL> SET TIMING ON
SQL>
SQL> PROMPT Now running the same query with different bind variables (this query should take very long time)
Now running the same query with different bind variables (this query should take very long time)
SQL>
SQL> SELECT
2 MIN(t1.created), MAX(t1.created)
3 FROM
4 t1
5 , t2
6 , t3
7 WHERE
8 t1.object_id = t2.object_id
9 AND t2.object_id = t3.object_id
10 AND t1.owner = :v
11 AND t2.owner = :v
12 AND t3.owner = :v
13 /

MIN(T1.CR MAX(T1.CR
——— ———
16-SEP-05 23-FEB-10

Elapsed: 00:00:00.08
SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(null,null));

PLAN_TABLE_OUTPUT
————————————————————————————————————————————————————————————
SQL_ID 5vy5qjd3fsn5c, child number 2
————————————-
SELECT MIN(t1.created), MAX(t1.created) FROM t1 , t2 , t3
WHERE t1.object_id = t2.object_id AND t2.object_id = t3.object_id
AND t1.owner = :v AND t2.owner = :v AND t3.owner = :v

Plan hash value: 710168226

—————————————————————————–
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
—————————————————————————–

PLAN_TABLE_OUTPUT
————————————————————————————————————————————————————————————
| 0 | SELECT STATEMENT | | | | 635 (100)| |
| 1 | SORT AGGREGATE | | 1 | 66 | | |
|* 2 | HASH JOIN | | 29374 | 1893K| 635 (1)| 00:00:08 |
|* 3 | TABLE ACCESS FULL | T3 | 30485 | 565K| 211 (1)| 00:00:03 |
|* 4 | HASH JOIN | | 29374 | 1348K| 423 (1)| 00:00:06 |
|* 5 | TABLE ACCESS FULL| T2 | 29375 | 545K| 211 (1)| 00:00:03 |
|* 6 | TABLE ACCESS FULL| T1 | 30301 | 828K| 211 (1)| 00:00:03 |
—————————————————————————–

Predicate Information (identified by operation id):
—————————————————

PLAN_TABLE_OUTPUT
————————————————————————————————————————————————————————————

2 – access(“T2″.”OBJECT_ID”=”T3″.”OBJECT_ID”)
3 – filter(“T3″.”OWNER”=:V)
4 – access(“T1″.”OBJECT_ID”=”T2″.”OBJECT_ID”)
5 – filter(“T2″.”OWNER”=:V)
6 – filter(“T1″.”OWNER”=:V)

29 rows selected.

Elapsed: 00:00:00.03
SQL>

Hey Tanel!

I have a similar problem on a production environment at Brazil.
Do you think you can help me?

My problem is a query that changes it’s behavior (execution plan) from time to time. When the time comes what happens is that we see a lot of “latch: cache buffer chains” and a huge CPU Spike because of the plan choosen.

All the colums of the tables involved have histograms and the table stat are not updated very often, also the sample used to collect stat from the tables are about 5%, what i think that can be too low.

I recommended to collect stat more often and with a bigger sample, but we have the problem even 2 days after the stat gathering.

What can i do next? Can you reply by e-mail?

Thank you very much.