南美丛林的一只蝴蝶煽动翅膀，可能导致莫斯科下大雪，说明的大气系统的复杂性。而DBA在日常工作中叶经常会面临类似的问题，我们从故障的表象上分析问题处理问题，而往往我们采取的措施仅仅是解决一些表象的问题，并没有找到问题的关键。也就是说，我们并没有抓到扇翅膀的那只蝴蝶，而仅仅抓住了莫斯科上空的乌云。
前几天碰到一个案例，写出来和大家共享。客户有一套系统下午1点多的时候，突然出现了故障，服务无法响应，新会话连不上去。最后只能通过杀掉了大量的会话，才恢复正常。客户想找到问题的原因。找到我的时候已经是下午的4点多了。出现故障的时段有大量这样的信息：
- Mon Apr 11 12:52:24 2011
- Errors in file /oracle/app/oracle/admin/sjzzw2/udump/sjzzw22_ora_10410.trc:
- ORA-00603: ORACLE server session terminated by fatal error
- ORA-27544: Failed to map memory region for export
- ORA-27300: OS system dependent operation:bind failed with status: 227
- ORA-27301: OS failure message: Can't assign requested address
- ORA-27302: failure occurred at: sskgxpcre3
- Mon Apr 11 12:55:01 2011
- Errors in file /oracle/app/oracle/admin/sjzzw2/udump/sjzzw22_ora_13426.trc:
- ORA-00603: ORACLE server session terminated by fatal error
- ORA-27544: Failed to map memory region for export
- ORA-27300: OS system dependent operation:bind failed with status: 227
- ORA-27301: OS failure message: Can't assign requested address
- ORA-27302: failure occurred at: sskgxpcre3
- Mon Apr 11 12:55:25 2011
- Errors in file /oracle/app/oracle/admin/sjzzw2/udump/sjzzw22_ora_13934.trc:
- ORA-00603: ORACLE server session terminated by fatal error
- ORA-27544: Failed to map memory region for export
- ORA-27300: OS system dependent operation:bind failed with status: 227
- ORA-27301: OS failure message: Can't assign requested address
- ORA-27302: failure occurred at: sskgxpcre3
- Mon Apr 11 12:55:25 2011
- Errors in file /oracle/app/oracle/admin/sjzzw2/udump/sjzzw22_ora_13936.trc:
- ORA-00603: ORACLE server session terminated by fatal error
- ORA-27504: IPC error creating OSD context
- ORA-27300: OS system dependent operation:bind failed with status: 227
- ORA-27301: OS failure message: Can't assign requested address
- ORA-27302: failure occurred at: sskgxpcre3
- Mon Apr 11 12:55:25 2011
- Errors in file /oracle/app/oracle/admin/sjzzw2/udump/sjzzw22_ora_13938.trc:
- ORA-00603: ORACLE server session terminated by fatal error
- ORA-27504: IPC error creating OSD context
- ORA-27300: OS system dependent operation:bind failed with status: 227
- ORA-27301: OS failure message: Can't assign requested address
- ORA-27302: failure occurred at: sskgxpcre3
- Mon Apr 11 12:56:00 2011
- Thread 2 advanced to log sequence 2945 (LGWR switch)
- Current log# 4 seq# 2945 mem# 0: /redolog/sjzzw2/redo04.log
- Mon Apr 11 12:56:01 2011
- Errors in file /oracle/app/oracle/admin/sjzzw2/udump/sjzzw22_ora_14554.trc:
- ORA-00603: ORACLE server session terminated by fatal error
- ORA-27544: Failed to map memory region for export
- ORA-27300: OS system dependent operation:bind failed with status: 227
同时还存在一些类似的ORA-27XXX错误：
- Mon Apr 11 12:56:33 2011
- Errors in file /oracle/app/oracle/admin/sjzzw2/udump/sjzzw22_ora_22957.trc:
- ORA-27509: IPC error receiving a message
- ORA-27300: OS system dependent operation:recvmsg failed with status: 216
- ORA-27301: OS failure message: Socket operation on non-socket
- ORA-27302: failure occurred at: sskgxprcv1
- Mon Apr 11 12:56:33 2011
- Errors in file /oracle/app/oracle/admin/sjzzw2/udump/sjzzw22_ora_25431.trc:
- ORA-27509: IPC error receiving a message
- ORA-27300: OS system dependent operation:recvmsg failed with status: 216
- ORA-27301: OS failure message: Socket operation on non-socket
- ORA-27302: failure occurred at: sskgxprcv1
- Mon Apr 11 12:57:24 2011
根据
- ORA-27300: OS system dependent operation:recvmsg failed with status: 216
现场工程师认为是BUG 6689903导致，建议关闭NUMA。客户准备晚上实施关闭NUMA的操作，想听听我的建议。我觉得关闭NUMA时一个十分大的操作，应该十分谨慎，因此先要搞清楚到底是什么导致了今天的问题。从ORA-27300来看，一般来说是某种OS资源不足导致的问题。因此我们首先要从分析错误信息开始，HP-UX的ERRNO=227，216
- # define ENOTSOCK 216 /* Socket operation on non-socket */
- # define EADDRNOTAVAIL 227 /* Can't assign requested address */
216是在非SOCKET上操作SOCKET操作，227是无法分配地址。对于BUG 6689903，Oracle官方解释是使用了NUMA后，Oracle存在一个BUG，导致一个会话使用了大量的UDP端口，造成UDP端口不足。可以通过打补丁或者关闭NUMA来解决这个问题。而UDP端口耗尽也可能出现ERRNO =227，无法分配地址的错误。因此可以初步判断是由于UDP端口耗尽导致了问题。在这种情况下打PATCH 6689903可以解决过多UDP端口被一个会话消耗的问题，但是不一定能解决所有的问题，当系统负载进一步加大（系统设置的PROCESSES=4500，而出故障时发现会话数无法突破1600）,可能还会出问题。关闭NUMA虽然可以减少UDP端口的使用，但是会降低系统的性能，无法充分享受大型SMP系统的架构优势，也是不足取的。因此较好的解决这个问题是打PATCH 6689903，避免由于BUG过多消耗UDP端口，另外调整UDP端口的范围，从而让OS提供更多的UDP端口。通过下面命令：
- oracle@sjzzw22:/usr/include/sys$ ndd -get /dev/udp udp_largest_anon_port
- 65535
- oracle@sjzzw22:/usr/include/sys$ ndd -get /dev/udp udp_smallest_anon_port
- 49152
我们看到系统的UDP端口使用了缺省值，通过调整这两个值，使中间的区间变大，就能提供更多的UDP端口号了。问题分析道这里，看样子已经解决的差不多了。可能大多数DBA到此就大功告成了。而老白认为其实不然，如果说建议NUMA只是看到了下雪时莫斯科上空的乌云，那么分析到这里也仅仅看到了西伯利亚冷空气的影响。离那只南美洲的蝴蝶还有万里之遥呢。
老白当然会继续分析下去，是什么原因导致了UDP端口号被消耗光呢？客户说平时这个系统会话数在1000出头，故障时会话数达到了1600。这个是UDP端口号被消耗光的一个很好的解释。但是为什么会话数会突增呢?通过对应用架构的了解，我们知道这个系统的大多数应用没有采用连接池，而是客户端直接连接的，当系统处理能力下降时，客户端连接数据库的连接会增加，以适应外部服务的请求。因此我们可以将怀疑点集中到系统出现了变慢的情况。如果在故障前的某个时段，系统突然变慢了，那么就有可能造成会话数增加的可能。会话数增加后，UDP端口配置过低的问题就暴露出来了。
那么接下来我们就需要分析系统为什么会变慢，在什么时间变慢的。我们继续分析ALERT LOG，发现第一次报错的时间是12点41分左右：
- Mon Apr 11 12:38:06 2011
- Thread 2 advanced to log sequence 2940 (LGWR switch)
- Current log# 3 seq# 2940 mem# 0: /redolog/sjzzw2/redo03.log
- Mon Apr 11 12:40:58 2011
- Errors in file /oracle/app/oracle/admin/sjzzw2/udump/sjzzw22_ora_25451.trc:
- ORA-00603: ORACLE server session terminated by fatal error
- ORA-27544: Failed to map memory region for export
- ORA-27300: OS system dependent operation:bind failed with status: 227
- ORA-27301: OS failure message: Can't assign requested address
- ORA-27302: failure occurred at: sskgxpcre3
- Mon Apr 11 12:40:59 2011
- Trace dumping is performing id=[cdmp_20110411124059]
看样子故障点应该在12点41分之前。于是我们做一个ASH报告，来看看12：:00-12:40之间系统发生了什么，为了便于分析，我们先按照10分钟周期做4个报告，在前面三个报告中，一切正常，在12:30-12:40的报告中，我们发现了一个疑点：
- gcs drm freeze in enter server 24
在1分钟内，活跃会话的采样中，出现了24次drm的等待平均等待时间600毫秒左右。而且这个时间段内的SQL执行次数，BUFFER GET等指标明显低于前面的时段。因此我们可以初步断定，这可能是导致会话数量突增的一个重要疑点。而这个系统的另外一个节点跑的是完全不同的应用，而且还没有投产，为什么会出现这么多DRM呢？通过LMD,LMON，LMS等的日志我们也看出，在12:36-38这段时间里的DRM数量比前面时段增加了数倍。于是我们在另外一个节点上的12:30-12:40生成了一个ASH报告，从这里我们终于看到了那只美丽的蝴蝶的真面目了，原来在这个时段，在另外一个节点上有人用SQLPLUS登陆上去，访问了大量的故障节点的数据。而这个操作导致了DRM事件增加，短暂降低了系统的性能。如果UDP端口号够用，这个影响不会被放大，而仅仅会在12点多钟业务不繁忙时段出现短暂几分钟的性能下降，很快就会平息。而正是由于UDP端口号不足，才放大了这个蝴蝶扇翅膀动作。
抓住了这只蝴蝶，那么如何解决这个问题就很明显了，尽可能不要出现类似的操作肯定是要提的。不过另外一个问题也是需要我们考虑的，在这样的一个系统中，DRM其实是不必要的，因为正常情况下，两个节点会跑自己的数据，不会交叉。因此关闭DRM是一个更靠谱的选择。
大家可能对关闭DRM这个结局感到意外，不过如果你看过了这个抓蝴蝶的全过程，你就会认为这是顺理成章的事情了。
事情就是这么简单，但是我想大多数人只会走到这个过程中的某个步骤，就停下了。这就是DBA之间的差距，不仅仅是技术上的，更多的是态度的问题。
本文链接：http://www.oraclefans.cn/blog/showblog.jsp?rootid=32059
【编辑推荐】
