最开始这位朋友是在微信群中留言，说有一个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%) |
我们来看看看问题节点，绝大部分的等待事件都在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 |
| 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 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 |
这个节点上的等待事件就完全不同了。可以看到很多和单实例数据库不同的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 |
| 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... |
当然了问题的原因基本定位，解决起来就容易多了，对于全表扫描的查询可以使用函数索引来临时解决。
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导致索引不可用，所以可以使用函数索引来做为临时解决方案，带问题解决之后就可以和开发协商来彻底解决绑定变量和全表扫描的问题了。