Secret of oracle logic IO: Full Table Scan: Part 1

Date: 2009-11-04 09:10:41

Share to

    How to calculate the io of a query? This question is the most concern of dba&developer when we do performance tuning. We know the IO is affected by many factors in different operations, e.g. , high water mark, index height, extents number of a segment, cr UNDO application and so on. However, for the details of the factors in IO calculation formula, are secrets for us. Even work with 10200 event, we can not count up to the final total CRs, because this trace ignored the meta data reads. By monitoring the buffer cache, we can just guess it also reads the segment header for times, and repeat reads for number of extents. From the fixed table sys.x$kcbwh, sys.x$kcbsw, we can find the buffer cache statisitcs data, which are directly related to the io behaviors. By comparing the statistic data before&after the query, we may peek some internal information for the Logical IO. However, this view is a db level statistics data, it will be affected by the backgroup processes, we may not get the truth from it. So, is there any other way to find out the secret? Yes! As we know, for each data reads, it will be pined in the cache, means if we can trace the pin behaviors, we will know IO behaviors. Read which block? For what purpose? How many times a block will be red? The switch is the undocumented parameter, "_trace_pin_time".

    Let start with the Full Table Scan.

Full Table Scan --- Small Table

    The parameter just mentioned is to trace how long a current pin is held, default is 0. Let set it be 1 to enable the trace. It need be changed in pfile/spfile.

SQL代码

HELLODBA.COM>alter system set "_trace_pin_time"=1 scope=spfile;



System altered.



HELLODBA.COM>startup force

...

Database mounted.

Database opened.

    Let's first trace a small table, tt, who has just 2 records, and is stored in an ASSM tablespace. Full table scan on this table will cause 7 Logical reads:

SQL代码

HELLODBA.COM>select * from tt;





Execution Plan

----------------------------------------------------------

Plan hash value: 264906180



----------------------------------

| Id  | Operation         | Name |

----------------------------------

|   0 | SELECT STATEMENT  |      |

|   1 |  TABLE ACCESS FULL| TT   |

----------------------------------



Note

-----

   - rule based optimizer used (consider using cbo)





Statistics

----------------------------------------------------------

          1  recursive calls

          0  db block gets

          7  consistent gets

          0  physical reads

          0  redo size

        440  bytes sent via SQL*Net to client

        385  bytes received via SQL*Net from client

          2  SQL*Net roundtrips to/from client

          0  sorts (memory)

          0  sorts (disk)

          2  rows processed

    As comparison, first make a 10200 trace for it:

SQL代码

HELLODBA.COM>conn demo/demo

Connected.

HELLODBA.COM>alter system flush buffer_cache;



System altered.



HELLODBA.COM>ALTER SESSION SET EVENTS '10200 trace name context forever, level 1';



Session altered.



HELLODBA.COM>select * from tt;



         X

----------

         1

         1

    From trace file, we can just find 5 consistent reads. By further checking the segment header, we should know they are the 5 data block under high watermark:

SQL代码

Consistent read started for block 5 : 0140e64c

  env: (scn: 0x0000.ebadbe91  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  statement num=0  parent xid: xid: 0x0000.000.00000000  scn: 0x0000.00000000 0sch: scn: 0x0000.00000000)

CR exa ret 9 on:  03C44148  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0

Consistent read finished for block 5 : 140e64c

Consistent read finished for block 5 : 140e64c

... ...

Consistent read started for block 5 : 0140e650

  env: (scn: 0x0000.ebadbe91  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  statement num=0  parent xid: xid: 0x0000.000.00000000  scn: 0x0000.00000000 0sch: scn: 0x0000.00000000)

CR exa ret 9 on:  03C44148  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0

pin kdswh01: kdstgr dba 140e650:1 time 2174161851

Consistent read finished for block 5 : 140e650

Consistent read finished for block 5 : 140e650

    It is not enough for us. Where did the other 2 io come from? From v$bh, we guess it read at least once on the segment header block.

SQL代码

HELLODBA.COM>select block#, class# from v$bh where file#=5 and status != 'free';



    BLOCK#     CLASS#

---------- ----------

     58957          1

     58959          1

     58960          1

     58958          1

     58955          4

     58956          1



6 rows selected.

    But there should be one more reads, happened on segment header or data block? The buffer cache pining tell us the answer. Work with 10046 trace, it will make things more clear.

SQL代码

HELLODBA.COM>conn demo/demo

Connected.

HELLODBA.COM>alter system flush buffer_cache;



