暂无图片
暂无图片
暂无图片
暂无图片
暂无图片

DBA手记:System State转储分析之问题定位

原创 eygle 2011-05-24
741
在《Oracle DBA手记 3》即将出版之际,我将《Oracle DBA手记 2》上收录的一些文章发布出来,与大家分享。


Oracle数据库的运行过程中,可能会因为一些异常遇到数据库挂起失去响应的状况,在这种状况下,我们可以通过对系统状态进行转储,获得跟踪文件进行数据库问题分析;很多时候数据库也会自动转储出现问题的进程或系统信息;这些转储信息成为我们分析故障、排查问题的重要依据。


本章通过实际案例的详细分析,讲解如何逐层入手、层层剖析的分析数据库故障。


1.1         
状态转储的常用命令


当数据库出现一些挂起状态时,往往会严重影响到数据库使用,进程级的问题影响范围较小,而系统级的问题则会影响全局。


在出现数据库系统或进程失去响应时,如果SQL*Plus工具仍然可以连接,可能视图查询没有相应,但是可以通过oradebug工具来进行进程及系统状态信息的转储,从而可以进行Hang分析。


DUMP进程状态可以使用:


      alter sessions set events
'immediate trace name processstate level <level>'


    或者使用:


      oradebug setmypid


      oradebug ulimit


      oradebug dump
processstate<level>


 


当诊断数据库挂起时,可以使用DUMP命令转储整个系统状态:


  alter
sessions set events 'immediate trace name systemstate level <level>'


  或:


  oradebug
setmypid


  oradebug
ulimit


  oradebug
dump systemstate <level>


如果为了获取全面一点的信息,可以使用Level 10


SQL> oradebug setmypid


SQL> oradebug unlimit


SQL> oradebug dump systemstate 10


另外如果系统挂起,无法用SQL*Plus连接,从Oracle 10g开始,可以使用sqlplus -prelim选项强制登录,然后即可进行系统状态信息转储:


sqlplus -prelim '/ as sysdba'


oradebug setmypid


oradebug unlimit;


oradebug dump systemstate 10


 


1.2         
WAITED TOO LONG FOR A ROW CACHE
ENQUEUE LOCK!
案例


在一次客户现场培训中,客户提出一个系统正遇到问题,请求我协助诊断解决,理论联系实践,这是我在培训中极力主张的,我们的案例式培训业正好遇到了实践现场。


 


问题是这样的:


此前一个Job任务可以在秒级完成,而现在运行了数小时也无法结束,一直挂起在数据库中,杀掉进程重新手工执行,尝试多次,同样无法完成。


客户的数据库环境为:


Oracle Database 10g
Enterprise Edition Release 10.2.0.3.0 - 64bit Production


With the
Partitioning, OLAP and Data Mining options


Node name:    SF2900 
Release:   5.9  Version: Generic_118558-33
Machine:  sun4u


 介入问题诊断首先需要收集数据,我最关注两方面的信息:


1. 告警日志文件,检查是否出现过异常


2. 生成AWR报告,检查数据库内部的运行状况


通常有了这两部信息,我们就可以做出初步判断了。


 


检查数据库的告警日志文件,我们发现其中出现过一个如下错误:


>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE
LOCK! <<<


这个错误提示出现在7点左右,正是JOB的调度时间附近,显然这是一个高度相关的可能原因。


1.3         
DUMP转储文件分析定位问题


 


这个异常生成了转储的DUMP文件,获得该文件进行进一步的详细分析。

该文件得头部信息如下:


Redo thread mounted
by this instance: 1


Oracle process number: 29


Unix process pid: 8371, image:
oracleEDW@SF2900


 


*** 2010-03-27
06:54:00.114


*** ACTION NAME:()
2010-03-27 06:54:00.106


*** MODULE NAME:(SQL*Plus) 2010-03-27 06:54:00.106


*** SERVICE
NAME:(EDW) 2010-03-27 06:54:00.106


*** SESSION ID:(120.46138) 2010-03-27
06:54:00.106


>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK!
<<<


row cache enqueue: session: 6c10508e8, mode: N, request: S


ROW CACHE队列锁无法获得,表明数据库在SQL解析时,遇到问题,DC层面出现竞争,导致超时。Row Cache位于Shared Pool中的Data Dictionary Cache,是用于存储表列定义、权限等相关信息的。


 


注意以上信息中的重要内容包括:


1. 超时告警的时间是06:54: 2010-03-27 06:54:00.106


2. 出现等待超时的数据库进程号是29Oracle process number: 29


3. 等待超时的29号进程的OS进程号为8317Unix process pid: 8371


4. 进程时通过SQL*Plus调度执行的:MODULE NAME:(SQL*Plus)


5. 会话的IDSerial#信息为120.46138SESSION ID:(120.46138)


6. 进程的State Object6c10508e8row cache enqueue: session: 6c10508e8


7. 队列锁的请求模式为共享(S):mode: N, request: S


 


有了这些重要的信息,我们就可以开始一些基本的分析。


首先可以在跟踪文件中找到29号进程,查看其中的相关信息。经过检查可以发现这些内容与跟踪文件完全相符合:


