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

2023-12-12 22:57:46

如果用过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的争用。

码农公寓

相关文章