你好,游客 登录 注册 搜索
背景:
阅读新闻

分析解决11gR2 双节点RAC环境下的gc cr block busy/gc buffer busy acquire等待

[日期:2016-06-26] 来源:Linux社区  作者:oliseh [字体: ]

?  系统环境

两节点的RACAIX6.1+Oracle 11.2.0.3.3  

?  AWR里展示出来的各种症状(数据来自实例2

虽然应用没有报障,但AWR报告里的各种迹象已经很明显了

(1)    gc buffer busy acquire排进了Top 5 Timed Foreground Events

-1

 

(2)    除去DB CPUgc buffer busy acquire之后的就是gc cr block busy

-2

 

 

(3)    2h21bq1mnc5kd这条sql的耗时里85%的时间都在等待集群有关的事件,且领先第二条太多了

-3

 

 

2h21bq1mnc5kd对应的完整SQL是:select t.* from SD.SYS_PARAMETER t where t.PARAM_CLASS in (:1 , :2 )

且从语句的执行频次来看1小时内(AWR的采样间隔是1小时)执行了260790次,约合72/秒,并发度还是非常高的

(4)    % of Capture=89.46表示在系统里每发生100次的gc buffer busy等待就有89次来自于对象SD.SYS_PARAMETER,该值同样遥遥领先第二条

-4

 

 

(5)    CR Blocks Received的比例达到了43%,为实现一致性读,SD.SYS_PARAMETER表上存在大量的跨节点传输

-5

 

 

(6)    最后看下从v$active_session_history获取的2h21bq1mnc5kd这条sqlgc事件,每秒钟都有等待产生,争用的焦点在93号数据文件的65696block

      select to_char(sample_time,'yyyymmdd hh24:mi:ss'),event,p1,p2,count(1) from gv$active_session_history where sql_id='2h21bq1mnc5kd' and event in ('gc cr block busy','gc buffer busy acquire') and inst_id=2 group by to_char(sample_time,'yyyymmdd hh24:mi:ss'),event,p1,p2;

-5-1

 

 

        虽然应用没有变慢,但上述种种迹象已经引起了我的关注,做运维不就是要防患于未然么。根据AWR采样到的结果,初步结论如下:

gc buffer busy acquiregc cr block busy这两个gc wait eventselect t.* from SD.SYS_PARAMETER t where t.PARAM_CLASS in (:1 , :2 )这条SQL有较大关系,该条SQL执行时存在大量的跨节点读,以实现一致性读。

(注:上述AWR数据都来自实例2,实例1AWR报告未现任何异常情况) 

?  了解gc buffer busy acquiregc cr block busy 

   以最简单的双节点RAC为例,当实例1发起一条select查询某个block的时候,如果这个block不在本地的Buffer cache,但是能在实例2buffer cache里找到,那么实例1LMS进程会通过私网将这个block从实例2cache获取到实例1cache,以避免physical reads,获取过程中会出现gc cr block 2-way相关的等待事件,这就是cache fusion的基本功能,之后如果这个block没有被任何一个实例更改,那么实例1与实例2访问这个block就只需从本地的buffer cache读取(假设buffer cache足够大,block未被flushbuffer cache),本地读取的情况下不会发生与gc相关的等待事件,对于同一个block只需跨节点传输一次,这是一种比较理想的情况。跨节点读取除了这种以读为主的情况外,还常见于以下场景:

   实例1和实例2buffer cache都含有这个blockT1时刻实例1修改了这个blockT2时刻实例2的会话读取这个block时就会从实例1buffer cache里读过来,过程中实例2会话统计里就会观察到gc cr block busy相关的等待事件。

gc buffer busy acquire

       沿用上面例子:实例1和实例2buffer cache都含有某个blockT1时刻实例1修改了这个blockT2时刻实例2上的会话1读取这个block,当这个读取还没有完成,实例2上的会话2也发起了读取相同block的操作,这时会话2就会等在gc buffer busy acquire上。实例2同时发起的读取相同block的会话数越多,我们就越容易观察到gc buffer busy acquire等待。   

gc cr block busy

   仍沿用上面例子:实例1和实例2buffer cache都含有某个blockT1时刻实例1修改了这个blockT2时刻实例2上的会话1读取这个block修改前的CR copy,因为CR copy需要通过应用undo record才能构造出来,且构造的过程中必须将改变记入到实例1online redo,因此实例2会话1读取的时候在可能会因为如下原因而发生gc cr block busy等待:

CR copy在实例1上构造过慢或者记入online redo过慢 

?  gc buffer busy acquiregc cr block busy有何联系

v$active_session_history里取出某一时刻select t.* from SD.SYS_PARAMETER t where t.PARAM_CLASS in (:1 , :2 )语句【sql_id=2h21bq1mnc5kd】的等待,

col sample_time format a30

col sql_opname format a10

col event format a30

set linesize 150

select t.session_id,t.sample_time,event,p1,p2,blocking_session,xid,sql_opname,in_parse,in_sql_execution from gv$active_session_history t where sample_id=111712902and sql_id='2h21bq1mnc5kd' and inst_id=2;

 

6

 

 

可以看出在10:03:34.682这个时刻存在以下两条session等待链:

17203(gc cr block busy)>15808(gc buffer busy acquire)>20203(gc buffer busy acquire)

17203(gc cr block busy)>12608(gc buffer busy acquire)

 

之后又看了其它时刻的采样结果(篇幅关系,不一一列出),基本都是这个情况,因此判断是gc cr block busy进一步导致了gc buffer busy acquire,某

一时刻对于同一个data block而言只会有一个会话等在gc cr block busy事件上,其它会话都在等gc buffer busy acquire。这也可以解释AWR报告里为

gc buffer busy acquire等待次数要远多于gc cr block busy。至此关注重点集中到了gc cr block busy上。

 

?  定位修改源头,模拟gc cr block busy等待

gc cr block busy事件的定义上来看,实例2上的会话在执行select t.* from SD.SYS_PARAMETER t where t.PARAM_CLASS in (:1 , :2 )语句时之所以会遇到

gc cr block busy等待,肯定是实例1上的会话对SD.SYS_PARAMETER表进行了DML操作,且这个修改操作涉及的记录主要集中在93号数据文件的65696

block上,但从开发人员处了解到SD.SYS_PARAMETER是一张配置表,平时不会有修改操作,口说无凭, 我们还是使用dbms_fga 包捕获到了针对

SD.SYS_PARAMETER表的修改操作,执行如下语句配置FGA捕获策略:

dbms_fga.add_policy(object_schema=>'SD',object_name=>'SYS_PARAMETER',policy_name=>'SYS_PARAMETER',enable=>TRUE,statement_types=>'INSERT,

UPDATE, DELETE');

 

不出五分钟就有结果了

col timestamp format a30

col sql_text format a70

col userhost format a15

set linesize 180

select timestamp,sql_text,userhost,instance_number  from dba_fga_audit_trail where object_name='SYS_PARAMETER' and timestamp > to_date('20160505

00:00:00','yyyymmdd hh24:mi:ss');

7

 

很有规律的每30update一次,来自于实例1。既然update的频率是30秒一次,select语句遇到的gc cr block busygc buffer busy acquire等待事件

也应该是每隔30秒出现一波,但现实却是分分秒秒都有这两种等待,以下是从v$active_session_history统计出来的信息:

set linesize 170

col sample_time format a40

col event format a40

select sql_id,sample_time,event,count(1) from v$active_session_history where sample_time between to_date('20160505 9:54:09','yyyymmdd hh24:mi:ss')

and to_date('20160505 9:58:38','yyyymmdd hh24:mi:ss') and sql_id='2h21bq1mnc5kd' and event in ('gc cr block busy','gc buffer busy acquire') group by

sql_id,sample_time,event;

8

 

 

为此在同版本的一套测试RAC数据库上进行了一组简单的测试,过程中用到了三个session

testnode 1上的session 1:对测试表进行200W次不间断的select

testnode 1上的session 2:与session 1执行相同的操作,与session 1同时发起

testnode 2上的session 1:在testnode 1的两个session运行过程中以每30秒一次的频度update测试表中的一条记录

testnode 1上的session 3:统计testnode 1 上两会话的等待事件

 

先将要用到的脚本贴出来:

/*+  circle_sel.sql 模拟连续的select行为 *****/

declare

cnt number;

type typ_t0505 is record (username VARCHAR2(30),user_id NUMBER,created DATE);

type lst_t0505 is table of typ_t0505;

v_rec_t0505 lst_t0505;

begin

cnt:=2000000;

while ( cnt> 0 ) loop

select * bulk collect into v_rec_t0505 from poweruser.t0505_1;

cnt:=cnt-1;

end loop;

end;

/

 

/*+  sess_1st.sql  记录会话初始event waits *****/

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  统计会话在两次执行间的event waits差值 *****/

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;

 

测试开始:

---session 1 on testnode 1: 用于执行select

create table poweruser.t0505_1 tablespace TS_AJX_DATATMP as select * from all_users;

 

select distinct dbms_rowid.rowid_relative_fno(rowid),dbms_rowid.rowid_block_number(rowid) from poweruser.t0505_1;  <---确保测试数据都在一个block

DBMS_ROWID.ROWID_RELATIVE_FNO(ROWID) DBMS_ROWID.ROWID_BLOCK_NUMBER(ROWID)

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

103                                19515

 

select s.sid,s.serial# from v$session s,v$process p where s.paddr=p.addr and s.sid=sys_context('userenv','sid');

      SID    SERIAL#

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

      3411      58063

     

---session 2 on testnode 1: 用于执行select

select s.sid,s.serial# from v$session s,v$process p where s.paddr=p.addr and s.sid=sys_context('userenv','sid');

      SID    SERIAL#

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

    13559      3597

   

------session 3 on testnode 1: 执行前的用户会话统计

@sess_1st.sql 1 3411 1 13559

 

---session 1 testnode 1 & session 2 testnode 1 : 同时执行

@circle_sel.sql

 

--- session 1 testnode 2:在testnode1上的两session执行期间每隔30秒执行一次update

Begin

While ( true ) loop

update poweruser.t0505_1 set username=dbms_random.string('u',5) where user_id=0;

commit;

dbms_lock.sleep(30);

end loop;

end;

/

 

------session 3 on testnode 1: 执行后的会话统计

@sess_2nd.sql 1 3411 1 13559

9

 

 

测试结果1

testnode 1上的两个session 分别执行耗时分别为118s120s,统计结果显示与它们同时执行的update语句并没有带来多大影响,gc cr block busy

待事件都在个位数,当然这也可能是因为测试环境里模拟的并发量只有2远小于生产环境里的实际并发数,再仔细想一下,每30update一次,120s

的时间内update最多也就执行4次,也就是说循环select期间的至多遇到4update,从testnode1上的会话统计信息看,gc cr block busy分别为2

3,非常接近于4,所以推测这2次、3次的gr cr block busy等待应该正好发生在每次update过后的第一次select里,从这以后到下一次update运行

前的这段空档期,不会再有gc cr block busy事件发生。而实际在生产环境表现出的症状却是每秒钟都有gc cr block busy等待。

这个显著的差异让我对测试方法稍加调整,把 session 1 testnode 2执行语句改成update后过30秒再commit,调整后的测试过程如下:

---session 1 testnode 1 & session 2 testnode 1 :同时执行

@circle_sel.sql

 

---session 1 node 2

Begin

While ( true ) loop

update poweruser.t0505_1 set username=dbms_random.string('u',5) where user_id=0;

dbms_lock.sleep(30);

commit;

end loop;

end;

/

 

---session 3 node 1: 实时捕捉gc事件的增长情况

select inst_id,sid,event,total_waits from gv$session_event where inst_id=1 and sid in (3411, 13559) and event in ('gc buffer busy acquire','gc cr block busy');

10

 

 

测试结果2

上述相邻查询间隔大概在1秒钟,可以看出gc buffer busy acquiregc cr block busy等待次数快速上升,增长的频率与update的频率(30秒一次)并没

有直接关系。至此测试结果与生产环境中的情况有点接近了,难道在生产环境也存在延时commit的情况?

 

?  找到生产环境里update后没有及时commit的证据

dba_fga_audit_trail视图有一列SQL_BIND会记录语句执行时的绑定变量信息:

col timestamp format a30

col sql_text format a70

col sql_bind format a50

col userhost format a15

set linesize 180

select timestamp,sql_text,sql_bind from dba_fga_audit_trail where object_name='SYS_PARAMETER' and timestamp >

to_date('20160505 00:00:00','yyyymmdd hh24:mi:ss');

11

 

拿上图的第一行来讲在20160505 09:54:08时刻,将绑定变量代入得到完整的update语句是:

update SD.SYS_PARAMETER set PARAM_VALUE ='2016-05-06 09:54:03'  where PARAM_CODE='CA_VCSMS_TIME';

所以最简单的方法就是实时监控dba_fga_audit_trail,每当观察到dba_fga_audit_trail视图新进来一条被审计到的SQL及其对应的绑定变量后,立刻执

select param_value from sd.sys_parameter where param_code='CA_VCSMS_TIME',来观察param_value字段何时变成绑定变量的值,如果一直没有变

化,那就证明没有提交,通过这个方法,我们发现commit操作果然是在update之后的30秒才执行的,准确的说应该是在下一条update开始之前commit

前一条update的修改结果。

 

还有一种能证明延时commit的方法是记录下dba_fga_audit_trail. TRANSACTIONID,然后到v$transaction根据XID查找是否存在对应记录,若能找到就

表明还未提交。

 

顺便也验证一下:parameter_code=’CA_VCSMS_TIME’所在的记录就位于争用最严重的file#:93/block#:65696

select dbms_rowid.rowid_relative_fno(rowid),dbms_rowid.rowid_block_number(rowid),param_code from SD.SYS_PARAMETER where

PARAM_CODE='CA_VCSMS_TIME';

11-1

 

 

?  深入gc cr block busy

 

文章开头处曾经介绍过其成因与blockCR copy在远程实例上的构造过程及写online redo过程有关。展开讲,当实例1和实例2buffer cache都含有某个blockT1时刻实例1修改了这个block,但没有commitT2时刻实例2上的会话1读取这个block,读取的大致过程分解可以分解为以下几个步骤:

1)实例2LMS向实例1LMS发起block 读请求;

       2)实例1buffer cache里已经存在了这个block修改后的最新副本B1’,实例1 LMS在本地的buffer cache里根据B1’再复制出一个新的副本

B1’’,此时B1’B1’’的内容是完全相同的;

3)实例1LMSundo segment里找到undo record用来appliedB1’’上,把B1’’回滚到修改前的状态,记为B1

