LMHB terminating RAC instance due to ora-29770

Roger 2019-06-17
65
0 0
摘要:根据这个原理,我们可以大致判断,lms1 进程hung的时间点到被kill的时间点,前后应该相差大概70+20=90秒。因此可能在14:04:43 时间点,lms1进程就出问题了。

问题描述

前段时间某客户的一套核心系统Oracle RAC节点实例突然被重启,如下是简单的分析过程,供参考。
节点1 alert log如下:

Sun Aug 02 12:00:13 2015
Archived Log entry 7156 added for thread 1 sequence 3618 ID 0x46c8ccfe dest 1:
Sun Aug 02 14:06:13 2015
LMS1 (ospid: 3867316) waits for event 'gcs remote message' for 95 secs.
Sun Aug 02 14:06:28 2015
Errors in file /u01/app/oracle/diag/rdbms/abs/abs1/trace/abs1_lmhb_4456870.trc  (incident=180130):
ORA-29770: global enqueue process LMS1 (OSID 3867316) is hung for more than 70 seconds
Incident details in: /u01/app/oracle/diag/rdbms/abs/abs1/incident/incdir_180130/abs1_lmhb_4456870_i180130.trc
Sun Aug 02 14:06:35 2015
Sweep [inc][180130]: completed
Sweep [inc2][180130]: completed
Sun Aug 02 14:06:39 2015
ERROR: Some process(s) is not making progress.
LMHB (ospid: 4456870) is terminating the instance.
Please check LMHB trace file for more details.
Please also check the CPU load, I/O load and other system properties for anomalous behavior
ERROR: Some process(s) is not making progress.
LMHB (ospid: 4456870): terminating the instance due to error 29770
Sun Aug 02 14:06:39 2015
opiodr aborting process unknown ospid (6946832) as a result of ORA-1092
Sun Aug 02 14:06:39 2015
ORA-1092 : opitsk aborting process
Sun Aug 02 14:06:39 2015
System state dump requested by (instance=1, osid=4456870 (LMHB)), summary=[abnormal instance termination].
System State dumped to trace file /u01/app/oracle/diag/rdbms/abs/abs1/trace/abs1_diag_5243044_20150802140639.trc
Instance terminated by LMHB, pid = 4456870
Sun Aug 02 14:07:05 2015
Starting ORACLE instance (normal)
LICENSE_MAX_SESSION = 0
LICENSE_SESSIONS_WARNING = 0
Initial number of CPU is 24
Number of processor cores in the system is 6


专家解答

我们可以看到,在14:06:28时,LMS1 进程被发现已经hung了超过70秒。 根据之前的时间点14:06:13 所报的信息来看,在14:06:13 时刻,已经LMS1进程等待gcs remote message超过95秒,这2个时间点前后相差了15秒。
根据时间点,我们可以大致推测至少在14:05:18时间点,LMS1进程已经hung。对于lms进程的check,Oracle 是20s检查一次,超过70s 无响应,则会被kill掉。根据这个原理,我们可以大致判断,lms1 进程hung的时间点到被kill的时间点,前后应该相差大概70+20=90秒。因此可能在14:04:43 时间点,lms1进程就出问题了。
由于lmhb进程负责check,那么我们首先来分析下该进程的trace内容,如下:

*** 2015-08-02 14:05:13.114
==============================
LMS1 (ospid: 3867316) has not moved for 38 sec (1438495512.1438495474)
kjfmGCR_HBCheckAll: LMS1 (ospid: 3867316) has status 2
  : waiting for event 'gcs remote message' for 35 secs with wait_id 54010017.
  ===[ Wait Chain ]===
  Wait chain is empty.
kjgcr_SlaveReqBegin: message queued to slave
kjgcr_Main: KJGCR_ACTION - id 3
CPU is high.  Top oracle users listed below:
     Session           Serial         CPU
     967                75             0
     1538               51             0
     681                43             0
     586                79             0
     2097              905             0

