all about oracle logic IO

最新推荐文章于 2021-04-10 01:20:45 发布

Aamirr

最新推荐文章于 2021-04-10 01:20:45 发布

阅读量1.4k

点赞数

分类专栏： Oracle

本文链接：https://blog.csdn.net/ora_unix/article/details/18046349

版权

Oracle 专栏收录该内容

54 篇文章 0 订阅

订阅专栏

Secret of oracle logic IO: Consistent Gets

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

Then, let's study the Consistent Gets case.The obvious feature of consistent gets is that it will read the undo block toapply to current data block correspond to the SCN. To monitor the undoapplication, we turn the 10201 event trace on. Here is the demo,

SQL代码

-- Session 1: Update withoutcommit

SQL> update tt setx=2;

2 rows updated.

SQL> update tt setx=3;

2 rows updated.

-- Session 2:

SQL> conn demo/demo

Connected.

SQL> alter system flushbuffer_cache;

System altered.

SQL> ALTER SESSION SETEVENTS '10201 trace name context forever, level 1';

Session altered.

SQL>ALTER SESSION SETEVENTS '10046 trace name context forever, level 8';

Session altered.

SQL>set autot tracestat

SQL>select * from tt;

Statistics

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

1 recursive calls

0 db block gets

13 consistent gets

8 physical reads

172 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

13 Logical reads, 6 more than the casewithout CR undo application. Look into the trace file, see what we catched.

First, it still need read the segmentheader twice, then read the data block in sequence,

代码

...

WAIT #3: nam='db filesequential read' ela= 22808 file#=5 block#=58955 blocks=1 obj#=200943tim=3948903234

pin ktewh25: kteinicnt dba140e64b:4 time 3948903366

pin ktewh26: kteinpscan dba140e64b:4 time 3948903443

WAIT #3: nam='db filescattered read' ela= 572 file#=5 block#=58956 blocks=5 obj#=200943tim=3948904149

pin kdswh01: kdstgr dba140e64c:1 time 3948904251

pin kdswh01: kdstgr dba 140e64d:1time 3948904308

pin kdswh01: kdstgr dba140e64e:1 time 3948904354

pin kdswh01: kdstgr dba140e64f:1 time 3948904408

...

It reached the 140e64f, the 1st blockcontain modified data without commit. It read the Transaction Table from UNDO segmentheader block, found the entries that need to be applied to the data block:

代码

WAIT #3: nam='db filesequential read' ela= 10503 file#=2 block#=73 blocks=1 obj#=0tim=3948916322

Then read UNDO Block and apply the entriesto the data block.

代码

Applying CR undo to block 5 :140e64f itl entry 02:

xid: 0x0005.00b.00023460 uba: 0x008012aa.7970.05

flg: ---- lkc: 1 fsc: 0x0000.00000000

Then the 2nd ITL in it, read the UNDO toapply, increase 1 Logic reads

Applying CR undo to block 5 :140e64f itl entry 02:

xid: 0x0005.00b.00023460 uba: 0x008012aa.7970.03

flg: ---- lkc: 1 fsc: 0x0000.00000000

Both of the undo entries were located atthe same UNDO block, thus it will just increase 1 logical read. After all ofthe changes in the uncommited ITLs have been apllied, it will generate anotherlogical read for the UNDOed data block. Here totally 9 logical reads: 2 segmentheader reads, 4 data block reads, 1 UNDO Segment Header, 1 UNDO block read, 1UNDOed data block.

Then it undo the next data block, whichwill cause the other 4 logical reads (1 data block, 1 UNDO Segment Header, 1UNDO block, 1 UNDOed data block),

SQL代码

pin kdswh01: kdstgr dba140e650:1 time 3948928294

Applying CR undo to block 5 :140e650 itl entry 02:

xid: 0x0005.00b.00023460 uba: 0x008012aa.7970.06

flg: ---- lkc: 1 fsc: 0x0000.00000000

