Friday, January 12, 2007

Jonathan Lewis is one smart dude

First, let me say that Jonathan Lewis has helped me immensely on my optimizer problem (here, here, and here). Without his help, I'd still be banging my head against a brick wall and arguing with Oracle Support as to why I need to upgrade to 10.2.0.3. A hundred thank you's, Jonathan. (I hope this doesn't land me on the "dummy list" of the next Scratchpad post)

Back to my optimizer issue, I should have known the plan was cached.

Let me take that back, I knew the plan was cached, but assumed (I know, I know) that the 10195 event would require a hard parse again. In retrospect, that was a silly thought, but seemed logical in the heat of battle. Anyway, the 10195 event does indeed turn off predicate generation for check constraints. Updated script and results to follow.

It still begs the question as to why Oracle evaluates the constraints this way (other than the response I got from Oracle Support "that's the way it works"), but at least we have a way out now.


Script:

set timing on
set echo on;
alter system flush shared_pool;
drop table t1;
create table t1 (
id number primary key,
date_matched date,
other_stuff varchar2(222),
constraint ck1 check (date_matched = trunc(date_matched))
);
drop table t2;
create table t2 (
id number primary key,
date_matched date,
other_stuff varchar2(222)
);
declare
dm date;
dc integer := 0;
begin
for i in 1..100000 loop
if mod(i,10) = 0 then
dm := trunc(sysdate + mod(dc,66));
dc := dc+1;
else
dm := to_date('12/31/4712','mm/dd/yyyy');
end if;
insert into t1 values (i, dm, rpad('x',mod(i,222)));
insert into t2 values (i, dm, rpad('x',mod(i,222)));
end loop;
commit;
dbms_stats.gather_table_stats(
ownname=>USER,
tabname=>'T1',
cascade=>true,
estimate_percent=>NULL);
dbms_stats.gather_table_stats(
ownname=>USER,
tabname=>'T2',
cascade=>true,
estimate_percent=>NULL);
end;
/
create index t1_dm on t1(date_matched);
create index t2_dm on t2(date_matched);

select * from v$version;

-- here's the explain plan before 10195 event
explain plan for select count(*) from t1 where date_matched = to_date('12/31/4712','mm/dd/yyyy');
select * from table(dbms_xplan.display);
explain plan for select count(*) from t2 where date_matched = to_date('12/31/4712','mm/dd/yyyy');
select * from table(dbms_xplan.display);

alter session set events '10195 trace name context forever, level 1';

-- here's the explain plan after
explain plan for select count(*) from t1 where date_matched = to_date('12/31/4712','mm/dd/yyyy');
select * from table(dbms_xplan.display);
explain plan for select count(*) from t2 where date_matched = to_date('12/31/4712','mm/dd/yyyy');
select * from table(dbms_xplan.display);

-- set the 10195 event off for now
alter session set events '10195 trace name context off';

-- lets get some blocks in cache
select count(*) from t1 where date_matched = to_date('12/31/4712','mm/dd/yyyy');
select count(*) from t2 where date_matched = to_date('12/31/4712','mm/dd/yyyy');

-- lets time one with tkprof
alter session set tracefile_identifier = 't1t2';
alter session set events '10046 trace name context forever, level 12';
-- add a comment to get a new plan
select /* 10195 OFF Q1 */ count(*) from t1 where date_matched = to_date('12/31/4712','mm/dd/yyyy');
select /* 10195 OFF Q2 */ count(*) from t2 where date_matched = to_date('12/31/4712','mm/dd/yyyy');
select /*+ rule 10195 OFF Q3 */ count(*) from t1 where date_matched = to_date('12/31/4712','mm/dd/yyyy');

-- set 10195 event on again
alter session set events '10195 trace name context forever, level 1';

-- do queries again with new comments
select /* 10195 ON Q1 */ count(*) from t1 where date_matched = to_date('12/31/4712','mm/dd/yyyy');
select /* 10195 ON Q2 */ count(*) from t2 where date_matched = to_date('12/31/4712','mm/dd/yyyy');
select /*+ rule 10195 ON Q3 */ count(*) from t1 where date_matched = to_date('12/31/4712','mm/dd/yyyy');

-- just for kicks, do the bad plan again
alter session set events '10195 trace name context off';
select /* 10195 OFF_AGAIN Q2 */ count(*) from t2 where date_matched = to_date('12/31/4712','mm/dd/yyyy');
select /*+ rule 10195 OFF_AGAIN Q3 */ count(*) from t1 where date_matched = to_date('12/31/4712','mm/dd/yyyy');
select /* 10195 OFF_AGAIN Q1 */ count(*) from t1 where date_matched = to_date('12/31/4712','mm/dd/yyyy');


Results:

SQL> alter system flush shared_pool;

System altered.

Elapsed: 00:00:00.18
SQL> drop table t1;

Table dropped.

Elapsed: 00:00:00.97
SQL> create table t1 (
2 id number primary key,
3 date_matched date,
4 other_stuff varchar2(222),
5 constraint ck1 check (date_matched = trunc(date_matched))
6 );

Table created.

Elapsed: 00:00:00.06
SQL> drop table t2;

Table dropped.

Elapsed: 00:00:00.05
SQL> create table t2 (
2 id number primary key,
3 date_matched date,
4 other_stuff varchar2(222)
5 );

Table created.

Elapsed: 00:00:00.03
SQL> declare
2 dm date;
3 dc integer := 0;
4 begin
5 for i in 1..100000 loop
6 if mod(i,10) = 0 then
7 dm := trunc(sysdate + mod(dc,66));
8 dc := dc+1;
9 else
10 dm := to_date('12/31/4712','mm/dd/yyyy');
11 end if;
12 insert into t1 values (i, dm, rpad('x',mod(i,222)));
13 insert into t2 values (i, dm, rpad('x',mod(i,222)));
14 end loop;
15 commit;
16 dbms_stats.gather_table_stats(
17 ownname=>USER,
18 tabname=>'T1',
19 cascade=>true,
20 estimate_percent=>NULL);
21 dbms_stats.gather_table_stats(
22 ownname=>USER,
23 tabname=>'T2',
24 cascade=>true,
25 estimate_percent=>NULL);
26 end;
27 /

PL/SQL procedure successfully completed.

Elapsed: 00:00:36.07
SQL> create index t1_dm on t1(date_matched);

Index created.

Elapsed: 00:00:00.34
SQL> create index t2_dm on t2(date_matched);

Index created.

Elapsed: 00:00:00.34
SQL>
SQL> select * from v$version;

BANNER
----------------------------------------------------------------
Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Prod
PL/SQL Release 10.2.0.1.0 - Production
CORE 10.2.0.1.0 Production
TNS for Linux: Version 10.2.0.1.0 - Production
NLSRTL Version 10.2.0.1.0 - Production

Elapsed: 00:00:00.05
SQL>
SQL> -- here's the explain plan before 10195 event
SQL> explain plan for select count(*) from t1 where date_matched = to_date('12/31/4712','mm/dd/yyyy');

Explained.

Elapsed: 00:00:00.03
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
Plan hash value: 1573756541

---------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 8 | 4 (0)| 00:00:01 |
| 1 | SORT AGGREGATE | | 1 | 8 | | |
|* 2 | INDEX RANGE SCAN| T1_DM | 15 | 120 | 4 (0)| 00:00:01 |
---------------------------------------------------------------------------

Predicate Information (identified by operation id):

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
---------------------------------------------------

2 - access("DATE_MATCHED"=TO_DATE('4712-12-31 00:00:00', 'yyyy-mm-dd
hh24:mi:ss'))
filter(TRUNC(INTERNAL_FUNCTION("DATE_MATCHED"))=TO_DATE('4712-12-
31 00:00:00', 'yyyy-mm-dd hh24:mi:ss'))

17 rows selected.

Elapsed: 00:00:00.15
SQL> explain plan for select count(*) from t2 where date_matched = to_date('12/31/4712','mm/dd/yyyy');

Explained.

Elapsed: 00:00:00.01
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
Plan hash value: 3430539338

---------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 8 | 4 (0)| 00:00:01 |
| 1 | SORT AGGREGATE | | 1 | 8 | | |
|* 2 | INDEX RANGE SCAN| T2_DM | 1493 | 11944 | 4 (0)| 00:00:01 |
---------------------------------------------------------------------------

Predicate Information (identified by operation id):

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
---------------------------------------------------

2 - access("DATE_MATCHED"=TO_DATE('4712-12-31 00:00:00', 'yyyy-mm-dd
hh24:mi:ss'))

15 rows selected.

Elapsed: 00:00:00.02
SQL>
SQL> alter session set events '10195 trace name context forever, level 1';

Session altered.

Elapsed: 00:00:00.00
SQL>
SQL> -- here's the explain plan after
SQL> explain plan for select count(*) from t1 where date_matched = to_date('12/31/4712','mm/dd/yyyy');

Explained.

Elapsed: 00:00:00.00
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
Plan hash value: 1573756541

---------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 8 | 4 (0)| 00:00:01 |
| 1 | SORT AGGREGATE | | 1 | 8 | | |
|* 2 | INDEX RANGE SCAN| T1_DM | 1493 | 11944 | 4 (0)| 00:00:01 |
---------------------------------------------------------------------------

Predicate Information (identified by operation id):

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
---------------------------------------------------

2 - access("DATE_MATCHED"=TO_DATE('4712-12-31 00:00:00', 'yyyy-mm-dd
hh24:mi:ss'))

15 rows selected.

Elapsed: 00:00:00.02
SQL> explain plan for select count(*) from t2 where date_matched = to_date('12/31/4712','mm/dd/yyyy');

Explained.

Elapsed: 00:00:00.00
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
Plan hash value: 3430539338

---------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 8 | 4 (0)| 00:00:01 |
| 1 | SORT AGGREGATE | | 1 | 8 | | |
|* 2 | INDEX RANGE SCAN| T2_DM | 1493 | 11944 | 4 (0)| 00:00:01 |
---------------------------------------------------------------------------

Predicate Information (identified by operation id):

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
---------------------------------------------------

2 - access("DATE_MATCHED"=TO_DATE('4712-12-31 00:00:00', 'yyyy-mm-dd
hh24:mi:ss'))

15 rows selected.

Elapsed: 00:00:00.01
SQL>
SQL> -- set the 10195 event off for now
SQL> alter session set events '10195 trace name context off';

Session altered.

Elapsed: 00:00:00.00
SQL>
SQL> -- lets get some blocks in cache
SQL> select count(*) from t1 where date_matched = to_date('12/31/4712','mm/dd/yyyy');

COUNT(*)
----------
90000

Elapsed: 00:00:00.09
SQL> select count(*) from t2 where date_matched = to_date('12/31/4712','mm/dd/yyyy');

COUNT(*)
----------
90000

Elapsed: 00:00:00.02
SQL>
SQL> -- lets time one with tkprof
SQL> alter session set tracefile_identifier = 't1t2';

Session altered.

Elapsed: 00:00:00.00
SQL> alter session set events '10046 trace name context forever, level 12';

Session altered.

Elapsed: 00:00:00.00
SQL> -- add a comment to get a new plan
SQL> select /* 10195 OFF Q1 */ count(*) from t1 where date_matched = to_date('12/31/4712','mm/dd/yyyy');

COUNT(*)
----------
90000

Elapsed: 00:00:00.10
SQL> select /* 10195 OFF Q2 */ count(*) from t2 where date_matched = to_date('12/31/4712','mm/dd/yyyy');

COUNT(*)
----------
90000

Elapsed: 00:00:00.03
SQL> select /*+ rule 10195 OFF Q3 */ count(*) from t1 where date_matched = to_date('12/31/4712','mm/dd/yyyy');

COUNT(*)
----------
90000

Elapsed: 00:00:00.02
SQL>
SQL> -- set 10195 event on again
SQL> alter session set events '10195 trace name context forever, level 1';

Session altered.

Elapsed: 00:00:00.01
SQL>
SQL> -- do queries again with new comments
SQL> select /* 10195 ON Q1 */ count(*) from t1 where date_matched = to_date('12/31/4712','mm/dd/yyyy');

COUNT(*)
----------
90000

Elapsed: 00:00:00.03
SQL> select /* 10195 ON Q2 */ count(*) from t2 where date_matched = to_date('12/31/4712','mm/dd/yyyy');

COUNT(*)
----------
90000

Elapsed: 00:00:00.02
SQL> select /*+ rule 10195 ON Q3 */ count(*) from t1 where date_matched = to_date('12/31/4712','mm/dd/yyyy');

COUNT(*)
----------
90000

Elapsed: 00:00:00.03
SQL>
SQL> -- just for kicks, do the bad plan again
SQL> alter session set events '10195 trace name context off';

Session altered.

Elapsed: 00:00:00.01
SQL> select /* 10195 OFF_AGAIN Q2 */ count(*) from t2 where date_matched = to_date('12/31/4712','mm/dd/yyyy');

COUNT(*)
----------
90000

Elapsed: 00:00:00.02
SQL> select /*+ rule 10195 OFF_AGAIN Q3 */ count(*) from t1 where date_matched = to_date('12/31/4712','mm/dd/yyyy');

COUNT(*)
----------
90000

Elapsed: 00:00:00.03
SQL> select /* 10195 OFF_AGAIN Q1 */ count(*) from t1 where date_matched = to_date('12/31/4712','mm/dd/yyyy');

COUNT(*)
----------
90000

Elapsed: 00:00:00.09
SQL>

4 comments:

OracleDoc said...

So Jeff,
I don't know if I've missed something here or not...
You've found that if you blow away the constriant you get your performance back but do you still have the issue of deciding which is the lesser of two evils? Performance or integrity?

Jeff Hunter said...

I want it all! I'm hesitant to drop the constraints as they serve a valid purpose. My preference is to get Oracle to do the "right" thing and keep the constraints.

OracleDoc said...

You said that adding hints into the code is a bad thing because they "go bad".
How about creating a view with the hint that you need, that way the code is contained and if and when it goes bad, you know exactly where the culprit is.

Jeff Hunter said...

That's true, if it were a single occurrance. While this was the most pronounced case because of the skewed data, I have lots of other tables where we're using the same type of constraint where we're potentially losing lots of CPU cycles.