4)这时实例1buffer cache 里包含了B1’B1,其中B1B1’修改前的内容。

5)利用undo recordB1’’回滚到B1这一过程是会产生redo的,实例1 LMS进程通知Lgwr进程把redo写入online redolog,写成功后才能

进入下一步

6)实例1上的Lgwr通知实例1上的LMS redo写入完成,实例1上的LMSB1传输给实例2LMS

7)实例2LMS将结果返回给实例2上的会话1server process

 

我们通过如下的简单测试可以大致观察到这个过程,还是在同版本的测试RAC环境下进行:

---session 1 testnode 2:执行update但不提交

select s.sid,s.serial# from v$session s,v$process p where s.paddr=p.addr and s.sid=sys_context('userenv','sid');

      SID    SERIAL#

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

      7338      3253

 

update poweruser.t0505_1 set username=dbms_random.string('u',5) where user_id=0;

 

1 row updated.

 

select t.xid,t.status,t.USED_UREC,s.sql_id,s.sid,s.serial# from v$transaction t,v$session s where t.ses_addr=s.saddr and s.sid=sys_context('userenv','sid');

12

 

 

---session 2 testnode 2: 记录testnode 2LMS进程的初始统计值

set linesize 150 pagesize 100

select s.sid,n.name,s.value from v$statname n,v$sesstat s where n.statistic#=s.statistic# and s.sid in (select sid from v$session where program like '%LMS%')

