zoukankan      html  css  js  c++  java
  • [摘]如何抓住蝴蝶效应中的那只蝴蝶

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

          蝴蝶效应可以参考这里

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

  • 相关阅读:
    Sentinel Dashboard(基于1.8.1)流控规则持久化到Nacos——涉及部分Sentinel Dashboard源码改造
    测试平台MeterSphere源码入门
    Java:利用BigDecimal类巧妙处理Double类型精度丢失
    SpringBoot整合任务调度框架Quartz及持久化配置
    任务调度框架Quartz快速入门!
    Kafka超详细学习笔记【概念理解,安装配置】
    Windows环境下Zookeeper安装配置
    SpringData JPA利用Specification多条件查询
    SpringBoot事件监听机制及观察者模式/发布订阅模式
    详解Java中的IO输入输出流!
  • 原文地址:https://www.cnblogs.com/killkill/p/2046321.html
Copyright © 2011-2022 走看看