首页 > 大数据 > 正文

使用system state dump分析mutex等待

2010-11-05 17:17:10  来源:博客

摘要:Mutex是Oracle从10g开始使用的一种数据结构,与latch极其类似,也是用于SGA内存结构的并发访问控制。
关键词: Oracle Ora
 Mutex是Oracle从10g开始使用的一种数据结构,与latch极其类似,也是用于SGA内存结构的并发访问控制。在10g中,Mutex主要用于保护Cursor相关的内存结构,Parent Cursor, Child Cursor , Cursor Stat,同时兼有Pin Cursor的并发访问控制作用。

  而从11g开始,Mutex又代替了library cache latch等多个与library cache相关的latch。

  Mutex与latch相比,有哪些优点?我个人认为最重要的有2点:

  Mutex通常在被保护对象内部,这样mutex的数量就多了很多,争用就更少。比如11g中,每一个Latch Latch Hash Bucket由一个mutex保护,而bucket数量高达131072,相比library cache latch最多只有67个child latch,数量上多了很多。很显然,分布在131072个Mutex上的竞争比67个Library cache latch上的竞争少得多。

  Mutex从结构上来讲比latch更多简单,整个Mutex只有十几个字节,而Oracle在对Latch的结构优化和精简的情况下最少也有100多个字节。这样更小的结构意味着在处理Mutex时也只需要更少的指令,而更快。

  Mutex代替Cursor上的library cache pin,比library cache pin更有效率。

  本文主要描述如何通过system state dump来分析mutex的等待,因此对Mutex的工作机制以及相应的等待事件详解不做过多介绍。有机会我会在另外的文章中专门来讲这两部分。

  我们来分析的system state dump来源于一个朋友,他的系统里面出现大量的’cursor: pin S wait on X’和’cursor: Mutex X’等待事件。他将产生的system state dump发给我,以分析出产生问题的root cause。由于system state dump比较在在,同时里面涉及的一些内容不适合放在网上,因此本文只给出分析过程,没有上传trace文件。数据库的版本是11.1.0.7。

  首先试图找到’cursor: pin S wait on X’等待的阻塞进程,随便找到一个等待cursor:pin S wait on X的会话,在dump trace 文件中查找waiting for ‘cursor: pin S wait on X’:

 (session) sid: 1471 ser: 57513 trans: (nil), creator: 0x450d504f0   
              flags: (0x45) USR
/- flags_idl: (0x1) BSY/-/-/-/-/-   
              flags2: (0x40008) 
-/-   
              DID: , short
-term DID:    
              txn branch: (nil)   
              
oct3, prv: 0, sql: 0x455d15680, psql: 0x45bd0c8c8, user: 92/XXXX   
    ksuxds 
FALSE at location: 0   
    service name: SYS$USERS   
    client details:   
      O
/S info: user: idol, term: unknown, ospid: 1234   
      machine:     program: JDBC Thin Client   
      application name: JDBC Thin Client, hash value
=2546894660   
    Current Wait Stack:   
     
0: waiting for 'cursor: pin S wait on X'  
        idn=de12d336, value=5cf00000000, where|sleeps=572cf03e3   
        wait_id
=56059196 seq_num=26772 snap_id=1   
        wait times: snap
=0.001772 sec, exc=0.001772 sec, total=0.001772 sec   
        wait times: max
=0.010000 sec   
        wait counts: calls
=1 os=1   
        in_wait
=1 iflags=0x5a2   
    There 
is at least one session blocking this session.   
    Dumping one blocker:   
      inst: 
1, sid: 1487, ser: 5556  

  其实这里已经指出“inst: 1, sid: 1487, ser: 5556”,表示阻塞的会话是sid,serial#为1487,5556。那么如果这里没有这个信息,那么我们从哪里去寻找blocker?注意前面一段信息:idn=de12d336(对cursor来说其实是sql的hash value的低4字节), value=5cf00000000, where|sleeps=572cf03e3,这里idn表示mutex的identifier,即mutex的标识,value的高8字节(64位系统是高8字节,而32位系统是高4位字节)是SID,0×5cf即10进制的1487。

  而在稍后面部分,可以看到:

KGX Atomic Operation Log 0x455507d20   
       Mutex 0x3ff3c3d28(
14870) idn de12d336 oper GET_SHRD   
       Cursor Pin uid 
1471 efd 0 whr 5 slp 13085   
       opr
=2 pso=0x454d03f00 flg=0   
       pcs
=0x3ff3c3ca8 nxt=0x41720aca0 flg=35 cld=0 hd=0x455d0dda8 par=0x3ff3c4650  
       ct
=0 hsh=0 unp=(nil) unn=0 hvl=ff3c4448 nhv=1 ses=0x45181f760   
       hep