CRS upd rd env: (scn:0x0000.ebadfff9 xid:0x0000.000.00000000 uba: 0x00000000.0000.00 statement num=0 parent xid: xid: 0x0000.000.00000000 scn: 0x0000.00000000 0sch: scn:0x0000.00000000) undo env: (scn: 0x0000.ebadfffb xid: 0x0005.00b.00023460 uba: 0x008012aa.7970.06

statement num=0 parent xid: xid: 0x0005.000.00000000 scn: 0x0000.00000001 1sch: scn:0xa098.1f7cd9b0)

CRS upd (before):1880FA90 scn: 0x0000.ebadfff9 xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 scn: 0x0000.ebadfffb sfl: 0

CRS upd (after) :1880FA90 scn: 0x0000.ebadfff9 xid: 0x0005.00b.00023460 uba: 0x008012aa.7970.06 scn: 0x0000.ebadfffb sfl: 0

Applying CR undo to block 5 :140e650 itl entry 02:

xid: 0x0005.00b.00023460 uba: 0x008012aa.7970.04

flg: ---- lkc: 1 fsc: 0x0000.00000000

CRS upd rd env: (scn:0x0000.ebadfff9 xid:0x0000.000.00000000 uba:0x00000000.0000.00 statement num=0 parent xid: xid: 0x0000.000.00000000 scn: 0x0000.00000000 0sch: scn:0x0000.00000000) undo env: (scn: 0x0000.ebadfffb xid: 0x0005.00b.00023460 uba: 0x008012aa.7970.04

statement num=0 parent xid: xid: 0x0005.000.00000000 scn: 0x0000.00000001 1sch: scn:0xa098.1f7cd9b0)

CRS upd (before):1880FA90 scn: 0x0000.ebadfff9 xid: 0x0005.00b.00023460 uba: 0x008012aa.7970.06 scn: 0x0000.ebadfffb sfl: 0

CRS upd (after) :1880FA90 scn: 0x0000.ebadfff9 xid: 0x0005.00b.00023460 uba: 0x008012aa.7970.04 scn: 0x0000.ebadfffb sfl: 0

WAIT #3: nam='SQL*Net messageto client' ela= 42 driver id=1111838976 #bytes=1 p3=0 obj#=0tim=3948929421

FETCH #3:c=0,e=1237,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=4,tim=3948929506

We should also noted that there 2 physicalreads/waits for the undo segment header & undo blocks.

Secret of oracle logic IO: Current Mode

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

When need update data, oracle will read thedata block in current mode. Let's see the IO in an UPDATE statement, here willbe more interesting things be found.

SQL代码

SQL>conn demo/demo

Connected.

SQL>alter system flushbuffer_cache;

System altered.

SQL>ALTER SESSION SETEVENTS '10046 trace name context forever, level 8';

Session altered.

SQL>set autot tracestat

SQL>update tt setx=1;

2 rows updated.

Statistics

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

0 recursive calls

4 db block gets

7 consistent gets

8 physical reads

824 redo size

665 bytes sent via SQL*Net to client

553 bytes received via SQL*Net from client

4 SQL*Net roundtrips to/from client

1 sorts (memory)

0 sorts (disk)

2 rows processed

SQL>alter system flushbuffer_cache;

System altered.

SQL>update tt setx=1;

2 rows updated.

Statistics

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

0 recursive calls

3 db block gets

7 consistent gets

7 physical reads

536 redo size

668 bytes sent via SQL*Net to client

553 bytes received via SQL*Net from client

4 SQL*Net roundtrips to/from client

1 sorts (memory)

0 sorts (disk)

2 rows processed

Check the 1st UPDATE, it has 4 db blockgets, means the reads in current mode. Look into the trace, besides theoperations we find in previous traces, we can find these entries.

SQL代码

pin kdswh01: kdstgr dba140e64f:1 time 3828486551

pin kduwh01: kdusru dba 140e64f:1time 3828486616

WAIT #1: nam='db filesequential read' ela= 7907 file#=2 block#=9 blocks=1 obj#=0 tim=3828495546

pin ktuwh01: ktugus dba800009:17 time 3828495628

WAIT #1: nam='db filesequential read' ela= 3984 file#=2 block#=7227 blocks=1 obj#=0tim=3828499685

pin kcbwh2: kcbchg1 dba801c3b:18 time 3828499816

