[摘]如何抓住蝴蝶效应中的那只蝴蝶

      原文地址:如何抓住蝴蝶效应中的那只蝴蝶

      蝴蝶效应可以参考这里

      南美丛林的一只蝴蝶煽动翅膀,可能导致莫斯科下大雪,说明的大气系统的复杂性。而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之间的差距,不仅仅是技术上的,更多的是态度的问题。

posted @ 2011-05-14 15:34  killkill  阅读(2593)  评论(2编辑  收藏