从上面的内容来看,14:05:13 报错lms1 进程超过38秒没有响应,根据计算,我们可以得知在14:04:35开始,lms1进程开始hung。hung的过程中表现出来的等待事件为gcs remote message。 同时也可以发现Oracle 认为在时间点CPU 使用率很高,而且还列出了TOP session.
然而仅仅从上述的分析,我们无法判断是什么原因导致实例被强行终止的。根据客户提供的信息,我还发现产生了一个diag文件,从该文件中我发现了如下的内容:

*** 2015-08-02 14:06:24.009
Suspected Hangs in the System
                     Root       Chain Total               Hang
  Hang Hang          Inst Root  #hung #hung  Hang   Hang  Resolution
    ID Type Status   Num  Sess   Sess  Sess  Conf   Span  Action
 ----- ---- -------- ---- ----- ----- ----- ------ ------ -------------------
      1 HANG    VALID    2  2002     2     3    LOW  LOCAL Terminate Process  

  inst# SessId  Ser#     OSPID Event
  ----- ------ ----- --------- -----
      2    862  3253  37290036 gc buffer busy acquire
      2   2002    85  43974802 gc current request

*** 2015-08-02 14:06:28.400
Process diagnostic dump for oracle@scdb01 (LMS1), OS id=3867316,
pid: 14, proc_ser: 1, sid: 1331, sess_ser: 1
-------------------------------------------------------------------------------
os thread scheduling delay history: (sampling every 1.000000 secs)
  0.000000 secs at [ 14:06:27 ]
    NOTE: scheduling delay has not been sampled for 0.954714 secs  0.000000 secs from [ 14:06:23 - 14:06:28 ], 5 sec avg
  0.000000 secs from [ 14:05:29 - 14:06:28 ], 1 min avg
  0.000915 secs from [ 14:01:28 - 14:06:28 ], 5 min avg
loadavg : 2.44 2.58 2.46
swap info: free_mem = 2108.95M rsv = 256.00M
           alloc = 150.32M avail = 65536.00M swap_free = 65385.68M
       F S      UID      PID     PPID   C PRI NI ADDR    SZ    WCHAN    STIME    TTY  TIME CMD
  240103 A   oracle  3867316        1   0  39 -- e58765590 223348            Jul 22      - 59:03 ora_lms1_abs1

从上述信息我们可以看出,部分会话已经挂起。同时我们还能看出当时该数据库节点的load 其实并不高,平均只有2.5左右。同时数据库节点的物理内存还有2G的free memory。因此似乎从这一点仍然无法直接判断是否是因为资源的问题,导致LMS1进程hung。
在Oracle RAC的案例分析中,我们通常会去分析几个相关的核心进程,因此这里我们再来看下lmd进程是否有什么异常:

---lmd0(节点1)
2015-08-02 06:05:32.652627 : 

* End DRM for pkey remastering request(s) (locally requested)
kjddt2vb: valblk  [0.22] > local ts [0.21]

*** 2015-08-02 14:04:52.128
kjddt2vb: valblk  [0.24] > local ts [0.23]

*** 2015-08-02 14:04:53.094
kjddt2vb: valblk  [0.27] > local ts [0.26]

*** 2015-08-02 14:04:54.199
kjddt2vb: valblk  [0.2c] > local ts [0.2b]
......
......
*** 2015-08-02 14:06:23.153
kjddt2vb: valblk  [0.27b] > local ts [0.27a]

*** 2015-08-02 14:06:24.039
kjddt2vb: valblk  [0.289] > local ts [0.288]

*** 2015-08-02 14:06:25.118
kjddt2vb: valblk  [0.28f] > local ts [0.28e]

从节点1的lmd进程trace内容来看,从14:04:52左右开始出现类似kjddt2vb: valblk  [0.22] > local ts [0.21]这样的信息。这部分信息的出现,说明当时有数据块正在通过cache fusion进行传输,这与lms进程表现的gcs remote message 完全一致。 然而这仍然不能说明什么问题。
此外,我在trace中发现lms1 进程的call stack内容如下:

