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

今天通过微信群和qq帮助一个网友分析了一个rac节点性能的问题，征得这位朋友的同学，和大家分享一下。
最开始这位朋友是在微信群中留言，说有一个rac的问题，现在已经严重影响在线业务了，希望我能够帮忙看看，有什么好的建议没，这对我来说着实是一个提高自己，分析问题的好机会，因为在地铁上，自己就简单确认了下环境，然后让他提供一些基本的错误日志或者报告。方便定位问题。
首先确认环境，得知这是一个rac 11g的环境，有两个节点，其它未知，根据这位朋友的反馈，有一个节点最近老出问题，前几天每天都报ora-00604,00609的错误，他查了下，说发现不是网络的问题就是sql语句的问题，然后今天节点又挂了，下午的时候报了ora-00020连接数超出的错误。作为临时解决方案，他把业务迁移到另外一个节点上之后就没有了问题，连接数也正常了。
从他的反馈来说，感觉这个节点存在一定的问题，但是不确定到底是什么原因，想让我来看一下。
很快从他那里得到了一个错误日志的截屏。

但是错误信息毕竟有限，而且这种错误还需要依赖上下文环境，这个时候手头也没有metalink来查看，就让这位朋友生成问题发生时间段的ash报告，把问题节点的ash报告和正常节点的ash报告都抓取一下。
过了一会，他就生成了ash报告，我让他把等待事件/top sql的部分贴出来。得到的截图如下：

在有限的信息中，这个问题着实让我捡了个大便宜，因为一看这部分，似乎问题的根源就有了眉目。
首先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导致索引不可用，所以可以使用函数索引来做为临时解决方案，带问题解决之后就可以和开发协商来彻底解决绑定变量和全表扫描的问题了。