SystemState分析案例（三）

westzq1984發表於2012-07-20
這個TRC來源於網上，TRC可以在這裡下載 http://www.oraclefans.cn/forum/showtopic.jsp?rootid=23872

ass109.awk格式化Systemstats後發現，主要會話在等待cursor: pin S wait on X。

搜尋 [ waiting for ‘cursor: pin S wait on X’ ]，大量會話等待的資源都相同
為驗證，接著搜尋[ idn=.*value= ]。根據資訊確定其等待的資源為943724ff，阻塞者為SID 3137，其以Exclusive持有該Mutex

搜尋 [ Mutex.*943724ff ]，發現大量會話在其上請求Shared鎖，而Process 134（SID 3137）在上面持有Exclusive

      KGX Atomic Operation Log 0x4aebe8aa0
       Mutex 0x508397d00(3137, 0) idn 943724ff oper EXCL
       Cursor Pin uid 3137 efd 0 whr 1 slp 0
       pr=3 pso=0x4c3043b18 flg=0
       pcs=0x508397d00 nxt=(nil) flg=34 cld=0 hd=0x3b8d004f8 par=0x5083980f0
       ct=0 hsh=0 unp=(nil) unn=0 hvl=83983c8 nhv=1 ses=0x55bc76f08
       hep=0x508397d80 flg=80 ld=1 b=0x5083972d0 ptr=0x40d96e2d0 fex=0x40d96d5e0

檢查Process 134，發現其在等待 DFS lock handle

PROCESS 134:
  ----------------------------------------
  SO: 0x55a1646f8, type: 2, owner: (nil), flag: INIT/-/-/0x00
  (process) Oracle pid=134, calls cur/top: 0x52ac62ef8/0x5053a18c8, flag: (0) -
            int error: 0, call error: 0, sess error: 0, txn error 0
  (post info) last post received: 0 0 172
              last post received-location: kqrbpr: post after requeueing
              last process to post me: 55a148c38 1 6
              last post sent: 0 0 90
              last post sent-location: KJCS Post snd proxy to flush msg
              last process posted by me: 55a144cf8 1 6
    (latch info) wait_event=0 bits=0
    Process Group: DEFAULT, pseudo proc: 0x55b43ce00
    O/S info: user: oracle, term: UNKNOWN, ospid: 19054
    OSD pid info: Unix process pid: 19054, image: oracle@nc02
*** 2010-09-27 10:05:47.633
    Short stack dump:
ksdxfstk()+32
    ----------------------------------------
    SO: 0x55bc76f08, type: 4, owner: 0x55a1646f8, flag: INIT/-/-/0x00
    (session) sid: 3137 trans: (nil), creator: 0x55a1646f8, flag: (41) USR/- BSY/-/-/-/-/-
              DID: 0002-0086-00000049, short-term DID: 0002-0086-0000004A
              txn branch: (nil)
              oct: 3, prv: 0, sql: 0x49b8c2830, psql: 0x4b5d062a0, user: 33/BBG519
    service name: ncrac
    O/S info: user: Administrator, term: , ospid: 1234, machine: bbgapp01
              program:
    waiting for 'DFS lock handle' blocking sess=0x(nil) seq=2106 wait_time=0 seconds since wait started=3021
                type|mode=43490005, id1=1e, id2=5
    Dumping Session Wait History
     for 'DFS lock handle' count=1 wait_time=1944973
                type|mode=43490005, id1=1e, id2=5
     for 'DFS lock handle' count=1 wait_time=489249
                type|mode=43490005, id1=1e, id2=5
     for 'DFS lock handle' count=1 wait_time=489252
                type|mode=43490005, id1=1e, id2=5
     for 'DFS lock handle' count=1 wait_time=489234
                type|mode=43490005, id1=1e, id2=5
     for 'DFS lock handle' count=1 wait_time=489263
                type|mode=43490005, id1=1e, id2=5
     for 'DFS lock handle' count=1 wait_time=489249
                type|mode=43490005, id1=1e, id2=5
     for 'DFS lock handle' count=1 wait_time=489235
                type|mode=43490005, id1=1e, id2=5
     for 'DFS lock handle' count=1 wait_time=489252
                type|mode=43490005, id1=1e, id2=5
     for 'DFS lock handle' count=1 wait_time=489259
                type|mode=43490005, id1=1e, id2=5
     for 'DFS lock handle' count=1 wait_time=489253
                type|mode=43490005, id1=1e, id2=5
    temporary object counter: 0

