RAC 性能诊断实例 --- TX - index contention

ALLSTARS_ORACLE

RAC 性能诊断实例 --- TX - index contention


最近，很多读者反应，希望能够写一些实际案例分析的文章。这种文章会和大家的实际工作更接近一些。
而且，最近解决了一些RAC 的性能问题。在这里，找到了一个比较有代表性的例子，和大家分享一下，也欢迎大家一起讨论。


问题的症状很明确，在一个双节点的RAC 数据库中，数据库大概hang住了10分钟，之后自动恢复正常了。而且，问题只发生在实例1上，实例2是正常的。


首先，我们搜集了问题期间的实例1 的 AWR报告（实例2的AWR也被搜集了，但是并没有什么异常，所以没有贴出来），发现了以下的信息。


Top 5 Timed Foreground Events


Event Waits Time(s) Avg wait (ms) % DB time Wait
Class

enq: TX - index contention 448 90,738 202540 51.18 Concurrency

enq: US - contention 134,660 64,312 478 36.27 Other

resmgr:cpu quantum 98,992 12,204 123 6.88 Scheduler

gc current grant busy 21,377 7,352 344 4.15 Cluster

latch: enqueue hash chains 2,126 6,422 3021 3.62 Other


我们能看到，等待事件“enq: TX - index contention” 是等待时间最长的事件，而且平均等待时间很长。


Instance Activity Stats

=================

branch node splits 6 0.00 0.00

leaf node 90-10 splits 124 0.09 0.00

leaf node splits 674 0.47 0.00


Segments by Row Lock Waits

=================


Owner Tablespace Name Object Name Subobject
Name Obj. Type Row Lock Waits % of Capture

XXXX XXXX A
INDEX 836 71.03

XXXX XXXX B
INDEX 185 15.72

XXXX XXXX C
INDEX 68 5.78

XXXX XXXX D
TABLE 59 5.01

XXXX XXXX E
TABLE 20 1.70


我们能看到，产生最高的row lock等待时间的对象是一个索引。


另外，客户确认以下的sql 语句是执行最频繁的。

insert into XXXX (......) values (:1, :2, :3, :4, :5, :6,
:7......);


从以上的信息，似乎我们很容易认为这个问题是由于过多的索引块分裂，或者由于过多相近的值被insert 到表里，导致了索引的争用。



但是，在和客户进一步确认后，发现上面的想法应该是错误的，因为我们得到了以下的反馈。

1. 经过和正常性能时的AWR报告相比，等待事件 “enq: TX - index contention” 的确在数据性能正常时没有出现。

2. 和正常性能时的AWR比较后，并没有看到索引分裂有明显增加。

3. 和性能正常时比较，insert语句执行的次数并没有增加。而且，数据库的负载并没有增长。

4. 另外，根据TX等待事件的平均等待时间（202540ms,
也就是超过200秒), 看起来更象是类似于某些进程hang住导致的。


接下来 ，我们查看了DBA_HIST_ACTIVE_SESS_HISTORY的信息，但是很遗憾，有大概10分钟的信息是空白的。比较幸运的是，问题开始的几分钟还是有信息出现的。所以，我们取到了最初几分钟的ASH报告，并发现，下面的进程阻塞了上面我们提到的insert 语句。

Blocking Sid (Inst) %
Activity Event Caused % Event User Program # Samples Active XIDs

1234, 5678( 1) 46.92
enq: TX - index contention 46.92 XXXX JDBC Thin Client 25/150 [ 17%] 1


另外，根据DBA_HIST_ACTIVE_SESS_HISTORY 中的信息，我们发现上面的blocker进程（1234,
5678( 1)）一直在等待“latch: object queue header operation”。问题到这一步，有些朋友可能会得出结论，问题是由于DRM导致的，因为等待事件“latch: object queue header
operation”是在DRM时产生的。但是，我们并没有相关的信息来支持我们的判断，而且，这时候我们只能确认问题和DRM 相关，但是不能确定就是DRM导致的，而是有两种可能性：

1. 问题的确是由于DRM导致的。

2. DRM在问题期间的确发生了，但是由于数据库性能的问题，DRM也是受害者之一。


我们知道，对于DRM，lms,lmd 和lmon进程都会参与。所以，接下来要做的事情是查看这些进程的trace file 和 OSW报告，来确认这些进程的状态。幸运的是，我们很快有了新的发现。

lmon 跟踪文件

......

*** 2013-xx-xx
xx:xx:xx.xxx

==============================