and n.name in ('data blocks consistent reads - undo records applied','redo size','redo entries','CR blocks created') order by sid,name;

13

 

 

---session 1 testnode 1select测试表

select * from poweruser.t0505_1;

 

---session 2 testnode 2: 检查testnode 2LMS进程的最新统计值

select s.sid,n.name,s.value from v$statname n,v$sesstat s where n.statistic#=s.statistic# and s.sid in (select sid from v$session where program like '%LMS%')

and n.name in ('data blocks consistent reads - undo records applied','redo size','redo entries','CR blocks created') order by sid,name;

14

 

计算差值: 一个RAC节点上有多个LMS进程以负载均衡的方式被使用,本测试中正好是7897这个sid对应的LMS进程被使用到

与前一次查询结果相比:

CR blocks created1098103->1098104,增加了1  <--- 因为poweruser.t0505_1表里只有一个块是有数据的

data blocks consistent reads - undo records applied11662578->11662580,增加了2  <--- v$transaction.used_urec值对应

redo entries1058951->1058955,增加了4

redo size111107920->111108232,增加了312

 

---session 1 testnode 1;再次select测试表

select * from poweruser.t0505_1;

 

---session 2 testnode 2: 检查testnode 2LMS进程的最新统计值

select s.sid,n.name,s.value from v$statname n,v$sesstat s where n.statistic#=s.statistic# and s.sid in (select sid from v$session where program like '%LMS%')