DFS lock handle其實就是enqueue，不過其是跨例項的請求。把4390005轉換出來，為CI 5。
DFS lock handle在RAC環境才發生，一般是在序列上的爭用/大量的TRUNC造成
接著分析程式，發現阻塞原因為：程式準備從CI2轉換為CI6，但是有1個程式持有CI6

      SO: 0x5510db2d8, type: 18, owner: 0x5598b41f8, flag: INIT/-/-/0x00
      ----------enqueue 0x0x5510db2d8------------------------
      lock version     : 21023
      Owner node       : 1
      grant_level      : KJUSERNL
      req_level        : KJUSEREX
      bast_level       : KJUSERNL
      notify_func      : (nil)
      resp             : 0x4c35eeb50
      procp            : 0x5598b41f8
      pid              : 19054
      proc version     : 54
      oprocp           : (nil)
      opid             : 0
      group lock owner : (nil)
      xid              : 0000-0000-00000000
      dd_time          : 0.0 secs
      dd_count         : 0
      timeout          : 0.0 secs
      On_timer_q?      : N
      On_dd_q?         : N
      lock_state       : OPENING CONVERTING
      Open Options     :  KJUSERPROCESS_OWNED
      Convert options  : KJUSERNODEADLOCKWAIT KJUSERNODEADLOCKBLOCK
      History          : 0x1495149a
      Msg_Seq          : 0x0
      res_seq          : 506
      valblk           : 0x00000000000000000000000000000000 .
      ----------resource 0x0x4c35eeb50----------------------
      resname       : [0x1e][0x5],[CI]
      Local node    : 1
      dir_node      : 0
      master_node   : 0
      hv idx        : 102
      hv last r.inc : 12
      current inc   : 12
      hv status     : 0
      hv master     : 0
      open options  :
      Held mode     : KJUSEREX
      Cvt mode      : KJUSERNL
      Next Cvt mode : KJUSERNL
      msg_seq       : 0x1
      res_seq       : 506
      grant_bits    : KJUSERNL KJUSEREX
      grant mode    : KJUSERNL  KJUSERCR  KJUSERCW  KJUSERPR  KJUSERPW  KJUSEREX
      count         : 2         0         0         0         0         1
      val_state     : KJUSERVS_NOVALUE
      valblk        : 0x00000000000000000000000000000000 .
      access_node   : 1
      vbreq_state   : 0
      state         : x8
      resp          : 0x4c35eeb50
      On Scan_q?    : N
      cache level   : 1
      Total accesses: 30124
      Imm.  accesses: 3705
      Granted_locks : 1
      Cvting_locks  : 2
value_block:  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
      GRANTED_Q :
      lp 0x54e0da060 gl KJUSEREX rp 0x4c35eeb50 [0x1e][0x5],[CI]
        master 0 pid 23479 bast 0 rseq 506 mseq 0 history 0x49a51495
        open opt  KJUSERPROCESS_OWNED
      CONVERT_Q:
      lp 0x5510db2d8 gl KJUSERNL rl KJUSEREX rp 0x4c35eeb50 [0x1e][0x5],[CI]
        master 0 pid 19054 bast 0 rseq 506 mseq 0 history 0x1495149a
        convert opt KJUSERNODEADLOCKWAIT KJUSERNODEADLOCKBLOCK  
      lp 0x54f0ec3a8 gl KJUSERNL rl KJUSEREX rp 0x4c35eeb50 [0x1e][0x5],[CI]
        master 0 pid 19516 bast 0 rseq 506 mseq 0 history 0x1495149a
        convert opt KJUSERNODEADLOCKWAIT KJUSERNODEADLOCKBLOCK  

在向下分析，程式在dc_sequences這個row cache enqueue上請求X鎖

                SO: 0x52ce82288, type: 50, owner: 0x54178fee8, flag: INIT/-/-/0x00
                row cache enqueue: count=1 session=0x55bc76f08 bject=0x55e9eac48, request=X
                savepoint=0x148f
                row cache parent object: address=0x55e9eac48 cid=13(dc_sequences)
                hash=9649e7e typ=11 transaction=(nil) flags=00000000
                wn=0x55e9ead18[0x55e9ead18,0x55e9ead18] wat=0x55e9ead28[0x52ce822b8,0x52ce822b8] mode=N
                status=-/-/-/-/-/-/-/-/-
                request=X release=FALSE flags=2
                instance lock id=QN 010cdbb3 b3b24847
                data=
                00000104 00000000 00000000 00000000 00000000 00000000 00000000 00000000
                00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
                00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
                00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
                00000000 00000000 00000000 00000000
               
接著分析，發現對爭用的SEQ進行了DUMP，DUMP的物件ID為260，在其他庫查詢發現為ORA_TQ_BASE$

                SO: 0x541b5ac58, type: 48, owner: 0x3d8abfbf8, flag: INIT/-/-/0x00
                Sequence State Object:
                kdnssflg =
                kdnsshiw = INACTIVE
                kdnsssqn = 0x46c83e3b0
                KGL Sequence Object #260:
                kdnsqflg  =                           
                kqdsnflg  = KQDSNCYC          KQDSNNOC
                kdnsqcus  = 0
                kdnsqisp  INACTIVE
                Increment =                              +1
                Minvalue  =                              +1
                Maxvalue  =                        +4294967
                Cachesize =                              +0
                Highwater =                         +789773
                Nextvalue = ###############################

以關鍵字 ORA_TQ_BASE$ 搜尋MOS，發現Bug 6027068 - Contention on ORA_TQ_BASE sequence [ID 6027068.8]

文件指出，該序列用於並行操作，預設使用nocache建立，導致了不必要的row cache contention。比對自己同版本的庫，該序列確實使用nocache的方式建立的

來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/8242091/viewspace-736144/，如需轉載，請註明出處，否則將追究法律責任。

相關文章