RAC环境，节点1被驱逐

mastermouse

环境信息：X86 + Redhat6.1 + Oracle 11.2.0.3 两节点RAC
故障的发生时间点大概为：25号的12点44分，节点1被驱逐后自动重启。
相关的日志如附件

Mille

    client details:
      O/S info: user: , term: , ospid: 1234
      machine: BPPF_OMP2 program: Hibernate with C3P0
      application name: Hibernate with C3P0, hash value=3432344232
    Current Wait Stack:
     0: waiting for 'latch: shared pool'
        address=0x601092e8, number=0x133, tries=0x0
        wait_id=17 seq_num=18 snap_id=1
        wait times: snap=11 min 40 sec, exc=11 min 40 sec, total=11 min 40 sec
        wait times: max=infinite, heur=11 min 40 sec
        wait counts: calls=0 os=0
        in_wait=1 iflags=0x2520

找一下hash value=3432344232语句优化一下，这个消耗1节点资源比较大

Maclean Liu(刘相兵

你说 的是 节点重启了 还是 实例重启了

似乎没有看到节点重启的信息


Fri Aug 23 18:19:31 2013
Received detach msg from inst 2 for dom 2
Received detach msg from inst 2 for dom 3
Fri Aug 23 18:21:16 2013
Received detach msg from inst 2 for dom 1
Fri Aug 23 18:21:19 2013
Reconfiguration started (old inc 4, new inc 6)
List of instances:
1 (myinst: 1)
Global Resource Directory frozen
Communication channels reestablished
Master broadcasted resource hash value bitmaps
Non-local Process blocks cleaned out
Fri Aug 23 18:21:19 2013
LMS 0: 0 GCS shadows cancelled, 0 closed, 0 Xw survived
Set master node info
Submitted all remote-enqueue requests
Dwn-cvts replayed, VALBLKs dubious
All grantable enqueues granted
Post SMON to start 1st pass IR
Submitted all GCS remote-cache requests
Post SMON to start 1st pass IR
Fix write in gcs resources
Reconfiguration complete
Fri Aug 23 19:28:02 2013
Reconfiguration started (old inc 6, new inc 8)
List of instances:
1 2 (myinst: 1)
Global Resource Directory frozen
Communication channels reestablished
Master broadcasted resource hash value bitmaps
Non-local Process blocks cleaned out
Fri Aug 23 19:28:03 2013
LMS 0: 0 GCS shadows cancelled, 0 closed, 0 Xw survived
Set master node info
Submitted all remote-enqueue requests
Dwn-cvts replayed, VALBLKs dubious
All grantable enqueues granted
Submitted all GCS remote-cache requests
Fix write in gcs resources
Reconfiguration complete
Sun Aug 25 12:45:13 2013
NOTE: ASM client bppfedb1:bppfedb disconnected unexpectedly.
NOTE: check client alert log.
NOTE: Trace records dumped in trace file /oracle/app/grid/diag/asm/+asm/+ASM1/trace/+ASM1_ora_16889.trc
Sun Aug 25 12:45:59 2013
NOTE: client bppfedb1:bppfedb registered, osid 7154, mbr 0x1
Mon Aug 26 06:56:56 2013
NOTE: [ocrcheck.bin@bppfedb1 (TNS V1-V3) 45447] opening OCR file
Mon Aug 26 11:45:46 2013
NOTE: [ocrcheck.bin@bppfedb1 (TNS V1-V3) 22422] opening OCR file



bppfedb1 实例是在25日 12:45重启了


Sun Aug 25 12:45:13 2013
NOTE: ASM client bppfedb1:bppfedb disconnected unexpectedly.

Maclean Liu(刘相兵

Sun Aug 25 12:45:08 2013
Received an instance abort message from instance 2
Please check instance 2 alert and LMON trace files for detail.
LMS0 (ospid: 16842): terminating the instance due to error 481
Sun Aug 25 12:45:09 2013
System state dump requested by (instance=1, osid=16842 (LMS0)), summary=[abnormal instance termination].
System State dumped to trace file /oracle/app/oracle/diag/rdbms/bppfedb/bppfedb1/trace/bppfedb1_diag_16828.trc
Sun Aug 25 12:45:09 2013


LMON的TRACE:

End DRM(83)
kjfmReceiverHealthCB_Check: Reciever [0] is not healthy.

*** 2013-08-25 12:44:10.648
2013-08-25 12:44:10.648596 : kjxgrDD_rr_read: Detect reconfig from inst 2, seq 12, reason 3
kjxgrrcfgchk: Initiating reconfig, reason=3
kjxgrrcfgchk: COMM rcfg - Disk Vote Required
kjfmReceiverHealthCB_CheckAll: Recievers are not healthy.
kjxgrrcfgchk: prev pstate 6  mapsz 512
kjxgrrcfgchk: new  bmp: 1 2
kjxgrrcfgchk: work bmp: 1 2
kjxgrrcfgchk: rr  bmp: 1 2

kjxgrrcfgchk: the instance is NOT in good health.

*** 2013-08-25 12:44:11.321
2013-08-25 12:44:11.321257 : kjxgrDD_rr_read: Detect reconfig from inst 2, seq 13, reason 3

*** 2013-08-25 12:44:11.945
2013-08-25 12:44:11.945261 : kjxgrDD_rr_read: Detect reconfig from inst 2, seq 13, reason 3
2013-08-25 12:44:12.569994 : kjxgrDD_rr_read: Detect reconfig from inst 2, seq 13, reason 3

*** 2013-08-25 12:44:13.193
2013-08-25 12:44:13.193572 : kjxgrDD_rr_read: Detect reconfig from inst 2, seq 13, reason 3

*** 2013-08-25 12:44:13.818
2013-08-25 12:44:13.818640 : kjxgrDD_rr_read: Detect reconfig from inst 2, seq 13, reason 3
2013-08-25 12:44:14.444551 : kjxgrDD_rr_read: Detect reconfig from inst 2, seq 13, reason 3

*** 2013-08-25 12:44:15.068
2013-08-25 12:44:15.068765 : kjxgrDD_rr_read: Detect reconfig from inst 2, seq 13, reason 3
2013-08-25 12:44:15.694014 : kjxgrDD_rr_read: Detect reconfig from inst 2, seq 13, reason 3

Maclean Liu(刘相兵

instance 2 发动 驱逐instance 1的原因是：

kjxgrrcfgchk: the instance is NOT in good health.

[root@vrh8 ~]# awk -f ass1038.awk bppfedb1_diag_16828.trc

Starting Systemstate 1
.........................................................
Ass.Awk Version 1.0.38
~~~~~~~~~~~~~~~~~~~~~~
Source file : bppfedb1_diag_16828.trc

System State 1  (2013-08-25 12:45:09.072)
~~~~~~~~~~~~~~   ~~~~~~~~~~~~~~~~~~~~~~~
1:                                      [DEAD]
2:  waiting for 'pmon timer'            [DEAD]
3:  waiting for 'latch free'           [Latch 60010d08] [DEAD]
4:  waiting for 'VKTM Logical Idle Wait' [DEAD]
5:  waiting for 'rdbms ipc message'     [DEAD]
     Cmd: Update
6:                                      
7:  waiting for 'rdbms ipc message'     [DEAD]
8:  waiting for 'PING'                  [DEAD]
9:  waiting for 'rdbms ipc message'     [DEAD]
10: waiting for 'ges DFS hang analysis phase 2 acks' [DEAD]
11: waiting for 'process diagnostic dump' [DEAD]
12: waiting for 'latch: ges resource hash list'[Latch 9d9a25be0] [DEAD]
13:                                    
14: waiting for 'gcs remote message'    [DEAD]
15: waiting for 'gcs remote message'    [DEAD]
16: waiting for 'rdbms ipc message'     [DEAD]
17: waiting for 'KSV master wait'      [Enq PV-00000000-00000000] [DEAD]
18: waiting for 'latch: shared pool'   [Latch 60109068]
19: waiting for 'rdbms ipc message'     
20: waiting for 'rdbms ipc message'     
21: waiting for 'rdbms ipc message'     
22: waiting for 'rdbms ipc message'     
23: waiting for 'rdbms ipc message'     
24: waiting for 'latch: shared pool'   [Latch 601092e8] [DEAD]
25: waiting for 'rdbms ipc message'     [DEAD]
26: waiting for 'enq: PR - contention' [Enq PR-00000000-00000000] [DEAD]
27: waiting for 'DFS lock handle'      
28: waiting for 'latch: shared pool'   [Latch 60109248] [DEAD]
29: waiting for 'rdbms ipc message'     [DEAD]
30: waiting for 'ASM background timer'  
31: waiting for 'os thread startup'    [Latch 60010d08] [DEAD]
32: waiting for 'rdbms ipc message'     [DEAD]
33:                                     [DEAD]
34:                                     [DEAD]
35: waiting for 'wait for unread message on broadcast channel' [DEAD]
36: waiting for 'enq: PV - syncstart'  [Enq PV-00000000-00000000] [DEAD]
37: waiting for 'rdbms ipc message'     [DEAD]
38: waiting for 'rdbms ipc message'     [DEAD]
39: waiting for 'SQL*Net message from client' [DEAD]
40: waiting for 'rdbms ipc reply' (from_process=46)[IPC 46] [DEAD]
41: waiting for 'rdbms ipc message'     [DEAD]
42: waiting for 'rdbms ipc message'     [DEAD]
43: waiting for 'rdbms ipc message'     [DEAD]
44: waiting for 'rdbms ipc message'     [DEAD]
45: waiting for 'latch: shared pool'   [Latch 60109068] [DEAD]
46: waiting for 'DFS lock handle'       [DEAD]
47: waiting for 'wait for unread message on broadcast channel' [DEAD]
48: waiting for 'Streams AQ: qmn coordinator idle wait' [DEAD]
49: waiting for 'latch free'           [Latch 60017dd8] [DEAD]
50: waiting for 'VKRM Idle'             [DEAD]
51: waiting for 'latch: shared pool'   [Latch 601091a8] [DEAD]
52: waiting for 'SQL*Net message from client' [DEAD]
     Cmd: PL/SQL Execute
53: waiting for 'latch: shared pool'   [Latch 601091a8] [DEAD]
54: waiting for 'SQL*Net message from client' [DEAD]
55: waiting for 'latch: shared pool'   [Latch 601092e8] [DEAD]
     Cmd: Select
56: waiting for 'library cache: mutex X'[Mutex a7c805e09] [DEAD]
     Cmd: Select
57: waiting for 'latch: shared pool'   [Latch 60109068]

Blockers
~~~~~~~~

        Above is a list of all the processes. If they are waiting for a resource
        then it will be given in square brackets. Below is a summary of the
        waited upon resources, together with the holder of that resource.
        Notes:
        ~~~~~
         o A process id of '???' implies that the holder was not found in the
           systemstate. (The holder may have released the resource before we
           dumped the state object tree of the blocking process).
         o Lines with 'Enqueue conversion' below can be ignored *unless*
           other sessions are waiting on that resource too. For more, see
           http://dlsunuk11.uk.oracle.com/Public/TOOLS/Ass.html#enqcnv)

                    Resource Holder State
              Latch 60010d08    ??? Blocker
             Latch 9d9a25be0    ??? Blocker
    Enq PV-00000000-00000000    31: 31: is waiting for Latch 60010d08
              Latch 60109068    ??? Blocker
              Latch 601092e8    ??? Blocker
    Enq PR-00000000-00000000    31: 31: is waiting for Latch 60010d08
              Latch 60109248    ??? Blocker
                      IPC 46     46 Blocker
              Latch 60017dd8    ??? Blocker
              Latch 601091a8    ??? Blocker
             Mutex a7c805e09    ??? Blocker

Some of the above latches may be child latches. Please check the section
named 'Child Latch Report' below for further notes.

Warning: The following processes have multiple session state objects and
may not be properly represented above :
    17:   31:                                                                  

Object Names
~~~~~~~~~~~~
Latch 60010d08                   OS process allocation        
Latch 9d9a25be0                 Child ges resource hash list  
Enq PV-00000000-00000000                                      
Latch 60109068                  Child shared pool            
Latch 601092e8                  Child shared pool            
Enq PR-00000000-00000000                                      
Latch 60109248                  Child shared pool            
IPC 46                                                        
Latch 60017dd8                  Parent ges value block free list
Latch 601091a8                  Child shared pool            
Mutex a7c805e09                                               

Child Latch Report
~~~~~~~~~~~~~~~~~~
Some processes are being blocked waiting for child latches.

At the moment this script does not detect the blocker because the
child latch address differs to the parent latch address. To manually
detect the blocker please take the following steps :
1. Determine the TYPE of latch (Eg library cache) that is involved.
2. Search the source trace file for a target of :
         holding.*Parent.*library cache
   (Assuming we have a child library cache and have vi-like regular expressions)

If this shows nothing then the blocker may have released the resource
before we got to dump the state object tree of the blocked process.

A list of processes that hold parent latches is given below :

  18:  (efd=3) 60036a08 Parent+children (7-2) shared pool level=7

Latch Wait List Information
~~~~~~~~~~~~~~~~~~~~~~~~~~~
Pid 3 is blocked waiting for latch ' OS process allocation' with 9 waiters.
.ossible holder is Pid 5614
Pid 12 is blocked waiting for latch 'Child ges resource hash list' with 1 waiters.
.ossible holder is Pid 5332
Pid 18 is blocked waiting for latch 'Child shared pool' with 129 waiters.
.ossible holder is Pid 12855
Pid 24 is blocked waiting for latch 'Child shared pool' with 15 waiters.
.ossible holder is Pid 16858
Pid 28 is blocked waiting for latch 'Child shared pool' with 14 waiters.
.ossible holder is Pid 16858
Pid 31 is blocked waiting for latch  OS process allocation with 9 waiters.
.ossible holder is Pid 5614
Pid 45 is blocked waiting for latch Child shared pool with 129 waiters.
.ossible holder is Pid 12855
Pid 49 is blocked waiting for latch 'Parent ges value block free list' with 50 waiters.
.ossible holder is Pid 1522
Pid 51 is blocked waiting for latch 'Child shared pool' with 16 waiters.
.ossible holder is Pid 16858
Pid 53 is blocked waiting for latch Child shared pool with 16 waiters.
.ossible holder is Pid 16858
Pid 55 is blocked waiting for latch Child shared pool with 15 waiters.
.ossible holder is Pid 16858
Pid 57 is blocked waiting for latch Child shared pool with 129 waiters.
.ossible holder is Pid 12855
Pid 57 is blocked waiting for latch Child shared pool with 1 waiters.
13 entries seen



可以看到 有一些阻塞

Maclean Liu(刘相兵

Parses:         640.8         15.1                  
Hard parses:         90.8         2.1                  

在问题发生前的快照里  显示硬解析较多  每秒90.8/s


parse time elapsed        1,866.21        27.46
hard parse elapsed time        778.68        11.46


解析占 db time 约30%， 硬解析11.46%

memory_target        42144366592


使用 11g AMM 管理



Pool        Name        Begin MB        End MB        % Diff
java        free memory        128.00        128.00        0.00
large        PX msg pool        7.81        7.81        0.00
large        free memory        119.81        119.81        0.00
shared        KGLDA        170.60        191.22        12.09
shared        KGLH0        3,296.13        3,690.60        11.97
shared        KGLHD        500.27        521.73        4.29
shared        SQLA        4,280.74        4,897.58        14.41
shared        free memory        2,783.54        1,730.25        -37.84
shared        gcs resources        304.89        304.89        0.00
shared        gcs shadows        177.85        177.85        0.00
shared        kglsim object batch        153.83        153.83        0.00
streams        free memory        128.00        128.00        0.00
        buffer_cache        12,160.00        12,160.00        0.00
        fixed_sga        2.13        2.13        0.00
        log_buffer        74.43        74.43        0.00


KGLH0 达到3G 这说明 很多SQL确实没绑定变量

shared        free memory        2,783.54        1,730.25        -37.84

共享池free memory 大幅下降

Maclean Liu(刘相兵

1520 sql area purged
16557614 sql area evicted
29555 CCursor + sql area evicted

PROCESS 31: MMON
  ----------------------------------------
  SO: 0x9d0bf8cf8, type: 2, owner: (nil), flag: INIT/-/-/0x00 if: 0x3 c: 0x3
   proc=0x9d0bf8cf8, name=process, file=ksu.h LINE:12616, pg=0
  (process) Oracle pid:31, ser:1, calls cur/top: 0x9b763e010/0x9c1237d50
            flags : (0x2) SYSTEM
            flags2: (0x20),  flags3: (0x10)
            intr error: 0, call error: 0, sess error: 0, txn error 0
            intr queue: empty
    ksudlp FALSE at location: 0
  (post info) last post received: 0 0 26
              last post received-location: ksa2.h LINE:285 ID:ksasnd
              last process to post me: 9c8bf6fc0 1 2
              last post sent: 0 0 26
              last post sent-location: ksa2.h LINE:285 ID:ksasnd
              last process posted by me: 9d0bf4a38 1 6
    (latch info) wait_event=0 bits=0
        Location from where call was made: kso2.h LINE:357 ID:ksoreq_cancel:1:
      waiting for 60010d08  OS process allocation level=4
        Location from where latch is held: kso2.h LINE:332 ID:kso_new_process:2:
        Context saved from call: 0
        state=busy [holder orapid=666] wlstate=free [value=0]
          waiters [orapid (seconds since: put on list, posted, alive check)]:
           3 (858, 1377405908, 858)
           667 (858, 1377405908, 858)
           668 (858, 1377405908, 858)
           669 (857, 1377405908, 857)
           670 (856, 1377405908, 856)
           671 (853, 1377405908, 853)
           672 (853, 1377405908, 853)
           673 (852, 1377405908, 852)
           31 (775, 1377405908, 4)
           waiter count=9
          gotten 1100382 times wait, failed first 423 sleeps 1

                  
                  
                  
                      SO: 0x9e9075da0, type: 4, owner: 0x9d0bf8cf8, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
     proc=0x9d0bf8cf8, name=session, file=ksu.h LINE:12624, pg=0
    (session) sid: 1955 ser: 1 trans: (nil), creator: 0x9d0bf8cf8
              flags: (0x51) USR/- flags_idl: (0x1) BSY/-/-/-/-/-
              flags2: (0x40409) -/-/INC
              DID: , short-term DID:
              txn branch: (nil)
              oct: 0, prv: 0, sql: (nil), psql: 0xa1f9cd7b0, user: 0/SYS
    ksuxds FALSE at location: 0
    service name: SYS$BACKGROUND
    Current Wait Stack:
     1: waiting for 'latch free'
        address=0x60010d08, number=0x4a, tries=0x0
        wait_id=568040 seq_num=45552 snap_id=1
        wait times: snap=12 min 56 sec, exc=12 min 56 sec, total=12 min 56 sec
        wait times: max=infinite, heur=12 min 56 sec
        wait counts: calls=0 os=0
        in_wait=1 iflags=0x2520
     0: waiting for 'os thread startup'
        =0x0, =0x0, =0x0
        wait_id=568035 seq_num=45551 snap_id=5
        wait times: snap=0.000000 sec, exc=1 min 58 sec, total=14 min 56 sec
        wait times: max=2 min 0 sec, heur=14 min 56 sec
        wait counts: calls=140 os=140
        in_wait=1 iflags=0x15e0
    There are 4 sessions blocked by this session.
    Dumping one waiter:
      inst: 1, sid: 1639, ser: 1
      wait event: 'enq: PR - contention'

Maclean Liu(刘相兵

在AWR中显示

        Begin        End               
Buffer Cache:         12,160M         12,160M        Std Block Size:         8K
Shared Pool Size:         12,672M         12,672M        Log Buffer:         76,212K

25-Aug-13 11:00:26  =》　25-Aug-13 11:59:44　　　　shared pool size 还是 12,672M


而在ASH中 25-Aug-13 11:46:00 ~ 25-Aug-13 12:46:00 ， Shared Pool         为11,668M (29.2%)


top latch是 latch: shared pool

Maclean Liu(刘相兵

现在查一下：

select name,value from v$sysstat where name like '%pga%';

Maclean Liu(刘相兵

随便看下 diag 的dump可以看到：

          Parent Cursor:  sql_id=7akf6xvjp5a6d parent=0x95ff45d10 maxchild=18 plk=y ppn=n
            CursorDiagnosticsNodes:
              ChildNode:  ChildNumber=15 ID=3 reason=Optimizer mismatch(12) size=2x216 _smm_px_max_size= 7929856 KB           7864320 KB
              ChildNode:  ChildNumber=17 ID=3 reason=Optimizer mismatch(12) size=2x216 _smm_px_max_size= 7602176 KB           7929856 KB
              ChildNode:  ChildNumber=16 ID=3 reason=Optimizer mismatch(12) size=2x216 _smm_px_max_size= 7667712 KB           7602176 KB
            AgedOutCursorDiagnosticNodes:
              ChildNode:  ChildNumber=15 ID=3 reason=Optimizer mismatch(12) size=2x216 _smm_px_max_size= 7929856 KB           7864320 KB
              ChildNode:  ChildNumber=11 ID=3 reason=Optimizer mismatch(12) size=2x216 _smm_px_max_size= 7733248 KB           7667712 KB
              ChildNode:  ChildNumber=9 ID=3 reason=Optimizer mismatch(12) size=2x216 _smm_px_max_size= 7798784 KB           7733248 KB
              ChildNode:  ChildNumber=8 ID=3 reason=Optimizer mismatch(12) size=2x216 _smm_px_max_size= 7864320 KB           7798784 KB
              ChildNode:  ChildNumber=6 ID=3 reason=Optimizer mismatch(12) size=2x216 _smm_px_max_size= 7995392 KB           7929856 KB
              ChildNode:  ChildNumber=5 ID=3 reason=Optimizer mismatch(12) size=2x216 _smm_px_max_size= 8060928 KB           7995392 KB
              ChildNode:  ChildNumber=14 ID=3 reason=Optimizer mismatch(12) size=2x216 _smm_px_max_size= 8257536 KB           8192000 KB

_smm_px_max_size 变化频繁说明， PGA TARGET一直在变

mastermouse

感谢刘大，昨晚有其它事没有及时跟进。
SQL> select name,value/1204/1204 from v$sysstat where name like '%pga%';

NAME                                                             VALUE/1204/1204
---------------------------------------------------------------- ---------------
session pga memory                                                    24777.1648
session pga memory max                                                86450.0504

这是你要的值

另我说的节点重启只是指实例重启了，主机没有重启

mastermouse

Mille 发表于 2013-8-26 16:40
client details:
      O/S info: user: , term: , ospid: 1234
      machine: BPPF_OMP2 program: H ...

有没有办法根据hashvalue，address查询过去的SQL，
我从v$sqlarea去根据hashvalue再不到这SQL了。
当然这只是其中一个，我们整体应用的SQL都相当糟糕

Maclean Liu(刘相兵

154489188112 session pga memory
351513660400 session pga memory max

154489188112 =143G

怀疑当时PGA使用量上升，导致shared pool shrink 以及后续的 latch:shared pool 等



可以上传  LMHB 和DBRM进程的trace


同时建议你 不要用AMM ，使用全部手动管理

mastermouse

刘大，你好，补充两个trc文件，多谢 ！

Maclean Liu(刘相兵

*** 2013-08-25 11:21:32.582
==============================
LCK0 (ospid: 16901) has not moved for 20 sec (1377400892.1377400872)
kjfmGCR_HBCheckAll: LCK0 (ospid: 16901) has status 2
  : waiting for event 'rdbms ipc message' for 0 secs with wait_id 33034901.
  ===[ Wait Chain ]===
  Wait chain is empty.

*** 2013-08-25 12:31:18.440
==============================
LMD0 (ospid: 16840) has not moved for 25 sec (1377405077.1377405052)
kjfmGCR_HBCheckAll: LMD0 (ospid: 16840) has status 2
  : waiting for event 'latch: ges resource hash list' for 22 secs with wait_id 18073280.
  : waiting for latch 'ges resource hash list'.
  ===[ Wait Chain ]===
  LMD0 (ospid: 16840) waits for event 'latch: ges resource hash list'.
  USER (ospid: 5332) waits for event 'latch free'.
  USER (ospid: 1522) waits for event 'latch: shared pool'.
  MMAN (ospid: 16858) waits for event 'latch: shared pool'.
  USER (ospid: 12855) waits for event 'library cache: mutex X'.
  M000 (ospid: 5330) is not in wait.
  ===[ Latch Chain ]===
  LMD0 (ospid: 16840) waits for latch 'ges resource hash list'.
  USER (ospid: 5332) waits for latch 'ges value block free list'.
  USER (ospid: 1522) waits for latch 'shared pool'.
  MMAN (ospid: 16858) waits for latch 'shared pool'.
  USER (ospid: 12855) is not waiting for any latch.

*** 2013-08-25 12:31:38.444
==============================
LMD0 (ospid: 16840) has not moved for 45 sec (1377405097.1377405052)
kjfmGCR_HBCheckAll: LMD0 (ospid: 16840) has status 2
  : waiting for event 'latch: ges resource hash list' for 42 secs with wait_id 18073280.
  : waiting for latch 'ges resource hash list'.
  ===[ Wait Chain ]===
  LMD0 (ospid: 16840) waits for event 'latch: ges resource hash list'.
  USER (ospid: 5332) waits for event 'latch free'.
  USER (ospid: 1522) waits for event 'latch: shared pool'.
  MMAN (ospid: 16858) waits for event 'latch: shared pool'.
  USER (ospid: 12855) waits for event 'library cache: mutex X'.
  M000 (ospid: 5330) is not in wait.
  ===[ Latch Chain ]===
  LMD0 (ospid: 16840) waits for latch 'ges resource hash list'.
  USER (ospid: 5332) waits for latch 'ges value block free list'.
  USER (ospid: 1522) waits for latch 'shared pool'.
  MMAN (ospid: 16858) waits for latch 'shared pool'.
  USER (ospid: 12855) is not waiting for any latch.



12:31:18.440 左右出现大量等待



*** 2013-08-25 12:26:43.435
   3  4273342124  4294964855       0.90      0.00
RQs:   < 5:      < 10:      < 50:      < 100:      < 200:     < 1000:       > 1K:
     59537        838        752          20          12           0           0

*** 2013-08-25 12:27:43.457
   3    21746749        2453       1.10      0.00
      9121        927        810          20          10           0           0

*** 2013-08-25 12:28:40.478
   3       56812           5       1.20      0.00
     45960        766        716          16          14           0           0

*** 2013-08-25 12:29:40.491
   3       49668           5       0.80      0.00
     28002        695        630           7           0           0           0

*** 2013-08-25 12:30:40.512
   3       33939           4       1.40      0.00
     36422        418        389          11           9           1           0

*** 2013-08-25 12:31:43.537
cpu%:     cputm:      cpuwt:    avgrun:    avgwt:
   3         617           0       1.00      0.00
RQs:   < 5:      < 10:      < 50:      < 100:      < 200:     < 1000:       > 1K:
      1863         15         11           0           0           0           0

*** 2013-08-25 12:32:40.549
   3          95           0       1.05      0.00
       210          1          1           0           0           0           0

*** 2013-08-25 12:32:55.555
kgsksysstop: non-blocking mode (6) timestamp: 1377405175555207
kgsksysstop: successful
kgsksysresume: successful

*** 2013-08-25 12:33:40.573
   3         109           0       1.00      0.00
       178          0          0           1           0           0           0

*** 2013-08-25 12:34:40.592
   3          52           0       1.00      0.00
       171          0          0           0           0           0           0

*** 2013-08-25 12:35:43.617
   3          14           0       1.00      0.00
        86          0          0           0           0           0           0

*** 2013-08-25 12:36:40.637
cpu%:     cputm:      cpuwt:    avgrun:    avgwt:
   3          92           0       1.00      0.00
RQs:   < 5:      < 10:      < 50:      < 100:      < 200:     < 1000:       > 1K:
       126          1          1           0           0           0           0

*** 2013-08-25 12:37:40.659
   3          14           0       1.00      0.00
        90          0          0           0           0           0           0

*** 2013-08-25 12:38:40.683
   3          20           0       1.00      0.00
       112          0          0           0           0           0           0

*** 2013-08-25 12:39:40.705
   3          35           0       1.00      0.00
       122          0          1           0           0           0           0

*** 2013-08-25 12:40:40.725
   3          15           0       1.00      0.00
       111          0          0           0           0           0           0
cpu%:     cputm:      cpuwt:    avgrun:    avgwt:

*** 2013-08-25 12:41:40.749
   3         190           0       1.00      0.00
RQs:   < 5:      < 10:      < 50:      < 100:      < 200:     < 1000:       > 1K:
       236          2          2           1           0           0           0

*** 2013-08-25 12:42:43.771
   3         203           0       1.00      0.00
       241          1          3           1           0           0           0

*** 2013-08-25 12:43:40.794
   3         226           0       1.00      0.00
       250          1          3           0           0           0           0

*** 2013-08-25 12:44:40.815
   3         169           0       1.05      0.00
       169          0          6           0           0           0           0


*** 2013-08-25 12:26:43.435
   3  4273342124  4294964855   似乎发生了什么