Once again about physical reads prefetch

It seems there is one mechanics for physical reads prefetch thoroughly described by Tanel Poder in his very useful blog:
http://blog.tanelpoder.com/2012/05/02/advanced-oracle-troubleshooting-guide-part-10-index-unique-scan-doing-multiblock-reads/

Let’s create a new table and populate it with an append operation:
like:

DROP TABLE IDXTEST;

CREATE TABLE IDXTEST
AS select (1e&pw) id, 1e4 id2, rpad(‘a’,999,’a’) filler
from dual where rownum <100;

———————————————————————–
disconnect
connect REMIDM/….@ORASOL11

insert /*+ APPEND */ into IDXTEST select 1e&pw + trunc(rownum/20)+1 id, mod(rownum,20) id2, rpad('a',999,'b') filler
from dual connect by level <=292*120+1 order by dbms_random.value;
commit;

CREATE INDEX IDXTEST_IX1 ON IDXTEST(id) PCTFREE 96;

let’s reconnect the session again (that’s an important part I’ll describe later),
parse the statement before to not spoil statistic by parsing the statement
and finally execute it:

disconnect
connect REMIDM/….@ORASOL11

DEFINE SQLSTMT =” /*+ dynamic_sampling(t 0) INDEX(t)*/ * from IDXTEST t WHERE id between :id1 and :id2 AND id2 IN (:l1,:l2,:l3,:l4,:l5,:l6,:l7,:l8)”

DECLARE
c number;
v_sql CLOB;
BEGIN
c := dbms_sql.open_cursor;
v_sql := ‘SELECT &SQLSTMT ‘;

DBMS_SQL.parse(c,v_sql,DBMS_SQL.NATIVE);
DBMS_SQL.close_cursor(c);
END;

alter session set events ‘sql_trace {pgadep: exactdepth 0} plan_stat=all_executions,wait=true,bind=false’;
—-
SELECT &SQLSTMT
/

alter session set events ‘sql_trace off’;

You would see quite common picture of the mix of db file scattered read/db file sequential read wait events:

WAIT #18446604434622825216: nam='db file scattered read' ela= 27 file#=4 block#=278163 blocks=5 obj#=78095 tim=5870483662
WAIT #18446604434622825216: nam='db file scattered read' ela= 23 file#=4 block#=277469 blocks=3 obj#=78095 tim=5870483776
................................
WAIT #18446604434622825216: nam='db file scattered read' ela= 30 file#=4 block#=277776 blocks=4 obj#=78095 tim=5870490796
WAIT #18446604434622825216: nam='db file scattered read' ela= 21 file#=4 block#=277366 blocks=2 obj#=78095 tim=5870490913
WAIT #18446604434622825216: nam='SQL*Net more data to client' ela= 355 driver id=1413697536 #bytes=8144 p3=0 obj#=78095 tim=5870491493
WAIT #18446604434622825216: nam='db file sequential read' ela= 28 file#=4 block#=277543 blocks=1 obj#=78095 tim=5870491962
FETCH #18446604434622825216:c=110000,e=112518,p=4966,cr=6785,cu=0,mis=0,r=1811,dep=0,og=1,plh=3072623726,tim=5870493352
STAT #18446604434622825216 id=1 cnt=1812 pid=0 pos=1 obj=0 op='FILTER  (cr=6790 pr=4974 pw=0 time=113400 us)'
STAT #18446604434622825216 id=2 cnt=1812 pid=1 pos=1 obj=78095 op='TABLE ACCESS BY INDEX ROWID IDXTEST (cr=6790 pr=4974 pw=0 time=103426 us cost=15855 size=527 card=1)'
STAT #18446604434622825216 id=3 cnt=6039 pid=2 pos=1 obj=78097 op='INDEX RANGE SCAN IDXTEST_IX1 (cr=758 pr=0 pw=0 time=37630 us cost=1767 size=0 card=33)'

It looks quite common so far: db file sequential read and db file scattered read
wait events in the trace file.

BUT let’s now comment out that reconnect part I mentioned before, like:
—disconnect
—connect REMIDM/…@ORASOL11
and almost the same code snippet would give a very different result:

WAIT #18446604434620761192: nam='SQL*Net more data to client' ela= 237 driver id=1413697536 #bytes=8145 p3=0 obj#=78100 tim=7011492476
WAIT #18446604434620761192: nam='db file parallel read' ela= 489 files=1 blocks=10 requests=10 obj#=78100 tim=7011493165
WAIT #18446604434620761192: nam='db file parallel read' ela= 1026 files=1 blocks=14 requests=14 obj#=78100 tim=7011494469
WAIT #18446604434620761192: nam='db file parallel read' ela= 510 files=1 blocks=12 requests=12 obj#=78100 tim=7011495247
WAIT #18446604434620761192: nam='db file parallel read' ela= 454 files=1 blocks=12 requests=12 obj#=78100 tim=7011495987
WAIT #18446604434620761192: nam='db file scattered read' ela= 31 file#=4 block#=270730 blocks=3 obj#=78100 tim=7011496204
WAIT #18446604434620761192: nam='db file parallel read' ela= 469 files=1 blocks=12 requests=12 obj#=78100 tim=7011496786
WAIT #18446604434620761192: nam='db file parallel read' ela= 478 files=1 blocks=11 requests=11 obj#=78100 tim=7011497492
WAIT #18446604434620761192: nam='db file scattered read' ela= 27 file#=4 block#=270323 blocks=3 obj#=78100 tim=7011497695
WAIT #18446604434620761192: nam='db file parallel read' ela= 247 files=1 blocks=5 requests=5 obj#=78100 tim=7011498056
WAIT #18446604434620761192: nam='db file parallel read' ela= 622 files=1 blocks=15 requests=15 obj#=78100 tim=7011498872
WAIT #18446604434620761192: nam='db file parallel read' ela= 525 files=1 blocks=14 requests=14 obj#=78100 tim=7011499608
WAIT #18446604434620761192: nam='db file parallel read' ela= 454 files=1 blocks=10 requests=10 obj#=78100 tim=7011500268
WAIT #18446604434620761192: nam='db file parallel read' ela= 466 files=1 blocks=11 requests=11 obj#=78100 tim=7011500960
WAIT #18446604434620761192: nam='db file parallel read' ela= 337 files=1 blocks=8 requests=8 obj#=78100 tim=7011501561
WAIT #18446604434620761192: nam='db file scattered read' ela= 34 file#=4 block#=271372 blocks=3 obj#=78100 tim=7011501748
FETCH #18446604434620761192:c=380000,e=191593,p=3769,cr=6777,cu=0,mis=0,r=1811,dep=0,og=1,plh=3072623726,tim=7011501866
STAT #18446604434620761192 id=1 cnt=1812 pid=0 pos=1 obj=0 op='FILTER  (cr=6786 pr=3817 pw=0 time=85684 us)'
STAT #18446604434620761192 id=2 cnt=1812 pid=1 pos=1 obj=78100 op='TABLE ACCESS BY INDEX ROWID IDXTEST (cr=6786 pr=3817 pw=0 time=79849 us cost=3976 size=527 card=1)'
STAT #18446604434620761192 id=3 cnt=6039 pid=2 pos=1 obj=78101 op='INDEX RANGE SCAN IDXTEST_IX1 (cr=759 pr=0 pw=0 time=11601 us cost=445 size=0 card=33)'

You see a plenty of “db file parallel read” waits, which seems a clear indication of “prefetch” mechanics in action.

One more indirect argument in supporting this thesis is behaviour after:

ALTER SYSTEM SET “_table_lookup_prefetch_size” =80 scope =spfile;

When “_table_lookup_prefetch_size” = 40 I see last wait events in the trace like:

WAIT #18446604434576175608: nam='db file parallel read' ela= 2068 files=1 blocks=39 requests=39 obj#=78158 tim=26289076453
WAIT #18446604434576175608: nam='db file scattered read' ela= 53 file#=4 block#=269568 blocks=8 obj#=78158 tim=26289076664
WAIT #18446604434576175608: nam='db file parallel read' ela= 1340 files=1 blocks=39 requests=39 obj#=78158 tim=26289078178
WAIT #18446604434576175608: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=78158 tim=26289078322
WAIT #18446604434576175608: nam='db file scattered read' ela= 78 file#=4 block#=269936 blocks=8 obj#=78158 tim=26289078584
WAIT #18446604434576175608: nam='db file parallel read' ela= 1566 files=1 blocks=38 requests=38 obj#=78158 tim=26289080288
WAIT #18446604434576175608: nam='db file scattered read' ela= 39 file#=4 block#=269289 blocks=7 obj#=78158 tim=26289080555
WAIT #18446604434576175608: nam='db file parallel read' ela= 1981 files=1 blocks=39 requests=39 obj#=78158 tim=26289082686

If “_table_lookup_prefetch_size” = 80:

WAIT #18446604434621780232: nam='db file parallel read' ela= 6790 files=1 blocks=79 requests=79 obj#=78168 tim=28714230362
WAIT #18446604434621780232: nam='db file sequential read' ela= 17 file#=4 block#=275977 blocks=1 obj#=78168 tim=28714230584
WAIT #18446604434621780232: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=78168 tim=28714230633
WAIT #18446604434621780232: nam='db file parallel read' ela= 2209 files=1 blocks=75 requests=75 obj#=78168 tim=28714233103
WAIT #18446604434621780232: nam='db file scattered read' ela= 71 file#=4 block#=276504 blocks=5 obj#=78168 tim=28714233474
WAIT #18446604434621780232: nam='db file parallel read' ela= 1774 files=1 blocks=77 requests=77 obj#=78168 tim=28714235434
WAIT #18446604434621780232: nam='db file sequential read' ela= 19 file#=4 block#=275970 blocks=1 obj#=78168 tim=28714235722
WAIT #18446604434621780232: nam='db file parallel read' ela= 19067 files=1 blocks=73 requests=73 obj#=78168 tim=28714255008
WAIT #18446604434621780232: nam='db file parallel read' ela= 2064 files=1 blocks=74 requests=74 obj#=78168 tim=28714257598

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s