PROCESS 29:


  ----------------------------------------


  SO: 6c1006740, type: 2, owner: 0, flag:
INIT/-/-/0x00


  (process) Oracle pid=29, calls cur/top: 6c1097430/6c1096bf0, flag: (0) -


            int error: 0, call error: 0, sess
error: 0, txn error 0


  (post info) last post received: 109 0 4


              last post received-location:
kslpsr


              last process to post me:
6c1002800 1 6


              last post sent: 0 0 24


              last post sent-location: ksasnd


              last process posted by me:
6c1002800 1 6


    (latch info) wait_event=0 bits=0


    Process Group: DEFAULT, pseudo proc:
4f818c298


    O/S info: user: oracle, term: UNKNOWN, ospid: 8371


    OSD pid info: Unix process pid: 8371, image: oracleEDW@SF2900


 


进一步的向下检查可以找到SO对象6c10508e8,这里显示该进程确实由客户端的SQL*Plus发起,并且客户端的主机名称及进程的OSPID都记录在案:


    SO:
6c10508e8
, type: 4, owner: 6c1006740, flag: INIT/-/-/0x00


    (session) sid: 120 trans: 6c285ea98,
creator: 6c1006740, flag: (100041) USR/- BSY/-/-/-/-/-


              DID: 0001-001D-001BC795,
short-term DID: 0000-0000-00000000


              txn branch: 0


              oct: 2, prv: 0, sql: 4f528d510,
psql: 491cbe3e8, user: 56/CACI


    O/S info: user:
Administrator, term: HOST03, ospid: 37692:38132, machine:


              program:
sqlplus.exe


application name:
SQL*Plus, hash value=3669949024


接下来的信息显示,进程一直在等待,等待事件为'ksdxexeotherwait'


    last wait for 'ksdxexeotherwait' blocking
sess=0x0 seq=36112 wait_time=5 seconds since wait started=3


                =0, =0, =0


    Dumping Session Wait History


     for 'ksdxexeotherwait' count=1 wait_time=5


                =0, =0, =0


     for 'ksdxexeotherwait' count=1 wait_time=5


                =0, =0, =0


     for 'ksdxexeotherwait' count=1 wait_time=3


                =0, =0, =0


     for 'ksdxexeotherwait' count=1 wait_time=5


                =0, =0, =0


     for
'ksdxexeotherwait' count=1 wait_time=4


                =0, =0, =0


     for 'ksdxexeotherwait' count=1 wait_time=3


                =0, =0, =0


     for 'ksdxexeotherwait' count=1 wait_time=4


                =0, =0, =0


     for 'ksdxexeotherwait' count=1 wait_time=4


                =0, =0, =0


     for 'ksdxexeotherwait' count=1 wait_time=3


                =0, =0, =0


     for 'ksdxexeotherwait' count=1 wait_time=3


                =0, =0, =0


    temporary object counter: 0


在这个进程跟踪信息的最后部分,有如下一个SO对象继承关系列表,注意这里的OWNER具有级联关系,下一层隶属于上一层的Owner,第一个SO对象的Owner 6c1006740就是PROCESS 29SO号。


到了最后一个级别的SO 4e86f03e8上,请求出现阻塞。


Row cache enqueue有一个(count=1)共享模式(request=S)的请求被阻塞:


    ----------------------------------------


    SO:
6c1096bf0, type: 3, owner: 6c1006740
, flag: INIT/-/-/0x00


    (call) sess: cur 6c10508e8, rec 6c10508e8,
usr 6c10508e8; depth: 0


      ----------------------------------------


      SO:
6c1096eb0, type: 3, owner: 6c1096bf0
, flag: INIT/-/-/0x00


      (call) sess: cur 6c10508e8, rec
6c10691f8, usr 6c10508e8; depth: 1


       
----------------------------------------


        SO:
6c1097430, type: 3, owner: 6c1096eb0
, flag: INIT/-/-/0x00


        (call) sess: cur 6c10691f8, rec
6c10691f8, usr 6c10508e8; depth: 2


         
----------------------------------------


          SO:
4e86f03e8, type: 50, owner: 6c1097430
, flag: INIT/-/-/0x00


          row cache enqueue: count=1 session=6c10508e8 object=4f4e57138,
request=S


          savepoint=0xf67b


 


回过头去对比一下跟踪文件最初的信息,注意这里的session信息正是跟踪文件头上列出的session信息:


>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK!
<<<


row cache enqueue: session: 6c10508e8, mode: N, request: S


至此我们找到了出现问题的根源,这里也显示请求的对象是object=4f4e57138



「喜欢这篇文章,您的关注和赞赏是给作者最好的鼓励」
关注作者
【版权声明】本文为墨天轮用户原创内容,转载时必须标注文章的来源(墨天轮),文章链接,文章作者等基本信息,否则作者和墨天轮有权追究责任。如果您发现墨天轮中有涉嫌抄袭或者侵权的内容,欢迎发送邮件至:contact@modb.pro进行举报,并提供相关证据,一经查实,墨天轮将立刻删除相关内容。

评论