=0x3ff3c3d28 flg=80 ld=1 ob=0x3ff3c3868 ptr=0x412040780 fex=0x41203faf0  

  这里有Mutex请求的更详细的信息,Mutex 0×3ff3c3d28(1487, 0) idn de12d336 oper GET_SHRD表明这个请求是以SHARE方式请求,但是Mutex被1487这个会话持有。idn与前面idn相匹配。Cursor Pin uid 1471 efd 0 whr 5 slp 13085 这里表明Mutex的类型是Cursor Pin,正是前面提到的Mutex的一种。uid 1471表明是当前请求的SID为1471。

  ‘cursor: pin S wait on X’等待类似于以往的library cache pin等待,表示需要将cursor pin在内存中。这个等待出现,表明有会话正在修改这个cursor,比如正在执行解析,生成执行计划等。

  接下来我们看SID=1487的会话正在等待什么,或者说是在执行什么操作,查找’(session) sid: 1487′:


    (session) sid: 
1487 ser: 5556 trans: (nil), creator: 0x450d514f0   
              flags: (0x45) USR
/- flags_idl: (0x1) BSY/-/-/-/-/-   
              flags2: (0x40008) 
-/-   
              DID: , short
-term DID:    
              txn branch: (nil)   
              
oct3, prv: 0, sql: 0x455d15680, psql: 0x45bd0c8c8, user: 92/XXXXX   
    ksuxds 
FALSE at location: 0   
    service name: SYS$USERS   
    client details:   
      O
/S info: user: idol, term: unknown, ospid: 1234   
      machine:       program: JDBC Thin Client   
      application name: JDBC Thin Client, hash value
=2546894660   
    Current Wait Stack:   
     
0: waiting for 'cursor: mutex X'  
        idn=5336, value=1, where|sleeps=3385a5f33   
        wait_id
=500096450 seq_num=64401 snap_id=1   
        wait times: snap
=0.000000 sec, exc=0.000000 sec, total=0.000000 sec   
        wait times: max
=0.000000 sec   
        wait counts: calls
=0 os=0   
        in_wait
=0 iflags=0x15e0  

  可以看到,这个会话正在等待’cursor: mutex X’。不幸的是,这一次没有直接表明holder是谁了。idn=5336, value=1, where|sleeps=3385a5f33,这里value=1,很简单,但是表明的意义却不简单,这表明什么?低8字节为1,表明这个Mutex是被共享持有,而高8字节为0,这是共享持有的Mutex的正常状况,Mutex可能被多个会话共享持有,因此只有引用计数,而不会有持有的SID。这里1就是引用计数,表示被1个会话持有。只有在会话获取Mutex的过程中,才会暂时性的将Mutex的SID设为正在获取的SID,而一旦完成获取,就将Mutex中的SID即value的高8字节部分清0。


  继续往后查看:

       KGX Atomic Operation Log 0x4543ce390   
       Mutex 0x3ff3c3d28(
14870) idn de12d336 oper EXCL   
       Cursor Pin uid 
1487 efd 0 whr 1 slp 0   
       opr
=3 pso=0x454daaa50 flg=0   
       pcs
=0x3ff3c3ca8 nxt=0x41720aca0 flg=35 cld=0 hd=0x455d0dda8 par=0x3ff3c4650  
       ct
=0 hsh=0 unp=(nil) unn=0 hvl=ff3c4448 nhv=1 ses=0x45181f760   
       hep
=0x3ff3c3d28 flg=80 ld=1 ob=0x3ff3c3868 ptr=0x412040780 fex=0x41203faf0  

  上面一段信息表明,正是1487这个会话以EXCLUSIVE方式持有idn=de12d336的这个mutex,这正是1471会话正需要以SHARE方式获取的Mutex。

      KGX Atomic Operation Log 0x45a2b7908   
       Mutex 0x44b764498(
01) idn 7fff00005336 oper GET_EXCL   
       Cursor Stat uid 
1487 efd 8 whr 3 slp 28652   
       oper
=OPERATION_DEFAULT pt1=(nil) pt2=(nil) pt3=(nil)   
       pt4
=(nil) u41=0 stt=0  

  上面一段信息表明,1487这个会话正在以EXCLUSIVE请求的mutex是idn=7fff00005336,Mutex类型是Cursor Stat。Cursor Stat类型的EXCLUSIVE方式请求通常是需要更新cursor的统计信息。而以SHARE方式请求通常是查询cursor的统计信息,比如说查询v$sqlstat视图。注意这里GET_EXCL表示正在以EXCLUSIVE方式请求获取(持有)mutex,而EXCL表示已经以EXCLUSIVE方式持有mutex。延伸开来,GET_SHRD表示请求SHARE方式的mutex,SHRD表示以SHARE方式持有mutex。REL_SHRD表示正在释放SHARE方式持有的mutex,也就是递减引用计数。

  那么,接下来我们就要寻找是哪个会话持有了idn=7fff00005336的mutex。查找’idn 7fff00005336 oper‘,找到如下内容:

       KGX Atomic Operation Log 0x45955b2f0   
       Mutex 0x44b764498(
01) idn 7fff00005336 oper SHRD   
       Cursor Stat uid 
