Look Oracle from inside (tracing internal calls) --- Logical IOs
[中文]
Author:
fuyuncat
Source:
www.HelloDBA.com
Date:
2010-06-10 05:43:58
Share to
WARNING: Never play OraTracer in any crytical system!
Logical IOs
For logical IO, it contains 2 kinds of figure: db block gets and consistent gets. We can get the figure by turning on AUTOTRACE before execute a SQL. Sometimes, we may not content with this statistics data, we want to know which blocks did the sql read exactly. Now, by tracing the db block gets and consistent gets internal functions, _kcbgcur&_kcbgtcr, we can get the details. Take below simple UPDATE statement as an example.
SQL代码
- HELLODBA.COM>update demo.tt set x=111 where x=1;
- 2 rows updated.
- Execution Plan
- ----------------------------------------------------------
- Plan hash value: 3408939625
- ---------------------------------------------------------------------------
- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
- ---------------------------------------------------------------------------
- | 0 | UPDATE STATEMENT | | 2 | 6 | 2 (0)| 00:00:03 |
- | 1 | UPDATE | TT | | | | |
- |* 2 | TABLE ACCESS FULL| TT | 2 | 6 | 2 (0)| 00:00:03 |
- ---------------------------------------------------------------------------
- Predicate Information (identified by operation id):
- ---------------------------------------------------
- 2 - filter("X"=1)
- Statistics
- ----------------------------------------------------------
- 0 recursive calls
- 3 db block gets
- 7 consistent gets
- 0 physical reads
- 744 redo size
- 677 bytes sent via SQL*Net to client
- 570 bytes received via SQL*Net from client
- 4 SQL*Net roundtrips to/from client
- 1 sorts (memory)
- 0 sorts (disk)
- 2 rows processed
- HELLODBA.COM>rollback;
- Rollback complete.
- HELLODBA.COM>set autot off
- HELLODBA.COM>select distinct spid from v$mystat m, v$session s, v$process p where m.sid=s.sid and s.paddr=p.addr;
- SPID
- ------------
- 9800
Set the trace points as below.
SQL代码
- _kcbgcur (8*1,0*2,0*2,0*2,0*2,0*2)
- _kcbgtcr (8*1,0*2,0*2,0*2)
Run OraTracer, trace the thread with TID 9800. Then execute the SQL in the session, we will get the trace log as below.
SQL代码
- [2010-06-09 14:27:55.528]User call: _kcbgtcr (TID: 9800)
- [Args(4)]:
- 0x799c5c4(=>0x050000004be64001)
- 0
- 0x1bc(=>NULL)
- 0
- [2010-06-09 14:27:55.528]User call: _kcbgtcr (TID: 9800)
- [Args(4)]:
- 0x799c3d8(=>0x050000004be64001)
- 0
- 0x1bd(=>NULL)
- 0
- [2010-06-09 14:27:55.528]User call: _kcbgtcr (TID: 9800)
- [Args(4)]:
- 0x839a5bc(=>0x050000004ce64001)
- 0
- 0x23f(=>NULL)
- 0
- [2010-06-09 14:27:55.543]User call: _kcbgtcr (TID: 9800)
- [Args(4)]:
- 0x839a5bc(=>0x050000004de64001)
- 0
- 0x23f(=>NULL)
- 0
- [2010-06-09 14:27:55.559]User call: _kcbgtcr (TID: 9800)
- [Args(4)]:
- 0x839a5bc(=>0x050000004ee64001)
- 0
- 0x23f(=>NULL)
- 0
- [2010-06-09 14:27:55.575]User call: _kcbgtcr (TID: 9800)
- [Args(4)]:
- 0x839a5bc(=>0x050000004fe64001)
- 0
- 0x23f(=>NULL)
- 0
- [2010-06-09 14:27:55.590]User call: _kcbgcur (TID: 9800)
- [Args(6)]:
- 0x839abf8(=>0x050000004fe64001)
- 2
- 0x250(=>NULL)
- 0
- 0x310ef(=>NULL)
- 0x839abb4(=>0x1ab26c3c(=>0x1a90fba8))
- [2010-06-09 14:27:55.590]User call: _kcbgcur (TID: 9800)
- [Args(6)]:
- 0x7995d88(=>0x0100000099008000)
- 2
- 0x17b(=>NULL)
- 0
- 0x1010010(=>0x89cc4d8b(=>NULL))
- 0x7995d88(=>1)
- [2010-06-09 14:27:55.606]User call: _kcbgtcr (TID: 9800)
- [Args(4)]:
- 0x839a5bc(=>0x0500000050e64001)
- 0
- 0x23f(=>NULL)
- 0
- [2010-06-09 14:27:55.621]User call: _kcbgcur (TID: 9800)
- [Args(6)]:
- 0x839abf8(=>0x0500000050e64001)
- 2
- 0x250(=>NULL)
- 0
- 0x310ef(=>NULL)
- 0x839abb4(=>0x1ab26c3c(=>0x1a90fba8))
Count the funcation calls, we get 7 _kcbgtcr calls and 3 _kcbgcur calls, which matched the statistics data. An interesting argument of these 2 functions is the 1st one, which contains the data block address (DBA) infomation. You may compare the actual DBA as below.
SQL代码
- HELLODBA.COM>select x, to_char(dbms_utility.make_data_block_address(dbms_rowid.rowid_relative_fno(rowid), dbms_rowid.rowid_block_number(rowid)), 'XXXXXXXX') DBA from demo.tt;
- X DBA
- ---------- ---------
- 8 140E64C
- 101 140E64D
- 101 140E64D
- 11 140E64D
- 1 140E64F
- 1 140E650
- 2 140E650
- 3 140E650
- 8 rows selected.
Two interesting consistent gets are the 1st & 2nd ones. With their DBA, it's not hard to get that it read the segment header block twice.
SQL代码
- HELLODBA.COM>select to_char(header_file, 'XXXXXXXX') file_no, to_char(header_block, 'XXXXXXXX') block_no from dba_segments where owner='DEMO' and segment_name = 'TT';
- FILE_NO BLOCK_NO
- --------- ---------
- 5 E64B
Another interesting consistent get is the 5th one. Check the table data, we found it actually does not contain any row. However, since it's a Full Table Scan, the data block under High Water Mark were scaned.
Therefore, we got 7 consistent gets: 2 segment header block reads, 5 data blocks under High Water Mark.For db block gets. Since the rows we updated locate at 2 data blocks, they were read in current mode. For the left one, by dumping the data block, we will find it's actuall the Undo Segment Header block.
SQL代码
- HELLODBA.COM>select dbms_utility.data_block_address_file(to_number('00800099', 'XXXXXXXX')) file_no, dbms_utility.data_block_address_block(to_number('00800099', 'XXXXXXXX')) block_no from dual;
- FILE_NO BLOCK_NO
- ---------- ----------
- 2 153
- HELLODBA.COM>alter system dump datafile 2 block 153;
- System altered.
The dumped data block contents.
SQL代码
- Start dump data blocks tsn: 1 file#: 2 minblk 153 maxblk 153
- buffer tsn: 1 rdba: 0x00800099 (2/153)
- scn: 0x0000.ec8f0f54 seq: 0x01 flg: 0x04 tail: 0x0f542601
- frmt: 0x02 chkval: 0x71d4 type: 0x26=KTU SMU HEADER BLOCK
- Hex dump of block: st=0, typ_found=1
- ...
You can download the OraTracer at here:
http://www.HelloDBA.com/Download/OraTracer.zip--- Fuyuncat ---