Oracle 10g upgrade gotcha

Everybody knows the Cost Based Optimizer needs decent statistics to figure out what his query plan should be. Sure, it takes time, but everybody does it. Some estimate, some compute, some think they have a better way.

After upgrading from 9.2.0.7 to 10.2.0.3, one of our systems suddenly slowed down. Not directly after the upgrade, but three days later. After some investigation, we found that some of the statistics had been estimated and not computed. That was pretty much a shock because my analyze method usually specifies estimate_percent=>null to make sure we compute. (Note, I already figured out that the default estimate_percent changed from 9i to 10g, so that wasn't it.)

I checked my custom analyze method and it reported that the table was never analyzed by me.

Hmmm, now it's getting real interesting. Just for kicks, I reran dbms_stats.gather_table_stats without an estimate_percent parameter and it estimated at about 8.3%. Aha! Must be using the AUTO_SAMPLE_SIZE for some reason.

So why?

Then I looked at the last_analyzed time of the tables that had been estimated. They all were run between 22:00 and 01:00. Aha, a schedule. Then I looked in dba_scheduler_jobs and there it was. A new job that Oracle automatically sets up to analyze stale objects.

When I checked in the morning, the objects didn't report as being stale. Then, after the day's data, Oracle decided the statistics were stale and analyzed the tables. When I went to gather statistics for stale objects the next morning, they had already been analyzed and weren't stale anymore. Except the statistics weren't optimal which made our queries "go bad".

Fortunately, there is a way you can disable this job just by tweaking the schedule.

BEGIN
DBMS_SCHEDULER.DISABLE('GATHER_STATS_JOB');
END;
/

10195 event, epilogue

You may recall my recent issues with Oracle and predicate generation, here, here, here, and here.

We set the 10195 event for the entire instance in once case to see if it would fix our general problem without breaking everything else. Alas, the 10195 event stopped generating predicates, but changed execution plans on other queries as well. We confirmed this by turning the 10195 event off at the session level and re-executing (and reparsing) the query. As a general observation, the 10195 had a tendency to favor hash joins over everything else. Now we get to decide what is more important; performance or data integrity.

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>

Just set the 10195 event

Going back and forth with Oracle on what I think is an optimizer problem. Thanks to JL, we pretty much have figured out what the short-term solution is, yet the nagging question is Why?

Oracle Support came up with an 10195 event (Doc: 271999.1 on ML for those interested) , which essentially disables predicate generation for check constraints. OK, fine and dandy. But it still doesn't solve our performance problem. Perhaps it's more than an optimizer problem after all. (I'll post at the end of the article the exact scripts I used to setup this example. I'd actually be interested if other people on other platforms experience this as well.)

Take for example:

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

Session altered.

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

Session altered.

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

Explained.

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

PLAN_TABLE_OUTPUT                                                             
--------------------------------------------------------------------------------
Plan hash value: 2788119336                                                   
                                                                            
---------------------------------------------------------------------------   
| 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'))                                                   
                                                                            
Note                                                                          
-----                                                                         
 - 'PLAN_TABLE' is old version                                              

19 rows selected.

Elapsed: 00:00:00.53

OK, my filter predicate is gone. But looking at the tkprof, I still find:

select count(*)
from
t1 where date_matched = to_date('12/31/4712','mm/dd/yyyy')


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.28       0.27          0        241          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.28       0.27          0        241          0           1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 5 

Rows     Row Source Operation
-------  ---------------------------------------------------
     1  SORT AGGREGATE (cr=241 pr=0 pw=0 time=277577 us)
 90000   INDEX RANGE SCAN T1_DM (cr=241 pr=0 pw=0 time=270112 us)(object id 649118)


Elapsed times include waiting on following events:
 Event waited on                             Times   Max. Wait  Total Waited
 ----------------------------------------   Waited  ----------  ------------
 SQL*Net message to client                       2        0.00          0.00
 SQL*Net message from client                     2        0.00          0.00
**************************************************************************
select count(*)
from
t2 where date_matched = to_date('12/31/4712','mm/dd/yyyy')


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.05       0.05          0        241          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.05       0.05          0        241          0           1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 5 

Rows     Row Source Operation
-------  ---------------------------------------------------
     1  SORT AGGREGATE (cr=241 pr=0 pw=0 time=51866 us)
 90000   INDEX RANGE SCAN T2_DM (cr=241 pr=0 pw=0 time=120 us)(object id 649119)


Elapsed times include waiting on following events:
 Event waited on                             Times   Max. Wait  Total Waited
 ----------------------------------------   Waited  ----------  ------------
 SQL*Net message to client                       2        0.00          0.00
 SQL*Net message from client                     2        0.00          0.00

Now what's the problem? I'm retrieving the same number of blocks (from cache, I might add). Yet, my elapsed time to retrieve data on the table with a constraint (even with the predicate constraint checking supposedly off) is .27 seconds vs. .05 for the table without the check constraint. To add insult to injury, if we pull out our old friend the Rule Based Optimizer:

select /*+ rule */ count(*)
from
t1 where date_matched = to_date('12/31/4712','mm/dd/yyyy')


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch        2      0.06       0.05          0        241          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        5      0.06       0.05          0        241          0           1

Misses in library cache during parse: 0
Optimizer mode: RULE
Parsing user id: 5 

Rows     Row Source Operation
-------  ---------------------------------------------------
     1  SORT AGGREGATE (cr=241 pr=0 pw=0 time=53206 us)
 90000   INDEX RANGE SCAN T1_DM (cr=241 pr=0 pw=0 time=86 us)(object id 649118)


Elapsed times include waiting on following events:
 Event waited on                             Times   Max. Wait  Total Waited
 ----------------------------------------   Waited  ----------  ------------
 SQL*Net message to client                       3        0.00          0.00
 SQL*Net message from client                     3        0.00          0.00

Ouch.

An omnipotent inside Oracle brings up a good point. It's the fetch where all the time is being spent. True, but Why? Why would the access path for the same plan be different? Still chugging along, looking for answers.

I'd be interested in your findings. I've tried this on Solaris 32, Solaris 64, Linux x86, and Linux x86_64. All similar (except x86_64 rocks and it's hard to tell a difference). I actually think the slower the box, the better.

script to reproduce:

set timing on
set echo on;
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;
end;
/
create index t1_dm on t1(date_matched);
create index t2_dm on t2(date_matched);
exec dbms_stats.gather_table_stats(ownname=>USER,tabname=>'T1',cascade=>true,estimate_percent=>NULL);
exec dbms_stats.gather_table_stats(ownname=>USER,tabname=>'T2',cascade=>true,estimate_percent=>NULL);
select * from v$version;
select date_matched, count(*) from t1 group by date_matched order by date_matched;
select date_matched, count(*) from t2 group by date_matched order by date_matched;
-- heres the explain plan
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);
-- here's the explain plan
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);
-- 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 events '10046 trace name context forever, level 12';
alter session set tracefile_identifier = 't1t2_10046';
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');
-- yet RBO yields basically same result as t2
select /*+ rule */ count(*) from t1 where date_matched = to_date('12/31/4712','mm/dd/yyyy');
-- lets get a plan with the event turned on
alter session set events '10195 trace name context forever, level 1';
alter session set events '10046 trace name context forever, level 12';
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);

