System State 转储分析案例一则

Oracle | 2016-02-05 08:37

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

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

1.1 状态转储的常用命令

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

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

DUMP 进程状态可以使用：

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

或者使用：

oradebug setmypid

oradebug ulimit

oradebug dumpprocessstate<level>

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

altersessions set events 'immediate trace name systemstate level <level>'；

或：

oradebugsetmypid

oradebugulimit

oradebugdump 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 CACHEENQUEUE LOCK! 案例

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

问题是这样的：

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

客户的数据库环境为：

Oracle Database 10gEnterprise Edition Release 10.2.0.3.0 - 64bit Production

With thePartitioning, OLAP and Data Mining options

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

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

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

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

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

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

>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUELOCK! <<<

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

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

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

该文件得头部信息如下：

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号进程，查看其中的相关信息。经过检查可以发现这些内容与跟踪文件完全相符合：

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

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

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

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

Row cache enqueue 有一个（count=1）共享模式（request=S）的请求被阻塞：

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

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

1.4 ROW CACHE 对象的定位

跟踪文件向下显示了更进一步的信息，地址为 4f4e57138 的 Row Cache Parent Object 紧跟着之前的信息显示出来，跟踪信息同时显示是在 DC_OBJECTS 层面出现的问题。

跟踪信息显示对象的锁定模式为排他锁定（mode=X）。

下图是跟踪文件的截取，我们可以看到 Oracle 的记录方式：

进一步的，跟踪文件里也显示了29号进程执行的 SQL为INSERT 操作：

好了，那么现在我们来看看是哪一个进程排他的锁定了之前的4f4e57138对象。在跟踪文件中搜索4f4e57138就可以很容易的找到这个持有排他锁定的 SO 对象。

以下显示了相关信息，Row Cache 对象的信息在此同样有所显示：

再向上找到这个进程的信息，发现其进程号为16：

在这里可以看到16号进程是一个 JOB 进程，其进程为J000，那么这个 JOB 进程在执行什么操作呢？下面的信息可以看出一些端倪，JOB 由 DBMS_SCHEDULER 调度，执行 AUTO_SPACE_ADVISOR_JOB 任务，处于 Wait for shrink lock 等待：

进一步向下查找，可以找到 Shrink 操作执行的 SQL 语句：

至此，真相大白于天下：

1． 系统通过 DBMS_SCHEDULER 调度执行 AUTO_SPACE_ADVISOR_JOB 任务

发出了 SQL 语句：

alter index"CACI"."IDX_CACI_INV_BLB_DC" modify partition"P_2010_Q1" shrink space CHECK

2． 定时任务不能及时完成产生了排他锁定

3． 客户端执行的 INSERT 操作挂起

INSERT 语句为：

INSERT /*+ APPEND*/ INTOCACI_INV_BLB_DC NOLOGGING SELECT :B1 , T.*, SYSDATE FROM CACI_INV_BLB T

Shrink Space 的语句所以不能成功完成是因为该索引的相关数据表的数据量过为巨大。在 Oracle10g 中，缺省的有一个任务定时进行分析为用户提供空间管理建议，在进行空间建议前，Oracle 执行 Shrink Space Check，这个检查工作和 Shrink 的具体内部工作完全相同，只是不执行具体动作。

这个 Shrink Space 的检查对于客户环境显得多余。

现场解决这个问题，只需要将16号进程 Kill 掉，即可释放了锁定，后面的操作可以顺利进行下去。

1.5 使用 ass109.awk 脚本辅助分析

对于类似的跟踪文件，可以通过 Oracle 提供的 ass109.awk 脚本来分析，分析之后可以获得简明的输出（我的 Windows 上做了 Unix 工具增强，可以直接运行 awk 工具进行分析）：

D:\>awk -f ass109.awk edw_ora_8371.trc

..........................

Ass.Awk Version 1.0.9 - Processingedw_ora_8371.trc

System State 1

~~~~~~~~~~~~~~~~

1:

2: waiting for 'rdbms ipc message' wait

3: waiting for 'pmon timer' wait

4: waiting for 'rdbms ipc message' wait

5: waiting for 'rdbms ipc message' wait

6: waiting for 'rdbms ipc message' wait

7: waiting for 'rdbms ipc message' wait

8:

9: waiting for 'rdbms ipc message' wait

10:

11: waiting for 'rdbms ipc message' wait

12: for 'Streams AQ: waiting for timemanagement or cleanup tasks' wait

13: waiting for 'rdbms ipc message' wait

14: waiting for 'Streams AQ: qmncoordinator idle wait' wait

15: waiting for 'rdbms ipc message' wait

