百度360必应搜狗淘宝本站头条
php redisredis 命令redis 锁redis 主从redis 删除
当前位置：网站首页 > 技术教程 > 正文

Oracle案例:一次gc buffer busy acquire诊断

mhr18 2025-01-10 15:24 13 浏览 0 评论


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

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

得到的关键信息点：

  • 对于LCPU 256的系统，AAS=13379.42/59.91=223，说明系统非常繁忙或者遇到了异常等待。
  • sessions异常增长好几倍，DB CPU/DB Time占比非常低，说明是遇到了异常等待。
  • 其余指标都还算正常。

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

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

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

可以看到每秒传输的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：

可以看到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节点LGWR写性能非常稳定，并且延迟也正常。那么就不是LGWR写性能的问题，很有可能是LGWR被阻塞。

通过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_osmio()+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相关。KST trace跟踪到的MMON的action如下：

(MMON) : (infrequent action) : acnum=[133] comment=[deferred controlfile autobackup action]     
(MMON) : (infrequent action) : acnum=[150] comment=[recovery area alert action]     
(MMON) : (infrequent action) : acnum=[167] comment=[undo usage]       
(MMON) : (infrequent action) : acnum=[171] comment=[Block Cleanout Optim, Undo Segment Scan]   
(MMON) : (infrequent action) : acnum=[175] comment=[Flashback Archive RAC Health Check]    
(MMON) : (infrequent action) : acnum=[178] comment=[tune undo retention lob]     
(MMON) : (infrequent action) : acnum=[179] comment=[MMON Periodic LOB MQL Selector]    
(MMON) : (infrequent action) : acnum=[180] comment=[MMON Periodic LOB Spc Analyze ]   
(MMON) : (infrequent action) : acnum=[183] comment=[tablespace alert monitor]      
(MMON) : (infrequent action) : acnum=[197] comment=[OLS Cleanup]       
(MMON) : (infrequent action) : acnum=[205] comment=[Sample Shared Server Activity]     
(MMON) : (infrequent action) : acnum=[212] comment=[Compute cache stats in background]    
(MMON) : (infrequent action) : acnum=[213] comment=[SPM: Auto-purge expired SQL plan baselines]   
(MMON) : (infrequent action) : acnum=[214] comment=[SPM: Check SMB size]     
(MMON) : (infrequent action) : acnum=[215] comment=[SPM: Delete excess sqllog$ batches]    
(MMON) : (infrequent action) : acnum=[219] comment=[KSXM Advance DML Frequencies]     
(MMON) : (infrequent action) : acnum=[220] comment=[KSXM Broadcast DML Frequencies]     
(MMON) : (infrequent action) : acnum=[225] comment=[Cleanup client cache server state in background]  
(MMON) : (infrequent action) : acnum=[226] comment=[MMON TSM Cleanup]      
(MMON) : (infrequent action) : acnum=[296] comment=[alert message cleanup]      
(MMON) : (infrequent action) : acnum=[297] comment=[alert message purge]      
(MMON) : (infrequent action) : acnum=[298] comment=[AWR Auto Flush Task]     
(MMON) : (infrequent action) : acnum=[299] comment=[AWR Auto Purge Task]     
(MMON) : (infrequent action) : acnum=[300] comment=[AWR Auto DBFUS Task]     
(MMON) : (infrequent action) : acnum=[301] comment=[AWR Auto CPU USAGE Task]    
(MMON) : (infrequent action) : acnum=[305] comment=[Advisor delete expired tasks]     
(MMON) : (infrequent action) : acnum=[313] comment=[run-once action driver]      
(MMON) : (infrequent action) : acnum=[319] comment=[metrics monitoring]       
(MMON) : (infrequent action) : acnum=[322] comment=[sql tuning hard kill defense]    
(MMON) : (infrequent action) : acnum=[323] comment=[autotask status check]      
(MMON) : (infrequent action) : acnum=[324] comment=[Maintain AWR Baseline Thresholds Task]    
(MMON) : (infrequent action) : acnum=[325] comment=[WCR: Record Action Switcher]     
(MMON) : (infrequent action) : acnum=[331] comment=[WCR: Replay Action Switcher]     
(MMON) : (infrequent action) : acnum=[338] comment=[SQL Monitoring Garbage Collector]     
(MMON) : (infrequent action) : acnum=[344] comment=[Coordinator autostart timeout]
(MMON) : (infrequent action) : acnum=[348] comment=[ADR Auto Purge Task]     
(MMON) : (infrequent action) : acnum=[41] comment=[reload failed KSPD callbacks]     
(MMON) : (infrequent action) : acnum=[75] comment=[flashcache object keep monitor]     
(MMON) : (interrupt action) : acnum=[108] comment=[Scumnt mount lock]      
(MMON) : (interrupt action) : acnum=[109] comment=[Poll system events broadcast channel]    
(MMON) : (interrupt action) : acnum=[20] comment=[KSB action for ksbxic() calls]    
(MMON) : (interrupt action) : acnum=[2] comment=[KSB action for X-instance calls]    
(MMON) : (interrupt action) : acnum=[306] comment=[MMON Remote action Listener]     
(MMON) : (interrupt action) : acnum=[307] comment=[MMON Local action Listener]     
(MMON) : (interrupt action) : acnum=[308] comment=[MMON Completion Callback Dispatcher]     
(MMON) : (interrupt action) : acnum=[309] comment=[MMON set edition interrupt action]    
(MMON) : (interrupt action) : acnum=[341] comment=[Check for sync messages from other instances]  
(MMON) : (interrupt action) : acnum=[343] comment=[Check for autostart messages from other instances]  
(MMON) : (interrupt action) : acnum=[350] comment=[Process staged incidents]      
(MMON) : (interrupt action) : acnum=[351] comment=[DDE MMON action to schedule async action slaves] 
(MMON) : (interrupt action) : acnum=[39] comment=[MMON request for RLB metrics]    
(MMON) : (requested action) : acnum=[314] comment=[shutdown MMON]       
(MMON) : (requested action) : acnum=[315] comment=[MMON DB open]      
(MMON) : (requested action) : acnum=[321] comment=[ADDM (KEH)]       
(MMON) : (requested action) : acnum=[347] comment=[Job Autostart action force]     
(MMON) : (requested action) : acnum=[349] comment=[Schedule slave to update incident meter]   
(MMON) : (requested action) : acnum=[63] comment=[SGA memory tuning parameter update]    
(MMON) : (timeout action) : acnum=[0] comment=[Monitor Cleanup]       
(MMON) : (timeout action) : acnum=[11] comment=[Update shared pool advice stats]    
(MMON) : (timeout action) : acnum=[154] comment=[Flashback Marker]       
(MMON) : (timeout action) : acnum=[172] comment=[Block Cleanout Optim, Rac specific code]   
(MMON) : (timeout action) : acnum=[173] comment=[BCO:]        
(MMON) : (timeout action) : acnum=[1] comment=[Update KGSTM Translation]      
(MMON) : (timeout action) : acnum=[3] comment=[KSB action for bast checking]    
(MMON) : (timeout action) : acnum=[42] comment=[reconfiguration MMON action]      
(MMON) : (timeout action) : acnum=[63] comment=[SGA memory tuning parameter update]    
(MMON) : (timeout action) : acnum=[69] comment=[SGA memory tuning]
。。。

