一个案例看Oracle的历史故障回放功 --技术人生系列第三十七期-我和数据中心的故事
11月25日，周五晚上，正在家里看电视,电话响了，是一位银行客户资深DBA的来电，也是我的好朋友、好兄弟，看来，他遇到麻烦了…
“远邦,11月20号晚上例行跑批的时候，在1分钟内出现了多笔联机交易超时！当时的CPU不高，内存很富余，没有换页。异常的SQL_ID是15vru8xqgdkjf，就是我们的联机交易会插入的交易报文表，这个表和批量没有关系。最严重的一笔，就是2016-11-20 20:44:04 ~ 20:44:34，时间达到了30秒。这些交易做的事情很简单，就是INSERT INTO VALUES，插入交易报文表。我已经把ASH dump的相关信息发到你邮箱了，尽快帮忙分析下原因吧。需要说明信息可以再找我…”
细心的同学，可能已经从这段话中发现了很多信息：
Ø举例故障发生已经过去五天了，还可以查么？
Ø故障只出现了不到1分钟，还可以查么？
Ø简单的一笔INSERT INTO VALUES 怎么可能需要30秒呢?
在Oracle中，答案是YES！
而帮助我们完成这项核查任务的正是客户提到的ASH dump.
接下来这个case的根因分析，可能会颠覆很多人的运维“经验”，“没想到，这么做，对高并发的系统的影响这么大啊…”，还可能会有很多人生收获哦，我们不妨一起往下看吧。
开启分析之旅
1 ASH科普
打开邮件，不仅只有awr报告、ash报告，
还有一个表ash_1120_2040的dump,即ASH DUMP，真是贴心极了！
这个表实际上是dba_hist_active_session_history的备份，该表按照10秒为粒度，记录数据库中活动的会话在执行的SQL和发生的等待，且不会随着重启而丢失。而gv$active_session_history则是按秒采样存储，但因为是存放在内存中，因此会随着重启而丢失，且保存的数量有限.
这就是ASH功能，即活动会话历史功能。
举个例子: 假设一个会话正在运行一条SQL语句，从4秒到34秒，总计30秒。 因为ASH功能是按照10秒间隔进行采样，因此，可能在4、14、24、34秒总计采集到4次，也可能在5、15、25秒采集到3次（34秒的时候运行结束，因此下一次35秒的采集将没有该会话）。
2 ASH初探—活动会话趋势
将ash_1120_2040的dump导入电脑后，
立刻发出下列查询，获得按时间分布的活动会话个数的趋势。
结果绘制为下图所示：
可以看到：
Ø两个红色竖线之间的30秒左右，正是出现部分联机交易超时的时候。
Ø但是在出问题前的几分钟，即红色加框部分，活动进程数已经上来了，这个和客户确认了一下，是批量调起来的时间，批量是多个进程并发处理的
3 交易超时期间进程都在等什么
接下来，我们发出下列查询，获得交易超时期间的等待事件
结果如下所示：
可以看到，都是和RAC global cache相关的等待,需要说明的是，不懂RAC也不影响对这个case的阅读和理解，小y主要是通过这个case传授给大家核查疑难历史问题的方法和思路，以及不断颠覆自己常识的勇气，才能不断进步。
可以看到:
排在第一位的是gc buffer busy acquire，表示数据库集群中的某个节点，如节点1向节点2请求一个BLOCK的时候，节点1已经先有人在我前面申请了同样一个BLOCK，所以连申请都是繁忙的，busyacquire。
这个等待说明什么呢？
两个或者两个以上的会话同时申请同一个BLOCK，撞上了。
常见原因：
通常和SQL的效率有关，如果SQL效率够高，则无需申请那么多BLOCK，就不会和其他会话撞在一起同时申请一个BLOCK去了。
但在这里，显然不是SQL效率的问题，因为他就是一条简单的INSERT INTO VALUES的语句而已，不存在执行计划不好的问题。
显然，在我之前的申请的那个进程，向节点2请求BLOCK的过程中遇到了异常，导致了问题的发生。
如果是你，接下来该怎么往下分析呢?
4 根因分析之分析阻塞源头
我们做根因分析，常用的手段就是梳理进程之间的关系。找到阻塞的源头后分析他在做什么，为什么比平时要慢很多，导致了问题的发生。
分析到了这里，也许有同学会问道，那“我可以查到本节点是哪个会话在我之前申请了BLOCK么？我想去看看排在我前面的会话在经历什么…”
答案是YES!！！
ASH中的blocking_session字段标识了“哪个会话在我之前先行申请了该BLOCK”
接下来，我们发出下列查询，找到某一瞬间，正在等gc buffer busy acquire的上百个会话，分别在申请哪些BLOCK(p1/p2)，被谁阻塞了(blocking_session)。
可以看到，在开始出现问题的时刻，即20:44:04
节点1有82个会话申请同一个BLOCK在等gc bufferbusy acquire,被节点1 SID为3200的会话阻塞了，即节点1 SID为3200的会话先于82个进程向节点2请求。
5 很多人倒在了去挖宝藏的路上…
乘胜追击，我们看看节点1SID为3200的会话在等什么，被谁阻塞了呢？
如此递归下去，直到我们找到源头,到底是谁在“一夫当关，万夫莫开呢”…
结果如下：
可以看到：
异常出现了！节点1 SID为3200的会话在请求收到文件号47，BLOCK号1540116的时候，无法快速获取，等待事件是gc current blockbusy,并且这次申请从20:44:04到20:44:24,持续了20秒以上，但是崩溃的是，没有办法知道谁是我的阻塞者了…
是的，ash是一座宝藏，但是很多人却倒在了去挖宝藏的路上。
接下来，该怎么往下查呢？到底去往宝藏的路在哪里呢？
很抱歉，小y带着大家走了一遍这条死路，现实中，确实有很多朋友在不断重复这条死路，不想继续重复这条死路，想找一个带路人的，来参加我们的通向高手系列培训吧。
6 跟随小y重新出发
其实，作为IT技术人员，我们有时往往在处理问题的时候把问题想的复杂了，太注重技巧了，太注重官方文档的描述，不知不觉中让自己走进了死胡同。最简单的查问题的方法，像说话一样顺着思路往下查就好了，很多问题从官方文档中无法得到答案的时候，其实，生活可以给我们答案。无招胜有招。 ----中亦科技小y（黄远邦）
小y喜欢化繁为简，既然客户已经提到，有一笔插入报文表的联机交易2016-11-20 20:44:04 ~ 20:44:34，时间达到了30秒。那么我们就从这里开始好了…
结果如下所示
可以看到：
SQL_ID为'15vru8xqgdkjf'在ASH中被连续采样到了4次，说明执行时间大于30秒.与客户描述完全一致。然后呢？如果是你，怎么接着往下查，不妨思考几十秒…
7 再一次倒下？
接下来，我们通过sql_exec_id即SQL的唯一执行标记，来看看这笔超长交易的情况：
结果如下所示:
确实，最长的一笔交易，在04秒到24秒期间，一直在等”gc current retry”
“完了，这个等待事件我没遇到过啊…”，好吧，我也没遇到过，如果是你，你会怎么往下查，此处建议停下来几分钟，度娘和google或MOS一下，看看是否可以获得继续往前走的思路呢…最后，您是否又倒在了这里呢？请留言告诉小y…
答案就在后面，什么时候往后翻，由你决定。
8 向生活问路，要答案
其实小y也不知道长交易的会话在等的那个人””gc current retry”到底是谁，因为“gc current retry”这个人，无论在度娘还是GOOGLE还是METALINK上都找不到任何解释。
这个时候，小y习惯于向生活要答案。
“gc currentretry”，从字面上，看是请求当前BLOCK，但是无法获取，在retry.既然是向节点2请求一个BLOCK，无法获取，需要retry,那么我们有必要查下节点2是谁负责供应这个BLOCK呢？没错！就是节点2的LMS进程！
接下来，我们于情于理，都应该去查下问题期间，LMS进程在做什么…
发出下列查询即可
结果如下图所示
可以看到，这些LMS进程在等gcs log flush sync,即LMS进程在把一个BLOCK传给其他节点前，需要把这个BLOCK在log buffer中的改变，刷到磁盘中的在线日志文件，但是很可惜，刷了很长时间都没有完成。所以没有办法快速将BLOCK传输给节点1，因此节点1在不断retry.这里” gcs log flush sync”的阻塞者2_2633显然就是我们所熟悉的LGWR进程，即log buffer的写进程。
9 一马平川
跨过了这道坎，显然，我们就可以一路南下，一马平川了！
接下来，看看节点2的LGWR进程是不是在忙其他事，无暇顾及LMS进程的刷日志请求呢？发出下列查询
结果如下所示：
可以看到：
节点2的LGWR进程，在等enq: CF-contention,即想要去写控制文件（例如切换日志时需要写控制文件），但是被其他人领先一步，这个人是节点1的1369会话。期间，LGWR进程傻傻的继续等控制文件的队列锁，但等了几十秒都无法获取。
乘胜追击，发出下列查询，看看节点1的1369会话为什么长时间持有控制文件的队列锁。
结果如下：
可以看到，sid=1369是节点1的ckpt检查点进程
ckpt正在进行控制文件的读写，因此持有控制文件的锁。
期间等待事件是控制文件的顺序度和并行写，并且没有阻塞，而是一直在变化。正常来说，如果IO比较快的话，那么持有控制文件的锁的时间是非常快的。
10 根因分析--查IO的来源
进一步检查IO的性能
从oswatcher数据可以看到，在问题时段，很多磁盘busy 100%,平均响应时间200多毫秒，IO基本上主要是写，但不是所有盘都100%，例如hdiskpower 11依然是有少量读写的。
检查大量写IO的来源
检查ASH中的等待事件
结果如下所示：
可以看到是问题时刻，在等db file parallel write的进程有24个，显然是DBWR进程在等该数据库总计24个DBWR进程，全部处于活动状态，说明有什么动作触发了大量刷脏块的操作。
11 真相大白，谁触发了大量脏块的写操作
检查alert日志，可以看到alter system archive log all（current）的命令，该命令必然会触发DBWR大量刷脏块，导致磁盘在短时间内极忙，导致HBA卡带宽也可能被占满。
到这里，大家不妨停下思考下，导致是谁执行了这个触发全量检查点的archivelog all(current)命令呢？
不妨思考几十秒…
答案就是我们大家所熟悉的RMAN备份脚本！
要说明的是，真相和你想的不一样！不是备份产生的IO影响了磁盘繁忙！
因为之前我们看到了，磁盘繁忙100%来自于写，而不是来自于读！RMAN主要是读！而且如果是RMAN的读IO影响磁盘繁忙，那么不可能只影响了30秒左右！
因为RMAN脚本开始执行时的alter system archive log all（current）的命令触发了DBWR大量刷脏块，导致磁盘很忙，而控制文件和数据文件在一起，导致ckpt进程在拿到控制文件队列锁后，操作很慢，继而阻塞了LGWR进程，LGWR进程于是不响应LMS进程，最后导致了GC等待数十秒，也就是联机交易大量超时。全量检查点完成后，交易恢复正常！
怎么再次验证呢alter system archivelog ..的影响呢？
接下来发出下面这条命令来验证下：
可以看到，RMAN就是在最初的04秒发起，之后的43分34秒往后RMAN进程都还在，但交易已经恢复正常，也就是说RMAN脚本里触发的全量检查点和批量并行写操作产生大量脏块叠加在一起，是问题的原因！
为什么以前没事？？
经确认，当天备份提前了，和批量重叠了，但不是因为RMAN备份的读IO导致问题，而是因为RMAN备份脚本在最开始执行的alter system archivelog ..命令触发的这次全量检查点和批量并行写操作产生大量脏块叠加在一起，导致30秒左右，检查的INSERT联机交易也出现了超时，这才是问题的真相和问题的根本原因！
12 还没完,你确认这就是问题的真相么？
你确认这就是问题的真相？
欢迎大家踊跃留言，说说你的想法，同时可以加小y微信shadow-huang-bj，一起加入学习探讨群.我将在下期（技术人生系列）揭晓答案。
问题原因与经验总结
故障原因总结： l故障的原因在于批量期间，产生大量脏块 lckpt进程持有控制文件的队列锁后，开始进行IO操作 l但期间rman备份调用alter system archive log的命令，从而触发dbwr进程往数据文件大量的写，导致磁盘100% busy.导致控制文件的IO读写无法快速完成。 l由于日志切换，因此lgwr进程需要获得控制文件的队列锁，而ckpt进程阻塞了lgwr进程，lgwr进程处于enq: CF–contention状态，无法响应LMS进程的日志写情况。LMS进程负责节点间的GC。因此，GC出现问题，INSERT语句出现超时
数据中心运维建议： Ø将控制文件和数据文件从底层RAID组就分开，放到其他磁盘组,避免被DBWR写IO和RMAN读IO影响。 ØRman备份脚本中的alter system archive log all命令会导致数据库做全量检查点，触发DBWR的大量IO操作，期间拖慢整体性能 Ø重新评估alter system archive log all的替代方式 Ø将RMAN备份和批量时间错开
这个案例下来，小y希望您至少有如下收获： ØRman的备份脚本中的altersystem archivelog ..命令居然影响这么大… Ø术很重要，这是基础！ Ø道也很重要，他可以让你到达更远的地方 Ø当技术里没有答案的时候，我们可以问生活，上天不会亏待认真、细心和爱思考的人
声明：本站所有文章资源内容，如无特殊说明或标注，均为采集网络资源。如若本站内容侵犯了原著者的合法权益，可联系本站删除。
