Saturday, November 3, 2012

Reduced consistent gets in 11g

Oracle database 11g has as Optimization with consistent gets involved in Nested loop joins.

drop table t1 purge;
drop table t2 purge;

create table t1
nologging as
select a.*,rownum as id
from all_objects a
where rownum <= 10000;

create table t2
nologging as
select * from t1;

begin
 dbms_stats.gather_table_stats(user,'T1');
 dbms_stats.gather_table_stats(user,'T2');
end;
/

create index t1_ind on t1(id);
select /*+ use_nl(t2,t1) */ count(*)
from t1, t2
where t1.id = t2.id
/

Tkprof from Oracle 10g database shows me this.


********************************************************************************
select /*+ use_nl(t2,t1) */ count(*)
from t1, t2
where t1.id = t2.id

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.02          0          0          0           0
Fetch        2      0.04       0.04          0      10157          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.04       0.06          0      10157          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 61 

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=10157 pr=0 pw=0 time=46412 us)
  10000   NESTED LOOPS  (cr=10157 pr=0 pw=0 time=50094 us)
  10000    TABLE ACCESS FULL T2 (cr=135 pr=0 pw=0 time=77 us)
  10000    INDEX RANGE SCAN T1_IND (cr=10022 pr=0 pw=0 time=36338 us)(object id 53690)


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
********************************************************************************


Where as Tkprof from Oracle 11g database shows me this.


********************************************************************************
select /*+ use_nl(t2,t1) */ count(*)
from t1, t2
where t1.id = t2.id

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.03       0.02          0        288          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.03       0.02          0        288          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84 

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=288 pr=0 pw=0 time=0 us)
  10000   NESTED LOOPS  (cr=288 pr=0 pw=0 time=26199 us cost=10047 size=80000 card=10000)
  10000    TABLE ACCESS FULL T2 (cr=140 pr=0 pw=0 time=2657 us cost=42 size=40000 card=10000)
  10000    INDEX RANGE SCAN T1_IND (cr=148 pr=0 pw=0 time=0 us cost=1 size=4 card=1)(object id 74845)


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
********************************************************************************


We are seeing a reduced consistent gets in Oracle 11g because the dedicated server decide in keeping the index block after each lookup in the hopes it could use it again right away. Instead of reading and re-reading the block time after time. The dedicated server is caching the block in your pga, so that it doesn't have to get and re-get from buffer cache.


drop table t1 purge;
drop table t2 purge;

create table t1
nologging as
select *
from (
select a.*,rownum as id
from all_objects a
where rownum <= 10000
  )
order by dbms_random.random;

create table t2
nologging as
select * from t1;

begin
 dbms_stats.gather_table_stats(user,'T1');
 dbms_stats.gather_table_stats(user,'T2');
end;
/

create index t1_ind on t1(id);

********************************************************************************
select /*+ use_nl(t2,t1) */ count(*)
from t1, t2
where t1.id = t2.id
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.03       0.03          0      10162          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.03       0.03          0      10162          0           1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84 
Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=10162 pr=0 pw=0 time=0 us)
  10000   NESTED LOOPS  (cr=10162 pr=0 pw=0 time=33540 us cost=10047 size=80000 card=10000)
  10000    TABLE ACCESS FULL T2 (cr=140 pr=0 pw=0 time=2911 us cost=42 size=40000 card=10000)
  10000    INDEX RANGE SCAN T1_IND (cr=10022 pr=0 pw=0 time=0 us cost=1 size=4 card=1)(object id 74848)

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
********************************************************************************

As soon as we start reading the index in random fashion the effect well disappered. Thus far optimization seems to be kicking in only if we repeaditly accessing the same block over and over again

1 comment:

  1. Hello Rajesh,

    I am focussing on the timings for the full table scans on T2.
    In Oracle 11 you see : TABLE ACCESS FULL T2 (cr=140 pr=0 pw=0 time=2657 us
    In Oracle 10 it was : TABLE ACCESS FULL T2 (cr=135 pr=0 pw=0 time=77 us)
    The full tablescan (without physical reads) is 30 times slower in 11g as in 10g !!!

    I have a similar execution plan where a more than half of a 4.000.000 rows table is cached in memory :
    In Oracle 10 tkprof shows: cr=195955 pr=0 time=64 us
    In Oracle 11 tkprof shows : cr=204160 pr=0 time=3211688 us

    Do you think I could tweak Oracle 11 to get the blocks (almost) as fast as in Oracle 10?

    ReplyDelete