and n.name in ('data blocks consistent reads - undo records applied','redo size','redo entries','CR blocks created') order by sid,name;

15

 

计算差值:

CR blocks created:增加了1  <--- 因为poweruser.t0505_1表里只有一个块是有数据的

data blocks consistent reads - undo records applied:增加了2  <--- v$transaction.used_urec值对应

redo entries:增加了1

redo size:增加了64

 

由此可以看出若远程节点修改某个block后未提交,那么本地节点去select远程节点上的这个block时每次都会引发CR块构造(CR blocks created)

undo record(data blocks consistent reads - undo records applied)、生成redo(redo entries& redo size )等一系列动作,查询未提交的block开销还是比较

大的,主要体现在远程节点LMSLGWR进程的cpu使用率上升(之后会有详细说明),读取undo block与写入online redo时的IO量增大。尤其是在本

地节点高并发select 的时候这一开销会无限放大。

 

?  本地节点select远程节点cache里未提交的数据块开销到底有多大

 

还是由实验数据来说话:

(1)    远程节点修改后及时提交,本地节点两个session并发select同一张表

 

---session 1 on testnode2:执行对于测试表的修改并提交

update poweruser.t0505_1 set username=dbms_random.string('u',5) where user_id=0;

commit;

 

---session 3 on testnode1:记录会话统计初始值

