通过systemstate dump转储文件分析a数据库hang原因

于 2024-11-27 14:59:06 发布
阅读量914 收藏 29
点赞数 19
文章标签： 程序人生
版权声明：本文为博主原创文章，遵循 CC 4.0 BY-SA 版权协议，转载请附上原文出处链接和本声明。
本文链接：https://blog.youkuaiyun.com/minebmw7/article/details/144084671
版权

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

  1. systemstate dump 介绍

当数据库出现严重的性能问题或者hang了的时候，非常需要通过systemstate dump来知道进程在做什么，在等待什么，谁是资源的持有者，谁阻塞了别人。在出现上述问题时，及时收集systemstate dump非常有助于问题原因的分析。

1.1 systemstate dump文件的生成

1.1.1 自动生成

在一些情况下，数据库会自动生成systemstate dump, 比如出现了“WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK”。 此时在alert 日志中会有提示：

WARNING: inbound connection timed out (ORA-3136)
Thu Feb 01 10:33:46 2024
NOTE: ASMB terminating
Errors in file /app/oracle/diag/rdbms/xxxxcogstb/xxxxcog2/trace/xxxxcog2_asmb_2425816.trc:
ORA-15064: communication failure with ASM instance
ORA-03135: connection lost contact
Process ID: 
Session ID: 993 Serial number: 44
Errors in file /app/oracle/diag/rdbms/xxxxcogstb/xxxxcog2/trace/xxxxcog2_asmb_2425816.trc:
ORA-15064: communication failure with ASM instance
ORA-03135: connection lost contact
Process ID: 
Session ID: 993 Serial number: 44
ASMB (ospid: 2425816): terminating the instance due to error 15064
Thu Feb 01 10:33:46 2024
System state dump requested by (instance=2, osid=2425816 (ASMB)), summary=[abnormal instance termination].
System State dumped to trace file /app/oracle/diag/rdbms/xxxxcogstb/xxxxcog2/trace/xxxxcog2_diag_6422788.trc
Thu Feb 01 10:33:47 2024
ORA-1092 : opitsk aborting process
Thu Feb 01 10:33:47 2024
ORA-1092 : opitsk aborting process

1.1.2 手动生成

systemstate dump大部分时候需要手工生成，具体的命令为： （如果连接很多，比如几千个连接，那么生成dump可能需要几十分钟，而且会占用几百M磁盘空间）

  1. 用sysdba登录到数据库上 
$sqlplus / as sysdba
或者
$sqlplus -prelim / as sysdba <==当数据库已经很慢或者hang到无法连接
  1. 生成systemstate dump文档 
SQL>oradebug setmypid
SQL>oradebug unlimit;
SQL>oradebug dump systemstate 266;
等1~2分钟
SQL>oradebug dump systemstate 266;
等1~2分钟
SQL>oradebug dump systemstate 266;
SQL>oradebug tracefile_name;==>这是生成的文件名
  1. 通常除了systemstate dump，最好同时生成hang analyze来直观地了解数据库进程间的等待关系。 
$sqlplus / as sysdba
或者
$sqlplus -prelim / as sysdba <==当数据库已经很慢或者hang到无法连接
SQL>oradebug setmypid
SQL>oradebug unlimit;
SQL>oradebug dump hanganalyze 3
等1~2分钟
SQL>oradebug dump hanganalyze 3
等1~2分钟
SQL>oradebug dump hanganalyze 3
SQL>oradebug tracefile_name;==>这是生成的文件名

对于RAC数据库，需要各个实例在同一时间的systemstate dump,那么登录到任意一个实例（无需在所有实例执行）：

$sqlplus / as sysdba
或者
$sqlplus -prelim / as sysdba <==当数据库已经很慢或者hang到无法连接

SQL>oradebug setmypid
SQL>oradebug unlimit
SQL>oradebug -g all dump systemstate 266  <==-g all 表示针对所有实例生成dump
等1~2分钟
SQL>oradebug -g all dump systemstate 266
等1~2分钟
SQL>oradebug -g all dump systemstate 266

在RAC上生成hang analyze:

SQL>oradebug setmypid
SQL>oradebug unlimit
SQL>oradebug -g all hanganalyze 3
等1~2分钟
SQL>oradebug -g all hanganalyze 3
等1~2分钟
SQL>oradebug -g all hanganalyze 3

