Secret of oracle logic IO: Full Table Scan: Part 2
[中文]
Author:
fuyuncat
Source:
www.HelloDBA.com
Date:
2009-11-05 09:16:25
Share to
Full Table Scan --- Medium Table
Then, let's involve more factors into the process. In the case, I will trace a medium size table, who has 2k records.
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 t_test2;
- 2072 rows selected.
- Statistics
- ----------------------------------------------------------
- 1 recursive calls
- 0 db block gets
- 198 consistent gets
- 63 physical reads
- 0 redo size
- 128551 bytes sent via SQL*Net to client
- 1903 bytes received via SQL*Net from client
- 140 SQL*Net roundtrips to/from client
- 0 sorts (memory)
- 0 sorts (disk)
- 2072 rows processed
Here is 198 Logical reads, 63 physical reads after the buffer cache be flushed. Let's check how many pins in the trace (I've removed the recursive ones and other session traces part).
SQL代码
- C:\oracle\product\10.2.0\admin\hellodba.com>for /f "tokens=1 delims=:" %i in ('findstr /C:"pin" C:\oracle\product\10.2.0\admin\edgar\udump\LIO_Medium_table.trc') do @set /a a+=1 > NUL
- C:\oracle\product\10.2.0\admin\hellodba.com>echo %a%
- 198
198, exactly sames as the Logical reads. Then, let's have a detail analysis for the pins, see is there new finding.
SQL代码
- pin ktewh25: kteinicnt dba 1409413:4 time 3753006116
- pin ktewh26: kteinpscan dba 1409413:4 time 3753006207
- pin ktewh27: kteinmap dba 1409413:4 time 3753006268
- pin kdswh01: kdstgr dba 1409414:1 time 3753007328
- pin kdswh01: kdstgr dba 1409414:1 time 3753008988
- ... ...
- pin kdswh01: kdstgr dba 1409465:1 time 3753219276
- pin kdswh01: kdstgr dba 1409465:1 time 3753220427
- pin kdswh01: kdstgr dba 1409465:1 time 3753221783
First, we can find there is one more read on the segment header block. From the operation name, easily to guess it's to read the extent map.
Second, for each data block, we found they were read for more than once. For example, data block 1409414 was read for 4 times. Another interesting you should note is return row number for each fetching after read data block.
SQL代码
- ...
- pin kdswh01: kdstgr dba 1409414:1 time 3753007328
- FETCH #2:c=15625,e=31484,p=6,cr=4,cu=0,mis=0,r=1,dep=0,og=4,tim=3753007423
- WAIT #2: nam='SQL*Net message from client' ela= 1261 driver id=1111838976 #bytes=1 p3=0 obj#=97820 tim=3753008817
- pin kdswh01: kdstgr dba 1409414:1 time 3753008988
- WAIT #2: nam='SQL*Net message to client' ela= 2 driver id=1111838976 #bytes=1 p3=0 obj#=97820 tim=3753009089
- FETCH #2:c=0,e=293,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=4,tim=3753009255
- WAIT #2: nam='SQL*Net message from client' ela= 782 driver id=1111838976 #bytes=1 p3=0 obj#=97820 tim=3753010133
- pin kdswh01: kdstgr dba 1409414:1 time 3753010282
- WAIT #2: nam='SQL*Net message to client' ela= 2 driver id=1111838976 #bytes=1 p3=0 obj#=97820 tim=3753010362
- FETCH #2:c=0,e=285,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=4,tim=3753010540
- ...
Except the 1st read for the 1st block, all of them are 15, the value of the array_size in sql*plus.
SQL代码
- HELLODBA.COM>show arraysize
- arraysize 15
For each fetching, it will get records number as the arraysize setting, if rest number for the last read in the data block did not reach the arraysize, it will continue to read the next data block to fullfil the array:
SQL代码
- WAIT #2: nam='SQL*Net message from client' ela= 766 driver id=1111838976 #bytes=1 p3=0 obj#=97820 tim=3753011411
- pin kdswh01: kdstgr dba 1409414:1 time 3753011535
- WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1111838976 #bytes=1 p3=0 obj#=97820 tim=3753011609
- pin kdswh01: kdstgr dba 1409415:1 time 3753011743
- FETCH #2:c=0,e=333,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=4,tim=3753011850
One thing need to be noted is that the 1st record in the 1st block is fetched in a single IO, maybe oracle need decide the columns information by this record. So, we have below plsql to calculte the IO in the non-empty blocks that affected by the arraysize:
SQL代码
- HELLODBA.COM>create global temporary table tmp_extents as select * from dba_extents where 1=2;
- Table created.
- HELLODBA.COM>set serveroutput on
- HELLODBA.COM>declare
- 2 cursor vc is select t2.extent_id, t1.block_add, t1.cnt
- 3 from (select to_char(dbms_utility.make_data_block_address(dbms_rowid.rowid_relative_fno(ROWID),
- 4 dbms_rowid.rowid_block_number(ROWID)),
- 5 'XXXXXXXX') block_add,
- 6 dbms_rowid.rowid_relative_fno(ROWID) relative_fno,
- 7 dbms_rowid.rowid_block_number(ROWID) block_number,
- 8 count(1) cnt
- 9 from &&owner..&&tabname
- 10 group by dbms_rowid.rowid_relative_fno(ROWID) ,
- 11 dbms_rowid.rowid_block_number(ROWID)
- 12 ) t1,
- 13 demo.tmp_extents t2
- 14 where t1.relative_fno = t2.relative_fno
- 15 and t1.block_number >= t2.block_id and t1.block_number < t2.block_id + t2.blocks
- 16 order by t2.extent_id, block_add;
- 17 comp_cnt pls_integer:=-1;
- 18 array_size pls_integer:=15;
- 19 total_io pls_integer:=1;
- 20 begin
- 21 dbms_output.enable(1000000);
- 22 delete from demo.tmp_extents;
- 23 insert into demo.tmp_extents select * from dba_extents where owner='&&owner' and segment_name='&&tabname';
- 24 for rec in vc loop
- 25 dbms_output.put_line(rec.block_add||' reads:'||(ceil((rec.cnt+comp_cnt)/array_size)));
- 26 total_io := total_io + ceil((rec.cnt+comp_cnt)/array_size);
- 27 comp_cnt := rec.cnt+comp_cnt - (floor((rec.cnt+comp_cnt)/array_size))*array_size;
- 28 end loop;
- 29 dbms_output.put_line('total reads:'||total_io);
- 30 show_space('&&tabname','&&owner');
- 31 rollback;
- 32 end;
- 33 /
- Enter value for owner: DEMO
- Enter value for tabname: T_TEST2
- old 9: from &&owner..&&tabname
- new 9: from DEMO.T_TEST2
- old 23: insert into demo.tmp_extents select * from dba_extents where owner='&&owner' and segment_name='&&tabname';
- new 23: insert into demo.tmp_extents select * from dba_extents where owner='DEMO' and segment_name='T_TEST2';
- old 30: show_space('&&tabname','&&owner');
- new 30: show_space('T_TEST2','DEMO');
- 1409414 reads:3
- 1409415 reads:4
- ... ...
- 1409463 reads:3
- 1409464 reads:3
- 1409465 reads:3
- total reads:195
- Unformatted Blocks ..................... 0
- FS1 Blocks (0-25) ..................... 61
- FS2 Blocks (25-50) ..................... 0
- FS3 Blocks (50-75) ..................... 1
- FS4 Blocks (75-100)..................... 0
- Full Blocks ..................... 0
- Total Blocks............................ 72
- Total Bytes............................. 589,824
- Total MBytes............................ 0
- Unused Blocks........................... 3
- Unused Bytes............................ 24,576
- Last Used Ext FileId.................... 5
- Last Used Ext BlockId................... 37,985
- Last Used Block......................... 5
- PL/SQL procedure successfully completed.
Here we can see, all of the data blocks contain data, total reads be figured out as 195, plus with the reads on the segment header (3), we can finnally get the Logical read times (198).
BTW, by counting the physical waits blocks, it's sum up to 63, same as the figure in the autotrace statistic data.
--- Fuyuncat TBC ---