本案例来自某客户两节点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 12020-03-07 15:44:41 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 12020-03-07 15:44:42 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 12020-03-07 15:44:43 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 12020-03-07 15:44:44 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 12020-03-07 15:44:45 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 12020-03-07 15:44:46 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 12020-03-07 15:44:47 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 12020-03-07 15:44:48 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 12020-03-07 15:44:49 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 12020-03-07 15:44:50 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 12020-03-07 15:44:51 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 12020-03-07 15:44:52 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 12020-03-07 15:44:53 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 12020-03-07 15:44:54 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 12020-03-07 15:44:55 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 12020-03-07 15:44:56 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 12020-03-07 15:44:57 oracle@sxdb02 (LGWR) 913 enq: CF - contention 3850 2224 12020-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 4792020-03-07 15:37:42 oracle@sxdb01 (M000) 2224 5662020-03-07 15:37:43 oracle@sxdb01 (M000) 2224 control file sequential read 6322020-03-07 15:37:44 oracle@sxdb01 (M000) 2224 control file sequential read 6842020-03-07 15:37:45 oracle@sxdb01 (M000) 2224 7362020-03-07 15:37:46 oracle@sxdb01 (M000) 2224 7812020-03-07 15:37:47 oracle@sxdb01 (M000) 2224 8242020-03-07 15:37:48 oracle@sxdb01 (M000) 2224 8652020-03-07 15:37:49 oracle@sxdb01 (M000) 2224 9152020-03-07 15:37:50 oracle@sxdb01 (M000) 2224 10312020-03-07 15:37:51 oracle@sxdb01 (M000) 2224 11832020-03-07 15:37:52 oracle@sxdb01 (M000) 2224 control file sequential read 13042020-03-07 15:37:53 oracle@sxdb01 (M000) 2224 14002020-03-07 15:37:54 oracle@sxdb01 (M000) 2224 14812020-03-07 15:37:55 oracle@sxdb01 (M000) 2224 control file sequential read 16312020-03-07 15:37:56 oracle@sxdb01 (M000) 2224 control file sequential read 18342020-03-07 15:37:57 oracle@sxdb01 (M000) 2224 control file sequential read 19472020-03-07 15:37:58 oracle@sxdb01 (M000) 2224 control file sequential read 20522020-03-07 15:37:59 oracle@sxdb01 (M000) 2224 control file sequential read 21592020-03-07 15:38:00 oracle@sxdb01 (M000) 2224 control file sequential read 22692020-03-07 15:38:01 oracle@sxdb01 (M000) 2224 control file sequential read 24042020-03-07 15:38:02 oracle@sxdb01 (M000) 2224 control file sequential read 25172020-03-07 15:38:03 oracle@sxdb01 (M000) 2224 control file sequential read 26722020-03-07 15:38:04 oracle@sxdb01 (M000) 2224 28012020-03-07 15:38:05 oracle@sxdb01 (M000) 2224 28572020-03-07 15:38:06 oracle@sxdb01 (M000) 2224 28662020-03-07 15:38:07 oracle@sxdb01 (M000) 2224 control file sequential read 28932020-03-07 15:38:08 oracle@sxdb01 (M000) 2224 30072020-03-07 15:38:09 oracle@sxdb01 (M000) 2224 control file sequential read 31112020-03-07 15:38:10 oracle@sxdb01 (M000) 2224 31842020-03-07 15:38:11 oracle@sxdb01 (M000) 2224 control file sequential read 32182020-03-07 15:38:12 oracle@sxdb01 (M000) 2224 control file sequential read 32632020-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()+380kraalac_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=16384118532=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/17494...（复制链接至浏览器查看)
对于作者
李翔宇，云和恩墨西区交付技术顾问，长期服务挪动运营商行业客户，相熟Oracle性能优化，故障诊断，非凡复原。