« [JOBS]DBA 和 数据挖掘 的招聘需求 | Blog首页 | DBA手记:System State转储之ROW CACHE对象 »
DBA手记:System State转储分析之问题定位
链接：https://www.eygle.com/archives/2011/05/dbasystem_state_file.html
在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． 出现等待超时的数据库进程号是29：Oracle process number: 29
3． 等待超时的29号进程的OS进程号为8317：Unix process pid: 8371
4． 进程时通过SQL*Plus调度执行的：MODULE NAME:(SQL*Plus)
5． 会话的ID、Serial#信息为120.46138：SESSION ID:(120.46138)
6． 进程的State Object为6c10508e8：row 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 29的SO号。
到了最后一个级别的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。
历史上的今天...
>> 2012-05-25文章:
>> 2010-05-25文章:
>> 2007-05-25文章:
By eygle on 2011-05-25 08:21 | Comments (7) | Case | 2803 |
技术文章总是难懂
能否把整个dump的trace文件发出来看看？以便于我们可以对照blog上的文字和真正的tracefile里面的内容。搞个压缩包也行。
能否把整个dump的trace文件发出来看看？以便于我们可以对照blog上的文字和真正的tracefile里面的内容。搞个压缩包也行。
大师，分享trace 文件吧:)
dba3啥时出啊
估计下个月出了,谢谢支持
看不到你21号的回复啊