16:waiting for 'Wait for shrink lock' wait

17: waiting for 'smon timer' wait

18: waiting for 'SQL*Net message fromclient' wait

19: waiting for 'rdbms ipc message' wait

21: waiting for 'rdbms ipc message' wait

23: waiting for 'rdbms ipc message' wait

25: waiting for 'SQL*Net message fromclient' wait

27: waiting for 'SQL*Net message fromclient' wait

29:last wait for 'ksdxexeotherwait' [Rcache object=4f4e57138,]

Cmd: Insert

30: waiting for 'Streams AQ: qmn slave idlewait' wait

33: for 'Streams AQ: waiting for messagesin the queue' wait

Blockers

~~~~~~~~

Aboveis a list of all the processes. If they are waiting for a resource

thenit will be given in square brackets. Below is a summary of the

waitedupon resources, together with the holder of that resource.

Notes:

~~~~~

o A process id of '???' implies that theholder was not found in the

systemstate.

Resource Holder State

Rcache object=4f4e57138, 16: waiting for 'Wait for shrink lock'

Object Names

~~~~~~~~~~~~

Rcache object=4f4e57138,

77807 Lines Processed.

注意，输出文件中清晰地指出，数据库的16号进程持有了对象4f4e57138的 Row Cache 锁，正在等待：Wait for shrink lock。而29号进程正是在4f4e57138对象上产生了等待，处于挂起状态，无法执行INSERT操作。

1.6 AWR 报告的辅助诊断

生成数据库出现问题时段的 AWR 报告，也可以辅助我们确定数据库的相关操作。在以下图示中显示，Top 4SQL 都运行超过3400秒没有完成，第一个正是任务调度：

相关的 SQL 简要列举如下：

calldbms_space.auto_space_advisor_job_proc ( )

alter index"CACI"."IDX_CACI_INV_BLB_DC" modify partition"P_2010_Q1" shrink space CHECK

而如果你不关心空间建议，则可以取消这个定时任务，避免不比要的麻烦：

executedbms_scheduler.disable('AUTO_SPACE_ADVISOR_JOB');

最后还有一点需要额外说明的是，既然是 ROW Cache在DC（DictionaryCache）层面产生的竞争，那到底是什么对象呢？如何获得显示的证据呢？

我们再来回顾一下 SO 对象的以下部分信息：

这部分 Data 信息是什么呢？我们稍微逆向的转换一下。这次动作涉及的 SQL 是：

alter index"CACI"."IDX_CACI_INV_BLB_DC" modify partition"P_2010_Q1" shrink space CHECK

对象是 IDX_CACI_INV_BLB_DC 索引的 P_2010_Q1 分区，使用 dump 函数取一下16进制编码，获得如下输出：

SO 对象的 Data 部分正是指出了需要的对象内容，而当这个对象被排他锁定后，接下来的访问就处于了挂起状态。

这个案例给我们的经验是：当你使用新的数据库版本时，一定要认真了解其新特性，确保不会因为新特性而带来麻烦。

1.7 状态转储的常用命令

在某些情况下，Oracle 数据库在遇到异常时，会自动转储数据库的系统状态信息，此时会在告警日志里记录类似如下的信息：

>>> WAITED TOO LONG FOR A ROWCACHE ENQUEUE LOCK! pid=212

System State dumped to trace file/opt/oracle/admin/eygle/udump/eygle_ora_2123.trc

分析这一类的转储文件，可以帮助我们快速定位和找到问题的根源。有些时候，在系统出现异常挂起或莫名的性能问题时，也可以通过手工转储来获得系统的状态信息输出，帮助我们进行数据库性能数据收集，进而分析可能的原因。

而通过这样的 DUMP 文件，辅助我们上一节提到的 ass109.awk 脚本，则可以很容易的同一般用户进行远程的诊断和故障处理，以下是一个朋友在系统出现 Hang 住挂起时转储的状态文件分析，通过分析结果我们可以清晰的判断是归档的原因导致了系统出现 Library Cache Lock 和 Buffer Busy Waits 等等待：

通过这个简单的分析结果，再结合原始跟踪文件分析，非常有助于我们理解 Oracle 数据库的的等待事件以及内部工作原理。

文章来源：《Oracle DBA 手记 2》- System State 转储分析案例一则 作者：盖国强

About Me

....................................................................................................................................................

本文来自于微信公众号转载文章，若有侵权，请联系小麦苗及时删除

ITPUB BLOG：http://blog.itpub.net/26736162

QQ：642808185 若加QQ请注明您所正在读的文章标题

【版权所有，文章允许转载，但须以链接方式注明源地址，否则追究法律责任】

....................................................................................................................................................