性能文章>Oracle实战优化!一次gc buffer busy acquire诊断>

Oracle实战优化!一次gc buffer busy acquire诊断转载

157203
本案例来自某客户两节点rac的一次生产故障,现象是大面积的gc buffer busy acquire导致业务瘫痪。

首先查看1节点AWR头部信息和load profile:

1节点AWR

得到的关键信息点:

  • 对于LCPU 256的系统,AAS=13379.42/59.91=223,说明系统非常繁忙或者遇到了异常等待。

  • sessions异常增长好几倍,DB CPU/DB Time占比非常低,说明是遇到了异常等待。

  • 其余指标都还算正常。

既然是遇到异常等待,那么就看看top event部分:

1节点AWR

可以看到大量的wait class为Cluster的session,top event也看到大量的gc buffer busy acquire等待事件,该等待事件非常常见就不单独解释了,粗略计算cluster等待事件占据了dbtime的90%左右。

当遇到大量Cluster 等待事件的时候,必须先看看RAC Statistics:

1节点AWR

可以看到每秒传输的block以及message都不多,流量也并不大,所以完全没有必要去查看SQL ordered by Cluster Wait Time部分,继续往下看发现Avg global cache cr block receive time (ms)过高,达到了1473ms。判断此次大量的cluster等待是由于接受远端实例发送cr block过慢导致。

gc cr block receive time =  gc cr block (flush time + build time + send time)

从公式可以看出是远端实例的 gc cr block flush time /build time/send time出现了问题,所以此时需要去看看2节点AWR的RAC Statistics:

2节点AWR

可以看到Avg global cache cr block flush time (ms)非常高,关于current block flush redo的行为有很多的介绍,这里就不解释了。对于cr block flush redo的行为,通常在需要从远端实例的current block构造cr block时才会产生。

Normally CR block buffer processing does not include the ‘gc cr block flush time’. However, when a CR buffer is cloned from a current buffer that has redo pending, a log flush for a CR block transfer is required. A high percentage is indicative of hot blocks with frequent read after write access.

对于current/cr flush time延迟较高,通常有两种可能:

  • LGWR写性能差;

  • LGWR被阻塞。

所以下一步思路是直接去看看2节点AWR的Background Wait Events和Wait Event Histogram查看LGWR的写性能如何,是否稳定。

2节点AWR

2节点AWR

可以看到2节点LGWR写性能非常稳定,并且延迟也正常。那么就不是LGWR写性能的问题,很有可能是LGWR被阻塞。

2节点AWR

通过top event看到了2节点有大量等待是等待日志切换完成,说明确实LGWR遭到了阻塞,这个时候是时候去分析ash了,可以直接过滤其他信息去单独查看LGWR的ash信息。