-- lets time one with tkprof
alter session set tracefile_identifier = 't1t2_10195';
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');
-- yet RBO yields basically same result as t2
select /*+ rule */ count(*) from t1 where date_matched = to_date('12/31/4712','mm/dd/yyyy');

The Optimizer, an update

My last post involving the optimizer was quite perplexing until Jonathan Lewis commented on it. Indeed, the check constraint was the problem in this particular case.

I was so frustrated, I went down the path of upgrading to the latest version since I knew Oracle wouldn't be submitting a bug on 9.2.0.5. I even changed platform just for kicks:

SQL> select * from v$version;

BANNER                                                                                      
----------------------------------------------------------------                            
Oracle Database 10g Release 10.2.0.2.0 - Production                                         
PL/SQL Release 10.2.0.2.0 - Production                                                      
CORE 10.2.0.2.0 Production                                                                  
TNS for Linux: Version 10.2.0.2.0 - Production                                              
NLSRTL Version 10.2.0.2.0 - Production                                                      

Alas, I still had the problem before Jonathan suggested the constraints.

SQL> select count(*) from activity_rtab where date_matched = '31-dec-4712';

COUNT(*)                                                                                   
----------                                                                                   
  370319                                                                                   

Elapsed: 00:00:00.27
SQL> select count(*) from activity_rtab where date_matched = '31-dec-4712';

