cursor: pin S wait on X等待事件的处理过程

最近负责的一个10204 for Linux as4的数据库(64bit)，会短暂出现大量cursor: pin S wait on X等待事件，部分操作会被挂起，最长等待时间大概4分钟，之后则会自行恢复。这个问题困扰了我一周多的时间，从现在的情况上看，我们应该是解决了这个问题。

　　以下则是事件的回放：

　　7月18日，应用反映17日下午16：56分左右，出现部分接口的调用操作无返回，要求协助检查原因。

　　要求应用提供数据进行核对，当时确认应用提供的那些需要处理的数据都是正常处理的，处理的时间与调用的时间并也无太大出入。

　　调用方设置的超时时间是60秒，60秒后会断开连接，判断为无返回。所以可能是延迟超过60秒未返回给调用方导致的。由于应用没有记录详细的接口调用日志，不能确定是数据库返回给应用延迟还是应用返回给调用方延迟。

　　我制作了发生问题的时间点的性能分析报告，可以确认部分sql的执行明显放缓，等待cursor: pin S wait on X事件，但是平均执行时间也就是1秒左右。应该不致导致应用60秒超时。几天以后我才意识到由于出现故障的时间很短，而正常情况下平均执行时间都是很短的，我的性能分析报告是1个小时的，但是出现故障的那一两分钟，插入记录的执行效率是非常低的，只是按照小时平均下来就没有那么明显了。

　　要求应用协助记录详细的调用及返回时间，便于确认是数据库的问题还是应用的问题。

　　7月23日左右，偶然发现当时核对的处理的数据都是取自A表的，调用该接口会在插入A表后，在B表也插入相应的记录，但是B表的插入时间则相差很多，也就是基本可以确定是数据库的延迟返回给应用导致的超时。进行了更详细的分析发现，A表的插入正常，但是B表在一段时间内没有插入任何记录，B表是插入频率相当高的表，所以这是非常不正常的，应该是被阻塞了。

　　想起6月29日和7月8日都出现过报警(ORA-03113: end-of-file on communication channel)，同一时间点大量的session中断了和数据库的连接，查询了报警时间点的B表记录，发现了相似的情况，阻塞的时间基本在1分多到2分多之间，但是已经不能得到那两个时间点的性能分析报告，不能确定当时的等待事件的情况。

　　出现问题的时间点，有时候是访问量稍大，有时候则完全是在低谷时，感觉上不应该是猛增的大量调用导致的问题。

　　由于6月29日、7月8日、7月17日出现的频率很像9-10天一次，所以我估计下一次出现在7月26日左右，并且企图寻找发生时间上的规律。

　　7月24日23点，又出现类似的现象，这次持续的时间在4分多钟，是最近几次发现的最长的一次。

　　从性能报告上看，仍然是cursor: pin S wait on X等待事件在首位，并发现大量的解析时间，但是解析的次数并没有变化。操作系统的参数上看，并没有发现io、cpu或者内存的异常。

　　之前我们一直怀疑是高负载导致的不同session之前的锁等待，这次可以确定不是由于高负载导致的锁等待，倒是大量的cursor等待导致了短时间的高负载。

　　这期间查询了metalink上很多的资料，主要从cursor: pin S wait on X着手处理，metalink上很多cursor: pin S wait on X的类似问题，有的确认是bug，有的是操作系统的问题，有的则因为不能重现就没了下文，但是并没有发现和我们完全吻合的情况，而且我们也不能重现这个问题。我们也察看过和mutex机制相关的视图，例如V$mutex_sleep，但是并没有得到有价值的信息。

　　有人提到是因为存在直方图，导致过度解析，建议如果不需要则删除直方图，他提到的现象中可以看到sql有大量的version count，检查我们的数据库，的确自动收集的统计信息中已经包括直方图，但是并没有发现发生过度解析，而且我们的程序编写是严格按照绑定变量调用的，不会存在因为sql不绑定变量导致的相关问题。

　　由于出现该等待的时候，数据库并不会抛出错误，新连接也是可以正常连接的，只有某个表的插入被阻塞，其他表的访问也都正常。这个等待事件平常也是出现的，只是不会占用大量的时间。所以我们的报警程序捕获不到这个问题，只能通过应用得反馈才知道又出现了，而等我们知道发生问题的时候，通常已经恢复正常了。我也一直没有下决心增加跟踪事件，因为不确定发生的频率和时间，担心跟踪文件把磁盘写满了。

　　因为这个表使用的复合分区，所以一度让我怀疑是这个版本的分区的bug。这个数据库在5月份打了最新的10204的补丁，在最初运行的一两个月里都没有出现过类似的情况，而最近应用都没有调整过，调用频率也没有大的变化。所以也可能是这个版本的bug。

　　周一上班后，应用反映最近几天都出现了类似问题，所以和发生的周期没有必然关系。

　　周二按照Leader的建议将函数、过程、触发器pin到shared pool，希望减少重载和解析，观察效果。周二17点左右再次出现，决定周三早上删除直方图观察效果。

