HelloDBA [中文]
Search Internet Search HelloDBA
  Oracle Technology Site. email: fuyuncat@gmail.com  MSN: fuyuncat@hotmail.com Add to circle  acoug  acoug 

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

[中文]

Author:  fuyuncat

Source:  www.HelloDBA.com

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

Share to  Twitter Facebook GMail Blogger Orkut Google Bookmarks Sina Weibo QQ Renren Tieba Kaixin Douban Taobao

    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代码
  1. HELLODBA.COM>alter system set "_trace_pin_time"=1 scope=spfile;   
  2.   
  3. System altered.   
  4.   
  5. HELLODBA.COM>startup force  
  6. ...   
  7. Database mounted.   
  8. 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代码
  1. HELLODBA.COM>select * from tt;   
  2.   
  3.   
  4. Execution Plan   
  5. ----------------------------------------------------------   
  6. Plan hash value: 264906180   
  7.   
  8. ----------------------------------   
  9. | Id  | Operation         | Name |   
  10. ----------------------------------   
  11. |   0 | SELECT STATEMENT  |      |   
  12. |   1 |  TABLE ACCESS FULL| TT   |   
  13. ----------------------------------   
  14.   
  15. Note   
  16. -----   
  17.    - rule based optimizer used (consider using cbo)   
  18.   
  19.   
  20. Statistics  
  21. ----------------------------------------------------------   
  22.           1  recursive calls   
  23.           0  db block gets   
  24.           7  consistent gets   
  25.           0  physical reads   
  26.           0  redo size  
  27.         440  bytes sent via SQL*Net to client   
  28.         385  bytes received via SQL*Net from client   
  29.           2  SQL*Net roundtrips to/from client   
  30.           0  sorts (memory)   
  31.           0  sorts (disk)   
  32.           2  rows processed  

    As comparison, first make a 10200 trace for it:

SQL代码
  1. HELLODBA.COM>conn demo/demo   
  2. Connected.   
  3. HELLODBA.COM>alter system flush buffer_cache;   
  4.   
  5. System altered.   
  6.   
  7. HELLODBA.COM>ALTER SESSION SET EVENTS '10200 trace name context forever, level 1';   
  8.   
  9. Session altered.   
  10.   
  11. HELLODBA.COM>select * from tt;   
  12.   
  13.          X   
  14. ----------   
  15.          1   
  16.          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代码
  1. Consistent read started for block 5 : 0140e64c   
  2.   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)   
  3. CR exa ret 9 on:  03C44148  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0   
  4. Consistent read finished for block 5 : 140e64c   
  5. Consistent read finished for block 5 : 140e64c   
  6. ... ...   
  7. Consistent read started for block 5 : 0140e650   
  8.   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)   
  9. CR exa ret 9 on:  03C44148  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0   
  10. pin kdswh01: kdstgr dba 140e650:1 time 2174161851   
  11. Consistent read finished for block 5 : 140e650   
  12. 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代码
  1. HELLODBA.COM>select block#, class# from v$bh where file#=5 and status != 'free';   
  2.   
  3.     BLOCK#     CLASS#   
  4. ---------- ----------   
  5.      58957          1   
  6.      58959          1   
  7.      58960          1   
  8.      58958          1   
  9.      58955          4   
  10.      58956          1   
  11.   
  12. 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代码
  1. HELLODBA.COM>conn demo/demo   
  2. Connected.   
  3. HELLODBA.COM>alter system flush buffer_cache;   
  4.   
  5. System altered.   
  6.   
  7. HELLODBA.COM>ALTER SESSION SET EVENTS '10046 trace name context forever, level 8';   
  8.   
  9. Session altered.   
  10.   
  11. HELLODBA.COM>set autot trace stat   
  12. HELLODBA.COM>select * from tt;   
  13.   
  14.   
  15. Statistics  
  16. ----------------------------------------------------------   
  17.           0  recursive calls   
  18.           0  db block gets   
  19.           7  consistent gets   
  20.           6  physical reads   
  21.           0  redo size  
  22.         440  bytes sent via SQL*Net to client   
  23.         385  bytes received via SQL*Net from client   
  24.           2  SQL*Net roundtrips to/from client   
  25.           0  sorts (memory)   
  26.           0  sorts (disk)   
  27.           2  rows processed  

    Let's see what was traced.

SQL代码
  1. ...   
  2. =====================   
  3. PARSING IN CURSOR #1 len=16 dep=0 uid=35 oct=3 lid=35 tim=4844921247 hv=1245498784 ad='1f121470'  
  4. select * from tt   
  5. END OF STMT   
  6. PARSE #1:c=0,e=100,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=4844921240   
  7. EXEC #1:c=0,e=63,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=4844940663   
  8. WAIT #1: nam='SQL*Net message to client' ela= 6 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=4844944958   
  9. WAIT #1: nam='db file sequential read' ela= 7875 file#=5 block#=58955 blocks=1 obj#=200943 tim=4844959196   
  10. pin ktewh25: kteinicnt dba 140e64b:4 time 549996100   
  11. pin ktewh26: kteinpscan dba 140e64b:4 time 550000143   
  12. WAIT #1: nam='db file scattered read' ela= 548 file#=5 block#=58956 blocks=5 obj#=200943 tim=4844972301   
  13. pin kdswh01: kdstgr dba 140e64c:1 time 550010236   
  14. pin kdswh01: kdstgr dba 140e64d:1 time 550014316   
  15. pin kdswh01: kdstgr dba 140e64e:1 time 550019679   
  16. pin kdswh01: kdstgr dba 140e64f:1 time 550023771   
  17. FETCH #1:c=15625,e=45716,p=6,cr=6,cu=0,mis=0,r=1,dep=0,og=4,tim=4844995430   
  18. WAIT #1: nam='SQL*Net message from client' ela= 232 driver id=1111838976 #bytes=1 p3=0 obj#=200943 tim=4844999516   
  19. pin kdswh01: kdstgr dba 140e650:1 time 550036200   
  20. WAIT #1: nam='SQL*Net message to client' ela= 5 driver id=1111838976 #bytes=1 p3=0 obj#=200943 tim=4845007458   
  21. FETCH #1:c=0,e=7879,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=4,tim=4845011351   
  22. WAIT #1: nam='SQL*Net message from client' ela= 925 driver id=1111838976 #bytes=1 p3=0 obj#=200943 tim=4845016805   
  23. 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)'  
  24. WAIT #0: nam='SQL*Net message to client' ela= 5 driver id=1111838976 #bytes=1 p3=0 obj#=200943 tim=4845025184   
  25. WAIT #0: nam='SQL*Net message from client' ela= 731 driver id=1111838976 #bytes=1 p3=0 obj#=200943 tim=4845029825   
  26. ...  

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

SQL代码
  1. 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 ---

Top

Copyright ©2005, HelloDBA.Com All reseverd.

Declaration
by fuyuncat