记一次远程协助分析rac问题的案例

今天通过微信群和qq帮助一个网友分析了一个rac节点性能的问题,征得这位朋友的同学,和大家分享一下。
最开始这位朋友是在微信群中留言,说有一个rac的问题,现在已经严重影响在线业务了,希望我能够帮忙看看,有什么好的建议没,这对我来说着实是一个提高自己,分析问题的好机会,因为在地铁上,自己就简单确认了下环境,然后让他提供一些基本的错误日志或者报告。方便定位问题。
首先确认环境,得知这是一个rac 11g的环境,有两个节点,其它未知,根据这位朋友的反馈,有一个节点最近老出问题,前几天每天都报ora-00604,00609的错误,他查了下,说发现不是网络的问题就是sql语句的问题,然后今天节点又挂了,下午的时候报了ora-00020连接数超出的错误。作为临时解决方案,他把业务迁移到另外一个节点上之后就没有了问题,连接数也正常了。
从他的反馈来说,感觉这个节点存在一定的问题,但是不确定到底是什么原因,想让我来看一下。
很快从他那里得到了一个错误日志的截屏。
记一次远程协助分析rac问题的案例
但是错误信息毕竟有限,而且这种错误还需要依赖上下文环境,这个时候手头也没有metalink来查看,就让这位朋友生成问题发生时间段的ash报告,把问题节点的ash报告和正常节点的ash报告都抓取一下。
过了一会,他就生成了ash报告,我让他把等待事件/top sql的部分贴出来。得到的截图如下:
记一次远程协助分析rac问题的案例
在有限的信息中,这个问题着实让我捡了个大便宜,因为一看这部分,似乎问题的根源就有了眉目。
首先top sql的等待事件中,都指向了CPU,而且可以很明显的看到这些sql都走了全表扫描。然后我们往左边看,plan_hashvalue都是一致的,但是sql_id确不相同。然后向右看,目前看到的sql_text都是一致的。由此我脑海中得到了一个大体的影响,CPU的大量等待都在一些很相似的sql语句上,而且这些sql语句都走了全表扫描。很有可能是硬解析的问题,sql语句基本相同,可能没有使用绑定变量之类的。作为一个猜想,在回家之后,朋友已经发来了两个节点的ash报告。
带着疑问简单看了看,来做一个基本的验证。
首先是系统环境,

DB Name DB Id Instance Inst num Release RAC Host
xxxx 804043370 xxxx 1 11.2.0.3.0 YES rac1.xxxx.com

CPUs SGA Size Buffer Cache Shared Pool ASH Buffer Size
80 30,583M (100%) 4,800M (15.7%) 5,504M (18.0%) 160.0M (0.5%)
缓存的部分由一个明显的问题,就是shared_pool+buffer_cache的大小还不到sga实际使用的30%左右,有很大的浪费。但这个似乎不是重点,
我们来看看看问题节点,绝大部分的等待事件都在CPU相关的等待上。

Top User Events

Event Event Class % Event Avg Active Sessions
CPU + Wait for CPU CPU 71.43 28.22
direct path read User I/O 10.23 4.04
db file sequential read User I/O 7.59 3.00
reliable message Other 3.36 1.33
log file sync Commit 2.37 0.94
而且几乎清一色都是select操作。
SQL Command Type Distinct SQLIDs % Activity Avg Active Sessions
SELECT 2,001 93.60 36.98

而select的部分都指向了相似的sql语句上。

Top SQL with Top Events

