关于consistent get的问题

对consistent get，始终不太理解。看了[url]http://www.itpub.net/viewthread.php?tid=225812&extra=&page=1[/url]，概念上清楚了一些，但是对consistent get 具体包括哪些读，get计数的计算公式还是不太明白。


-------------------------------------------------------------------------------------------------------------------------
SQL> alter session set events '10200 trace name context forever,level 1';

Session altered.

SQL> select * from t8;

C                ID
-------- ----------
az             1330
by             1331
Candy          1332
Deskbook       1333
EggReady       1334
finefine       1335
aaa              32
aaa              33

8 rows selected.

SQL> alter session set events '10200 trace name context off';

Session altered.
---------------------------------------------------------------------------------------------------------------
Dump file f:oracleadmin        estdbudump        est_ora_1464.trc
Fri Jun 27 11:38:13 2008
ORACLE V9.2.0.1.0 - Production vsnsta=0
vsnsql=12 vsnxtr=3
Windows 2000 Version 5.1 Service Pack 2, CPU type 586
Oracle9i Enterprise Edition Release 9.2.0.1.0 - Production
With the Partitioning, OLAP and Oracle Data Mining options
JServer Release 9.2.0.1.0 - Production
Windows 2000 Version 5.1 Service Pack 2, CPU type 586
Instance name: test

Redo thread mounted by this instance: 1

Oracle process number: 12

Windows thread id: 1464, image: ORACLE.EXE