pin release 4305 ktuwh01: ktugus dba 800009:17

pin release 176 kcbwh2: kcbchg1 dba 801c3b:18

pin release 13432 kduwh01: kdusru dba 140e64f:1

pin kdswh01: kdstgr dba140e650:1 time 3828500148

pin kduwh01: kdusru dba140e650:1 time 3828500249

pin kcbwh5: kcbchg1 dba801c3b:18 time 3828500352

pin release 63 kcbwh5: kcbchg1 dba 801c3b:18

pin release 207 kduwh01: kdusru dba 140e650:1

Let me guess what are these new operations:

@ kdusru:Read in current mode for update

@ ktugus: Get Undo Segment Header

@ kcbchg1: Change buffer content

P.S. the UNDO block's class:

@ 17,19,21...: UNDO header;

@ 18,20,22...: UNDO block.

All of these operations will lead to thecurrent mode reading. In this UPDATE, there 4 db block gets, 2 data block(140e64f, 140e650), 1 undo header (800009), and 1 undo block (801c3b). Plsnoted the undo block 801c3b be read twice for the 2 records, and just 1 currentmode in one transaction.

In the second UPDATE, there is bit ofdifference.

@ There is no UNDO header read --- just 1 UNDO header read for eachtransaction;

@ Since the buffer cache be flushed, even though the undo block is same asthe one in the 1st UPDATE, it still be read in current mode.

Therefore, there are 3 db block gets in the2nd update.

SQL代码

pinkduwh01: kdusru dba 140e64f:1 time 3832560411

WAIT #2: nam='db filesequential read' ela= 201 file#=2 block#=7227 blocks=1 obj#=0 tim=3832560683

pin kcbwh2: kcbchg1 dba801c3b:18 time 3832560736

pin release 69 kcbwh2: kcbchg1 dba 801c3b:18

pin release 477 kduwh01: kdusru dba 140e64f:1

pin kdswh01: kdstgr dba140e650:1 time 3832561310

pin kduwh01: kdusru dba140e650:1 time 3832561392

pin kcbwh5: kcbchg1 dba801c3b:18 time 3832561465

pin release 74 kcbwh5: kcbchg1 dba 801c3b:18

pin release 199 kduwh01: kdusru dba 140e650:1

EXEC #2:c=15625,e=17973,p=7,cr=7,cu=3,mis=0,r=2,dep=0,og=4,tim=3832561659

One thing to be noted, the pin of currentmode read was released immediately.

Here we study another case, 2 transactionswith 3 UPDATE statement, no buffer be flushed during the transactions.

SQL代码

SQL>conn demo/demo

Connected.

SQL>alter system flushbuffer_cache;

System altered.

SQL>ALTER SESSION SETEVENTS '10046 trace name context forever, level 8';

Session altered.

SQL>set autot tracestat

SQL>update tt setx=1;

2 rows updated.

Statistics

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

0 recursive calls

4 db block gets

7 consistent gets

8 physical reads

904 redo size

665 bytes sent via SQL*Net to client

553 bytes received via SQL*Net from client

4 SQL*Net roundtrips to/from client

1 sorts (memory)

0 sorts (disk)

2 rows processed

SQL>rollback;

Rollback complete.

SQL>update tt setx=1;

2 rows updated.

Statistics

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

0 recursive calls

4 db block gets

7 consistent gets

1 physical reads

788 redo size

668 bytes sent via SQL*Net to client

553 bytes received via SQL*Net from client

4 SQL*Net roundtrips to/from client

1 sorts (memory)

0 sorts (disk)

2 rows processed

SQL>update tt setx=1;

2 rows updated.

Statistics

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

0 recursive calls

2 db block gets

7 consistent gets

0 physical reads

536 redo size

668 bytes sent via SQL*Net to client

553 bytes received via SQL*Net from client

4 SQL*Net roundtrips to/from client

1 sorts (memory)

0 sorts (disk)

2 rows processed

The 1st UPDATE is same as in the previouscase. As the buffer not be flushed, there 1 new UNDO block be physical read inthe 1st UPDATE of the 2nd transaction, with 4 db block gets.

SQL代码

...

