gc buffer busy acquire等待

？ 系统环境两节点的RAC：AIX6.1+Oracle 11.2.0.3.3 ？ AWR里展示出来的各种症状（数据来自实例2）虽然应用没有报障，但AWR报告里的各种迹象已经很明显了（1） gc buffer busy acquire排进了Top 5 Timed Foreground Events图-1 （2）除去DB CPU在gc 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这条sql的gc事件，每秒钟都有等待产生，争用的焦点在93号数据文件的65696号block上 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 acquire、gc cr block busy这两个gc wait event与select t.* from SD.SYS_PARAMETER t where t.PARAM_CLASS in （:1 , :2 ）这条SQL有较大关系，该条SQL执行时存在大量的跨节点读，以实现一致性读。（注：上述AWR数据都来自实例2，实例1的AWR报告未现任何异常情况）？了解gc buffer busy acquire和gc cr block busy 以最简单的双节点RAC为例，当实例1发起一条select查询某个block的时候，如果这个block不在本地的Buffer cache，但是能在实例2的buffer cache里找到，那么实例1的LMS进程会通过私网将这个block从实例2的cache获取到实例1的cache，以避免physical reads，获取过程中会出现gc cr block 2-way相关的等待事件，这就是cache fusion的基本功能，之后如果这个block没有被任何一个实例更改，那么实例1与实例2访问这个block就只需从本地的buffer cache读取（假设buffer cache足够大，block未被flush出buffer cache），本地读取的情况下不会发生与gc相关的等待事件，对于同一个block只需跨节点传输一次，这是一种比较理想的情况。跨节点读取除了这种以读为主的情况外，还常见于以下场景：实例1和实例2的buffer cache都含有这个block，T1时刻实例1修改了这个block，T2时刻实例2的会话读取这个block时就会从实例1的buffer cache里读过来，过程中实例2会话统计里就会观察到gc cr block busy相关的等待事件。—gc buffer busy acquire 沿用上面例子：实例1和实例2的buffer cache都含有某个block，T1时刻实例1修改了这个block，T2时刻实例2上的会话1读取这个block，当这个读取还没有完成，实例2上的会话2也发起了读取相同block的操作，这时会话2就会等在gc buffer busy acquire上。实例2同时发起的读取相同block的会话数越多，我们就越容易观察到gc buffer busy acquire等待。 —gc cr block busy 仍沿用上面例子：实例1和实例2的buffer cache都含有某个block，T1时刻实例1修改了这个block；T2时刻实例2上的会话1读取这个block修改前的CR copy，因为CR copy需要通过应用undo record才能构造出来，且构造的过程中必须将改变记入到实例1的online redo，因此实例2会话1读取的时候在可能会因为如下原因而发生gc cr block busy等待：CR copy在实例1上构造过慢或者记入online redo过慢？ gc buffer busy acquire与gc 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 a30col sql_opname format a10col event format a30set linesize 150select 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 a30col sql_text format a70col userhost format a15set linesize 180select 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 很有规律的每30秒update一次，来自于实例1。既然update的频率是30秒一次，select语句遇到的gc cr block busy、gc buffer busy acquire等待事件也应该是每隔30秒出现一波，但现实却是分分秒秒都有这两种等待，以下是从v$active_session_history统计出来的信息：set linesize 170col sample_time format a40col event format a40select 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次不间断的selecttestnode 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行为 *****/declarecnt 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;begincnt:=2000000;while （ cnt> 0 ） loopselect * bulk collect into v_rec_t0505 from poweruser.t0505_1;cnt:=cnt-1;end loop;end;/ /*+ sess_1st.sql 记录会话初始event waits *****/define v_inst1=&1define v_inst2=&3define v_sid1=&2define v_sid2=&4drop 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=&1define v_inst2=&3define v_sid1=&2define v_sid2=&4drop 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 a30set linesize 120 pagesize 60select 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: 用于执行selectcreate 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: 用于执行selectselect 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秒执行一次updateBeginWhile （ true ） loopupdate 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 分别执行耗时分别为118s、120s，统计结果显示与它们同时执行的update语句并没有带来多大影响，gc cr block busy等待事件都在个位数，当然这也可能是因为测试环境里模拟的并发量只有2远小于生产环境里的实际并发数，再仔细想一下，每30秒update一次，120s的时间内update最多也就执行4次，也就是说循环select期间的至多遇到4次update，从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：BeginWhile （ true ） loopupdate 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 acquire，gc cr block busy等待次数快速上升，增长的频率与update的频率（30秒一次）并没有直接关系。至此测试结果与生产环境中的情况有点接近了，难道在生产环境也存在延时commit的情况？？ 找到生产环境里update后没有及时commit的证据dba_fga_audit_trail视图有一列SQL_BIND会记录语句执行时的绑定变量信息：col timestamp format a30col sql_text format a70col sql_bind format a50col userhost format a15set linesize 180select 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 文章开头处曾经介绍过其成因与block的CR copy在远程实例上的构造过程及写online redo过程有关。展开讲，当实例1和实例2的buffer cache都含有某个block，T1时刻实例1修改了这个block，但没有commit；T2时刻实例2上的会话1读取这个block，读取的大致过程分解可以分解为以下几个步骤：1）实例2的LMS向实例1的LMS发起block 读请求； 2）实例1的buffer cache里已经存在了这个block修改后的最新副本B1’，实例1的 LMS在本地的buffer cache里根据B1’再复制出一个新的副本B1’’，此时B1’和B1’’的内容是完全相同的；3）实例1的LMS从undo segment里找到undo record用来applied到B1’’上，把B1’’回滚到修改前的状态，记为B1；4）这时实例1的buffer cache 里包含了B1’，B1，其中B1是B1’修改前的内容。5）利用undo record将B1’’回滚到B1这一过程是会产生redo的，实例1 的LMS进程通知Lgwr进程把redo写入online redolog，写成功后才能进入下一步6）实例1上的Lgwr通知实例1上的LMS redo写入完成，实例1上的LMS将B1传输给实例2的LMS7）实例2的LMS将结果返回给实例2上的会话1的server 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 2上LMS进程的初始统计值set linesize 150 pagesize 100select 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 1；select测试表select * from poweruser.t0505_1; ---session 2 testnode 2: 检查testnode 2上LMS进程的最新统计值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 created：1098103->1098104，增加了1 <--- 因为poweruser.t0505_1表里只有一个块是有数据的data blocks consistent reads - undo records applied：11662578->11662580，增加了2 <--- 与v$transaction.used_urec值对应redo entries：1058951->1058955，增加了4redo size：111107920->111108232，增加了312 ---session 1 testnode 1；再次select测试表select * from poweruser.t0505_1; ---session 2 testnode 2: 检查testnode 2上LMS进程的最新统计值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：增加了1redo size：增加了64 由此可以看出若远程节点修改某个block后未提交，那么本地节点去select远程节点上的这个block时每次都会引发CR块构造（CR blocks created）、应用undo record（data blocks consistent reads - undo records applied）、生成redo（redo entries& redo size ）等一系列动作，查询未提交的block开销还是比较大的，主要体现在远程节点LMS、LGWR进程的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.99ssession 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.89ssession 2 on testnode1的执行耗时：485.91s ---session 3 on testnode1：输出会话统计值（仅列出与gc相关的等待）@sess_2nd.sql 1 14678 1 15251图17 附testnode1节点select执行期间testnode2上的LMS、LGWR进程的cpu使用率图18 其中8585392是LGWR、5571040是LMSps -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 testnode1：30W次select表t0505_1@circle_sel1.sql ---session 2 on testnode1：30W次select表t0506@circle_sel2.sql session 1 on testnode1的执行耗时：501.94ssession 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本文永久更新链接地址