*** 2008-06-27 11:38:13.000
*** SESSION ID:(9.7) 2008-06-27 11:38:13.000
Consistent read started for block 6 : 01800014
  env: (scn: 0x0000.00678f54  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:  01FEE950  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0
Consistent read finished for block 6 : 1800014
Consistent read finished for block 6 : 1800014
Consistent read started for block 6 : 01800014
  env: (scn: 0x0000.00678f54  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:  01FEE950  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0
Consistent read finished for block 6 : 1800014
Consistent read finished for block 6 : 1800014
Consistent read started for block 6 : 01800015
  env: (scn: 0x0000.00678f54  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:  01FEE950  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0
Consistent read finished for block 6 : 1800015
Consistent read finished for block 6 : 1800015
Consistent read started for block 6 : 01800016
  env: (scn: 0x0000.00678f54  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:  01FEE950  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0
Consistent read finished for block 6 : 1800016
Consistent read finished for block 6 : 1800016
Consistent read started for block 6 : 01800017
  env: (scn: 0x0000.00678f54  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:  01FEE950  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0
Consistent read finished for block 6 : 1800017
Consistent read finished for block 6 : 1800017
Consistent read started for block 6 : 01800018
  env: (scn: 0x0000.00678f54  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:  01FEE950  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0
Consistent read finished for block 6 : 1800018
Consistent read finished for block 6 : 1800018
------------------------------------------------------------------------------------------------------------------------------------------------



SQL> set autot trace
SQL> select * from t8;

8 rows selected.


Execution Plan
----------------------------------------------------------
   0      SELECT STATEMENT Optimizer=CHOOSE (Cost=2 Card=11 Bytes=88)
   1    0   TABLE ACCESS (FULL) OF 'T8' (Cost=2 Card=11 Bytes=88)




Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
          8  consistent gets
          0  physical reads
          0  redo size
        554  bytes sent via SQL*Net to client
        503  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          8  rows processed

SQL> set autot off

SQL> select id,dbms_rowid.rowid_relative_fno(rowid) file#,
  2  dbms_rowid.rowid_block_number(rowid) block#,
  3  dbms_rowid.rowid_row_number(rowid) row#
  4  from t8;

        ID      FILE#     BLOCK#       ROW#
---------- ---------- ---------- ----------
      1330          6         20          4
      1331          6         20          5
      1332          6         20          6
      1333          6         20          7
      1334          6         20          8
      1335          6         20          9
        32          6         22          0
        33          6         22          1

疑问：从trace看，这个查询要8个consistent get。但是在dump里看，似乎只有6个？我对这个10200事件也不太懂。8个consistent get是怎么计算出来的？consistent gets=blocks+rownum/arraysize这个公式成立吗？

I can reproduce it, in 10.2.0.4. Here's my guess. The "consistent gets" reported by sqlplus autotrace is the same named database statistic "consistent gets", which is "Number of times a consistent read was requested for a block" according to the Reference manual. But the dump of 10200 (or 10202) event is "no work - consistent read gets", which is "Number consistent gets that require neither block cleanouts nor rollbacks".

So what's the difference? I'm guessing again. It's possible the "consistent gets" is only requests for CR reads while the "no work..." stat is the actual reads. For some reason, 2 of the 8 buffer reads become unnecessary. Maybe the 2 buffers are the same as 2 of the existing 6? Or maybe there's table prefetch so that 2 buffers are already "piggyback" read during the 6 buffer read? If the latter, we can turn off prefecth and prove the theory.

Yong Huang

我曾经想过这个问题，没有太深入，你看看对你有没有启发
[url]http://valen.blog.ccidnet.com/blog-htm-do-showone-uid-51502-type-blog-itemid-273622.html[/url]

[quote]原帖由 [i]wang5[/i] 于 2008-6-28 00:55 发表 [url=http://www.itpub.net/redirect.php?goto=findpost&pid=10796639&ptid=1012771][img]http://www.itpub.net/images/common/back.gif[/img][/url]
我曾经想过这个问题，没有太深入，你看看对你有没有启发
[url]http://valen.blog.ccidnet.com/blog-htm-do-showone-uid-51502-type-blog-itemid-273622.html[/url] [/quote]

Thanks. I read your blog. It's good. But it doesn't explain the missing 2 CR gets in the 10200 or 10202 dump compared to autotrace or v$sesstat statistic.

Yong Huang

As Yong said, 10200  trace file doesn't include "UNDO blocks"

For example:

Session A:

SQL> select * from t;

         X
----------
         5

  1  begin
  2   for i in 1..1000 loop
  3    update t set x=i;
  4   end  loop;
  5* end;
SQL> /

PL/SQL procedure successfully completed.

Session B:


SQL> alter session set events '10200 trace name context forever,level 1';

Session altered.

SQL> alter session set events '10046 trace name context forever, level 8';

Session altered.

SQL> select * from t;

         X
----------
         5

trace file:

*** 2008-06-29 20:04:55.592
*** SESSION ID:(16.623) 2008-06-29 20:04:55.591
APPNAME mod='SQL*Plus' mh=3669949024 act='' ah=4029777240
=====================
PARSING IN CURSOR #3 len=68 dep=0 uid=74 oct=42 lid=74 tim=7575093677479 hv=2212335334 ad='a8fb0e38'
alter session set events '10046 trace name context forever, level 8'
END OF STMT
EXEC #3:c=0,e=226,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=7575093675639
WAIT #3: nam='SQL*Net message to client' ela= 7 p1=1650815232 p2=1 p3=0
WAIT #3: nam='SQL*Net message from client' ela= 6440262 p1=1650815232 p2=1 p3=0
=====================
PARSING IN CURSOR #3 len=15 dep=0 uid=74 oct=3 lid=74 tim=7575100119767 hv=520543201 ad='a9a75fe0'
select * from t
END OF STMT
PARSE #3:c=0,e=1206,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=7575100119756
EXEC #3:c=0,e=122,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=7575100120167
WAIT #3: nam='SQL*Net message to client' ela= 5 p1=1650815232 p2=1 p3=0
Consistent read started for block 25 : 0780c3f3
  env: (scn: 0x0002.bceb3889  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:  380012b98  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0
CR exa ret 1 on:  381fd5490  scn: 0x0002.bceb386f  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0x0002.bceb386f  sfl: 0
CR exa ret 1 on:  381fbf890  scn: 0x0002.bceb386e  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0x0002.bceb386e  sfl: 0
CR exa ret 1 on:  381fcc890  scn: 0x0002.bceb386d  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0x0002.bceb386d  sfl: 0
CR exa ret 1 on:  382fa1d90  scn: 0x0002.bceb386c  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0x0002.bceb386c  sfl: 0
CR exa ret 1 on:  381fef890  scn: 0x0002.bceb386b  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0x0002.bceb386b  sfl: 0
Consistent read finished for block 25 : 780c3f3
Consistent read finished for block 25 : 780c3f3
[color=Red]FETCH #3:c=0,e=8232,p=0,cr=1004,cu=0,mis=0,r=1,dep=0,og=4,tim=7575100128586[/color]
WAIT #3: nam='SQL*Net message from client' ela= 836 p1=1650815232 p2=1 p3=0
FETCH #3:c=0,e=13,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=7575100129645
WAIT #3: nam='SQL*Net message to client' ela= 2 p1=1650815232 p2=1 p3=0
WAIT #3: nam='SQL*Net message from client' ela= 2737371 p1=1650815232 p2=1 p3=0
XCTEND rlbk=0, rd_only=1
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=22022 op='TABLE ACCESS FULL OBJ#(22022) '

Thanks, eagle_fan. When you have time, please come to this forum more often. One suggestion. When you post, please give some more explanations. For instance, what do the highlighted numbers mean?

I actually didn't think in the line of not counting UNDO blocks by 10200 trace, but you may be right. Now when I read my past messages, I was probably digressing too much. If my simple test is correct, i.e., CR gets in 10200 trace only corresponds to "no work - consistent read gets", not "consistent gets" or the same named number in autotrace (unless accidentally), then we just need to explain the number difference by saying that the extra CR gets (2 in our tests) are due to either rollback (UNDO) or cleanouts. If we can make sure there's neither rollback of inconsistent blocks nor block cleanouts, the 10200 trace should show the same number as autotrace "consistent gets". You agree?

Yong Huang

In my last test, I put 10046 trace & 10200 trace togerther. The highlighted line comes from 10046 trace, not 10200 trace. I used 10046 trace instead of autotrace "consistent gets".

BTW: why it's 10200 not 10202 trace? I searched my msn blog and found that I was using 10202 trace.

[url]http://oracledba.spaces.live.com/blog/cns!57D0C396BA028F14!247.entry[/url]

10200 block cleanout
10201 consistent read undo application
10202 consistent read block header

I'm working on my laptop and it doesn't have test environment installed.

Yong, if you have time, you can do some tests.

[quote]原帖由 [i]eagle_fan[/i] 于 2008-6-30 09:56 发表 [url=http://www.itpub.net/redirect.php?goto=findpost&pid=10814709&ptid=1012771][img]http://www.itpub.net/images/common/back.gif[/img][/url]
In my last test, I put 10046 trace & 10200 trace togerther. The highlighted line comes from 10046 trace, not 10200 trace. I used 10046 trace instead of autotrace "consistent gets". [/quote]

I understand that. I'd like you to explain the highlighted numbers. For instance, what's the signicance of "cr=1004"? How is it related to other part of your message?

Yong Huang

"cr=1004" means consistent reads = 1004 blocks.

But in 10200 trace part, it only has one block:

Consistent read started for block 25 : 0780c3f3.

1004 = 1000 undo apply reads + 3 segment header reads + 1 data block read (no work - consistent read gets)

10201 trace will give you undo apply information.

[[i] 本帖最后由 eagle_fan 于 2008-7-1 10:30 编辑 [/i]]

Thank Yong Huang and eagle_fan.

I did some experiments on my 9i box with full scan table in which case undo blocks should not be read. I followed eagle_fan's procedures by set events 10046 and 10200, and got a trace file. I extract the part which corresponds to 'select * from t8'.

=====================
PARSING IN CURSOR #1 len=16 dep=0 uid=39 oct=3 lid=39 tim=101212509339 hv=1430366237 ad='12ec1ebc'
select * from t8
END OF STMT
PARSE #1:c=0,e=717,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=101212509330
EXEC #1:c=0,e=57,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=101212528139
Consistent read started for block 6 : 01800014
  env: (scn: 0x0000.0068eba3  xid: 0x0010.01f.0000000d  uba: 0x02000016.0019.05  statement num=0  parent xid: xid: 0x0000.000.00000000  scn: 0x0000.0068eb46 0sch: scn: 0x0000.00000000)
CR exa ret 9 on:  01FEE950  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0
Consistent read finished for block 6 : 1800014
Consistent read finished for block 6 : 1800014
[color=red]FETCH #1:c=15625,e=18005,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=4,tim=101212549286[/color]
Consistent read started for block 6 : 01800014
  env: (scn: 0x0000.0068eba3  xid: 0x0010.01f.0000000d  uba: 0x02000016.0019.05  statement num=0  parent xid: xid: 0x0000.000.00000000  scn: 0x0000.0068eb46 0sch: scn: 0x0000.00000000)
CR exa ret 9 on:  01FEE950  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0
Consistent read finished for block 6 : 1800014
Consistent read finished for block 6 : 1800014
Consistent read started for block 6 : 01800015
  env: (scn: 0x0000.0068eba3  xid: 0x0010.01f.0000000d  uba: 0x02000016.0019.05  statement num=0  parent xid: xid: 0x0000.000.00000000  scn: 0x0000.0068eb46 0sch: scn: 0x0000.00000000)
CR exa ret 9 on:  01FEE950  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0
Consistent read finished for block 6 : 1800015
Consistent read finished for block 6 : 1800015
Consistent read started for block 6 : 01800016
  env: (scn: 0x0000.0068eba3  xid: 0x0010.01f.0000000d  uba: 0x02000016.0019.05  statement num=0  parent xid: xid: 0x0000.000.00000000  scn: 0x0000.0068eb46 0sch: scn: 0x0000.00000000)
CR exa ret 9 on:  01FEE950  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0
Consistent read finished for block 6 : 1800016
Consistent read finished for block 6 : 1800016
Consistent read started for block 6 : 01800017
  env: (scn: 0x0000.0068eba3  xid: 0x0010.01f.0000000d  uba: 0x02000016.0019.05  statement num=0  parent xid: xid: 0x0000.000.00000000  scn: 0x0000.0068eb46 0sch: scn: 0x0000.00000000)
CR exa ret 9 on:  01FEE950  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0
Consistent read finished for block 6 : 1800017
Consistent read finished for block 6 : 1800017
Consistent read started for block 6 : 01800018
  env: (scn: 0x0000.0068eba3  xid: 0x0010.01f.0000000d  uba: 0x02000016.0019.05  statement num=0  parent xid: xid: 0x0000.000.00000000  scn: 0x0000.0068eb46 0sch: scn: 0x0000.00000000)
CR exa ret 9 on:  01FEE950  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0
Consistent read finished for block 6 : 1800018
Consistent read finished for block 6 : 1800018
[color=red]FETCH #1:c=93750,e=95620,p=0,cr=5,cu=0,mis=0,r=7,dep=0,og=4,tim=101212648544[/color]
*** SESSION ID:(9.33) 2008-07-02 12:07:25.000
STAT #1 id=1 cnt=8 pid=0 pos=1 obj=27749 op='TABLE ACCESS FULL T8 '


As it shows, the overall consistent get is 8 comprising 2 fetchs. The first fetch has 3 consistent gets and the second fetch has 5 consistent get.  I find that the first row always fetch 1 row but has several consistent gets(in this case, cr=3. But while I tested on a biger table, the first fetch has cr=4. I wonder what this means). After the first fetch, there are consequent fetches which scan all blocks under highwater mark even though there are no rows in them at all. I don't think the formula 'consistent gets=blocks+ceil(rownum/arraysize)' is true for all cases.

eagle_fan:
'1004 = 1000 undo apply reads + 3 segment header reads + 1 data block read (no work - consistent read gets)
'
What is '3 segment header reads' for? Does a 'select' need bitmap info? Or a table scan includes (pagetable segment header+SECOND LEVEL BITMAP BLOCK+FIRST LEVEL BITMAP BLOCK)? Is the number of this kind of cr always 3?
What if cr=4?