Oracle Performance and Engineering

I was trying to build a simple, SQL*Plus based test case for cost of parsing (i.e., recursive calls coming back with each different literals). And I had some surprising finds on 9i - yet to explain it or say it's a 'bug' - but here goes the test.

Test Bed -

create table t (a number,
b number,
c number,
d number,
e number,
f varchar2(200),
g date);

declare
j pls_integer;
begin
for i in 1..1000000 loop
j := dbms_random.random;
insert into t values (j,j+1, j-1, j+7, j/2,'this is a row which will be tested...', sysdate);
end loop;
commit;
end;
/


create index i1 on t(b);

create index i2 on t(g);

analyze table t compute statistics for table
for all indexes
for all columns;


Now on 10g --

SQL> select * from t where b = 233221323 and g > (sysdate - 1);

no rows selected

Elapsed: 00:00:00.00

Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=1 Card=1 Bytes=79)
1 0 TABLE ACCESS (BY INDEX ROWID) OF 'T' (TABLE) (Cost=1 Card=
1 Bytes=79)

2 1 INDEX (RANGE SCAN) OF 'I1' (INDEX) (Cost=3 Card=1)




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

on 9i --

SQL> select * from t where b = 2332213523 and g > (sysdate - 1);

no rows selected

Elapsed: 00:00:00.62

Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=2 Card=1 Bytes=79)
1 0 TABLE ACCESS (BY INDEX ROWID) OF 'T' (Cost=2 Card=1 Bytes=
79)

2 1 INDEX (RANGE SCAN) OF 'I1' (NON-UNIQUE) (Cost=1 Card=1)




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


Both were immediate first execution of a SQL after the index creation!!

Is it a SQL*Plus issue or Oracle version issue. Hmm.. Setting up the "sql_trace = true" on both beds and changing the literal --

on 10g --
--------
SQL> alter session set sql_trace = true;

Session altered.

Elapsed: 00:00:00.04
SQL> select * from t where b = 2332523 and g > (sysdate - 1);

no rows selected

Elapsed: 00:00:00.01

Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=1 Card=1 Bytes=79)
1 0 TABLE ACCESS (BY INDEX ROWID) OF 'T' (TABLE) (Cost=1 Card=
1 Bytes=79)

2 1 INDEX (RANGE SCAN) OF 'I1' (INDEX) (Cost=3 Card=1)




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

on 9i
-----

SQL> alter session set sql_trace = true;

Session altered.

Elapsed: 00:00:00.04
SQL> select * from t where b = 2332523 and g > (sysdate - 1);

no rows selected

Elapsed: 00:00:00.63

Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=2 Card=1 Bytes=79)
1 0 TABLE ACCESS (BY INDEX ROWID) OF 'T' (Cost=2 Card=1 Bytes=
79)

2 1 INDEX (RANGE SCAN) OF 'I1' (NON-UNIQUE) (Cost=1 Card=1)




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

Note -- still shows 'recursive calls = 0"!

Let's look at the trace files -


for 10g --

select *
from
t where b = 2332523 and g > (sysdate - 1)


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 1 0.00 0.00 0 3 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 3 0 0

Misses in library cache during parse: 1
Optimizer mode: CHOOSE
Parsing user id: 147

Rows Row Source Operation
------- ---------------------------------------------------
0 TABLE ACCESS BY INDEX ROWID T (cr=3 pr=0 pw=0 time=55 us)
0 INDEX RANGE SCAN I1 (cr=3 pr=0 pw=0 time=48 us)(object id 394056)


for 9i --

select *
from
t where b = 2332523 and g > (sysdate - 1)


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 1 0.00 0.00 2 3 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 2 3 0 0

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

Rows Row Source Operation
------- ---------------------------------------------------
0 TABLE ACCESS BY INDEX ROWID T
0 INDEX RANGE SCAN I1 (object id 95644)

Plus, on 9i trace file we actually see a recursive call which is missing on 10g file --

select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,
o.dataobj#,o.flags
from
obj$ o where o.obj#=:1


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 1 0.00 0.00 0 3 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 3 0 1

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: SYS (recursive depth: 1)

Overall for 10g --

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

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

Overall for 9i --

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.00 0.00 0 0 0 0
Execute 4 0.00 0.00 0 1 5 3
Fetch 1 0.00 0.00 0 3 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 0.00 0.00 0 4 5 4


So, in spite of 9i actually doing more recursive calls than 10g -- 'autotrace' shows 9i doing less (actually none!).

I'm a little lost on why 9i autotrace shows '0 recursive calls' at this moment!!