大概有几百种action，平时对MMON关注还是太少了。

墨天轮原文链接：https://www.modb.pro/db/174948?sjhy（复制链接至浏览器或点击文末阅读原文查看)

关于作者

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

相关推荐

redis 7.4.3更新!安全修复+性能优化全解析

一、Redis是什么？为什么选择它？Redis（RemoteDictionaryServer）是一款开源的高性能内存键值数据库，支持持久化、多数据结构（如字符串、哈希、列表等），广泛应用于缓存、消...

C# 读写Redis数据库的简单例子

CSRedis是一个基于C#的Redis客户端库，它提供了与Redis服务器进行交互的功能。它是一个轻量级、高性能的库，易于使用和集成到C#应用程序中。您可以使用NuGet包管理器或使用以下命令行命令...

十年之重修Redis原理

弱小和无知并不是生存的障碍，傲慢才是。--------面试者总结Redis可能都用过，但是从来没有理解过，就像一个熟悉的陌生人，本文主要讲述了Redis基本类型的使用、数据结构、持久化、单线程模型...

高频L2行情数据Redis存储架构设计(含C++实现代码)

一、Redis核心设计原则内存高效：优化数据结构，减少内存占用低延迟访问：单次操作≤0.1ms响应时间数据完整性：完整存储所有L2字段实时订阅：支持多客户端实时数据推送持久化策略：RDB+AOF保障数...