　begin
　　DBMS_SHARED_POOL.KEEP ('owner.f_**','P');
　　end;
　　begin
　　DBMS_SHARED_POOL.KEEP ('owner.tr_**','R');
　　end;

　　周三早上删除直方图，周四中午12:58:25开始到00:01:35再次出现，决定周五凌晨修改session_cached_cursor重起数据库观察。

　begin
　　dbms_stats.gather_table_stats(ownname=> '***', tabname=> '****', estimate_percent=>10 , partname=> NULL,cascade => true,method_opt => 'FOR ALL COLUMNS SIZE 1');
　　end;

　　同时周三在测试环境修改隐含参数_kks_use_mutex_pin关闭cursor MUTEX进行测试，准备不得以的情况下通过修改隐含参数恢复使用原有的library cache机制。

　　周四下午我们详细的分析了v$active_session_history在出现问题时的情况，可以看到最初只有4个session在等待cursor: pin S wait on X，然后等待的session不断的增加，并且已经等待的session一直都是在等待中，直到某个时间点，所有session的等待都结束了，系统恢复了正常运行。我一直很费解的是为啥要以独占的方式获得锁，这些都是很频繁执行的sql，不需要反复解析的，而且业务并不复杂，都是绑定变量的，总共就那么几个屈指可数的sql，sharedpool也足够大了……总之是没想明白。

　　在检查v$active_session_history的时候，偶然发现在最初出现cursor: pin S wait on X等待的时候，伴随两个其他的等待事件，分别是buffer exterminate和library cache load lock，library cache load lock等待事件伴随阻塞的期间一直存在，但是只有一个session在等待，总体的等待时间很短。buffer exterminate等待事件则只在阻塞得最开始出现，马上就消失了。所以这两个等待事件在做性能分析报告的时候没有表现出来。分析这两个等待事件，buffer exterminate应该和sga的自动调整有关系，library cache load lock和sharedpool有关系，metalink上关于library cache load lock等待事件的建议是：

　　How to reduce the Library cache load lock?

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

　　If an object is not in memory, then a library cache lock cannot be acquired on it.

　　So the object has to be loaded into the memory to to acquire the lock.

　　Then the session tries to find the load lock for the database object so that it can load the object.

　　In order to prevent multiple processes to request the load of the same object simultaneously, the other requesting sessions have to wait for the library cache load lock as the lock is busy with loading the object into the memory.

　　The waits on the library cache load lock is due to the objects not available in the memory.

　　The inavailability of the library cache object in the library cache is due to the undersized shared pool causing reloads often, too many hard parse because of unshared sqls.

　　To avoid this, the general recommendation would be

　　1. To increase the shared pool ( to avoid the reloads often)

　　2. To increase the session cached cursors (to avoid the cursors flushing out of shared pool)

　　3. To set cursor_sharing to force (to reduce hard parsing)

　　由于sharedpool的大小是sga自动分配的，所以，我们系统修改session cached cursors观察效果，这个参数我们原来使用的是默认值20，需要重起生效。

　　同时，检查v$sga_resize_ops视图，发现在出现阻塞期间有sga的动态调整，调整的时间和阻塞得时间基本吻合。而且这个视图中记录了大量的sga变化，一会儿sharedpool减少一点儿，给了db buffer，一会儿又改回去了，我们觉得这些自动调整地必要性并不是很高，且怀疑等待事件的产生和sga的自动调整有关系，所以决定重起时关闭sga的自动调整，固定各个池的大小。

　　8月1日周五凌晨6点10分左右应用停服务，开始shutdown，shutdown时，数据库报ora-600：

　　ORA-00600: internal error code, arguments: [LibraryCacheNotEmptyOnClose], [], [], [], [], [], [], []

　　当时因判断和librarycache有关，应该不会影响启动，所以没有继续跟踪问题。

　　后来到公司后确认是oracle的bug：Bug 4483084 - OERI[LibraryCacheNotEmptyOnClose] on shutdown。

　　从重起到现在，没有再出现cursor: pin S wait on X的等待事件，有可能是关闭sga自动调整导致的，也有可能跟数据库重起有关，需要继续观察。

　　总结：

　　1、 v$active_session_history用来研究过去某个时间点的数据库的状况非常好用。

　　2、 SGA的自动调整的算法不知道怎样的，为什么会调整地那么频繁，对于我们这种访问比较固定且业务相对简单的数据库，也许不需要让他自动调整更好些。

　　3、 如果可以，我还是倾向于使用9i的稳定版本，大部分的问题都有人遇到过了，都会有比较稳妥的解决方案。新版本虽然可以使用新特性，但是总给人不太稳妥的感觉。

文章出处：飞诺网(www.firnow.com):http://dev.firnow.com/course/7_databases/oracle/oraclejs/20100624/211262.html

来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/8102208/viewspace-667253/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/8102208/viewspace-667253/