COUNT(*)                                                                                   
----------                                                                                   
  370319                                                                                   

Elapsed: 00:00:00.27

If I had only chased down the filter predicate using the new dbms_xplan.display method, I might have had some more clues:

SQL> explain plan for select count(*) from activity_rtab where date_matched = '31-dec-4712';

Explained.

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

PLAN_TABLE_OUTPUT                                                                            
----------------------------------
Plan hash value: 3790338984                                                                  
                                                                                           
----------------------------------------------------------------------------------------------
| Id  | Operation         | Name                     | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |                          |     1 |     8 |   269   (3)| 00:00:04 |
|   1 |  SORT AGGREGATE   |                          |     1 |     8 |            |          |
|*  2 |   INDEX RANGE SCAN| IX_ACTIVITY_DATE_MATCHED |  3801 | 30408 |   269   (3)| 00:00:04 |
----------------------------------------------------------------------------------------------
                                                                                           
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'))                                                      

16 rows selected.

I dropped the constraint and sure enough, the performance problem went away:

SQL> select count(*) from activity_rtab where date_matched = '31-dec-4712';

COUNT(*)                                                                                   
----------                                                                                   
  370319                                                                                   

Elapsed: 00:00:00.06
SQL> explain plan for select count(*) from activity_rtab where date_matched = '31-dec-4712';

Explained.

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

PLAN_TABLE_OUTPUT                                                                            
-----------------------------------------------------------------------------------------------
Plan hash value: 3790338984                                                                  
                                                                                           
----------------------------------------------------------------------------------------------
| Id  | Operation         | Name                     | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |                          |     1 |     8 |   264   (1)| 00:00:04 |
|   1 |  SORT AGGREGATE   |                          |     1 |     8 |            |          |
|*  2 |   INDEX RANGE SCAN| IX_ACTIVITY_DATE_MATCHED |   380K|  2969K|   264   (1)| 00:00:04 |
----------------------------------------------------------------------------------------------
                                                                                           
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'))        

14 rows selected.

Now we have to decide; use the constraint to ensure data integrity or suffer the performance penalty for the sake of the data. A classic trade-off.

What is the optimizer doing?

Interesting problem here. I have a table in one of my Oracle 9.2.0.5 databases on Solaris called ACTIVITY_RTAB:

SQL> desc activity_rtab;
Name              Null?    Type
----------------- -------- --------------
ID                NOT NULL NUMBER(19)
FLAG1             NOT NULL CHAR(1)
MONEY_AMOUNT      NOT NULL MONEYAMOUNT_T
DATE1             NOT NULL DATE
DATE2             NOT NULL DATE
DATE3             NOT NULL DATE
DATE_MATCHED      NOT NULL DATE
FLAG2             NOT NULL CHAR(1)
STR1              NOT NULL VARCHAR2(100)
FLAG3             NOT NULL CHAR(1)
ID2               NOT NULL NUMBER(19)
STR2              NOT NULL VARCHAR2(10)
ID3               NOT NULL NUMBER(19)
FLAG4             NOT NULL CHAR(1)
DATE4             NOT NULL DATE
DATE5             NOT NULL DATE
ID4               NOT NULL NUMBER(38)
DATE6             NOT NULL DATE

This table has two indicies; a Primary Key on ID, and a NON-UNIQUE index on DATE_MATCHED. The data in DATE_MATCHED is pretty skewed. I have about 10K rows per day in this table, except for the date '31-DEC-4712', which I have about 355K rows.

select
  before_on,
  avg(rows_per_day) avg_rows_per_day
from (
  select
     case
        when date_matched < '31-dec-4712' then 'before'
        else 'on'
     end before_on,
     trunc(date_matched) dm,
     count(*) rows_per_day
  from activity_rtab
  group by
     case
        when date_matched < '31-dec-4712' then 'before'
        else 'on'
    end,
    trunc(date_matched)
 )
 group by before_on
 /