SQL> select to_char(sample_time,'yyyy-mm-dd hh24:mi:ss'),program,session_id,event,seq#,BLOCKING_SESSION,BLOCKING_INST_ID from m_ash where program like '%LGWR%' and inst_id=2 order by 1;
TO_CHAR(SAMPLE_TIME PROGRAM SESSION_ID EVENT SEQ# BLOCKING_SESSION BLOCKING_INST_ID
------------------- ------------------------------ ---------- ------------------------------ ---------- ---------------- ----------------
...
2020-03-07 15:44:40 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 1
2020-03-07 15:44:41 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 1
2020-03-07 15:44:42 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 1
2020-03-07 15:44:43 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 1
2020-03-07 15:44:44 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 1
2020-03-07 15:44:45 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 1
2020-03-07 15:44:46 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 1
2020-03-07 15:44:47 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 1
2020-03-07 15:44:48 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 1
2020-03-07 15:44:49 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 1
2020-03-07 15:44:50 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 1
2020-03-07 15:44:51 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 1
2020-03-07 15:44:52 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 1
2020-03-07 15:44:53 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 1
2020-03-07 15:44:54 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 1
2020-03-07 15:44:55 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 1
2020-03-07 15:44:56 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 1
2020-03-07 15:44:57 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 1
2020-03-07 15:44:58 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 1
...

可以看到从 15:44:40 开始,LGWR就开始等待CF队列,并且一直持续非常长的时间,阻塞会话是节点1的sid为2224的会话。结合之前AWR的分析这里猜测是在 15:44:40 进行了日志切换,因为日志切换需要去读取控制文件。那么下面看看blocking session的信息。

SQL> select to_char(sample_time,'yyyy-mm-dd hh24:mi:ss'),program,session_id,event,seq#,BLOCKING_SESSION,BLOCKING_INST_ID from m_ash where session_id=2224 and inst_id=1 order by 1;
TO_CHAR(SAMPLE_TIME PROGRAM SESSION_ID EVENT SEQ# BLOCKING_SESSION BLOCKING_INST_ID
------------------- ------------------------- ---------- ------------------------------ ---------- ---------------- ----------------
...
2020-03-07 15:37:41 oracle@sxdb01 (M000) 2224 control file sequential read 479
2020-03-07 15:37:42 oracle@sxdb01 (M000) 2224 566
2020-03-07 15:37:43 oracle@sxdb01 (M000) 2224 control file sequential read 632
2020-03-07 15:37:44 oracle@sxdb01 (M000) 2224 control file sequential read 684
2020-03-07 15:37:45 oracle@sxdb01 (M000) 2224 736
2020-03-07 15:37:46 oracle@sxdb01 (M000) 2224 781
2020-03-07 15:37:47 oracle@sxdb01 (M000) 2224 824
2020-03-07 15:37:48 oracle@sxdb01 (M000) 2224 865
2020-03-07 15:37:49 oracle@sxdb01 (M000) 2224 915
2020-03-07 15:37:50 oracle@sxdb01 (M000) 2224 1031
2020-03-07 15:37:51 oracle@sxdb01 (M000) 2224 1183
2020-03-07 15:37:52 oracle@sxdb01 (M000) 2224 control file sequential read 1304
2020-03-07 15:37:53 oracle@sxdb01 (M000) 2224 1400
2020-03-07 15:37:54 oracle@sxdb01 (M000) 2224 1481
2020-03-07 15:37:55 oracle@sxdb01 (M000) 2224 control file sequential read 1631
2020-03-07 15:37:56 oracle@sxdb01 (M000) 2224 control file sequential read 1834
2020-03-07 15:37:57 oracle@sxdb01 (M000) 2224 control file sequential read 1947
2020-03-07 15:37:58 oracle@sxdb01 (M000) 2224 control file sequential read 2052
2020-03-07 15:37:59 oracle@sxdb01 (M000) 2224 control file sequential read 2159
2020-03-07 15:38:00 oracle@sxdb01 (M000) 2224 control file sequential read 2269
2020-03-07 15:38:01 oracle@sxdb01 (M000) 2224 control file sequential read 2404
2020-03-07 15:38:02 oracle@sxdb01 (M000) 2224 control file sequential read 2517
2020-03-07 15:38:03 oracle@sxdb01 (M000) 2224 control file sequential read 2672
2020-03-07 15:38:04 oracle@sxdb01 (M000) 2224 2801
2020-03-07 15:38:05 oracle@sxdb01 (M000) 2224 2857
2020-03-07 15:38:06 oracle@sxdb01 (M000) 2224 2866
2020-03-07 15:38:07 oracle@sxdb01 (M000) 2224 control file sequential read 2893
2020-03-07 15:38:08 oracle@sxdb01 (M000) 2224 3007
2020-03-07 15:38:09 oracle@sxdb01 (M000) 2224 control file sequential read 3111
2020-03-07 15:38:10 oracle@sxdb01 (M000) 2224 3184
2020-03-07 15:38:11 oracle@sxdb01 (M000) 2224 control file sequential read 3218
2020-03-07 15:38:12 oracle@sxdb01 (M000) 2224 control file sequential read 3263
2020-03-07 15:38:13 oracle@sxdb01 (M000) 2224 3304
..

这里看到阻塞进程为1节点的M000,从15:37分就开始持有CF锁一直在读取控制文件,持续了非常久的时间,导致2节点日志切换时,2节点LGWR无法持有CF锁。M000为MMON进程的slave进程,关于MMON进程我们知道通常都是跟AWR有关,为什么会不断的读取控制文件呢?

结合diag产生的systemstate dump里去查看M000的short_stack信息:

Short stack dump: ksedsts()+380<-ksdxfstk()+52<-ksdxcb()+3592<-sspuser()+140<-__sighndlr()+12<-call_user_handler()+868<-sigacthandler()+92<-__pread()+12<-pread()+112<-skgfqio()+532<-ksfd_skgfqio()+756<-ksfd_io()+676<-ksfdread()+640<-kfk_ufs_sync_io()+416<-kfk_submit_io()+260<-kfk_io1()+916<-kfk_transitIO()+2512<-kfioSubmitIO()+408<-kfioRequestPriv()+220<-kfioRequest()+472<-ksfd_kfioRequest()+444<-ksfd_o**io()+2956<-ksfd_io()+1868<-ksfdread()+640<-kccrbp()+496<-kccrec_rbl()+296<-kccrec_read_write()+1680<-kccrrc()+1072<-krbm_cleanup_map()+28<-kgghstmap()+92<-krbm_cleanup_backup_records()+1100<-kraalac_slave_action()+1016<-kebm_slave_main()+744<-ksvrdp()+1928<-opirip()+1972<-opidrv()+748<-sou2o()+88<-opimai_real()+512<-ssthrdmain()+324<-main()+316<-_start()+380
kraalac_slave_action ->krbm_cleanup_backup_records-> krbm_cleanup_map -> kccrrc
这里可以看到M000当时在清理备份记录而去读取的控制文件,从M000 trace或者ash里M000的action name可以看到当时m000的action为Monitor FRA Space,说明是MMON发起slave去做Monitor FRA Space,而FRA空间不足所以触发的清理一些FRA里的备份记录从而读取的控制文件。

知道了M000为何要去读取控制文件,那么下一个问题就是为什么会读那么久呢?控制文件过大?控制文件读取过慢?还是从systemstate dump中找到了答案:

 SO: 0x22e13908e0, type: 10, owner: 0x23012ace68, flag: INIT/-/-/0x00 if: 0x1 c: 0x1
proc=0x23012ace68, name=FileOpenBlock, file=ksfd.h LINE:6688 ID:, pg=0
(FOB) 22e13908e0 flags=2560 fib=22fde0d288 incno=0 pending i/o cnt=0
fname=+FASTDG/sxboss/controlfile/current.256.907844431
fno=1 lblksz=16384 fsiz=118532

控制文件大小为 lblksz* fsiz=16384*118532=1.8g,为何控制文件会那么大呢?

因为control_file_record_keep_time设置为了365天。

解决方案:

1.根据备份策略合理设置 control_file_record_keep_time;

2.重建控制文件。

该案例得到的收获就是平时对MMON进程的作用了解过少,通过KST trace跟踪MMON,发现MMON的作用非常非常多,并不只是与AWR相关。


墨天轮原文链接

关于作者
李翔宇,云和恩墨西区交付技术顾问,长期服务移动运营商行业客户,熟悉Oracle性能优化,故障诊断,特殊恢复。

文章来源:微信公众号

原文链接:https://mp.weixin.qq.com/s/ulQ5H-tkZ6ldGETB3T2dtQ

分类:
标签:
请先登录,再评论

暂无回复,快来写下第一个回复吧~

为你推荐

构建企业级业务高可用的延时消息中台
业务场景剖析公司业务系统(比如:电商系统)中有大量涉及定时任务的业务场景,例如:实现买卖双方在线沟通的IM系统,为了确保接收方能够收到消息,服务端一般都会有重试策略,即服务端在消息发出的一段时间内,如
5G时代,如何彻底搞定海量数据库的设计与实践
5G时代,业务数据越来越丰富,业务使用MySQL数据库作为后台存储,存储引擎使用InnoDB,会带来哪些挑战?如何针对公司业务特点及MySQL数据库特性,制定若干数据库使用规范供一线RD在设计业务时参
Redis client链接池配置不当引起的频繁full gc
现象笔者负责的一个RPC服务就是简单的从Redis Cluster中读取数据,然后返回给上游。理论上该服务的对象大部分都应该是朝生夕死的,但是笔者查看gc log 的时候发现 age =2 的对象还真
记一次线上请求偶尔变慢的排查
前言最近解决了个比较棘手的问题,由于排查过程挺有意思,于是就以此为素材写出了本篇文章。 Bug现场这是一个偶发的性能问题。在每天几百万比交易请求中,平均耗时大约为300ms,但总有那么100多笔会超过
MySQL之KEY分区引发的血案
需求背景业务表tb_image部分数据如下所示,其中id唯一,image_no不唯一。image_no表示每个文件的编号,每个文件在业务系统中会生成若干个文件,每个文件的唯一ID就是字段id:业务表t
记一次中间件导致的慢SQL排查过程
前言最近发现线上出现一个奇葩的问题,这问题让笔者定位了好长时间,期间排查问题的过程还是挺有意思的,正好博客也好久不更新了,就以此为素材写出了本篇文章。 Bug现场我们的分库分表中间件在经过一年的沉淀之
Oracle实战优化!一次gc buffer busy acquire诊断
本案例来自某客户两节点rac的一次生产故障,现象是大面积的gc buffer busy acquire导致业务瘫痪。首先查看1节点AWR头部信息和load profile:1节点AWR 得到的关键信息点:对于LCPU 256的系统,AAS=13379.42/59.91
一次非常艰难的drop多个PDB的恢复
导言 关于Oracle的性能优化能保证Oracle性能的保障性,本篇给大家介绍的是Oracle的数据被误删后如何恢复的优化。 背景 在一次恢复中,遇到了一个非常棘手的case,客户环境中的一套rac cdb中原本存在10个PDB在同一个ASM磁盘组中,但误删