如果用過RAC那麼你一定見到過這些等待事件：gc buffer busy acquire/release、gc cr/current block 2-way、gc cr/current block busy ..... 不一一列舉了。對於這些事件的具體含義網上資料不少，因此不作深入介紹，本文關注的是這類等待事件在何種情況下會出現，設計了部分場景儘可能的模擬出這些等待

#########要用到的指令碼清單
~~~~~~~~~~~~~~~~~
sess_1st.sql
~~~~~~~~~~~~~~~~~
define v_inst1=&1
define v_inst2=&3
define v_sid1=&2
define v_sid2=&4
drop table sess_evt_1st;
create table sess_evt_1st as select inst_id,sid,event,total_waits from gv$session_event where (inst_id=&v_inst1 and sid in (&v_sid1)) or (inst_id=&v_inst2 and sid in (&v_sid2)) order by inst_id,sid,event;

~~~~~~~~~~~~~~~~~
sess_2nd.sql
~~~~~~~~~~~~~~~~~
define v_inst1=&1;
define v_sid1=&2;
declare
v_count_1st number;
begin
select count(1) into v_count_1st from sess_evt_1st;
if (v_count_1st < 1)
then
insert into sess_evt_1st select * from sess_evt_2nd;
commit;
end if;
end;
/

truncate table sess_evt_2nd;
insert into sess_evt_2nd select inst_id,sid,event,total_waits from gv$session_event where inst_id=&v_inst1 and sid in (&v_sid1) and wait_class!='Idle' order by inst_id,sid,event;
commit;

col event format a30
set linesize 120 pagesize 60
select nd.sid,nd.event,nd.total_waits-nvl(st.total_waits,0) diff_waits from sess_evt_1st st,sess_evt_2nd nd where st.inst_id(+)=nd.inst_id and st.sid(+)=nd.sid
and st.event(+)=nd.event order by event,sid;

truncate table sess_evt_1st;

~~~~~~~~~~~~~~~~~
sess_1st_4p.sql
~~~~~~~~~~~~~~~~~
define v_inst1=&1
define v_inst2=&3
define v_sid1=&2
define v_sid2=&4
drop table sess_evt_1st;
create table sess_evt_1st as select inst_id,sid,event,total_waits from gv$session_event where (inst_id=&v_inst1 and sid in (&v_sid1)) or (inst_id=&v_inst2 and
sid in (&v_sid2)) order by inst_id,sid,event;

~~~~~~~~~~~~~~~~~
sess_2nd_4p.sql
~~~~~~~~~~~~~~~~~
define v_inst1=&1
define v_inst2=&3
define v_sid1=&2
define v_sid2=&4
drop table sess_evt_2nd;
create table sess_evt_2nd as select inst_id,sid,event,total_waits from gv$session_event where (inst_id=&v_inst1 and sid in (&v_sid1)) or (inst_id=&v_inst2 and
sid in (&v_sid2)) order by inst_id,sid,event;
col event format a30
set linesize 120 pagesize 60
select nd.sid,nd.event,nd.total_waits-nvl(st.total_waits,0) diff_waits from sess_evt_1st st,sess_evt_2nd nd where st.inst_id(+)=nd.inst_id and st.sid(+)=nd.sid
and st.event(+)=nd.event order by event,sid;

~~~~~~~~~~~~~~~~~
query_xbh.sql
~~~~~~~~~~~~~~~~~
col object_name format a20
set heading off
set linesize 80
select '------x$bh------' from dual;
set heading on
select inst_id,dbarfil,dbablk,CR_SCN_BAS,DECODE(state,0,'free',1,'xcur',2,'scur',3,'cr', 4,'read',5,'mrec',6,'irec',7,'write',8,'pi', 9,'memory',10,'mwrite',11,'donated', 12,'protected', 13,'securefile', 14,'siop',15,'recckpt', 16, 'flashfree', 17, 'flashcur', 18, 'flashna') state_name,tch from x$bh where ((dbarfil=&fileno and dbablk=&blkno) or (dbarfil=&ufileno and dbablk=&ublkno)) and state!=0;

~~~~~~~~~~~~~~~~~
query_vbh.sql
~~~~~~~~~~~~~~~~~
set heading off
select '------v$bh------' from dual;
set heading on
select inst_id,file#,block#,status from gv$bh where ((file#=&fileno and block#=&blkno) or (file#=&ufileno and block#=&ublkno)) and status!='free';

/////////////////////
//gc cr disk read事件
/////////////////////
事件描述：
當node 1需要讀取的block在node 2的buffer cache裡，且block中包含尚未提交的事務，那麼node 2的LMS程式需要使用undo record將該block回滾至node 1發起那一時刻的內容後再傳給node 1，假如這時undo record所在的undo block不在node 2的buffer cache裡，node 1上就會出現gc cr disk read事件，表示node 1正等待node 2的LMS授予其直接從磁碟讀取undo block的許可權。

模擬事件產生：gc cr disk read
--session 1 node 1：update col2='A'的記錄
select * from scott.t0820_1;
ID C
---------- -
7.68176826 A
2.14433612 B

select dbms_rowid.rowid_relative_fno(rowid) rfno,dbms_rowid.rowid_block_number(rowid) blkno from scott.t0820_1;
RFNO BLKNO
---------- ----------
6 253
6 253

update scott.t0820_1 set id=dbms_random.value(1,10) where col2='A';

--session 2 node 1: 記錄一下session 1 node 1使用的undo block，查詢v$bh、x$bh裡與本次update有關的data block和undo block
select xidusn,ubafil,ubablk,used_ublk from v$transaction ;
XIDUSN UBAFIL UBABLK USED_UBLK
---------- ---------- ---------- ----------
7 3 7954 1

set heading on
define fileno=6
define blkno=253
define ufileno=3
define ublkno=7954
@query_xbh.sql
INST_ID DBARFIL DBABLK CR_SCN_BAS STATE_NAME TCH
---------- ---------- ---------- ---------- ---------- ----------
1 6 253 0 xcur 2
1 6 253 2759860 cr 2
1 3 7954 0 xcur 3

@query_vbh.sql
INST_ID FILE# BLOCK# STATUS
---------- ---------- ---------- ----------
1 6 253 xcur
1 3 7954 xcur
1 6 253 cr