@sess_1st.sql 1 14678 1 15251

 

---session 1 on testnode1 & session 2 on testnode1: 同时执行

Set timing on

@circle_sel1.sql  <---circle_sel1.sql和之前circle_sel.sql的区别在于执行次数从200W下调至30W,仅为了节省等待时间,更快得出结论

 

session 1 on testnode1的执行耗时:17.99s

session 2 on testnode1的执行耗时:17.72s

 

---session 3 on testnode1:输出会话统计值(仅列出与gc相关的等待)

@sess_2nd.sql 1 14678 1 15251

16

 

 

(2)    远程节点修改后未提交,本地节点两个session并发select同一张��

 

---session 1 on testnode2:修改测试表但不提交

update poweruser.t0505_1 set username=dbms_random.string('u',5) where user_id=0;

 

---session 3 on testnode1:记录会话统计初始值

@sess_1st.sql 1 14678 1 15251

 

---session 1 on testnode1 & session 2 on testnode1: 同时执行

Set timing on

@circle_sel1.sql

 

session 1 on testnode1的执行耗时:485.89s

session 2 on testnode1的执行耗时:485.91s

 

---session 3 on testnode1:输出会话统计值(仅列出与gc相关的等待)

@sess_2nd.sql 1 14678 1 15251

17

 

 