BEFORE  AVG_ROWS_PER_DAY                                                       
------ -----------------                                                       
before           9413.75                                                       
on             355606.00                                                       

Queries using the index on DATE_MATCHED index are somewhat quick for any day other than '31-DEC-4712'. This behaviour doesn't really surprise me since I'll be fetching 355K rows basically a single block at a time.

select
  count(*)
from activity_rtab
where date_matched = '31-DEC-4712';

 COUNT(*)                                                                     
----------                                                                     
   355606                                                                     

Elapsed: 00:00:03.48

Execution Plan
----------------------------------------------------------                     
  0      SELECT STATEMENT Optimizer=CHOOSE (Cost=8 Card=1 Bytes=8)            
  1    0   SORT (AGGREGATE)                                                   
  2    1     INDEX (RANGE SCAN) OF 'IX_ACTIVITY_DATE_MATCHED' (NON-UNIQUE) (Cost=29 Card=99 Bytes=792)
Statistics
----------------------------------------------------------                     
        56  recursive calls                                                   
         0  db block gets                                                     
      1031  consistent gets                                                   
         0  physical reads                                                    
         0  redo size                                                         
       381  bytes sent via SQL*Net to client                                  
       499  bytes received via SQL*Net from client                            
         2  SQL*Net roundtrips to/from client                                 
         0  sorts (memory)                                                    
         0  sorts (disk)                                                      
         1  rows processed           

I know what you're thinking, "OK, so what's your problem?". In order to do some maintenance, I did a CTAS and created a new table in the same tablespace. I put both indicies on the new table and ran a quick query.

select count(*) from jh$activity_rtab where date_matched = '31-DEC-4712';

 COUNT(*)                                                                     
----------                                                                     
   355606                                                                     

Elapsed: 00:00:00.53

Execution Plan
----------------------------------------------------------                     
  0      SELECT STATEMENT Optimizer=CHOOSE (Cost=8 Card=1 Bytes=8)            
  1    0   SORT (AGGREGATE)                                                   
  2    1     INDEX (RANGE SCAN) OF 'JH$DATE_MATCHED' (NON-UNIQUE) (Cost=29 Card=9867 Bytes=78936)
                                                                              
Statistics
----------------------------------------------------------                     
        14  recursive calls                                                   
         0  db block gets                                                     
       949  consistent gets                                                   
         0  physical reads                                                    
         0  redo size                                                         
       381  bytes sent via SQL*Net to client                                  
       499  bytes received via SQL*Net from client                            
         2  SQL*Net roundtrips to/from client                                 
         0  sorts (memory)                                                    
         0  sorts (disk)                                                      
         1  rows processed                                                    

Huh? Why is this returning in less than a second where the query on the real table takes 3? At first, I thought something must be wrong with the storage so I moved the table and rebuilt the indexes. Same thing.

Then I looked closer at the plan and noticed the query on JH$ACTIVITY_RTAB had "Card=9867" and the query against ACTIVITY_RTAB had "Card=99". Aha! A statistics problem. I calculated statistics on both tables using the following commands:

exec dbms_stats.gather_table_stats(ownname=>USER,tabname=>'activity_rtab',cascade=>true);

No dice. The query on JH$ACTIVITY_RTAB was still significantly faster than ACTIVITY_RTAB. Then I decided to take my own advice and ran a 10046 trace on both queries. The TKPROF confirmed my observations, but still offered no clues as to what the real problem was.

select count(*)
from
jh$activity_rtab where date_matched = '31-DEC-4712'


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        3      0.00       0.01          0          0          0           0
Execute      3      0.00       0.00          0          0          0           0
Fetch        6      0.92       0.91          0       2838          0           3
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       12      0.92       0.92          0       2838          0           3

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 42 

Rows     Row Source Operation
-------  ---------------------------------------------------
     1  SORT AGGREGATE
355606   INDEX RANGE SCAN JH$DATE_MATCHED (object id 43980)


Elapsed times include waiting on following events:
 Event waited on                             Times   Max. Wait  Total Waited
 ----------------------------------------   Waited  ----------  ------------
 SQL*Net message to client                       6        0.00          0.00
 SQL*Net message from client                     6        0.00          0.00