--session 1 node 2: 會話資訊
select sid,serial# from v$session where sid=sys_context('userenv','sid');
SID SERIAL#
---------- ----------
14 9

select value from v$diag_info where name='Default Trace File';
/oracle/app/oracle/diag/rdbms/susedb1/susedb12/trace/susedb12_ora_30958.trc

--session 2 node 2：儲存session 1 node 2執行select前的會話資訊，開啟10046 trace
@sess_1st.sql 2 14
exec dbms_monitor.session_trace_enable(14,9);

--session 1 node 2: select col2='B'的記錄
select * from scott.t0820_1 where col2='B';
ID C
---------- -
2.14433612 B

--session 2 node 2：收集執行期間的wait events，結束跟蹤
@sess_2nd.sql 2 14

SID EVENT DIFF_WAITS
---------- ------------------------------ ----------
14 Disk file operations I/O 1
14 SQL*Net message to client 2
14 events in waitclass Other 0
14 gc cr multi block request 1
14 gc current block 2-way 2
14 library cache lock 0
14 library cache pin 0
14 row cache lock 16

exec dbms_monitor.session_trace_disable(14,9);

--session 2 node 2：查詢v$bh、x$bh找到與Scott.t0820_1表及undo有關的block
define fileno=6
define blkno=253
define ufileno=3
define ublkno=7954
@query_xbh.sql
INST_ID DBARFIL DBABLK CR_SCN_BAS STATE_NAME TCH
---------- ---------- ---------- ---------- ---------- ----------
2 6 253 2760009 cr 1

@query_vbh.sql
INST_ID FILE# BLOCK# STATUS
---------- ---------- ---------- ----------
2 6 253 cr
1 6 253 xcur
1 3 7954 xcur
1 6 253 cr
1 6 253 cr

--session 2 node 1：查詢x$bh與Scott.t0820_1表及undo有關的block
define fileno=6
define blkno=253
define ufileno=3
define ublkno=7954
@query_xbh.sql

INST_ID DBARFIL DBABLK CR_SCN_BAS STATE_NAME TCH
---------- ---------- ---------- ---------- ---------- ----------
1 6 253 2760009 cr 0 <---從CR_SCN_BAS可以看出這個cr與node 2上的cr是一個版本，TCH=0可以看出cr構造於node 1然後傳輸到node 2，在node 1上並沒有被訪問
1 6 253 0 xcur 2
1 6 253 2759860 cr 2
1 3 7954 0 xcur 4

生成的trace檔案susedb12_ora_30958.trc裡與scott.t0820_1表及undo有關的條目摘錄如下：
WAIT #140341723483448: nam='gc current block 2-way' ela= 460 p1=6 p2=250 p3=4 obj#=15976 tim=1474008654658633
。。。省略了部分內容
WAIT #140341723483448: nam='gc cr multi block request' ela= 2505 file#=6 block#=253 class#=1 obj#=15976 tim=1474008654665173
FETCH #140341723483448:c=0,e=3294,p=0,cr=5,cu=0,mis=0,r=1,dep=0,og=1,plh=168131571,tim=1474008654665281

這其中6/253是我們所操作的資料塊本身，6/250是scott.t0820_1的segment header
col owner format a13
col segment_name format a25
col header_file format 999
col header_block format 999
set linesize 100
select owner,segment_name,header_file,header_block from dba_segments where segment_name='T0820_1';
OWNER SEGMENT_NAME HEADER_FILE HEADER_BLOCK
------------- ------------------------- ----------- ------------
SCOTT T0820_1 6 250

6/250引發了gc current block 2-way，因為node 2從未訪問過segment_header，所以node 2必須從node 1得到最新的segment header資訊；6/253引發了gc cr multi block request，因為node 1 update之後沒有commit，所以node 2發起的select是一次Consistent read從node 1的buffer cache將6/253讀到local buffer cache

---session 1 node 2: flush buffer cache
alter system flush buffer_cache;

define fileno=6
define blkno=253
define ufileno=3
define ublkno=7954
@query_xbh.sql

no rows selected

@query_vbh.sql

no rows selected

---session 2 node 1: 雖然是在node 2上執行的flush操作，node 1本地的buffer cache裡也找不到這些buffer了
define fileno=6
define blkno=253
define ufileno=3
define ublkno=7954
@query_xbh.sql

no rows selected

@query_vbh.sql

no rows selected

---session 1 node 2: 獲取diag file name
select value from v$diag_info where name='Default Trace File';
/oracle/app/oracle/diag/rdbms/susedb1/susedb12/trace/susedb12_ora_30958.trc

--session 2 node 2：儲存session 1 node 2執行select前的會話資訊，開啟10046 trace
@sess_1st.sql 2 14
exec dbms_monitor.session_trace_enable(14,9);

--session 1 node 2: 再一次select col2='B'的記錄
select * from scott.t0820_1 where col2='B';
ID C
---------- -
2.14433612 B

--session 2 node 2：收集執行期間的wait events，結束跟蹤
@sess_2nd.sql 2 14

SID EVENT DIFF_WAITS
---------- ------------------------------ ----------
14 Disk file operations I/O 3
14 SQL*Net message to client 2
14 db file scattered read 1 <---6/251~6/255
14 db file sequential read 2 <---6/250、3/7954
14 events in waitclass Other 1
14 gc cr block 2-way 1 <---3/224
14 gc cr disk read 1 <---3/7954
14 gc cr multi block request 0
14 gc current block 2-way 0
14 library cache lock 0
14 library cache pin 0
14 os thread startup 1
14 row cache lock 2

exec dbms_monitor.session_trace_disable(14,9);

trace檔案susedb12_ora_30958.trc裡的相關條目按順序摘錄如下：
WAIT #140341723494584: nam='db file sequential read' ela= 621 file#=6 block#=250 blocks=1 obj#=15976 tim=1474009210968492
WAIT #140341723494584: nam='db file scattered read' ela= 14721 file#=6 block#=251 blocks=5 obj#=15976 tim=1474009210984834
WAIT #140341723494584: nam='gc cr block 2-way' ela= 1900 p1=3 p2=224 p3=29 obj#=0 tim=1474009210988479
WAIT #140341723494584: nam='gc cr disk read' ela= 1547 p1=3 p2=7954 p3=30 obj#=0 tim=1474009210991241
WAIT #140341723494584: nam='db file sequential read' ela= 19524 file#=3 block#=7954 blocks=1 obj#=0 tim=1474009211100974