testnode1节点select执行期间testnode2上的LMSLGWR进程的cpu使用率

18

 

其中8585392LGWR5571040LMS

ps -ef|grep -E "lms|lgwr" | grep -vE "asm|grep"

  oracle  2949308        1  1  Apr 19      - 56:08 ora_lms0_shajx2

  oracle  6094878        1  0  Apr 19      - 53:54 ora_lms2_shajx2

  oracle  8585392        1  0  Apr 19      - 15:11 ora_lgwr_shajx2

  oracle  5571040        1  0  Apr 19      - 46:06 ora_lms1_shajx2

 

(3)    扩展一下,本地节点两个session并发select不同的两张表

---session 1 on testnode2:分别修改两张测试表,都不提交

update poweruser.t0505_1 set username=dbms_random.string('u',5) where user_id=0;

update poweruser.t0506 set username=dbms_random.string('u',5) where user_id=0;

 

---session 3 on testnode1:记录会话统计初始值

@sess_1st.sql 1 14678 1 15251

 

---session 1 on testnode130Wselectt0505_1

@circle_sel1.sql

 

---session 2 on testnode130Wselectt0506

@circle_sel2.sql

 

session 1 on testnode1的执行耗时:501.94s

session 2 on testnode1的执行耗时:482.88s

 

---session 3 on testnode1:输出会话统计值(仅列出与gc相关的等待)

@sess_2nd.sql 1 14678 1 15251

19

 

 

测试结论:

对于(1)(2)两个场景可以看出远程节点修改后未提交的场景下测出的select时长为485s远远大于提交情况下的17s,且后一种场景下远程节点的LMS

LGWR进程分别占用了1.9%2.5%cpu资源,对于32 cores的主机来说这两个进程占去了约1.5 cores,况且现在仅仅是两个并发的情况。

对于(3)场景而言,Select两张不同的表,仍然出现了各30W次的gc cr block busy等待,且耗时与(2)场景差不多。可见是否select相同的表不重要,

关键在于远程节点的构造cr block->flush redo这个过程是相当耗时的

 

?  优化举措

短期考虑:

1)  修改后及时提交,且修改的操作尽量与select操作放在同一个节点

2)  鉴于sd.sys_parameter是一张配置表,配置表里的记录应该保持相对稳定,所以将update的动作挪至新建的一张表进行

   长远考虑:

       3)把sd.sys_parameter放到App缓存里,避免过于频繁从数据库里进行select

 

当前已经完成上述第1项优化,效果明显

 

?  这个案例告诉我们

 

       Cache Fusion是一把双刃剑,虽然能以节点间的通信来避免更多的物理读,但我们也要避免节点间某些不合理的通信行为,比如对于同一个block的读和写分别在两个节点进行,本文的案例和测试使我们认识到block跨节点传输所产生的开销是如此之大。对于应用设计者而言应该认识到修改后不及时的提交在单节点环境下可能最多会引起row lock,但在多节点RAC环境下,在节点间存在大量通信的场景下,会对性能产生不可估量的影响。

 更多Oracle相关信息见Oracle 专题页面 http://www.linuxidc.com/topicnews.aspx?tid=12

本文永久更新链接地址http://www.linuxidc.com/Linux/2016-06/132674.htm

linux
相关资讯       RAC环境  11gR2 双节点 
本文评论   查看全部评论 (0)
表情: 表情 姓名: 字数

       

评论声明
  • 尊重网上道德,遵守中华人民共和国的各项有关法律法规
  • 承担一切因您的行为而直接或间接导致的民事或刑事法律责任
  • 本站管理人员有权保留或删除其管辖留言中的任意内容
  • 本站有权在网站内转载或引用您的评论
  • 参与本评论即表明您已经阅读并接受上述条款