********************************************************************************

select count(*)
from
ACTIVITY_RTAB where date_matched = '31-DEC-4712'


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.01       0.00          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch        4      6.05       6.22          0       2030          0           2
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        8      6.06       6.23          0       2030          0           2

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 42 

Rows     Row Source Operation
-------  ---------------------------------------------------
     1  SORT AGGREGATE
355606   INDEX RANGE SCAN IX_ACTIVITY_DATE_MATCHED (object id 37979)


Elapsed times include waiting on following events:
 Event waited on                             Times   Max. Wait  Total Waited
 ----------------------------------------   Waited  ----------  ------------
 SQL*Net message to client                       4        0.00          0.00
 SQL*Net message from client                     4        0.00          0.00
********************************************************************************

At this point, I had a hunch that it was an optimizer problem but couldn't convince myself. I couldn't get around the fact that both tables had nearly exact characteristics but the queries performed radically different. Time for a 10053 trace on both tables:

Table stats    Table: JH$ACTIVITY_RTAB   Alias: JH$ACTIVITY_RTAB
 TOTAL ::  CDN: 7538301  NBLKS:  121877  AVG_ROW_LEN:  109
-- Index stats
 INDEX NAME: JH$DATE_MATCHED  COL#: 9
   TOTAL ::  LVLS: 2   #LB: 19996  #DK: 764  LB/K: 26  DB/K: 253  CLUF: 194025
 INDEX NAME: JH$PK  COL#: 1
   TOTAL ::  LVLS: 2   #LB: 16754  #DK: 7538301  LB/K: 1  DB/K: 1  CLUF: 908531
_OPTIMIZER_PERCENT_PARALLEL = 0
***************************************
SINGLE TABLE ACCESS PATH
Column: DATE_MATCH  Col#: 9      Table: JH$ACTIVITY_RTAB   Alias: JH$ACTIVITY_RTAB
   NDV: 764       NULLS: 0         DENS: 1.3089e-03 LO:  2453031  HI: 3442447
   NO HISTOGRAM: #BKT: 1 #VAL: 2
 TABLE: JH$ACTIVITY_RTAB     ORIG CDN: 7538301  ROUNDED CDN: 9867  CMPTD CDN: 9867
 Access path: tsc  Resc:  11723  Resp:  11723
 Access path: index (iff)
     Index: JH$DATE_MATCHED
 TABLE: JH$ACTIVITY_RTAB
     RSC_CPU: 0   RSC_IO: 1925
 IX_SEL:  0.0000e+00  TB_SEL:  1.0000e+00
 Access path: iff  Resc:  1925  Resp:  1925
 Access path: index (equal)
     Index: JH$DATE_MATCHED
 TABLE: JH$ACTIVITY_RTAB
     RSC_CPU: 0   RSC_IO: 29
 IX_SEL:  0.0000e+00  TB_SEL:  1.3089e-03
 BEST_CST: 8.00  PATH: 4  Degree:  1
***************************************
OPTIMIZER STATISTICS AND COMPUTATIONS
***************************************
GENERAL PLANS
***********************
Join order[1]:  JH$ACTIVITY_RTAB[JH$ACTIVITY_RTAB]#0
Best so far: TABLE#: 0  CST:          8  CDN:       9867  BYTES:      78936
Final - All Rows Plan:
 JOIN ORDER: 1
 CST: 8  CDN: 9867  RSC: 7  RSP: 7  BYTES: 78936
 IO-RSC: 7  IO-RSP: 7  CPU-RSC: 1  CPU-RSP: 1
PLAN
Cost of plan:  8
Operation...........Object name.....Options.........Id...Pid..
SELECT STATEMENT                                        0
SORT                                AGGREGATE           1
INDEX               JH$DATE_MATCHED RANGE SCAN          2    1
BASE STATISTICAL INFORMATION
***********************
Table stats    Table: ACTIVITY_RTAB   Alias: ACTIVITY_RTAB
 TOTAL ::  CDN: 7538301  NBLKS:  121875  AVG_ROW_LEN:  109