System altered.



HELLODBA.COM>ALTER SESSION SET EVENTS '10046 trace name context forever, level 8';



Session altered.



HELLODBA.COM>set autot trace stat

HELLODBA.COM>select * from tt;





Statistics

----------------------------------------------------------

          0  recursive calls

          0  db block gets

          7  consistent gets

          6  physical reads

          0  redo size

        440  bytes sent via SQL*Net to client

        385  bytes received via SQL*Net from client

          2  SQL*Net roundtrips to/from client

          0  sorts (memory)

          0  sorts (disk)

          2  rows processed

    Let's see what was traced.

SQL代码

...

=====================

PARSING IN CURSOR #1 len=16 dep=0 uid=35 oct=3 lid=35 tim=4844921247 hv=1245498784 ad='1f121470'

select * from tt

END OF STMT

PARSE #1:c=0,e=100,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=4844921240

EXEC #1:c=0,e=63,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=4844940663

WAIT #1: nam='SQL*Net message to client' ela= 6 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=4844944958

WAIT #1: nam='db file sequential read' ela= 7875 file#=5 block#=58955 blocks=1 obj#=200943 tim=4844959196

pin ktewh25: kteinicnt dba 140e64b:4 time 549996100

pin ktewh26: kteinpscan dba 140e64b:4 time 550000143

WAIT #1: nam='db file scattered read' ela= 548 file#=5 block#=58956 blocks=5 obj#=200943 tim=4844972301

pin kdswh01: kdstgr dba 140e64c:1 time 550010236

pin kdswh01: kdstgr dba 140e64d:1 time 550014316

pin kdswh01: kdstgr dba 140e64e:1 time 550019679

pin kdswh01: kdstgr dba 140e64f:1 time 550023771

FETCH #1:c=15625,e=45716,p=6,cr=6,cu=0,mis=0,r=1,dep=0,og=4,tim=4844995430

WAIT #1: nam='SQL*Net message from client' ela= 232 driver id=1111838976 #bytes=1 p3=0 obj#=200943 tim=4844999516

pin kdswh01: kdstgr dba 140e650:1 time 550036200

WAIT #1: nam='SQL*Net message to client' ela= 5 driver id=1111838976 #bytes=1 p3=0 obj#=200943 tim=4845007458

FETCH #1:c=0,e=7879,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=4,tim=4845011351

WAIT #1: nam='SQL*Net message from client' ela= 925 driver id=1111838976 #bytes=1 p3=0 obj#=200943 tim=4845016805

STAT #1 id=1 cnt=2 pid=0 pos=1 obj=200943 op='TABLE ACCESS FULL TT (cr=7 pr=6 pw=0 time=49667 us)'

WAIT #0: nam='SQL*Net message to client' ela= 5 driver id=1111838976 #bytes=1 p3=0 obj#=200943 tim=4845025184

WAIT #0: nam='SQL*Net message from client' ela= 731 driver id=1111838976 #bytes=1 p3=0 obj#=200943 tim=4845029825

...

    Aha, things are understandable! Look at the pin trace entry:

SQL代码

pin ktewh25: kteinicnt dba 140e64b:4 time 549996100

    ktewh25 is the module name, and kteinicnt is the operation, right same as descripted in the x$kcbwh.kcbwhdes;

dba 140e64b is the data block address;

4 is the class of the block;

1: data block;

2: sort block;

4: segment header block;

8: 1st level bmp block;

9: 2nd level bmp block;

10: 3rd level bmp block;

...

    Identified by the pins, we know the Logical reads. In this case,

1st, it reads the segment header(140e64b), for kteinicnt (I guess it to count the extents number);

2nd, it still reads the segment header, for kteinpscan (I guess it to read the high water mark);

From 3rd to 7th, it reads the data block under high watermark (kdstgr).

    By additional, I flushed the buffer cache before query, there is totally 6 physical reads. By reading the waits in 10046 trace, it's easily for us understand the physical reads:

For segment header reading, it's single block read, whose wait event is 'db file sequential read'. The blocks number in this waits is 1.

For full table scan data block reading, it's multiple blocks read, whose wait event is 'db file scattered read'. The blocks number in this waits is 5.

    Totally, there are 6 (1+5) physical reads. While the segment header was read twice, the 2nd read was from buffer.

    --- Fuyuncat TBC ---

Previous： Transaction Enqueue analysis --- Other Contentions

Next：Secret of oracle logic IO: Full Table Scan: Part 2

Return To this Category