SQL ID Planhash Sampled # of Executions % Activity Event % Event Top Row Source % RwSrc SQL Text
bkd82h036rphd 2942880414 57 3.00 CPU + Wait for CPU 2.50 TABLE ACCESS - FULL 2.50 select t.tradeflg from posmeri...
66v9yv1d33222 2942880414 57 2.81 CPU + Wait for CPU 2.32 TABLE ACCESS - FULL 2.32 select t.tradeflg from posmeri...
9tg81jgjfkyxx 2942880414 55 2.61 CPU + Wait for CPU 2.19 TABLE ACCESS - FULL 2.19 select t.tradeflg from posmeri...
f67j53520vtx1 2942880414 58 2.42 CPU + Wait for CPU 2.03 TABLE ACCESS - FULL 2.03 select t.tradeflg from posmeri...
98fvraaavv7f8 2942880414 60 2.41 CPU + Wait for CPU 2.00 TABLE ACCESS - FULL 2.00 select t.tradeflg from posmeri...
查看完整的sql文本就基本证明了自己的猜测。确实没有使用绑定变量,导致全表扫描+硬解析导致了大量的cpu等待。
66v9yv1d33222 select t.tradeflg from posmeriskcontrol t, posmercinf z where trim(z.mercid)='83xxxxxx' and trim(t.mercnum)=trim(z.mercnum) and t.tradeflg='0'
98fvraaavv7f8 select t.tradeflg from posmeriskcontrol t, posmercinf z where trim(z.mercid)='83xxxxxx' and trim(t.mercnum)=trim(z.mercnum) and t.tradeflg='0'
9tg81jgjfkyxx select t.tradeflg from posmeriskcontrol t, posmercinf z where trim(z.mercid)='83xxxxxx' and trim(t.mercnum)=trim(z.mercnum) and t.tradeflg='0'
bkd82h036rphd select t.tradeflg from posmeriskcontrol t, posmercinf z where trim(z.mercid)='8x3xxxxx' and trim(t.mercnum)=trim(z.mercnum) and t.tradeflg='0'
f67j53520vtx1 select t.tradeflg from posmeriskcontrol t, posmercinf z where trim(z.mercid)='83xxxxxx' and trim(t.mercnum)=trim(z.mercnum) and t.tradeflg='0'

而朋友反馈,另外一个节点情况良好,我们来看看这个节点的情况。
SQL Command Type Distinct SQLIDs % Activity Avg Active Sessions
SELECT 5,177 34.17 1.06
INSERT 5,847 29.63 0.92
UPDATE 5,411 29.11 0.91
基本上select,insert,update达到了1:1:1的比例。
这个节点上的等待事件就完全不同了。可以看到很多和单实例数据库不同的gc等待事件。
Event Event Class % Event Avg Active Sessions
gc buffer busy acquire Cluster 39.64 1.23
CPU + Wait for CPU CPU 24.46 0.76
gc cr block busy Cluster 12.18 0.38
gc current block busy Cluster 8.59 0.27
db file sequential read User I/O 3.34 0.10
如果对这个问题比较疑惑可以在top sql中找到答案,因为在top sql中也确实存在着一些和问题节点相似的sql语句了,可以理解在并发的dml操作中,一个节点在做满负荷的全表扫描查询,而另外一个节点也在做一些update和select,势必对性能是一个极大的考验。
FORCE_MATCHING_SIGNATURE % Activity # of Sampled SQL Versions Example SQL 1 Example SQL TEXT 1 Example SQL 2 Example SQL TEXT 2
8559161600712222867 18.13 2719 1fjpfssnnt690 update pos_termtrans_info set ... gn0whttj0yhxu update pos_termtrans_info set ...
5572193741054430457 13.28 2253 000pp0pk294wy select t.tradeflg from posmeri... gzwf98yawzrvg select t.tradeflg from posmeri...
所以到此问题就可以基本定性了,在两个节点中,存在着并发的读写,同时因为全表扫描把这个问题进行了放大,加上没有使用绑定变量,对于CPU的消耗还是很大的。
当然了问题的原因基本定位,解决起来就容易多了,对于全表扫描的查询可以使用函数索引来临时解决。

 select t.tradeflg from posmeriskcontrol t, posmercinf z where trim(z.mercid)='83xxxxxx' and trim(t.mercnum)=trim(z.mercnum) and t.tradeflg='0'

比如上面这个语句,很可能存在索引,但是因为trim导致索引不可用,所以可以使用函数索引来做为临时解决方案,带问题解决之后就可以和开发协商来彻底解决绑定变量和全表扫描的问题了。

 

上一篇:图解 Promise 实现原理(四)—— Promise 静态方法实现


下一篇:JSON解析-Jackson