前言
不知不觉，技术人生系列·我和数据中心的故事来到了第四期。小y又和大家见面了！
当您看到业务系统压测呈现以下波浪形的tps曲线时，你会怎么下手？
小y(中亦科技)今天要和大家分享的就是这样一个业务系统压测性能问题的分析和解决过程。这个问题困扰了客户相当长一段时间，幸运的是，小y通过远程在10分钟定位到了问题的原因并帮助客户最终解决了问题。需要说明的是，在这个CASE中，只调整数据库参数是不够的，还需要做其他分析和调整才可以解决问题。为了保持原汁原味，同时增加文章的趣味性，小y除了会继续坚持以往分析报告的写法外，会尝试开始引入一些问题处理的心理历程，希望朋友们可以了解到小y的真实工作状态。我们能学到什么
Oracle数据库在11.2.0.3及以上的版本上必须要调整的一个重要的性能相关的参数！
如何在诊断失败后坚持或快速调整问题甄别方向的技巧！
如何在处理跨团队/部门的综合型问题中掌握主动权的一些经验！
温馨提示
如果您的高并发、事务型的OLTP核心业务系统中中经常会出现一些性能的抖动。比如交易响应时间突然急剧上升,同时伴随着ap服务器端口数/进程活动数/jdbc连接数升高、数据库每秒DB TIME升高等现象，并且Oracle版本在11.2.0.3或以上，那么很可能和该文章提到的一个重要参数有关系哦！如果调整参数后还无法解决，可以联系小y诊断哦(mian fei de)。
Part 1
问题来了
上午10点，QQ突然闪了起来，来活了！
小y,有空吗？帮忙看个awr。
我一会跟你电话说一下情况。
今年他们新上的一个关键业务系统，在做上线前的压力测试时，应用的并发无法达到上线前的并发指标和响应时间指标要求。压测时TPS的曲线如下所示：发来QQ消息的是国内一个大型航空公司的DBA，一般的问题他都可以自己解决，这次看上去他遇到麻烦了。
可以看到，压测时的TPS呈现波浪形，极不稳定。
客户自己做了很多分析，资源层面，CPU、内存使用率、IO均正常，不过客户自己也发现了，压测时后端Oracle数据库中出现了大量的异常等待，主要是gc类型的等待，客户怀疑是不是私网交换机有问题。但可惜的是，网络团队却未检查出异常。
这个问题，他们也请现有的Oracle服务商进行了分析，但问题迟迟没有解决。这样一来，离业务系统要求上线的时间越来越近了，客户的压力也越来越大！
小y最近一直在跟这个客户，从心里真心希望能有机会为他们提供服务，所以这样的机会来了，小y自然是打起了十二分精神，准备开始战斗。
环境介绍：
操作系统Redhat 64 bit，64C 128G
数据库 Oracle 11.2.0.3 ,2节点RAC
Part 2
分析过程
2.1分析Oracle数据库每秒的DB TIME
我们用DB Time除以Elapsed，可以看到每秒DB TIME达到75！这是极度不正常的。
说明数据库正在经历严重的等待，需要查看数据库top等待事件继续分析。
2.2分析交易时间都消耗到哪了（TOP 5 wait event）
1）节点1等待事件如下所示：
事件分析
Oracle top 5等待里，gc buffer busy acquire排在第一位，占了51.2%，平均每次等待时间达到惊人的277毫秒！这里的gc buffer busy acquire表示在进程A之前已经有进程B先行向节点2请求同样的一个数据块，并且还没有完成，因此处在等待上。
排在第二位的是log file sync,占了18.58%，平均每次达到293毫秒。这里的log file sync表示当进程发出commit时，需要等lgwr后台进行将log buffer中的改变向量持久化到磁盘中的redo log中所发生的等待。
排在第三位的是DB CPU，在一个小时的采样里，总的等待时间是24648秒，也就是说大概占了7颗CPU时间，该服务器配置了64颗CPU，因此平均CPU使用率只用到了10%。这里小y顺便提一下，通常情况下，我们期望DB CPU的比例越高越好，这样就意味着SQL在执行的过程中，几乎不用发生等待，SQL的响应时间也就越快。但不代表就没问题，比如高逻辑读的SQL，如果要操作的数据都在内存中，也会导致DB CPU过高，此时就需要对高逻辑读的SQL进行优化了，从而降低 DB CPU。
排在第四位的是direct path read,平均等待时间也到了153毫秒。这里的direct path read表示进程直接将数据块读入PGA内存而不是读进buffer cache共享内存。这种情况下，IO的吞吐显然会更大，每个进程都各自读各自的哪怕是相同的数据。如果不同的进程同时读取的是相同的数据，并且读进共享内存，那么只需要一个进程负责读取，其他进程直接操作内存中的数据即可，此时IO吞吐会小很多。
排在第五位的是buffer busy wait,平均等待时间到了惊人的499毫秒。这里的buffer busy wait表示当两个或者两个以上的进程需要同时对一个数据块进行写/写、写/读操作时发生冲突，即热块冲突。
看到这里，小Y已经基本知道答案了！
不过从严谨的角度，还是要把RAC 2节点的等待事件也稍微过一下。
2）节点2等待事件如下所示：
和节点1相比，没有buffer busy wait,多了gc current block busy。
总体来说，两个节点的等待事件差别不大！
2.3 前2分钟里小y的头脑风暴
2.3.1是不是RAC私网的问题？
看到这里，也许有人会说:
gc等待那么高，是不是把另外一个RAC节点临时关掉，问题就解决了呢？
首先答案是NO！其次，这样的做法是生产出现紧急gc性能问题时可以临时采用的，但是对于这样一个case,客户显然是不接受的。
小y从技术层面来回答下这个问题。
首先，如下图所示
两个节点的私网不过是每秒3M，而RAC两台服务器为私网配置的是千兆交换机。
其次，RAC两个节点的CPU和内存均处于低位，也就没有出现因为资源问题导致一个节点运行缓慢，继而导致无法快速响应另外一个节点的gc请求的情况。
如果是该类问题，我们通常还可以看到gc*congested*类型的等待（拥堵）。
2.3.2是不是SQL效率导致gc/bbw/direct path read的问题？
其中bbw即buffer busy wait,
gc即表示gc buffer busy acquire等gc等待。
也许有人会说：
gc等待那么高，还有buffer busy wait等待,如果SQL效率足够高，那么访问的数据块就少了，那么进程发生gc请求的个数就很少，同时由于读/写造成的热块冲突自然也就没了。
答案是NO！
见下图，可以看到该应用还是写的相当不错的，大部分SQL都控制在100个逻辑读以下，只有3个SQL的逻辑读在几千到几万，这样的SQL效率和逻辑读数量不足以导致如此高的gc/bbw等待！另外，落到SQL效率不高这个点上，是没有办法解释log file sync/direct path read也处于平均单次长时间等待的！错误的方向是不能解决根本问题的！也就是说，即使你再花精力优化掉这几个逻辑读稍微高一些的SQL，压测的问题还是会依然存在，因为这不是根本原因，优化SQL对于这个CASE而言是锦上添花而非雪中送炭！
2.3.3是不是direct path read导致IO带宽占满的问题？
也许有人会说，会不会有这样一种可能：
先是direct path read导致IO带宽被占满
说明：多个进程把数据块读进PGA私有内存而不是buffer cache共享内存，以多块读16计算，每个BLOCK 8K，每个进程可以读取30M左右，15个以上的进程同时多块读就可以把hba卡带宽占满，设置10949 event可禁止该特性。
由于IO带宽被占满，影响了lgwr写日志的响应时间，继而导致log file sync等待长。
而log file sync又是gc和buffer busy wait的一个环节，从而将gc和buffer busy等待时间拉高，因此出现了AWR报告的等待？
首先，可以做出该假设的朋友，可以发小y发一份简历，说明你对数据库有非常深入的理解，并且有非常丰富的TroubleShooting经验，而且也已经不在割裂的分析问题的层面上了！
欢迎你加入中亦科技DBA团队！来了就是兄弟，我们一起并肩战斗，一起挑战各种疑难问题，一起分享收益！
简历请发至[email protected]
那么Log file sync和gc有什么关系呢？
引用一张RAC SG的图，其中原理如下图所示
从上图可以看到：
gc类的请求，在第二步中包含了lgwr进程写日志的过程，
即log file sync是gc请求的一个子步骤，严格来说，该步骤叫gc log flush sync.
但答案依然是NO！
从下图load profile中可以看到，每秒的物理读是498个BLOCK，每个BLOCK是8K，也就是说每秒的IO才4M左右。IOPS和IO带宽都非常低，显然不是该问题！
2.3.42.小y快速锁定问题分析方向！
小y这两分钟里如同上述的分析一样，飞速的进行着各种假设和排除、问题串联。
很快小y就锁定了问题的分析方向——那就是要把分析焦点放在log file sync等待上！
原因很简单，通过分析top 5等待，不难看到，他们之间是有关联关系的：
log file sync是gc和buffer busy wait的一个环节！（见2.3.3中的图）
如果log file sync等待解决了，自然gc*等待和buffer busy wait等待也就下去了！
问题也就得到解决了！
2.4 聚焦在“log file sync“等待上
从上文，我们已经知道，“log file sync”等待事件表示：
当进程发出commit时，需要等lgwr后台进行将log buffer中的改变向量持久化到磁盘中的redo log的过程中所发生的等待。因此，最常见的是lgwr写日志写的慢，或者是因为commit太频繁所导致！
接下来小y依次检查了这两个方面。
ORACLE当中，如果lgwr写日志写的慢，会体现到log file parallel write单次响应时间慢上。
节点1
节点2
可以看到，两个节点无论是log file parallel write还是gc log flush sync都只在5个毫秒以下，其中log file parallel write更是只有1毫秒和3毫秒。排除该问题！
接下来检查commit次数！
如下图所示,每秒的transactions（commits/rollbacks）只有48个！
小y服务过的一些大型银行的高并发的核心系统中，包括每秒事务数在10000以上的，log file sync也都控制在10个毫秒以内。所以每秒transactions只有48个是非常小的指标，不至于引起这么严重的等待！
2.5 原因基本定位并开始第一次调整
分析到了这里,小y已经已经找到本次压测的根本原因了，只需要调整验证即可。
建议朋友们，读到这里也可以先停一下，看看自己是否找到了问题原因。
也就是客户AWR报告发过来后的两分钟，小y告诉他
“我知道原因了，你把lgwr进程的trace发我最后确认一下，我们就开始调整”
其实并不奇怪，这样的case小y在几年前做大量系统升级到11g时就遇到过N次!客户很惊讶，他甚至还来不及电话小y，小y怎么可以这样…
这应该是一个上线前的标配，虽然现象不一样，但本质上是一个问题。
这也就是小y标题中要重点提示大家的一个重要的数据库参数。
如果Log file sync等待事件很长，但是lgwr写日志的时间很快，并且commit次数也不大的话，那就是在发起commit的进程和lgwr之间的通讯环节上出了问题。
关键知识点:
ORACLE从11G开始，为lgwr写日志引入了polling机制，而在以前只有post/wait机制。
同时引入了一个隐含参数，"_use_adaptive_log_file_sync"，即在两个机制之间自适应的切换。在11.2.0.3以下，该参数的默认值为false,即只启用post/wait机制。
从11.2.0.3开始，该参数的默认值为true,即Oracle会在post/wait机制和polling机制自适应。
Post/wait进制下，lgwr进程在写完log buffer中的改变向量后，立刻通知待commit的进程，因此log file sync等待时间短，但lgwr相对来说，负担要重一些。毕竟12C以下lgwr进程只有1个，当同时commit的进程比较多的时候，通知待commit的进程也是一种负担。
Polling模式下，待commit的进程，通知lgwr进程进行写入操作后，会进入sleep环节，并在timeout后去看是否log buffer中的内容被写入了磁盘，lgwr进程不再单独通知待commit的进程写已经完成。Polling机制下，解放了一部分lgwr的工作，但是会带来待commit的进程长时间处于log file sync等待下。对于交易型的系统而言，该机制是极度不适用的！
在post/wait和polling机制之间的切换，ORACLE会记录到lgwr进程的trace当中，如下所示。
当切换到polling模式下时，很容易引起log file sync等待而影响交易的响应时间！
Log file sync switching to polling
……
Log file sync switching to post/wait
在Oracle 11.2.0.3以下，建议关闭自适应log file sync,务必让lgwr进程运行在post/wait机制下，以确保数据库性能不会出现大的抖动！关闭的命令如下，可在线修改！因此，小y在这里提示各位
alter system set "_use_adaptive_log_file_sync"=false sid=‘*‘;
没错，小y的第一次调整措施就是调整该参数为false。
2.6 第一次调整后的结果让是失望！
在线调整参数后，为了安全起见，客户把两个节点数据库都重启了一遍。
并且重新做了压力测试,重新收集后的AWR报告如下所示！
看到节点1的这个AWR报告，gc等待和log file sync等待依然存在，并且看上去单次等待的时间更长了！
难道小y的分析出了问题? 或者说，小y这次遇到了好几个掺杂在一起的问题？冷静了一下，RAC的问题，切记只看单个节点，因此，小y让客户出了节点2的AWR报告，调整后节点2的awr报告如下图所示：
可以看到：
虽然等待还在，但节点2的log file sync等待没有了！这说明这次调整还是起到效果了的！
并且细心的朋友，可能已经发现了，节点1的第一位的等待gc buffer busy acquire完全没有了（说明节点2 log file sync快了），从gc buffer busy acquire变成了gc buffer busy release。这不正好说明调整还是起到作用了么？到这里，先不要着急，这里因为节点1依然存在log file sync,所以节点2的gc buffer busy acquire还依然存在！那么接下来，小y就要集中精力再解决掉节点1的log file sync就好了！
2.7 真相浮出水面（怀疑一切）
总结一下，这里调整log file sync自适应后，问题还是没有得到解决，那么回到传统思路上，最可能的问题那就还是lgwr进程写日志慢了！虽然awr报告中log file parallel write指标只有几个毫秒，但是awr报告毕竟是一个工具，提供的只是参考值，因此我们还是要抱着怀疑一切的态度，再来塞查一次！
这一次，我们来实时观察lgwr进程写日志的情况。发出SQL语句，结果如下图所示：
可以看到：
RAC两个节点中，只有1个节点出现log file parallel write的等待，刚好和前面的所有分析相互吻合！
在state是waiting的情况下，log file parallel等待的seq#都是35693，但是seconds_in_wait达到了21秒。简单来说，就是lgwr进程写一个IO需要21秒！
至此，我们可以肯定，IO子系统有问题，需要重点排查IO路径下的光纤线、SAN交换机、存储的报错和性能情况。
2.8 如何进一步证明IO路径环节有问题（跨部门合作）
考虑到客户那边管存储的团队/部门可能不承认数据库的IO慢的证据，同时为了让对方增加排查力度，小y让客户发出以下命令，查看多路径软件的IO情况，结果如下图所示：
节点1上出现明显的IO ERROR，并且在持续增加！
继续检查节点2，发现节点2上没有任何IO ERROR！
回顾前面的分析，节点2在调整数据库自适应log file sync为false后，并且没有出现IO ERROR，因此已经没有log file sync。
至此，分析结束！所有问题都得到了完美的解释！
找到原因了，还拿到了说服力极强的证据，客户终于松了一口气，不怕存储团队不认账了！
2.9 问题得到圆满解决
在铁的证据面前，客户的存储团队没有再挣扎，而是开始认认真真逐个在排查，最终在更换了光纤线后问题得到圆满解决。以下是更换光纤线后再次压测的等待事件！
压测的TPS曲线从原来的波浪形：
变成了如下的良好曲线
Part 3
问题原因和总结和风险提示
3.1 问题原因总结
该航空客户业务上线时压测无法达到并发和响应时间指标的原因在于同时遇到了两个混在一起的问题：
1）Oracle 11.2.0.3上log file sync默认打开自适应，当切换到polling模式后，导致log file sync等待时间变长，而log file sync是gc和buffer busy wait的一个环节，因此导致大量的等待
小y将"_use_adaptive_log_file_sync"调整为false后，就解决了一部分的log file sync等待的问题
2）由于节点1的光纤线存在质量问题，会导致IO错误，继而导致IO重发，影响了lgwr写日志的性能。
在调整数据库参数默认值并且更换光纤线后，问题得到圆满解决。
压测的TPS曲线从原来的波浪形
变成了如下的良好曲线
3.2 解决问题的关键点回顾
1）对Oracle等待事件不要割裂的来分析
小y在本case中通过梳理等待事件的共同点为log file sync,从而找到了突破口
2）了解不同版本数据库的特性和行为
小y平时在不断了解11g的新特性，并且通过大量的故障处理深入理解了这些特性，因此，当log file sync出现的时候，可以很快定位到新特性引起
3）不要完全相信AWR报告，他只是个工具，要怀疑一切去验证。
在这个case中，awr报告的指标并不能真实反映lgwr写性能的情况，要怀疑一切
4）一个Oracle服务人员，如果只懂数据库，就会出现你怀疑这怀疑那，但是其他人根本不认账的情况，因此必须掌握更多的包括操作系统、存储、网络、中间件的技能。当然了，找一家综合服务能力强的服务商也是不错的选择。
在这个case中，小y通过多路径的命令，找到了直接证据，最终获得了其他团队的大力度排查也是这次问题最终解决的关键。
风险提示
ORACLE从11G开始，为lgwr写日志引入了polling机制，而在以前只有post/wait机制。
同时引入了一个隐含参数，"_use_adaptive_log_file_sync"，即在两个机制之间自适应的切换。在11.2.0.3以下，该参数的默认值为false,即只启用post/wait机制。
从11.2.0.3开始，该参数的默认值为true,即Oracle会在post/wait机制和polling机制自适应。
Post/wait进制下，lgwr进程在写完log buffer中的改变向量后，立刻通知待commit的进程，因此log file sync等待时间短，但lgwr相对来说，负担要重一些。毕竟12C以下lgwr进程只有1个，当同时commit的进程比较多的时候，通知待commit的进程也是一种负担。
Polling模式下，待commit的进程，通知lgwr进程进行写入操作后，会进入sleep环节，并在timeout后去看是否log buffer中的内容被写入了磁盘，lgwr进程不再单独通知待commit的进程写已经完成。Polling机制下，解放了一部分lgwr的工作，但是会带来待commit的进程长时间处于log file sync等待下。对于交易型的系统而言，该机制是极度不适用的！
进制之间的切换回记录到lgwr进程的trace当中，如下所示。
当切换到polling模式下时，很容易引起log file sync等待而影响交易的响应时间！
Log file sync switching to polling
……
Log file sync switching to post/wait
因此，小y在这里提示各位。
在Oracle 11.2.0.3以下，建议关闭自适应log file sync,务必让lgwr进程运行在post/wait机制下，以确保数据库不会出现严重的性能抖动！关闭的命令如下，可在线修改！