上面的命令执行后会在每个实例都生成systemstate dump，生成的信息放到了每个实例的backgroud_dump_dest下的diag trace文件中。 上面的这些命令执行三次是为了比较进程的变化情况，查看是真的hang了，还是很慢。

1.2 systemstate dump级别

2:    dump (不包括lock element)
10:   dump
11:   dump + global cache of RAC
256: short stack （函数堆栈）
258: 256+2   -->short stack +dump(不包括lock element)
266: 256+10 -->short stack+ dump
267: 256+11 -->short stack+ dump + global cache of RAC

1.3 级别使用建议

  1. level 11和 267会 dump global cache, 会生成较大的trace 文件，一般情况下不推荐。

  2. 一般情况下，如果进程不是太多，推荐用266，因为这样可以dump出来进程的函数堆栈，可以用来分析进程在执行什么操作，但是生成short stack比较耗时。

  3. 如果进程非常多，比如2000个进程，那么可能耗时30分钟以上。这种情况下，可以生成level 10 或者 level 258， level 258 比 level 10会多收集short short stack, 但比level 10少收集一些lock element data.

  4. 对于RAC系统，请关注Bug 11800959 - A SYSTEMSTATE dump with level >= 10 in RAC dumps huge BUSY GLOBAL CACHE ELEMENTS - can hang/crash instances (Doc ID 11800959.8)。这个Bug在11.2.0.3上被修复，对于<=11.2.0.2的RAC，当系统中的lock element 很多的时候，如果执行level 10、266或者 267的systemstate dump时，可能会导致数据库hang或者crash，这种情况下可以采用level 258。

  5. 案例分析

2.1 问题描述

此前一个 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-33 Machine: sun 4u

2.2 关注点

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

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

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

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

2.3 分析过程

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

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

如果这个错误提示出现在Oracle 默认或规划的JOB 的调度时间附近，显然业务与调度job冲突是一个高度相关的可能原因。

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

2.3.1 DUMP 转储文件分析定位问题 这个异常生成了转储的 DUMP 文件，获得该文件进行进一步的详细分析。 文件头部信息如下：

alt

以上信息中的重要内容包括：

1． 超时告警的时间是06:54: 2023-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号进程，查看其中的相关信息。经过检查可以发现这些内容与跟踪文件完全相符合：

alt

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

alt

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

alt

在这个进程跟踪信息的最后部分，有如下一个 SO 对象继承关系列表，注意这里的 OWNER 具有级联关系，下一层隶属于上一层的 Owner，第一个 SO对象的 Owner 6c1006740 就是 PROCESS 29 的 SO 号。 到了最后一个级别的 SO 4e86f03e8上，请求出现阻塞。 Row cache enqueue 有一个（count=1）共享模式（request=S）的请求被阻塞：

alt

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

alt

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

1.4 ROW CACHE 对象的定位

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

跟踪信息显示对象的锁定模式为排他锁定（mode=X）。 下图是跟踪文件的截取，可以看到 Oracle 的记录方式：

alt

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

alt

现在看看是哪一个进程排他的锁定了之前的4f4e57138对象。在跟踪文件中搜索4f4e57138就可以很容易的找到这个持有排他锁定的 SO 对象。 以下显示了相关信息，Row Cache 对象的信息在此同样有所显示：

alt

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

alt

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

alt

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

alt

2.3.2 数据库hang产生过程

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*/ INTO CACI_INV_BLB_DC NOLOGGING SELECT :B1 , T.*, SYSDATE FROM CACI_INV_BLB T

2.3.3 数据库hang原因

Shrink Space 的语句所以不能成功完成是因为该索引的相关数据表的数据量过为巨大。在 Oracle10g 中，缺省的有一个任务定时进行分析为用户提供空间管理建议，在进行空间建议前，Oracle 执行 Shrink Space Check，这个检查工作和 Shrink 的具体内部工作完全相同，只是不执行具体动作。 这个 Shrink Space 的检查对于一般环境是多余的。 现场解决这个问题，只需要将16号进程 Kill 掉，即可释放了锁定，后面的操作可以顺利进行下去。

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