Magic-Boot开源引擎:零代码玩转企业级开发，效率暴涨!

一、项目介绍基于magic-api搭建的快速开发平台，前端采用Vue3+naive-ui最新版本搭建，依赖较少，运行速度快。对常用组件进行封装。利用Vue3的@vue/compiler-sfc单文...

项目不行简历拉胯?3招教你从面试陪跑逆袭大厂offer!

项目不行简历拉胯？3招教你从面试陪跑逆袭大厂offer！老铁们！是不是每次面试完都感觉自己像被大厂面试官婉拒的渣男？明明刷了三个月题库，背熟八股文，结果一被问项目就支支吾吾，简历写得像大学生课程设计？...

谷歌云平台:开发者部署超120个开源包

从国外相关报道了解，Google与Bitnami合作为Google云平台增加了一个新的功能，为了方便开发人员快捷部署程序，提供了120余款开源应用程序云平台的支持。这些应用程序其中包括了WordPre...

知名互联网公司和程序员都看好的数据库是什么?

2017年数据库领域的最大趋势是什么？什么是最热的数据处理技术？学什么数据库最有前途？程序员们普遍不喜欢的数据库是什么？本文都会一一揭秘。大数据时代，数据库的选择备受关注，此前本号就曾揭秘国内知名互联...

腾讯云发布云存储MongoDB服务

近日，著名安全专家兼Shodan搜索引擎的创建者JohnMatherly发现，目前至少有35000个受影响的MongoDB数据库暴露在互联网上，它们所包含的数据暴露在网络攻击风险之中。据估计，将近6...

已跪，Java全能笔记爆火，分布式/开源框架/微服务/性能调优全有

前言程序员，立之根本还是技术，一个程序员的好坏，虽然不能完全用技术强弱来判断，但是技术水平一定是基础，技术差的程序员只能CRUD，技术不深的程序员也成不了架构师。程序员对于技术的掌握，除了从了解-熟悉...

面试官:举个你解决冲突的例子?别怂!用这个套路……

面试官：举个你解决冲突的例子？别怂！用这个套路……最近收到粉丝私信，说被问到：团队技术方案有分歧怎么办？当场大脑宕机……兄弟！这不是送命题，是展示你情商+技术判断力的王炸题！今天教你们3招，用真实案例...

面试碰到MongoDB?莫慌，跟面试官这样吹MongoDB 复制集

推荐阅读：吊打MySQL：21性能优化实践+学习导图+55面试+笔记+20高频知识点阿里一线架构师分享的技术图谱，进阶加薪全靠它十面字节跳动，依旧空手而归，我该放弃吗？文末会分享一些MongoDB的学...

SpringBoot集成扩展-访问NoSQL数据库之Redis和MongoDB!

与关系型数据库一样，SpringBoot也提供了对NoSQL数据库的集成扩展，如对Redis和MongoDB等数据库的操作。通过默认配置即可使用RedisTemplate和MongoTemplate...

Java程序员找工作总卡项目关?

Java程序员找工作总卡项目关？3招教你用真实经历写出HR抢着要的简历！各位Java老哥，最近刷招聘软件是不是手都划酸了？简历投出去石沉大海，面试邀请却总在飞别人的简历？上周有个兄弟，13年经验投了5...

Java多租户SaaS系统实现方案

嗯，用户问的是Java通过租户id实现的SaaS方案。首先，我需要理解用户的需求。SaaS，也就是软件即服务，通常是指多租户的架构，每个租户的数据需要隔离。用户可能想知道如何在Java中利用租户ID来...

取消回复欢迎 你 发表评论:

一周热门
最近发表
标签列表