db file sequential read：6/250，segment header，單塊從磁碟讀取
db file scattered read：file#=6 block#=251 blocks=5表示從6/251開始的連續5個block透過multi block read方式一次性從磁碟讀取
gc cr block 2-way：3/224是undo header，從node 1的buffer cache裡一致讀訪問這個block，我們透過dba_rollback_segs與v$transaction關聯得到undo header block：

select segment_id,file_id,block_id from dba_rollback_segs,v$transaction where segment_id=xidusn;
SEGMENT_ID FILE_ID BLOCK_ID
---------- ---------- ----------
7 3 224 <---7號undo segment 的header存在於block 3/224

上面的等待事件驗證了node 2一致讀的過程：讀到6/253時發現包含未提交的事務，要先訪問undo header(訪問期間產生了gc cr block 2-way事件)，以從其事務槽裡獲取包含6/253修改前映像的undo block，然後再對undo block進行訪問，因undo block已被刷出node 1的buffer cache，gc cr disk read表示node 2獲得node 1 LMS程式的准許從磁碟讀取node 1的undo block 3/7954，下一個db file sequential read等待事件就是完成從磁碟上讀取3/7954這個動作，最後利用undo block裡的undo record構造出select發起時刻的一致性結果資料返回node 1

/////////////////////////////
//gc current/cr block 2-way
/////////////////////////////
事件描述：
gc current block 2-way
node 1、node 2的buffer cache裡都沒有block A，這時node 1讀取了某個block A裡的某一行，隨後node 2也讀取了block A或者對block A裡的某一行作了DML操作，這兩種情況下node 2上都會出現"gc current block 2-way"等待，current在這裡表示node 2讀取或修改的block版本是最新的，該block裡不存在未提交的事務。值得注意的是在"gc current block 2-way"事件發生之後，GRD裡會為該block上KJUSERPR(讀操作)或者KJUSEREX鎖(寫操作)

gc cr block 2-way
細分一下有兩種情況
(1)、node 1修改了記錄但沒有提交：
node 1、node 2的buffer cache裡都沒有block A，這時node 1修改了block A裡的某一行，但沒有提交；隨後node 2執行了Select block A操作，按照一致性讀的定義，node 2此時應該收到block A在select發起那一時刻所對應的快照block A'，block A'將由node 1上的LMS程式以應用undo record到block A的方式構造出來後傳給node 2，此時在node 2上就發生了一次"gc cr block 2-way"等待事件，node 2接收到的block A'在buffer cache中標記為cr型別，cr類的block僅滿足當次查詢的需要，無法被之後的查詢所重用，也就是說假如node 2僅接著又發起一次對於block A的select操作，node 1上的LMS程式還是會重新構造出一個block A''後傳遞給node 2，儘管block A''與block A'的內容是完全一樣的。這一特性決定了cr block在構造及傳輸的過程中在GRD裡不需要任何的鎖來保護。