pin kduwh01: kdusru dba140e64f:1 time 680961643

WAIT #2: nam='db filesequential read' ela= 6579 file#=2 block#=73 blocks=1 obj#=0tim=4975935594

pin ktuwh01: ktugus dba800049:25 time 680968375

pin ktuwh03: ktugnb dba8012cb:26 time 680968434

pin release 141 ktuwh01: ktugus dba 800049:25

pin release 123 ktuwh03: ktugnb dba 8012cb:26

pin release 6954 kduwh01: kdusru dba 140e64f:1

pin kdswh01: kdstgr dba140e650:1 time 680968657

pin kduwh01: kdusru dba140e650:1 time 680968719

pin kcbwh5: kcbchg1 dba8012cb:26 time 680968776

pin release 49 kcbwh5: kcbchg1 dba 8012cb:26

pin release 146 kduwh01: kdusru dba 140e650:1

EXEC #2:c=0,e=7657,p=1,cr=7,cu=4,mis=0,r=2,dep=0,og=4,tim=4975936219

...

While in the 2nd UPDATE of the 2ndtransaction, the UNDO block is be reused, so it just has 2 db block gets.

SQL代码

...

pin kduwh01: kdusru dba140e64f:1 time 680977322

pin kcbwh5: kcbchg1 dba8012cb:26 time 680977384

pin release 63 kcbwh5: kcbchg1 dba 8012cb:26

pin release 166 kduwh01: kdusru dba 140e64f:1

pin kdswh01: kdstgr dba140e650:1 time 680977538

pin kduwh01: kdusru dba140e650:1 time 680977595

pin kcbwh5: kcbchg1 dba8012cb:26 time 680977642

pin release 48 kcbwh5: kcbchg1 dba 8012cb:26

pin release 136 kduwh01: kdusru dba 140e650:1

EXEC#2:c=0,e=829,p=0,cr=7,cu=2,mis=0,r=2,dep=0,og=4,tim=4975945080

...

Secret of oracle logic IO: Sorting

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

In this case, I will involve the sorting.

SQL代码

SQL>conn demo/demo

Connected.

SQL>alter system flushbuffer_cache;

System altered.

SQL>ALTER SESSION SETEVENTS '10046 trace name context forever, level 8';

Session altered.

SQL>set autot tracestat

SQL>select * from t_test2order by table_name;

2072 rows selected.

Statistics

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

7 recursive calls

21 db block gets

65 consistent gets

201 physical reads

0 redo size

131049 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)

1 sorts (disk)

2072 rows processed

Review the trace file, we can get theLogical reads number: 62 data block rows fetching + 3 segment header reads =65.

Check the file in detail, you will foundthe FETCH came after all the sorting operation completed, that means thearraysize will not affect the data block reads, so, each of the data block wasjust read once in this case! compare to the previous test case that query thesame table without sorting, its Logical reads is lower.

Since this case involved the sorting, wecan find below new entries,

SQL代码

pin stswh00: stsswr dba402f3f:2 time 857155584

pin release 43 stswh00: stsswr dba 402f3f:2

WAIT #2: nam='direct pathwrite temp' ela= 0 file number=201 first dba=12080 block cnt=1 obj#=97820tim=857155720

It's not hard to guess thestsswr is the operationto write sorting data in temp segments. Since it's to write data, it's countedas db block gets. There are 21 db block gets.

SQL代码

C:\oracle\product\10.2.0\admin\SQL>set/a a=0

C:\oracle\product\10.2.0\admin\SQL>for/f "tokens=1 delims=:" %i in ('findstr /C:"pin stswh00"C:\oracle\product\10.2.0\admin\edgar\udump\LIO_Sort.trc') do @set /a a+=1 >NUL

C:\oracle\product\10.2.0\admin\SQL>echo%a%

Read all of the sorting operation entries,we can find all of them wrote into the same block, so there was just 1 sorts indisk.

SQL代码

pin stswh00: stsswr dba402f3f:2 time 857147806

...

pin stswh00: stsswr dba402f3f:2 time 857255971

pin stswh00: stsswr dba402f3f:2 time 857256077