*** 2015-08-02 14:06:39.455
==============================
LMS1 (ospid: 3867316) has not moved for 124 sec (1438495598.1438495474)
kjzduptcctx: Notifying DIAG for crash event
----- Abridged Call Stack Trace -----
ksedsts()+240<-kjzdssdmp()+240<-kjzduptcctx()+228<-kjzdicrshnfy()+120<-ksuitm()+5136<-kjgcr_KillInstance()+160<-kjgcr_Main()+3564<-kjfmlmhb_Main()+104<-ksbrdp()+2216<-opirip()+1620<-opidrv()+608<-sou2o()+136<-opimai_real()+188<-ssthrdmain()+276<-main()+204
<-__start()+112
----- End of Abridged Call Stack Trace -----

同时lms1进程的diag dump 信息如下:

--DDE Diagnostic Information Dump
----- Invocation Context Dump -----
Address: 0x1108e8948
Phase: 3
flags: 0x1AE0005
Incident ID: 180130
Error Descriptor: ORA-29770 [LMS1] [3867316] [70] [] [] [] [] [] [] [] [] []
Error class: 0
Problem Key # of args: 0
Number of actions: 9
----- Incident Context Dump -----
Address: 0xfffffffffff21a8
Incident ID: 180130
Problem Key: ORA 29770
Error: ORA-29770 [LMS1] [3867316] [70] [] [] [] [] [] [] [] [] []
[00]: dbgexExplicitEndInc [diag_dde]
[01]: dbgeEndDDEInvocationImpl [diag_dde]
[02]: dbgeEndSpltInvokOnRec [diag_dde]
[03]: dbgePostErrorKGE [diag_dde]
[04]: dbkePostKGE_kgsf [rdbms_dde]
[05]: kgeade []
[06]: kgesev []
[07]: ksesec3 [KSE]
[08]: ksdx_cmdreq_wait_for_pending [VOS]<-- Signaling
[09]: ksdxdocmdmultex [VOS]
[10]: ksdxdocmdmult [VOS]
[11]: ksudmp_proc_short_stack [ksu]
[12]: ksdhng_diag_proc_int [hang_analysis]
[13]: ksdhng_diag_proc [hang_analysis]
[14]: kjdgpstack_wTimeout []
[15]: kjfmHealth_Proc_Dump []
[16]: kjfmHBgenerateReport_i []
[17]: kjfmHBgenerateADR []
[18]: kjfmGCR_VerifyNoHeartbeatProc []
[19]: kjfmGCR_HBdisambig []
[20]: kjgcr_ChooseAction []
[21]: kjgcr_Main []
[22]: kjfmlmhb_Main []
[23]: ksbrdp [background_proc]
[24]: opirip []
[25]: opidrv []
[26]: sou2o []
[27]: opimai_real []
[28]: ssthrdmain []
[29]: main []
[30]: __start []
MD [00]: 'SID'='1521.1' (0x2)
MD [01]: 'ProcId'='16.1' (0x2)
MD [02]: 'Client ProcId'='oracle@scdb01.4456870_1' (0x0)
Impact 0:

根据上述的call stack信息,我认为根据Oracle bug 13539862 基本上完全一致。
Bug 13539862 : ORA-29770 AND LMHB (OSPID: 21429) IS TERMINATING THE INSTANCE
根据Oracle mos的描述,该bug所影响版本为11.2.0.2,但是并没说在之后的版本中已经修复,由于客户的环境为Oracle 11.2.0.4,因此是不是完全确认是这个bug 导致,这个难以确认;实际上,我们也遇到过多次bug在老版本出现,Oracle说明已经在新版本修复,但是发现仍然存在的这种情况。因此,我们不完全排除这个bug.
备注:该bug的call stack信息,需要使用Oracle 原厂账户进行查看。
除此之外,我认为还可能跟Oracle的read mostly locking特性有关系,这是Oracle DRM的功能之一;虽然Oracle support坚持认为trace中没有出现DRM相关的动作;即使如此,我们仍然建议屏蔽该特性。可以通过如下的方式:alter system set “_gc_read_mostly_locking”=false scope=spfile; alter system set “_gc_bypass_readers”=false scope=spfile;
上述是我的个人分析,然而oracle support似乎并不认同,认为可能是tickets不足导致的,实际上这一点很容易排除。 首先从故障前的awr数据也可以大致判断:

                            % of direct sent messages:    77.17
                          % of indirect sent messages:    22.59
                        % of flow controlled messages:     0.23