对于类似的跟踪文件，可以通过 Oracle 提供的 ass109.awk 脚本来分析，分析之后可以获得简明的输出

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操作。

2.5 用于分析systemstate dump文件的awk脚本

使用说明：ass109.awk脚本包含在LTOM431版本中，主要用于分析systemstate生成的trace文件。

示例如下：
[root@pr7 ~]# awk -f ass109.awk lsyy1_ora_17433530.trc

2.6 AWR 报告的辅助诊断

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

alt

相关的 SQL 简要列举如下：

calldbms_space.auto_space_advisor_job_proc ( )
alter index"CACI"."IDX_CACI_INV_BLB_DC" modify partition"P_2010_Q1" shrink space CHECK

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

execute dbms_scheduler.disable('AUTO_SPACE_ADVISOR_JOB');

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

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

alt

这部分 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进制编码，获得如下输出：

alt

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

  1. Library Cache Lock 和 Buffer Busy Waits案例

由于归档的原因导致了系统出现 Library Cache Lock 和 Buffer Busy Waits 等等待。

可以通过上面对Hang 住挂起时转储的状态文件分析方法，对下面的文件进行解读。kill 掉数据库15号进程可以解决数据库hang原因。

alt
alt

本文由 mdnice 多平台发布

minebmw7
关注
IPC Send timeout detected. Receiver ospid IPC超时的问题
weixin_tank88921的博客
08-02 934
IPC Send timeout 是 Oracle10g Rac中非常让人头痛的一个问题，在资源紧张、网络拥堵等情况下，就有可能发生IPC超时的问题，而RAC随后就会将问题节点驱逐，引发一轮重新配置。可喜的是Metalink上针对10.2.0.3有了一个Patch可以修正，而且在10.2.0.4中彻底修正了该问题。这个BUG号是Bug 519059610.2.0.3的确常有这个问题，而10.2.0.4却很少看到。
Oracle报错ORA-00603 ORA-00600[4193]错误 解决方案
ZSY老司机的博客
10-02 4084
5、删除原有的undo tablespace创建新的undo tablespace。根据MOS介绍，此故障一般和undo segment有关。1、在做了redo log当前日志组被破坏恢复的测试后。2、启动数据库后出现ORA-600 【4193】的错误。查看告警日志，数据库启动正常，问题解决！3、通过pfile启动Instance。6、关闭数据库，重新通过spfle启动。1、通过spfile生成pfile。2、编辑pfile文件。3、数据库被强制关闭。
利用systemstate dump trace文件寻找dg terminated原因
conghe6716的博客
01-26 670
上午收到告警，一台 dataguard 宕机了。软件版本为 11.2.0.4. 登录上来首先查看 alert 文件 . Fri Jan 25 1...
Oracle 启动故障案例之--ORA-600 [4193]错误
天涯客*Blog
12-14 7726
Oracle 启动故障案例之--ORA-600 [4193]错误 操作系统：Oracle Linux 5 数据库：    Oracle 11gR2（11.2.0.3.0） 一、故障现象： 1、在做了redo log当前日志组被破坏恢复的测试后 2、启动数据库后出现ORA-600 【4193】的错误 3、数据库被强制关闭 查看告警日志： [oracle@ocm1 ~]$ ta
Oracle1463,Oracle LTOM数据库故障诊断工具！
weixin_35808305的博客
04-06 383
LTOM和上一篇文章提到的OSW工具类似，都是oracle提供的一个诊断工具，不过OSW是基于OS层面的信息统计，LTOM则倾向于统计数据库的相关信息，结合这2个诊断工具，可以给DBA减少不少的工作量。和OSW一样，LTOM同样支持多平台：Solaris,Linux,HP-UX,AIX,Tru64. 目前最新版本是4.3.1，文章末尾有下载地址。下面简单是来看一下LTOM的安装和使用。1. 上传L...
存储问题
weixin_30772105的博客
05-14 1014
2019-05-14T15:17:31.522473+08:00 requested by (instance=3, osid=193847 (DIA0)), summary=[process state dump request (kjznHA)] requested by (instance=3, osid=193847 (DIA0)), summary=[process state...
Oracle常用dump命令，记录一下备查。
09-14
Oracle dump命令是Oracle数据库管理员和开发者在日常工作中经常使用的命令之一。该命令可以帮助用户快速地获取数据库的各种信息，包括Global Area、Library Cache、Row Cache、Buffers、Buffer、Heap、Sub Heap、...
Oracle常用dump命令介绍
07-31
**Hang Analysis** 用于分析挂起情况： - **`ALTER SESSION SET EVENTS 'immediate trace name hanganalyze level n'`** ##### 12\. Work Area **Work Area** 命令可以获取Work Area Table的信息： - **`ALTER ...
oracle系统状态trace文件分析器
06-29
oracle系统状态trace文件分析器 当系统hang住时，或者进程间有阻塞时，你可以产生下面两种跟踪文件，一种是进程状态跟踪文件，一种是系统状态跟踪文件：　 process state dumps ==> 一个进程的所有对象状态,...
Oracle DBA日常运维及应急故障处理手册
05-24
在处理这类问题时，建议先进行系统状态转储（systemstate dump），并多次执行3级hang analyze来定位引起问题的会话。 总之，Oracle数据库管理员需要熟练掌握各种运维工具和诊断技术，才能有效地处理各种故障，保证...
LTOM系统监控
05-27
Introduction The Lite Onboard Monitor (LTOM) is a java program designed as a real-time diagnostic platform for deployment to a customer site. LTOM differs from other support tools, as it is proactive rather than reactive. LTOM provides real-time automatic problem detection and data collection. LTOM runs on the customer's UNIX server, is tightly integrated with the host operating system and provides an integrated solution for detecting and collecting trace files for system performance issues. The ability to detect problems and collect data in real-time will hopefully reduce the amount of time it takes to solve problems and reduce customer downtime.
Oracle数据库性能障碍分析利器：SYSTEMSTATE DUMP介绍
Joy0921的博客
04-07 656
当数据库出现严重的性能问题或者hang了的时候，我们非常需要通过SYSTEMSTATE DUMP来知道进程在做什么，在等待什么，谁是资源的持有者，谁阻塞了别人。在出现上述问题时，及时收集SYSTEMSTATE DUMP非常有助于问题原因的分析。 　SYSTEMSTATE DUMP级别简介： 级别2:dump(不包括lock element) 级别10:dump 级别11...
systemstate dump 介绍
love4959的专栏
04-22 449
当数据库出现严重的性能问题或者hang了的时候，我们非常需要通过systemstate dump来知道进程在做什么，在等待什么，谁是资源的持有者，谁阻塞了别人。在出现上述问题时，及时收集systemstate dump非常有助于问题原因的分析。 在一些情况下，数据库会自动生成systemstate dump, 比如出现了“WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK”。 systemstate dump大部分时候需要手工生成，具体的命令为： 如果连接很多，比如
内核参数导致的备库宕机分析
congbao6525的博客
11-19 393
在前几天搭建好备库之后，因为同步文件着实花了些时间，首先配置备库能够正常接收归档，然后内核参数也基本没有设置，简单使用脚本算出一个Hugepage的值，就直接改了。当时从数据库日志中确实也没有发现hugepage启用的情况，但是...
JVM内存模型测试--Thread
iteye_17344的博客
01-25 568
 今天在SUN的jdk上测试了Thread栈占用内存的情况，帮助进一步了解JVM的内存模型。配置如下： WIN7+4G    SUN JDK： D:\maven\smart\smart&gt;java -version java version "1.6.0_21" Java(TM) SE Runtime Environment (build 1.6.0_21-b06) Java H...
lms oracle 启动失败,11gr2 的一个节点crs无法启动 asm也起不来
weixin_42131633的博客
04-11 708
Fri Dec 20 09:56:09 2013NOTE: No asm libraries found in the systemMEMORY_TARGET defaulting to 411041792.* instance_number obtained from CSS = 2, checking for the existence of node 0...* node 0 does no...
评论
添加红包

请填写红包祝福语或标题

个

红包个数最小为10个

元

红包金额最低5元

当前余额3.43元 前往充值 >
需支付：10.00元
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付元
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明：

1.余额是钱包充值的虚拟货币，按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载，可以购买VIP、付费专栏及课程。

余额充值