Finally, let's calculate the physicalreads. By counting the "db file sequential read" & "db filescattered read" waits blocks, we get 63 PIO. Then count the "directpath read temp", we get the other 138 PIO.

SQL代码

C:\oracle\product\10.2.0\admin\SQL>set/a a=0

C:\oracle\product\10.2.0\admin\SQL>for/f "tokens=1 delims=:" %i in ('findstr /C:"direct path readtemp" C:\oracle\product\10.2.0\admin\edgar\udump\LIO_Sort.trc') do @set /aa+=1 > NUL

C:\oracle\product\10.2.0\admin\SQL>echo%a%

138

Btw, in other test cases with same process,I noted sometimes the "direct path read temp" number is more thanexcepted, I still not found the reason, just guess it may caused by therecursive calls.

Secret of oracle logic IO: Index Scan

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

Let study the index scan case.

SQL代码

SQL>conndemo/demo

Connected.

SQL>set linesize 300

SQL>alter system flushbuffer_cache;

System altered.

SQL>ALTER SESSION SETEVENTS '10046 trace name context forever, level 8';

Session altered.

SQL>set autot trace

SQL>select * from t_test2where owner = 'OUTLN';

Execution Plan

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

Plan hash value:1900296288

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

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

| 0 | SELECT STATEMENT | | 3 | 630 | 1 (0)| 00:00:01 |

| 1 | TABLE ACCESS BY INDEX ROWID| T_TEST2 | 3 | 630 | 1 (0)| 00:00:01 |

|* 2 | INDEX RANGE SCAN |T_TEST2_IDX1 | 3 | | 1 (0)| 00:00:01 |

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

Predicate Information(identified by operation id):

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

2 - access("OWNER"='OUTLN')

Statistics

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

0 recursive calls

0 db block gets

6 consistent gets

5 physical reads

0 redo size

3622 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)

3 rows processed

There are 6 Logical reads. Check the traceoutput, just find 5 pins.

SQL代码

WAIT #2: nam='db filesequential read' ela= 15454 file#=5 block#=66164 blocks=1 obj#=100897tim=999288447

WAIT #2: nam='db filesequential read' ela= 35067 file#=5 block#=66176 blocks=1 obj#=100897tim=999323645

pin kdiwh09: kdiixs dba1410280:1 time 999323748

WAIT #2: nam='db filesequential read' ela= 14164 file#=5 block#=37922 blocks=1 obj#=97820tim=999337989

pin kdswh05: kdsgrp dba1409422:1 time 999338144

FETCH#2:c=0,e=65288,p=3,cr=3,cu=0,mis=0,r=1,dep=0,og=4,tim=999338229

WAIT #2: nam='SQL*Net messagefrom client' ela= 718 driver id=1111838976 #bytes=1 p3=0 obj#=97820tim=999339051

pin kdiwh16: kdifxs dba1410280:1 time 999339159

WAIT #2: nam='db filesequential read' ela= 3066 file#=5 block#=37944 blocks=1 obj#=97820tim=999342291

pin kdswh05: kdsgrp dba1409438:1 time 999342355

WAIT #2: nam='SQL*Net messageto client' ela= 2 driver id=1111838976 #bytes=1 p3=0 obj#=97820 tim=999342411

WAIT #2: nam='db filesequential read' ela= 1935 file#=5 block#=37958 blocks=1 obj#=97820tim=999344410

pin kdswh05: kdsgrp dba1409446:1 time 999344463

FETCH#2:c=0,e=5388,p=2,cr=3,cu=0,mis=0,r=2,dep=0,og=4,tim=999344518

P.S. Guess the operation meaning,

@ kdiixs: Index Scan;

@ kdsgrp: Access table by index rowid.

Where is the other reads? Look at the 1st'db file sequential read', the block was physically read without pining. What'skind of such block? Get its datablock address first,

SQL代码

SQL>selectto_char(dbms_utility.make_data_block_address(5, 66164), 'XXXXXXXX') fromdual;

TO_CHAR(D

---------

1410274

Then, dump the index tree.

SQL代码

SQL>alter session setevents 'immediate trace name treedump level 100897';

Session altered.

Here is the tree,

SQL代码

----- begin tree dump