百度360必应搜狗淘宝本站头条
分布式事务框架grpc框架shiro框架java日志框架框架图模板
当前位置：网站首页 > 技术文章 > 正文

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

ccwgpt 2024-12-03 10:18 43 浏览 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性能优化，故障诊断，特殊恢复。

相关推荐

自己动手写Android数据库框架_android开发数据库搭建

http://blog.csdn.net/feiduclear_up/article/details/50557590推荐理由关于Android数据库操作，由于每次都要自己写数据库操作，每次还得去...

谷歌开源大模型评测工具LMEval，打通谷歌、OpenAI、Anthropic

智东西编译|金碧辉编辑|程茜智东西5月28日消息，据科技媒体TheDecoder5月26日报道，当天，谷歌正式发布开源大模型评测框架LMEval，支持对GPT-4o、Claude3.7...

工信部:着力推动大模型算法、框架等基础性原创性的技术突破

工信部新闻发言人今日在发布会上表示，下一步，我们将坚持突出重点领域，大力推动制造业数字化转型，推动人工智能创新应用。主要从以下四个方面着力。一是夯实人工智能技术底座。通过科技创新重大项目，着力推动大模...

乒乓反复纠结“框架不稳定”的三个小误区

很多球友由于对框架的认知不清晰，往往会把“框架不稳定”当成一种心理负担，从而影响学球进度，其典型状态就是训练中有模有样，一旦进入实战，就像被捆住了手脚。通过训练和学习，结合“基本功打卡群”球友们交流发...

前AMD、英特尔显卡架构师Raja再战GPU，号称要全面重构堆栈

IT之家8月5日消息，知名GPU架构师拉贾科杜里(RajaKoduri)此前曾先后在AMD和英特尔的显卡部门担任要职。而在今日，由Raja创立的GPU软件与IP初创企...

三种必须掌握的嵌入式开发程序架构

前言在嵌入式软件开发，包括单片机开发中，软件架构对于开发人员是一个必须认真考虑的问题。软件架构对于系统整体的稳定性和可靠性是非常重要的，一个合适的软件架构不仅结构清晰，并且便于开发。我相...

怪不得别人3秒就知道软考案例怎么做能50+

软考高级统一合格标准必须三科都达到45分，案例分析也一直是考生头疼的一门，但是掌握到得分点，案例能不能50+还不是你们说了算吗？今天就结合架构案例考点，分享实用的备考攻略～一、吃透考点，搭建知识框架从...

UML统一建模常用图有哪些，各自的作用是什么?一篇文章彻底讲透

10万+爆款解析：9大UML图实战案例，小白也能秒懂！为什么需要UML？UML（统一建模语言）是软件开发的“蓝图”，用图形化语言描述系统结构、行为和交互，让复杂需求一目了然。它能：降低沟通成本避...

勒索软件转向云原生架构，直指备份基础设施

勒索软件组织和其他网络犯罪分子正越来越多地将目标对准基于云的备份系统，对久已确立的灾难恢复方法构成了挑战。谷歌安全研究人员在一份关于云安全威胁演变的报告中警告称，随着攻击者不断改进数据窃取、身份泄露和...

ConceptDraw DIAGRAM:释放创意，绘就高效办公新未来

在当今数字化时代，可视化工具已成为提升工作效率和激发创意的关键。ConceptDrawDIAGRAM，作为一款世界顶级的商业绘图软件，凭借其强大的功能和用户友好的界面，正逐渐成为众多专业人士的首选绘...

APP 制作界面设计教程:一步到位_app界面设计模板一套

想让APP界面设计高效落地，无需繁琐流程，掌握“框架搭建—细节填充—体验优化”三步法，即可一步到位完成专业级设计。黄金框架搭建是基础。采用“三三制布局”：将屏幕横向三等分，纵向保留三...

MCP 的工作原理:关键组件_mcp部件

以下是MCP架构的关键组件：MCP主机：像ClaudeDesktop、GitHubCopilot或旅行助手这样的AI智能体，它们希望通过MCP协议访问工具、资源等。MCP主机会...

软件架构_软件架构师工资一般多少

软件架构师自身需要是程序员，并且必须一直坚持做一线程序员。软件架构应该是能力最强的一群程序员，他们通常会在自身承接编程任务的同时，逐渐引导整个团队向一个能够最大化生产力的系统设计方向前进。软件系统的架...

不知不觉将手机字体调大!老花眼是因为“老了吗”?

现在不管是联系、交友，还是购物，都离不开手机。中老年人使用手机的时间也在逐渐加长，刷抖音、看短视频、发朋友圈……看手机的同时，人们也不得不面对“视力危机”——老花眼，习惯眯眼看、凑近看、瞪眼看，不少人...

8000通用汉字学习系列讲座(第046讲)

[表声母字]加(续)[从声汉字]伽茄泇迦枷痂袈笳嘉驾架咖贺瘸(计14字)嘉[正音]标准音读jiā。[辨形]上下结构，十四画。会意形声字，从壴从加，加也表声。注：从壴，字义与鼓乐有关；从加，字义与...

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

一周热门
最近发表
标签列表
赣ICP备2024040476号-14