不知不觉,技术人生系列•我和数据中心的故事来到了第四期。小y又和大家见面了!
当您看到业务系统压测呈现以下波浪形的tps曲线时,你会怎么下手?
为了保持原汁原味,同时增加文章的趣味性,小y除了会继续坚持以往分析报告的写法外,会尝试开始引入一些问题处理的心理历程,希望朋友们可以了解到小y的真实工作状态。
耐心读完该分享的朋友们,你们可以了解到:
温馨提示:
如果您的高并发、事务型的OLTP核心业务系统中中经常会出现一些性能的抖动,比如交易响应时间突然急剧上升,同时伴随着ap服务器端口数/进程活动数/jdbc连接数升高、数据库每秒DB TIME升高等现象,并且Oracle版本在11.2.0.3或以上,那么很可能和该文章提到的一个重要参数有关系哦!如果调整参数后还无法解决,可以联系小y诊断哦(mian fei de)。
你们的点赞和收藏就是小y继续坚持分享的动力!
上午10点,QQ突然闪了起来,来活了!
小y,有空吗?帮忙看个awr。
我一会跟你电话说一下情况。
发来QQ消息的是国内一个大型航空公司的DBA,一般的问题他都可以自己解决,这次看上去他遇到麻烦了。
今年他们新上的一个关键业务系统,在做上线前的压力测试时,应用的并发无法达到上线前的并发指标和响应时间指标要求。压测时TPS的曲线如下所示:
小y最近一直在跟这个客户,从心里真心希望能有机会为他们提供服务,所以这样的机会来了,小y自然是打起了十二分精神,准备开始战斗。
环境介绍:
操作系统 Redhat 64 bit,64C 128G
数据库 Oracle 11.2.0.3 ,2节点RAC
我们用DB Time除以Elapsed,可以看到每秒DB TIME达到75!这是极度不正常的。
说明数据库正在经历严重的等待,需要查看数据库top等待事件继续分析。
看到这里,小Y已经基本知道答案了!
不过从严谨的角度,还是要把RAC 2节点的等待事件也稍微过一下。
看到这里,也许有人会说:
gc等待那么高,是不是把另外一个RAC节点临时关掉,问题就解决了呢?
首先答案是NO!其次,这样的做法是生产出现紧急gc性能问题时可以临时采用的,但是对于这样一个case,客户显然是不接受的。
小y从技术层面来回答下这个问题。
首先,如下图所示
两个节点的私网不过是每秒3M,而RAC两台服务器为私网配置的是千兆交换机。
其中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而言是锦上添花而非雪中送炭!
也许有人会说,会不会有这样一种可能:
先是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团队!
那么Log file sync和gc有什么关系呢?
引用一张RAC SG的图,其中原理如下图所示
但答案依然是NO!
从下图load profile中可以看到,每秒的物理读是498个BLOCK,每个BLOCK是8K,也就是说每秒的IO才4M左右。IOPS和IO带宽都非常低,显然不是该问题!
小y这两分钟里如同上述的分析一样,飞速的进行着各种假设和排除、问题串联。
很快小y就锁定了问题的分析方向——那就是要把分析焦点放在log file sync等待上!
原因很简单,通过分析top 5等待,不难看到,他们之间是有关联关系的:
log file sync是gc和buffer busy wait的一个环节!(见2.3.3中的图)
如果log file sync等待解决了,自然gc*等待和buffer busy wait等待也就下去了!
问题也就得到解决了!
从上文,我们已经知道,“log file sync”等待事件表示:
当进程发出commit时,需要等lgwr后台进行将log buffer中的改变向量持久化到磁盘中的redo log的过程中所发生的等待。因此,最常见的是lgwr写日志写的慢,或者是因为commit太频繁所导致!
接下来小y依次检查了这两个方面。
ORACLE当中,如果lgwr写日志写的慢,会体现到log file parallel write单次响应时间慢上。
接下来检查commit次数!
如下图所示,每秒的transactions(commits/rollbacks)只有48个!
小y服务过的一些大型银行的高并发的核心系统中,包括每秒事务数在10000以上的,log file sync也都控制在10个毫秒以内。所以每秒transactions只有48个是非常小的指标,不至于引起这么严重的等待!
分析到了这里,小y已经已经找到本次压测的根本原因了,只需要调整验证即可。
建议朋友们,读到这里也可以先停一下,看看自己是否找到了问题原因。
也就是客户AWR报告发过来后的两分钟,小y告诉他
“我知道原因了,你把lgwr进程的trace发我最后确认一下,我们就开始调整”
客户很惊讶,他甚至还来不及电话小y,小y怎么可以这样…
其实并不奇怪,这样的case小y在几年前做大量系统升级到11g时就遇到过N次!
这应该是一个上线前的标配,虽然现象不一样,但本质上是一个问题。
这也就是小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机制自适应。
进制之间的切换回记录到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机制下,以确保数据库性能不会出现大的抖动!关闭的命令如下,可在线修改!
alter system set "_use_adaptive_log_file_sync"=false sid='*';
没错,小y的第一次调整措施就是调整该参数为false.
在线调整参数后,为了安全起见,客户把两个节点数据库都重启了一遍。
并且重新做了压力测试,重新收集后的AWR报告如下所示!
总结一下,这里调整log file sync自适应后,问题还是没有得到解决,那么回到传统思路上,最可能的问题那就还是lgwr进程写日志慢了!虽然awr报告中log file parallel write指标只有几个毫秒,但是awr报告毕竟是一个工具,提供的只是参考值,因此我们还是要抱着怀疑一切的态度,再来塞查一次!
这一次,我们来实时观察lgwr进程写日志的情况。发出SQL语句,结果如下图所示:
至此,我们可以肯定,IO子系统有问题,需要重点排查IO路径下的光纤线、SAN交换机、存储的报错和性能情况。
考虑到客户那边管存储的团队/部门可能不承认数据库的IO慢的证据,同时为了让对方增加排查力度,小y让客户发出以下命令,查看多路径软件的IO情况,结果如下图所示:
在铁的证据面前,客户的存储团队没有再挣扎,而是开始认认真真逐个在排查,最终在更换了光纤线后问题得到圆满解决。以下是更换光纤线后再次压测的等待事件!
该航空客户业务上线时压测无法达到并发和响应时间指标的原因在于同时遇到了两个混在一起的问题:
1)Oracle 11.2.0.3上log file sync默认打开自适应,当切换到polling模式后,导致log file sync等待时间变长,而log file sync是gc和buffer busy wait的一个环节,因此导致大量的等待
如果log file sync等待解决了,自然gc*等待和buffer busy wait等待也就下去了!
2)由于节点1的光纤线存在质量问题,会导致IO错误,继而导致IO重发,影响了lgwr写日志的性能。
在调整数据库参数默认值并且更换光纤线后,问题得到圆满解决。
压测的TPS曲线从原来的波浪形
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机制下,以确保数据库性能不会出现大的抖动!关闭的命令如下,可在线修改!
alter system set "_use_adaptive_log_file_sync"=false sid='*';
如果觉得我的文章对您有用,请点赞。您的支持将鼓励我继续创作!
赞4
添加新评论4 条评论
2017-04-21 17:56
2017-04-21 10:25
2017-04-21 10:18
2017-04-15 23:45