kjfmHBcheck: LMS0
(ospid: xxxxxx) not moving for 21 sec (1367110915.1367110894)

: Not in wait; last wait ended 0 secs ago.

: last wait_id 655230104 at 'latch: gc
element'.


*** 2013-xx-xx
xx:xx:xx.xxx

==============================

kjfmHBcheck: LMS1
(ospid: xxxxxx) not moving for 20 sec (1367110916.1367110896)

: Not in wait; last wait ended 0 secs ago.

: last wait_id 671495420 at 'latch: gc
element'.


看起来lms 进程的确有性能问题。

lms 跟踪文件

......

*** 2013-xx-xx
xx:xx:xx.xxx

DRM(516) win(1) lms 0
finished replaying gcs resources

kjfmHBupdateTime: took
33 seconds for 255 heartbeats

lms 0 finished fixing
gcs write protocol


*** 2013-xx-xx
xx:xx:xx.xxx

DRM(517) win(1) lms 0
finished replaying gcs resources


*** 2013-xx-xx
xx:xx:xx.xxx

lms 0 finished fixing
gcs write protocol


*** 2013-xx-xx
xx:xx:xx.xxx

SKGXP_TRACE_FLUSH:
output truncated 11 traces lost

SKGXP_TRACE_FLUSH:
start

SKGXP: (16520 <-
7836)SKGXPDOCON:can't accept new connections under timed wait context

SKGXP: (16520 <-
7390)SKGXPDOCON:can't accept new connections under timed wait context

SKGXP: (16520 <-
7404)SKGXPDOCON:can't accept new connections under timed wait context

SKGXP: (16520 <-
9004)SKGXPDOCON:can't accept new connections under timed wait context

SKGXP: (16520 <-
9089)SKGXPDOCON:can't accept new connections under timed wait context

SKGXP: (16520 <-
7344)SKGXPDOCON:can't accept new connections under timed wait context

SKGXP: (16520 <-
7470)SKGXPDOCON:can't accept new connections under timed wait context

SKGXP: (16520 <-
9495)SKGXPDOCON:can't accept new connections under timed wait context

SKGXP: (16520 <-
7676)SKGXPDOCON:can't accept new connections under timed wait context

SKGXP: (16520 <-
9192)SKGXPDOCON:can't accept new connections under timed wait context

SKGXP: (16520 <-
8758)SKGXPDOCON:can't accept new connections under timed wait context

SKGXP_TRACE_FLUSH: end

看起来，lms的确能够完成DRM的工作，但是正在忙于接受新的数据库链接。对于RAC数据库，当新的数据库连接被建立时lms进程需要在实例之间对新的会话进行一些数据的传递，这是正常的。而且，虽然客户没有安装OSW，但是从客户安装的第三方操作系统监控软件，我们发现在问题期间lms进程占用了100% cpu时间。

所以，我们可以看到，DRM并不是导致问题的原因，而是受害者之一。而问题的真正的原因可能有以下的两种可能。

1. 过多的数据库连接导致lms 忙于处理新的数据库连接，而无法处理其他的请求。

2. Oracle 存在bug，导致了lms 进程在处理新的连接时spin 在了某个地方。这种判断的主要依据是lms进程占用了100% cpu，这说明lms进程很忙。

最后，我们搜集到了问题期间的listener 日志。但是无法拿到lms进程的堆栈信息（diag和 lmon进程并没dump
lms进程的堆栈信息，而且客户也没有在问题期间搜集lms进程的pstack信息输出）。接下来，问题的原因水落石出----“连接风暴”。因为我们在问题出现之前的大概5分钟到问题结束，每分钟会有大概300个链接尝试连接数据库，而在正常期间，每分钟大概只有10个链接左右。当连接风暴结束之后，数据库也恢复正常运行了。

总结：实际工作中我们会遇到很多常见的问题，可以利用经验进行判断，并直接给出所谓的原因和解决方案，而且有时候的确是正确的。但是，从oracle support的角度来讲，在诊断问题过程中，我们需要的是了解在问题期间系统到底发生了什么，同时运用我们的知识来进行分析，并且找到相应的证据支持自己的分析，最后找到问题真正的原因，并给出相应的解决方案。而且，即使我们不能得到足够的信息进行完整的分析，我们也需要利用我们的知识和已有的信息，来给出问题可能的原因和比较“靠谱”的解决方案，而不能仅仅依靠我们的经验。

注意：以上问题中AWR和跟踪文件中的涉及客户系统的信息已经被修改或者没有贴出来。