SystemState分析案例（三）

这个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/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/8242091/viewspace-736144/