2、node 1修改了記錄且已經提交：
node 1、node 2的buffer cache裡都沒有block A，這時node 1修改了block A裡的某一行，並且已經提交。因為_fairness_threshold引數的作用，當node 2執行了Select block A操作，仍然有可能觸發node 1上的LMS程式構造cr block然後傳輸給node 2的動作，node 2就會遇到gc cr block 2-way等待。關於_fairness_threshold引數的詳細介紹可參考我的另一篇文章"探究隱含引數_fairness_threshold"(http://blog.itpub.net/53956/viewspace-2124241)

模擬事件的產生：gc current block 2-way
前提：scott.tst0625_1表不存在於任何節點的buffer cache裡

--session 1 node 1：每個block僅有一行資料，共20行，算上segment header載入buffer cache的block共有21個
set pagesize 30
select distinct dbms_rowid.rowid_relative_fno(rowid) rfno,dbms_rowid.rowid_block_number(rowid) from scott.tst0625_1 t order by 1,2;
RFNO DBMS_ROWID.ROWID_BLOCK_NUMBER(ROWID)
---------- ------------------------------------
6 131
6 132
6 133
6 134
6 135
6 136
6 137
6 138
6 139
6 140
6 141
6 142
6 143
6 145
6 146
6 147
6 148
6 149
6 150
6 151

select count(*) from scott.tst0625_1;
COUNT(*)
----------
20

set pagesize 100
select inst_id,file#,block#,STATUS,objd from gv$bh where objd=15698 and status!='free' order by inst_id,block#;
INST_ID FILE# BLOCK# STATUS OBJD
---------- ---------- ---------- ---------- ----------
1 6 130 scur 15698 <---是segment header
1 6 131 scur 15698
1 6 132 scur 15698
1 6 133 scur 15698
1 6 134 scur 15698
1 6 135 scur 15698
1 6 136 scur 15698
1 6 137 scur 15698
1 6 138 scur 15698
1 6 139 scur 15698
1 6 140 scur 15698
1 6 141 scur 15698
1 6 142 scur 15698
1 6 143 scur 15698
1 6 145 scur 15698
1 6 146 scur 15698
1 6 147 scur 15698
1 6 148 scur 15698
1 6 149 scur 15698
1 6 150 scur 15698
1 6 151 scur 15698

--session 1 node 2：獲取會話資訊
select sid,serial# from v$session where sid=sys_context('userenv','sid');
SID SERIAL#
---------- ----------
14 11

select value from v$diag_info where name='Default Trace File';
/oracle/app/oracle/diag/rdbms/susedb1/susedb12/trace/susedb12_ora_5935.trc

--session 2 node 2：儲存會話的初始waitevent，開啟10046 trace
@sess_1st.sql 2 14
exec dbms_monitor.session_trace_enable(14,11);

--session 1 node 2：select指定rowid訪問特定行
select id,length(N1),length(N2) from scott.tst0625_1 where rowid in ('AAAD1SAAGAAAACDAAA','AAAD1SAAGAAAACEAAA');
ID LENGTH(N1) LENGTH(N2)
---------- ---------- ----------
1 3000 3200
3 3000 3200

--session 2 node 2
@sess_2nd.sql 2 14
SID EVENT DIFF_WAITS
---------- ------------------------------ ----------
14 Disk file operations I/O 1
14 SQL*Net message to client 2
14 db file parallel read 0
14 db file scattered read 0
14 db file sequential read 0
14 events in waitclass Other 0
14 gc cr grant 2-way 0
14 gc cr grant congested 0
14 gc cr multi block request 0
14 gc current block 2-way 2 <---兩次gc current block 2-way，每次對應一個block
14 library cache lock 0
14 library cache pin 0
14 row cache lock 4

exec dbms_monitor.session_trace_disable(14,11);

select inst_id,file#,block#,STATUS,objd from gv$bh where objd=15698 and status!='free' order by inst_id,block#;
INST_ID FILE# BLOCK# STATUS OBJD
---------- ---------- ---------- ---------- ----------
1 6 130 scur 15698
1 6 131 scur 15698
1 6 132 scur 15698
1 6 133 scur 15698
1 6 134 scur 15698
1 6 135 scur 15698
1 6 136 scur 15698
1 6 137 scur 15698
1 6 138 scur 15698
1 6 139 scur 15698
1 6 140 scur 15698
1 6 141 scur 15698
1 6 142 scur 15698
1 6 143 scur 15698
1 6 145 scur 15698
1 6 146 scur 15698
1 6 147 scur 15698
1 6 148 scur 15698
1 6 149 scur 15698
1 6 150 scur 15698
1 6 151 scur 15698
2 6 131 scur 15698 <---dbms_rowid.rowid_block_number('AAAD1SAAGAAAACDAAA')=131
2 6 132 scur 15698 <---dbms_rowid.rowid_block_number('AAAD1SAAGAAAACEAAA')=132

Trace檔案susedb12_ora_5935.trc裡的內容可以看出兩次gc current block 2-way等待分別來自6/131、6/132，紅色部分；用了兩次邏輯讀每次返回一行
PARSING IN CURSOR #140532781792704 len=111 dep=0 uid=0 oct=3 lid=0 tim=1474026770006054 hv=1561302837 ad='88d4bb28' sqlid='50mu165fhz5tp'
select id,length(N1),length(N2) from scott.tst0625_1 where rowid in ('AAAD1SAAGAAAACDAAA','AAAD1SAAGAAAACEAAA')
END OF STMT
PARSE #140532781792704:c=4001,e=10969,p=0,cr=13,cu=0,mis=1,r=0,dep=0,og=1,plh=950802872,tim=1474026770006050
EXEC #140532781792704:c=0,e=37,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=950802872,tim=1474026770006141
WAIT #140532781792704: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1474026770006175
WAIT #140532781792704: nam='Disk file operations I/O' ela= 5 FileOperation=2 fileno=6 filetype=2 obj#=-1 tim=1474026770006284

*** 2016-09-16 19:52:50.008
WAIT #140532781792704: nam='gc current block 2-way' ela= 1581 p1=6 p2=131 p3=1 obj#=15698 tim=1474026770007998
FETCH #140532781792704:c=0,e=1993,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=950802872,tim=1474026770008190
WAIT #140532781792704: nam='SQL*Net message from client' ela= 167 driver id=1650815232 #bytes=1 p3=0 obj#=15698 tim=1474026770008416
WAIT #140532781792704: nam='gc current block 2-way' ela= 856 p1=6 p2=132 p3=1 obj#=15698 tim=1474026770009429
WAIT #140532781792704: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=15698 tim=1474026770009543
FETCH #140532781792704:c=0,e=1119,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=950802872,tim=1474026770009568
STAT #140532781792704 id=1 cnt=2 pid=0 pos=1 obj=0 op='INLIST ITERATOR (cr=2 pr=0 pw=0 time=1960 us)'
STAT #140532781792704 id=2 cnt=2 pid=1 pos=1 obj=15698 op='TABLE ACCESS BY USER ROWID TST0625_1 (cr=2 pr=0 pw=0 time=2978 us cost=1 size=3129 card=1)'

因為所有block在node 1 buffer cache裡的型別都是scur，即shared current，表示block的當前最新版本，所以node 2訪問6/131、6/132兩個block是產生的等待事件是gc current block 2-way，而不是gc cr block 2-way

上例使用了rowid in ... 作為條件，僅為能夠比較清晰的看清gc current block 2-way的本質，在實際應用中很少使用rowid作為條件，用的更多的是
select id,length(N1),length(N2) from scott.tst0625_1 where id in (1,3)這種可讀性更為強的寫法，我們來看下，以"id in (1,3)"為條件的情況下是否還會出現gc current block 2-way事件

--session 1 node 1：每個block僅有一行資料，共20行，算上segment header，載入buffer cache的block共有21個
alter system flush buffer_cache;

select count(*) from scott.tst0625_1;
COUNT(*)
----------
20

select id,length(N1),length(N2),dbms_rowid.rowid_block_number(rowid) from scott.tst0625_1;
ID LENGTH(N1) LENGTH(N2) DBMS_ROWID.ROWID_BLOCK_NUMBER(ROWID)
---------- ---------- ---------- ------------------------------------
1 3000 3200 131
3 3000 3200 132
4 3000 3200 133
5 3000 3200 134
2 3000 3200 135
11 3000 3200 136
12 3000 3200 137
13 3000 3200 138
6 3000 3200 139
7 3000 3200 140
8 3000 3200 141
9 3000 3200 142
10 3000 3200 143
14 3000 3200 145
16 3000 3200 146
17 3000 3200 147
18 3000 3200 148
19 3000 3200 149
20 3000 3200 150
15 3000 3200 151

set pagesize 100
select inst_id,file#,block#,STATUS,objd from gv$bh where objd=15698 and status!='free' order by inst_id,block#;
INST_ID FILE# BLOCK# STATUS OBJD
---------- ---------- ---------- ---------- ----------
1 6 130 scur 15698 <---segment header block
1 6 131 scur 15698
1 6 132 scur 15698
1 6 133 scur 15698
1 6 134 scur 15698
1 6 135 scur 15698
1 6 136 scur 15698
1 6 137 scur 15698
1 6 138 scur 15698
1 6 139 scur 15698
1 6 140 scur 15698
1 6 141 scur 15698
1 6 142 scur 15698
1 6 143 scur 15698
1 6 145 scur 15698
1 6 146 scur 15698
1 6 147 scur 15698
1 6 148 scur 15698
1 6 149 scur 15698
1 6 150 scur 15698
1 6 151 scur 15698

--session 1 node 2：獲取會話資訊
select sid,serial# from v$session where sid=sys_context('userenv','sid');
SID SERIAL#
---------- ----------
14 13

select value from v$diag_info where name='Default Trace File';
/oracle/app/oracle/diag/rdbms/susedb1/susedb12/trace/susedb12_ora_11146.trc

--session 2 node 2：儲存會話的初始waitevent，開啟10046 trace
@sess_1st.sql 2 14
exec dbms_monitor.session_trace_enable(14,13);

--session 1 node 2：select指定rowid訪問特定行
select id,length(N1),length(N2) from scott.tst0625_1 where id in (1,2); <---id欄位沒有索引，因此會引起全表掃描，下面會觀察到表中的所有block都load到了buffer cache
ID LENGTH(N1) LENGTH(N2)
---------- ---------- ----------
1 3000 3200
3 3000 3200

--session 2 node 2
@sess_2nd.sql 2 14
SID EVENT DIFF_WAITS
---------- ------------------------------ ----------
14 Disk file operations I/O 1
14 SQL*Net message to client 2
14 db file parallel read 0
14 db file scattered read 0
14 db file sequential read 0
14 events in waitclass Other 0
14 gc cr grant 2-way 0
14 gc cr grant congested 0
14 gc cr multi block request 3
14 gc current block 2-way 2 <---其中只有一次來自於和tst0625_1表相關的block 6/130，6/130是segment header，trcfile的分析見下
14 row cache lock 3

exec dbms_monitor.session_trace_disable(14,13);

SQL> select inst_id,file#,block#,STATUS,objd from gv$bh where objd=15698 and status!='free' order by inst_id,block#;

INST_ID FILE# BLOCK# STATUS OBJD
---------- ---------- ---------- ---------- ----------
1 6 130 scur 15698
1 6 131 scur 15698
1 6 132 scur 15698
1 6 133 scur 15698
1 6 134 scur 15698
1 6 135 scur 15698
1 6 136 scur 15698
1 6 137 scur 15698
1 6 138 scur 15698
1 6 139 scur 15698
1 6 140 scur 15698
1 6 141 scur 15698
1 6 142 scur 15698
1 6 143 scur 15698
1 6 145 scur 15698
1 6 146 scur 15698
1 6 147 scur 15698
1 6 148 scur 15698
1 6 149 scur 15698
1 6 150 scur 15698
1 6 151 scur 15698
2 6 130 scur 15698
2 6 131 scur 15698
2 6 132 scur 15698
2 6 133 scur 15698
2 6 134 scur 15698
2 6 135 scur 15698
2 6 136 scur 15698
2 6 137 scur 15698
2 6 138 scur 15698
2 6 139 scur 15698
2 6 140 scur 15698
2 6 141 scur 15698
2 6 142 scur 15698
2 6 143 scur 15698
2 6 145 scur 15698
2 6 146 scur 15698
2 6 147 scur 15698
2 6 148 scur 15698
2 6 149 scur 15698
2 6 150 scur 15698
2 6 151 scur 15698

select segment_name,extent_id,file_id,block_id,blocks from dba_extents where segment_name='TST0625_1';

SEGMENT_NAME EXTENT_ID FILE_ID BLOCK_ID BLOCKS
------------------ ----------- ---------- ---------- ----------
TST0625_1 0 6 128 8
TST0625_1 1 6 136 8
TST0625_1 2 6 144 8

Trace檔案susedb12_ora_11146.trc內容看到僅出現一次針對segment header block 6/130的gc current block 2-way等待事件，剩下三次都是gc cr multi block request
PARSING IN CURSOR #140600891635672 len=70 dep=0 uid=0 oct=3 lid=0 tim=1474029113549743 hv=2015775894 ad='88c94360' sqlid='1tvrcqtw2cm4q'
select id,length(N1),length(N2) from scott.tst0625_1 where id in (1,2)
END OF STMT
PARSE #140600891635672:c=8000,e=7666,p=0,cr=19,cu=0,mis=1,r=0,dep=0,og=1,plh=2149608728,tim=1474029113549738
EXEC #140600891635672:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2149608728,tim=1474029113549842
WAIT #140600891635672: nam='SQL*Net message to client' ela= 17 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1474029113549895
WAIT #140600891635672: nam='Disk file operations I/O' ela= 7 FileOperation=2 fileno=6 filetype=2 obj#=-1 tim=1474029113550070
WAIT #140600891635672: nam='gc current block 2-way' ela= 443 p1=6 p2=130 p3=4 obj#=15698 tim=1474029113550650
WAIT #140600891635672: nam='gc cr multi block request' ela= 1453 file#=6 block#=135 class#=1 obj#=15698 tim=1474029113552591
FETCH #140600891635672:c=0,e=2721,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=2149608728,tim=1474029113552744
WAIT #140600891635672: nam='SQL*Net message from client' ela= 231 driver id=1650815232 #bytes=1 p3=0 obj#=15698 tim=1474029113553032
WAIT #140600891635672: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=15698 tim=1474029113553161
WAIT #140600891635672: nam='gc cr multi block request' ela= 1697 file#=6 block#=143 class#=1 obj#=15698 tim=1474029113555335
WAIT #140600891635672: nam='gc cr multi block request' ela= 1450 file#=6 block#=151 class#=1 obj#=15698 tim=1474029113557108
FETCH #140600891635672:c=4000,e=4093,p=0,cr=19,cu=0,mis=0,r=1,dep=0,og=1,plh=2149608728,tim=1474029113557166
STAT #140600891635672 id=1 cnt=2 pid=0 pos=1 obj=15698 op='TABLE ACCESS FULL TST0625_1 (cr=23 pr=0 pw=0 time=2662 us cost=7 size=49872 card=16)'

可以看到gc cr multi block request的三次等待都是以每個extent裡的最後一個block_id作為標識，但這並不能說明有多少個extent就會觸發多少次gc cr multi block request，後面會有詳細說明
WAIT #140600891635672: nam='gc cr multi block request' ela= 1453 file#=6 block#=135 class#=1 obj#=15698 tim=1474029113552591
。。。
WAIT #140600891635672: nam='gc cr multi block request' ela= 1697 file#=6 block#=143 class#=1 obj#=15698 tim=1474029113555335
WAIT #140600891635672: nam='gc cr multi block request' ela= 1450 file#=6 block#=151 class#=1 obj#=15698 tim=1474029113557108

這三次gc cr multi block request產生了多少讀，下面這行給出了說明：
FETCH #140600891635672:c=4000,e=4093,p=0,cr=19,cu=0,mis=0,r=1,dep=0,og=1,plh=2149608728,tim=1474029113557166

cr=19表示一致性讀取了19個block，r=1表示返回1行，結合前面dba_extents和gv$bh的輸出我們具體分析一下cr=19，r=1是如何得到的：
extent 0 範圍：6/128~6/135，其中6/128~6/130分別是1st level BMB、2nd level BMB、Segment header，6/131~6/135是data block，包含segment header的extent比較特殊從第二個data block也就是6/132才開始記入gc cr multi block request，因此貢獻了4次cr
extent 1 範圍：6/136~6/143，都是data block，共8個，貢獻了8次cr
extent 2 範圍：6/144~6/151，6/144沒有被讀入buffer cache，剩下的6/145~6/151共7個是data block，貢獻了7次cr
因此三次gc cr multi block request就產生了19次cr，因為在6/132~6/135、6/136~6/143、6/144~6/151這19個block裡包含id=2的記錄，所以r=1

Trace File裡還有一行，cr=4，讀取的這4個block範圍就是6/128~6/131，其中僅6/131是Data block且包含id=1的記錄，所以r=1
FETCH #140600891635672:c=0,e=2721,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=2149608728,tim=1474029113552744

順帶提一下，在表沒有索引的情況下gc cr multi block request等待次數和表裡有多少個extent，也和db_file_multiblock_read_count的值有關，若db_file_multiblock_read_count < 單個extent裡的block個數，那麼訪問一個extent就有可能產生多次gc cr multi block request等待，反之一個extent觸發一次gc cr multi block request，有興趣的童鞋可以自行驗證一下

模擬事件產生：gc cr block 2-way
session 1 node 2 sid: 16
session 1 node 1 sid: 425

---session 1 node 1：
create table scott.tst0628_1(id number,n1 varchar2(3000),n2 varchar2(3200)) tablespace test1;

declare
begin
for i in 1..20 loop
insert into scott.tst0628_1 values(i,dbms_random.string('l',3000),dbms_random.string('l',3200));
end loop;
commit;
end;
/

set pagesize 100
select object_id from dba_objects where object_name='TST0628_1';
OBJECT_ID
----------
15781

select inst_id,file#,block#,STATUS,objd from gv$bh where objd=15781 and status!='free' order by inst_id,block#;
INST_ID FILE# BLOCK# STATUS OBJD
---------- ---------- ---------- ---------- ----------
1 6 152 xcur 15781
1 6 153 xcur 15781
1 6 154 xcur 15781
1 6 155 xcur 15781
1 6 156 xcur 15781
1 6 157 xcur 15781
1 6 158 xcur 15781
1 6 159 xcur 15781
1 6 160 xcur 15781
1 6 161 xcur 15781
1 6 162 xcur 15781
1 6 163 xcur 15781
1 6 164 xcur 15781
1 6 165 xcur 15781
1 6 166 xcur 15781
1 6 167 xcur 15781
1 6 168 xcur 15781
1 6 169 xcur 15781
1 6 170 xcur 15781
1 6 171 xcur 15781
1 6 172 xcur 15781
1 6 173 xcur 15781
1 6 174 xcur 15781
1 6 175 xcur 15781

select rowid from scott.tst0628_1;
ROWID
------------------
AAAD2lAAGAAAACbAAA
AAAD2lAAGAAAACcAAA
AAAD2lAAGAAAACdAAA
AAAD2lAAGAAAACeAAA
AAAD2lAAGAAAACfAAA
AAAD2lAAGAAAACgAAA
AAAD2lAAGAAAAChAAA
AAAD2lAAGAAAACiAAA
AAAD2lAAGAAAACjAAA
AAAD2lAAGAAAACkAAA
AAAD2lAAGAAAAClAAA
AAAD2lAAGAAAACmAAA
AAAD2lAAGAAAACnAAA
AAAD2lAAGAAAACpAAA
AAAD2lAAGAAAACqAAA
AAAD2lAAGAAAACrAAA
AAAD2lAAGAAAACsAAA
AAAD2lAAGAAAACtAAA
AAAD2lAAGAAAACuAAA
AAAD2lAAGAAAACvAAA

--session 1 node 2: 開啟10046
select value from v$diag_info where name='Default Trace File';
/oracle/app/oracle/diag/rdbms/susedb1/susedb12/trace/susedb12_ora_7114.trc

alter session set optimizer_dynamic_sampling=0;

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

--session 2 node 2 : 統計session 1 node 2 (sid=452)的初始等待事件值
@/home/oracle/sess_1st.sql 2 16

--session 1 node 2:
select * from scott.tst0628_1 where rowid in ('AAAD2lAAGAAAACbAAA','AAAD2lAAGAAAACcAAA');

--session 2 node 2：統計出sid=452的最終等待事件次數
@/home/oracle/sess_2nd.sql 2 16
SID EVENT DIFF_WAITS
---------- ------------------------------ ----------
16 Disk file operations I/O 0
16 SQL*Net break/reset to client 2
16 SQL*Net message to client 12
16 SQL*Net more data to client 6
16 db file sequential read 0
16 events in waitclass Other 0
16 gc cr block 2-way 4 <--其中三次與scott.tst0628_1表裡的塊有關6/154(segment header)、6/155(AAAD2lAAGAAAACbAAA)、6/156(AAAD2lAAGAAAACcAAA)，
16 gc cr grant 2-way 0
16 gc cr multi block request 0
16 gc current block 2-way 2 <--沒有與scott.tst0628_1相關的表
16 gc current block congested 0
16 library cache lock 1
16 library cache pin 1
16 row cache lock 6

--session 1 node 2：關閉10046
alter session set events '10046 trace name context off';

觀察TraceFile:susedb12_ora_7114.trc裡能發現以下段落
WAIT #139749596070128: nam='gc cr block 2-way' ela= 716 p1=6 p2=154 p3=4 obj#=15781 tim=1467290171765964
WAIT #139749596070128: nam='gc cr block 2-way' ela= 611 p1=6 p2=155 p3=1 obj#=15781 tim=1467290171771829
WAIT #139749596070128: nam='gc cr block 2-way' ela= 811 p1=6 p2=156 p3=1 obj#=15781 tim=1467290171773509

set pagesize 100
select inst_id,file#,block#,STATUS,objd from gv$bh where objd=15781 and status!='free' order by inst_id,block#; <---注意這時的buffer型別
INST_ID FILE# BLOCK# STATUS OBJD
---------- ---------- ---------- ---------- ----------
1 6 152 xcur 15781
1 6 153 xcur 15781
1 6 154 scur 15781
1 6 155 scur 15781
1 6 156 scur 15781
1 6 157 xcur 15781
1 6 158 xcur 15781
1 6 159 xcur 15781
1 6 160 xcur 15781
1 6 161 xcur 15781
1 6 162 xcur 15781
1 6 163 xcur 15781
1 6 164 xcur 15781
1 6 165 xcur 15781
1 6 166 xcur 15781
1 6 167 xcur 15781
1 6 168 xcur 15781
1 6 169 xcur 15781
1 6 170 xcur 15781
1 6 171 xcur 15781
1 6 172 xcur 15781
1 6 173 xcur 15781
1 6 174 xcur 15781
1 6 175 xcur 15781
2 6 154 cr 15781 <---6/154 新增型別為cr的buffer,segment header
2 6 155 cr 15781 <---6/155 新增型別為cr的buffer
2 6 156 cr 15781 <---6/156 新增型別為cr的buffer

可以看到雖然node 1在往tst0628_1表insert了記錄且已經提交，但node 2 讀到的還是cr 型別的block，所以觸發的是"gc cr block 2-way"

值得一提的是不管是gc cr block 2-way還是gc current block 2-way，它們的出現並不意味著RAC的效能出現了問題，可以認為這是訊息類的等待事件，僅僅表示兩節點間存在block的傳輸，但如果在AWR裡發現這兩種等待事件平均耗時較長(>10ms)，就可以認為網路上存在瓶頸，需要聯絡網路管理員介入處理

////////////////////////////
//gc cr/current block busy事件
////////////////////////////
事件描述：
gc current block busy
node 1正在更新block A的時候node 2也發起了對block A的更新，這時node 2在等待接收node 1上的LMS程式構造出block A在node 2發起更新時刻的block映像，node 2在接收到block A映像之前，就會處於gc current block busy狀態

gc cr block busy
當node 1正在更新block A的時候，node 2發起了對block A的查詢，這時node 2在等待接收node 1上的LMS程式構造出block A在node 2發起查詢時刻的block映像，node 2在接收到block A映像之前，就會處於gc cr block busy狀態

模擬gc current block busy、gc cr block busy：
---session 1 node 1
select id,col2,dbms_rowid.rowid_block_number(rowid) from scott.t0820_1;
ID C DBMS_ROWID.ROWID_BLOCK_NUMBER(ROWID)
---------- - ------------------------------------
2.28795961 A 253
2.35719885 B 253

select sid,serial# from v$session where sid=sys_context('userenv','sid');
SID SERIAL#
---------- ----------
17 57

select value from v$diag_info where name='Default Trace File';
/oracle/app/oracle/diag/rdbms/susedb1/susedb11/trace/susedb11_ora_18905.trc

---session 1 node 2
select sid,serial# from v$session where sid=sys_context('userenv','sid');
SID SERIAL#
---------- ----------
17 81

select value from v$diag_info where name='Default Trace File';
/oracle/app/oracle/diag/rdbms/susedb1/susedb12/trace/susedb12_ora_15878.trc

---session 2 node 1
@sess_1st_4p.sql 1 17 2 17

exec dbms_monitor.session_trace_enable(17,57);

---session 2 node 2
exec dbms_monitor.session_trace_enable(17,81);

---session 1 node 1
set timing on
declare
i number:=0;
begin
while ( i < 10000 )
loop
update scott.t0820_1 set id=dbms_random.value(0,10) where col2='A';
commit;
i:=i+1;
end loop;
end;
/

---session 1 node 2
set timing on
declare
i number:=0;
begin
while ( i < 10000 )
loop
update scott.t0820_1 set id=dbms_random.value(0,10) where col2='B';
commit;
i:=i+1;
end loop;
end;
/

---session 2 node 1
@sess_2nd_4p.sql 1 17 2 17

INST_ID SID EVENT DIFF_WAITS
---------- ---------- ------------------------------ ----------
1 17 Disk file operations I/O 2
2 17 Disk file operations I/O 3
1 17 SQL*Net break/reset to client 0
1 17 SQL*Net message from client 5
2 17 SQL*Net message from client 5
1 17 SQL*Net message to client 5
2 17 SQL*Net message to client 5
2 17 enq: TM - contention 1
1 17 events in waitclass Other 2
2 17 events in waitclass Other 9
1 17 gc buffer busy release 4522
2 17 gc buffer busy release 2932
1 17 gc cr block 2-way 2748
2 17 gc cr block 2-way 3179
1 17 gc cr block busy 144
2 17 gc cr block busy 1045
1 17 gc cr block congested 58
2 17 gc cr block congested 56
1 17 gc cr failure 2
2 17 gc cr multi block request 1
1 17 gc current block 2-way 9
2 17 gc current block 2-way 42
1 17 gc current block busy 4680
2 17 gc current block busy 4686
1 17 gc current block congested 1
2 17 gc current block congested 1
1 17 latch: cache buffers chains 60
2 17 latch: cache buffers chains 110
2 17 latch: shared pool 1
1 17 library cache lock 0
2 17 library cache lock 1
1 17 library cache pin 0
2 17 library cache pin 1
1 17 log file sync 1
2 17 log file sync 1
2 17 resmgr:cpu quantum 1
2 17 row cache lock 193

exec dbms_monitor.session_trace_disable(17,57);

---session 2 node 2
exec dbms_monitor.session_trace_disable(17,81);

node 1、node 2的trcfile內容比較相似，僅摘錄了node 1的trcfile：susedb11_ora_18905的片段進行分析：
沒有gc等待的trace取樣：
EXEC #139646861365968:c=0,e=78,p=0,cr=0,cu=1,mis=0,r=0,dep=1,og=0,plh=0,tim=1474783113862791
CLOSE #139646861365968:c=0,e=4,dep=1,type=3,tim=1474783113862842
EXEC #139646864444920:c=0,e=425,p=0,cr=7,cu=3,mis=0,r=1,dep=1,og=1,plh=2096051787,tim=1474783113863291
CLOSE #139646864444920:c=0,e=73,dep=1,type=3,tim=1474783113863529
XCTEND rlbk=0, rd_only=0, tim=1474783113863573

有gc等待的trace取樣片段1
EXEC #139646861365968:c=0,e=196,p=0,cr=0,cu=1,mis=0,r=0,dep=1,og=0,plh=0,tim=1474783114286635
CLOSE #139646861365968:c=0,e=7,dep=1,type=3,tim=1474783114286722
WAIT #139646864444920: nam='gc cr block 2-way' ela= 444 p1=4 p2=208 p3=47 obj#=0 tim=1474783114287931
WAIT #139646864444920: nam='gc buffer busy release' ela= 439 file#=6 block#=253 class#=1 obj#=15976 tim=1474783114288553
WAIT #139646864444920: nam='gc current block busy' ela= 34279 p1=6 p2=253 p3=33554433 obj#=15976 tim=1474783114322972
WAIT #139646864444920: nam='gc buffer busy release' ela= 1727 file#=6 block#=253 class#=1 obj#=15976 tim=1474783114325229
WAIT #139646864444920: nam='gc current block busy' ela= 2608 p1=6 p2=253 p3=33554433 obj#=15976 tim=1474783114328053
EXEC #139646864444920:c=4000,e=41550,p=0,cr=9,cu=3,mis=0,r=1,dep=1,og=1,plh=2096051787,tim=1474783114328300
CLOSE #139646864444920:c=0,e=5,dep=1,type=3,tim=1474783114328438
XCTEND rlbk=0, rd_only=0, tim=1474783114328560

有gc等待的trace取樣片段2
EXEC #139646861365968:c=0,e=525,p=0,cr=0,cu=1,mis=0,r=0,dep=1,og=0,plh=0,tim=1474783114628065
CLOSE #139646861365968:c=0,e=15,dep=1,type=3,tim=1474783114628356
WAIT #139646864444920: nam='gc cr block 2-way' ela= 16928 p1=4 p2=272 p3=55 obj#=0 tim=1474783114646861
WAIT #139646864444920: nam='gc cr block busy' ela= 10248 p1=4 p2=12133 p3=56 obj#=0 tim=1474783114657967
WAIT #139646864444920: nam='gc current block busy' ela= 14530 p1=6 p2=253 p3=33554433 obj#=15976 tim=1474783114674653
WAIT #139646864444920: nam='gc buffer busy release' ela= 6202 file#=6 block#=253 class#=1 obj#=15976 tim=1474783114683424
WAIT #139646864444920: nam='gc current block busy' ela= 17825 p1=6 p2=253 p3=33554433 obj#=15976 tim=1474783114701812
EXEC #139646864444920:c=8000,e=74095,p=0,cr=9,cu=3,mis=0,r=1,dep=1,og=1,plh=2096051787,tim=1474783114702583
CLOSE #139646864444920:c=0,e=20,dep=1,type=3,tim=1474783114703614
XCTEND rlbk=0, rd_only=0, tim=1474783114703784

等待事件次數統計裡以gc current block busy、gc cr block busy、gc cr block 2-way、gc buffer busy release四類事件居多
(1) gc current block busy
該事件集中發生在data block 6/253上，node 1、node 2同時在以很高的頻率update block 6/253裡的兩條不同記錄，當node 1 update時發現node 2已在GRD裡給6/253上了獨佔鎖，此時node 1就必須等待node 2上的LMS程式構造出6/253的映像，所以node 1會一直等在gc current block busy事件上直至接收到從node 2傳過來的block映像

(2) gc cr block busy
node 1的144次gc cr block busy等待裡，有128次發生在了undo segment header或者undo block上，在RAC的機制裡為了防止遠端節點的LMS過度忙於構造一致讀的block，有時會將構造的工作交由請求節點的foreground process完成，具體來講node 1因為一致讀的需要其foreground process在構造6/253某一時刻映像的過程中需要讀取node 2曾經使用過的undo segment header或者undo block，而恰好這時node 2也在更新同一個undo segment header或者undo block，node 1就有可能遇到gc cr block busy等待，v$cr_block_server.LIGHT_WORKS用來計數有多少次塊構造是由foreground process來完成的；還有16次發生在了data block 6/253上，這種情形是由node 2的LMS程式而不是node 1的foreground process來構造一致讀塊。

(3) gc buffer busy release
集中發生在6/253這個block上。node 1嘗試修改本地buffer cache中的block時，發現node 2已經在修改該block，並且該修改尚未完成，這時node 1就會出現gc buffer busy release等待。gc buffer busy release往往是被其它的等待事件觸發的，比如gc cr block busy，其自身並非問題的根源

(4) gc cr block 2-way
集中發生在undo segment header或者undo block上，node 1上foreground process在構造6/253一致性讀映像的過程中需要從node 2節點獲取undo segment header裡的事務槽資訊，gc cr block 2-way僅表示本地與遠端節點有過塊傳輸，並不意味著例項間存在block的爭用。

那些你眼熟的global cache等待事件是如何被觸發的(一)

相關文章