1497 efd 7 whr 6 slp 0   
       oper
=OPERATION_DEFAULT pt1=(nil) pt2=(nil) pt3=(nil)   
       pt4
=(nil) u41=0 stt=0  

  可以看到的确有会话(1497)正在以共享方式持有idn=7fff00005336的mutex。往前查看,可以看到会话信息:

    (session) sid: 1497 ser: 29349 trans: (nil), creator: 0x45cccc3f0   
              flags: (0x51) USR
/- flags_idl: (0x1) BSY/-/-/-/-/-   
              flags2: (0x408) 
-/-   
              DID: , short
-term DID:    
              txn branch: (nil)   
              
oct0, prv: 0, sql: (nil), psql: (nil), user: 0/SYS   
    ksuxds 
FALSE at location: 0   
    service name: SYS$BACKGROUND   
    Current Wait Stack:   
      
Not in wait; last wait ended 14005 min 23 sec ago    
    Wait State:   
      auto_close
=0 flags=0x21 boundary=(nil)/-1   
    Session Wait History:   
     
0: waited for 'db file sequential read'  
        file#=2, block#=1952c, blocks=1   
        wait_id
=1171 seq_num=1174 snap_id=1   
        wait times: snap
=0.018420 sec, exc=0.018420 sec, total=0.018420 sec   
        wait times: max
=infinite   
        wait counts: calls
=0 os=0   
        occurred after 
0.000034 sec of elapsed time  

  再往前可以找到进程信息:

PROCESS 38:   
  
----------------------------------------   
  SO: 0x45cccc3f0, type: 
2, owner: (nil), flag: INIT/-/-/0x00 if: 0x3 c: 0x3   
   proc
=0x45cccc3f0, name=process, file=ksu.h LINE:10706, pg=0   
  (process) Oracle pid:
38, ser:76, calls cur/top: 0x440d0ae48/0x43c5e5f88   
            flags : (0x2) SYSTEM   
            flags2: (0x30),  flags3: (0x0)    
            
int error0call error0, sess error0, txn error 0   
  ksudlp 
FALSE at location: 0   
  (post info) last post received: 
0 0 42   
              last post received
-location: ksv2.h LINE:1603 ID:ksvpst: run   
              last process 
to post me: 450d4b4f0 1 2   
              last post sent: 
0 0 151   
              last post sent
-location: kcrf.h LINE:3095 ID:kcrfw_redo_gen: wake LGWR after redo copy   
              last process posted by me: 45ccbe3f0 
1 6   
    (latch info) wait_event
=0 bits=0   
    Process Group: DEFAULT, pseudo proc: 0x4510353e0   
    O
/S info: user: oracle, term: UNKNOWN, ospid: 13549    
    OSD pid info: Unix process pid: 
13549, image: oracle@xxxxx (m001)  

  可以看到m001这个进程持有了mutex。但是会话没有在执行任何sql语句,而从会话的等待来看,last wait ended 14005 min 23 sec ago ,这个是不正常的,m001进程应该是出现了异常。

  m001进程是什么,这是mmon的slave进程,其中一个作用就是执行awr snapshot。很显然这个进程要访问v$sqlstat,是需要持有Cursor Stat类型的mutex的。

  至此就找到了所有等待的root holder。不过把这个结果告诉维护这个库的朋友时,告知服务器之前“死”了,已经重启了。重启后检查数据库,发现在故障期间很长一段时间内的确是没有产生awr snapshot。至于m001进程出了什么异常,为什么会出现异常,本文就不再详细讨论。实际上服务器重启之后也没有继续跟踪这一问题。

  mutex从设计上来说,与latch相比有着很明显的优点,只是作为新生事务(相对于目前仍然在广泛使用的10g来说), 存在BUG的可能性比较大。深入了解mutex,可以帮助我们更好地诊断mutex引起的相关问题。


第三十八届CIO班招生
国际CIO认证培训
首席数据官(CDO)认证培训
责编:lyre

免责声明:本网站(http://www.ciotimes.com/)内容主要来自原创、合作媒体供稿和第三方投稿,凡在本网站出现的信息,均仅供参考。本网站将尽力确保所提供信息的准确性及可靠性,但不保证有关资料的准确性及可靠性,读者在使用前请进一步核实,并对任何自主决定的行为负责。本网站对有关资料所引致的错误、不确或遗漏,概不负任何法律责任。
本网站刊载的所有内容(包括但不仅限文字、图片、LOGO、音频、视频、软件、程序等)版权归原作者所有。任何单位或个人认为本网站中的内容可能涉嫌侵犯其知识产权或存在不实内容时,请及时通知本站,予以删除。