Global Messaging Statistics               DB/Inst: ABS/abs1  Snaps: 9963-9964

Statistic                                    Total   per Second    per Trans
--------------------------------- ---------------- ------------ ------------
acks for commit broadcast(actual)           64,640         17.9          1.0
acks for commit broadcast(logical           65,720         18.2          1.0
broadcast msgs on commit(actual)            66,994         18.6          1.0
broadcast msgs on commit(logical)           67,554         18.7          1.0
broadcast msgs on commit(wasted)               303          0.1          0.0
dynamically allocated gcs resourc                0          0.0          0.0
dynamically allocated gcs shadows                0          0.0          0.0
flow control messages received                   0          0.0          0.0
flow control messages sent                       0          0.0          0.0

如果是ticket不足,那么flow controled的指标应该会比较高的。不过,这个awr是13-14点的,故障在14:05分,因此也不能完全否认。但是根据经验来看,我认为跟tickets不足的现象完全符合。
其次,从trace 内容也可以得到确认:

Dest 2  rcvr 0  inc 4  state 0x10041  tstate 0x0
  batch-type quick  bmsg 0x0  tmout 0xa39c37  msg_in_batch 0
  <span style="color: #ff0000;">tkt total</span> 1000  <span style="color: #ff0000;">avl</span> 750 sp_rsv 250 max_sp_rsv 250
  seq wrp 0  lst 2743820  ack 0  snt 2743815
  sync seq 0.2743815  inc 0
  sndq enq seq :[0]0.2652465:[1]0.0:[2]0.2743815
  batch snds 46270  tot msgs 92586  max sz 29 fullload 0 snd seq 46270
  pbatch snds 1320047  tot msgs 1430965
  sndq msg tot 1495723  tm (0 253301)
  sndq msg 0  maxlmt 2231853  maxlen 52  wqlen 223061
  sndq msg 0  start_tm 0  end_tm 0

从trace 内容来看,实际上tickets还有750,只用了1/4。 基于这2种原因,我可以肯定的说,这不是tickets不足导致的。那么话又说回来,说了这么多,到底是神马问题导致的呢? 前面说提到的Oracle Bug 13539862 吗?
我们从根本上来分析下,lms1进程为什么会hung ? 导致进程hung的原因,我认为无非就如下几种:
1) CPU 严重不足,即大家所说的CPU饥饿

2)  IO/memory问题,导致数据库极慢,以至于LMS1响应极度缓慢,例如swap使用极高。

3) cache fusion数据交互量极大

4)  Oracle bug

5) tickets不足(实际上,当数据交互较大时,就建议调整tickets数量)
上面的5个原因中,除了第4个,基本上其他的都可以排除。这里需要注意的是,如果要排除CPU的问题,那么我们可能还需要看数据库环境是什么?是虚拟化的还是物理机 ?比较巧合的是客户的这套环境正好是IBM PowerVM,这里我不否认PowerVM的优点,实际上在我们这一年的案例中,至少遇到3起PowerVM导致rac节点重启的案例。
其中比较关键的一点是PowerVM的processor folding功能,俗称CPU折叠,当该功能启用时,PowerVM会动态调节资源。这很可能会导致Oracle 进程无法获得资源的情况。
PowerVM的虚拟化比较复杂,其中包括微分区、VIOS等,微分区即是将CPU进行分片,一个CPU可以最多分1份,然后以1%的粒度来动态调整资源。那么这次故障是不是PowerVM的这个功能导致的呢? 我认为可能性还是比较大的,暂时分析到这里!


「喜欢文章,快来给作者赞赏墨值吧」

评论

0
0
Oracle
订阅
欢迎订阅Oracle频道,订阅之后可以获取最新资讯和更新通知。
墨值排行
今日本周综合
近期活动
全部
相关课程
全部