记一次远程协助分析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...