-- Index stats
 INDEX NAME: ACTIVITY_PK  COL#: 1
   TOTAL ::  LVLS: 2   #LB: 16748  #DK: 7538301  LB/K: 1  DB/K: 1  CLUF: 908561
 INDEX NAME: IX_ACTIVITY_DATE_MATCHED  COL#: 9
   TOTAL ::  LVLS: 2   #LB: 20112  #DK: 764  LB/K: 26  DB/K: 253  CLUF: 194021
_OPTIMIZER_PERCENT_PARALLEL = 0
***************************************
SINGLE TABLE ACCESS PATH
Column: DATE_MATCH  Col#: 9      Table: ACTIVITY_RTAB   Alias: ACTIVITY_RTAB
   NDV: 764       NULLS: 0         DENS: 1.3089e-03 LO:  2453031  HI: 3442447
   NO HISTOGRAM: #BKT: 1 #VAL: 2
 TABLE: ACTIVITY_RTAB     ORIG CDN: 7538301  ROUNDED CDN: 99  CMPTD CDN: 99
 Access path: tsc  Resc:  11723  Resp:  11723
 Access path: index (iff)
     Index: IX_ACTIVITY_DATE_MATCHED
 TABLE: ACTIVITY_RTAB
     RSC_CPU: 0   RSC_IO: 1936
 IX_SEL:  0.0000e+00  TB_SEL:  1.0000e+00
 Access path: iff  Resc:  1936  Resp:  1936
 Access path: index (equal)
     Index: IX_ACTIVITY_DATE_MATCHED
 TABLE: ACTIVITY_RTAB
     RSC_CPU: 0   RSC_IO: 29
 IX_SEL:  0.0000e+00  TB_SEL:  1.3089e-03
 BEST_CST: 8.00  PATH: 4  Degree:  1
***************************************
OPTIMIZER STATISTICS AND COMPUTATIONS
***************************************
GENERAL PLANS
***********************
Join order[1]:  ACTIVITY_RTAB[ACTIVITY_RTAB]#0
Best so far: TABLE#: 0  CST:          8  CDN:         99  BYTES:        792
Final - All Rows Plan:
 JOIN ORDER: 1
 CST: 8  CDN: 99  RSC: 7  RSP: 7  BYTES: 792
 IO-RSC: 7  IO-RSP: 7  CPU-RSC: 1  CPU-RSP: 1

The queries are basically the same except for that darn Cardinality (CDN). I pulled out Jonathan Lewis' latest book and went through the calculations but still don't see how the CDN of 99 is being computed. I played around with histograms and different bucket sizes, but always came back to the simple premise of "If performance is fine with JH$ACTIVITY_RTAB, why does it suck with ACTIVITY_RTAB"?

I just don't understand it. For kicks, I tried the query with a +RULE hint and it returned in .48 seconds.

SQL> select /*+ rule */ count(*) from ACTIVITY_RTAB where date_matched = '31-DEC-4712';

 COUNT(*)                                                                     
----------                                                                     
   355606                                                                     

Elapsed: 00:00:00.48

Execution Plan
----------------------------------------------------------                     
  0      SELECT STATEMENT Optimizer=HINT: RULE                                
  1    0   SORT (AGGREGATE)                                                   
  2    1     INDEX (RANGE SCAN) OF 'IX_ACTIVITY_DATE_MATCHED' (NON-UNIQUE)                                                                
                                                                              

Statistics
----------------------------------------------------------                     
         0  recursive calls                                                   
         0  db block gets                                                     
      1015  consistent gets                                                   
         0  physical reads                                                    
         0  redo size                                                         
       381  bytes sent via SQL*Net to client                                  
       499  bytes received via SQL*Net from client                            
         2  SQL*Net roundtrips to/from client                                 
         0  sorts (memory)                                                    
         0  sorts (disk)                                                      
         1  rows processed  

I'm really perplexed at this point. Sure, I have two workarounds; use the +RULE hint or drop the table and recreate it. I'm not a big fan of hinting since hinted queries seem to be the first queries that "go bad" when you upgrade. Dropping the table seems reasonable, but since I don't know how I got into this situation, I'm not sure how to detect it. Sort of like choosing between a root canal and a colonoscopy.

An update is here.