oracle_systemstate dump分析

最新推荐文章于 2021-04-22 20:45:04 发布

yrg5101

最新推荐文章于 2021-04-22 20:45:04 发布

阅读量305

点赞数

分类专栏： oracle 性能优化

oracle 性能优化专栏收录该内容

99 篇文章 0 订阅

订阅专栏

首先简单的介绍一下 event systemstate。
很多人把 systemstate 事件理解为dump发生的那一刻的系统内所有进程的信息，这是个错误的概念，事实上，
转储 system state 产生的跟踪文件是从dump那一刻开始到dump任务完成之间一段事件内的系统内所有进程的信息。

dump systemstate产生的跟踪文件包含了系统中所有进程的进程状态等信息。每个进程对应跟踪文件中的一段内容，反映该进程的状态信息，包括进程信息，会话信息，enqueues信息（主要是lock的信息），缓冲区的信息和该进程在SGA区中持有的（held）对象的状态等信息。

那么通常在什么情况下使用systemstate比较合适呢？
Oracle推荐的使用systemstate事件的几种情况是：

数据库 hang 住了
数据库很慢
进程正在hang
数据库出现某些错误
资源争用

dump systemstate的语法为：
ALTER SESSION SET EVENTS 'immediate trace name systemstate level 10';

也可以使用ORADEBUG实现这个功能
ORADEBUG DUMP SYSTEMSTATE level 10

如果希望在数据库发生某种错误时调用systemstate事件，可以在参数文件（spfile或者pfile）中设置event参数，
例如，当系统发生死锁（出现ORA-00060错误）时dump systemstate：
event = "60 trace name systemstate level 10"

言归正传，我们dump系统状态：
SQL> ALTER SESSION SET EVENTS 'IMMEDIATE TRACE NAME SYSTEMSTATE LEVEL 8';

Session altered.

以library cache lock为例来解读dump文件

首先，通过在跟踪文件中查找字符串"waiting for 'library cache lock'"，我们找到了被阻塞进程的信息：

PROCESS 28: ----------------被阻塞的Oracle进程，这里PROCESS 28对应了V$PROCESS中的PID的值，
    也就是说我们可以根据这一信息在V$PROCESS和V$SESSION找到被阻塞的会话的信息
----------------------------------------
SO: c000000109c83bf0, type: 2, owner: 0000000000000000, flag: INIT/-/-/0x00
(process) Oracle pid=28, calls cur/top: c00000010b277890/c00000010b277890, flag: (0) -
            int error: 0, call error: 0, sess error: 0, txn error 0
(post info) last post received: 17 24 6
              last post received-location: ksusig
              last process to post me: c000000109c840f8 25 0
              last post sent: 0 0 15
              last post sent-location: ksasnd
              last process posted by me: c000000109c7ff90 1 6
    (latch info) wait_event=0 bits=0
    Process Group: DEFAULT, pseudo proc: c000000109eefda0
    O/S info: user: ora9i, term: pts/th, ospid: 22580 ----------------该进程的操作系统进程号，对应于V$PROCESS中的SPID
    OSD pid info: Unix process pid: 22580, image: oracle@cs_dc02 (TNS V1-V3)
    ----------------------------------------
    SO: c000000109f02c68, type: 4, owner: c000000109c83bf0, flag: INIT/-/-/0x00
    (session) trans: 0000000000000000, creator: c000000109c83bf0, flag: (100041) USR/- BSY/-/-/-/-/-
              DID: 0002-001C-00000192, short-term DID: 0000-0000-00000000
              txn branch: 0000000000000000
              oct: 0, prv: 0, sql: c00000011f8ea068, psql: c00000011f8ea068, user: 50/PUBUSER
    O/S info: user: ora9i, term: , ospid: 22536, machine: cs_dc02
              program: sqlplus@cs_dc02 (TNS V1-V3)
    application name: SQL*Plus, hash value=3669949024
    waiting for 'library cache lock' blocking sess=0x0 seq=18589 wait_time=0
                handle address=c000000122e2a6d8, lock address=c00000011a449e20, 100*mode+namespace=515

。。。。。。

    SO: c00000010b277890, type: 3, owner: c000000109c83bf0, flag: INIT/-/-/0x00
    (call) sess: cur c000000109f02c68, rec 0, usr c000000109f02c68; depth: 0
      ----------------------------------------
      SO: c00000011a449e20, type: 51, owner: c00000010b277890, flag: INIT/-/-/0x00
      LIBRARY OBJECT LOCK: lock=c00000011a449e20 handle=c000000122e2a6d8 request=S
      call pin=0000000000000000 session pin=0000000000000000
      htl=c00000011a449e90[c00000011a4bc350,c00000011a4bc350] htb=c00000011a4bc350
      user=c000000109f02c68 session=c000000109f02c68 count=0 flags=[00] savepoint=463
      the rest of the object was already dumped

。。。。。。

请注意下面的信息：
waiting for 'library cache lock' blocking sess=0x0 seq=18589 wait_time=0
handle address=c000000122e2a6d8, lock address=c00000011a449e20, 100*mode+namespace=515

这段信息告诉我们ORACLE PID为 28的进程(PROCESS 28)，正在等待'library cache lock' ，通过‘handle address=c000000122e2a6d8’我们可以找到阻塞它的会话的ORACLE PID信息。

还要注意这段信息：
      LIBRARY OBJECT LOCK: lock=c00000011a449e20 handle=c000000122e2a6d8 request=S
      call pin=0000000000000000 session pin=0000000000000000
      htl=c00000011a449e90[c00000011a4bc350,c00000011a4bc350] htb=c00000011a4bc350
      user=c000000109f02c68 session=c000000109f02c68 count=0 flags=[00] savepoint=463

这里就是阻塞PROCESS 28进程的会话的信息。

简单的记住这个依据的要点是：

waiting session的'handle address'的值对应于blocking session的'handle'的值。

回过头来，看看这个值，它应于上面我们在V$SESSION_WAIT中看到的P1和P2的值：
SQL> select to_number('C000000122E2A6D8','XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX') from dual;

TO_NUMBER('C000000122E2A6D8','XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX')
----------------------------------------------------------------
1.3835E+19

SQL>

问题的成因已经基本上明确了，这里推荐两种解决问题的方法：
方法1，根据 c000000122e2a6d8 地址，我们可以得到当前在library cache中相应的锁信息：
SQL> l
1 select INST_ID,USER_NAME,KGLNAOBJ,KGLLKSNM,KGLLKUSE,KGLLKSES,KGLLKMOD,KGLLKREQ,KGLLKPNS,KGLLKHDL
2* from X$KGLLK where KGLLKHDL = 'C000000122E2A6D8' order by KGLLKSNM,KGLNAOBJ
SQL> /

   INST_ID USER_NAME     KGLNAOBJ                 KGLLKSNM KGLLKUSE         KGLLKSES       KGLLKMOD   KGLLKREQ KGLLKPNS         KGLLKHDL
---------- ------------- ---------------------- ---------- ---------------- ---------------- ---------- ---------- ---------------- ----------------
         2 PUBUSER       CSNOZ629926699966              30 C000000109F02C68 C000000109F02C68      0          2 00               C000000122E2A6D8
         2 PUBUSER       CSNOZ629926699966              37 C000000108C99E28 C000000108C99E28      3          0 00               C000000122E2A6D8

SQL>

按照Oracle推荐的做法，我们现在应该使用'alter system kill session'命令kill掉SID 37，
结果得到了ORA-00031错误：
SQL> alter system kill session '37,2707';

alter system kill session '37,2707'
*
ERROR at line 1:
ORA-00031: session marked for kill

SQL>

检查SID 37的状态：
SQL> set linesize 150
SQL> col program for a50
SQL> select sid,serial#,status,username,program from v$session where sid=37;

SID SERIAL# STATUS USERNAME PROGRAM
---------- ---------- -------- ------------------------------ --------------------------------------------------
37 2707 KILLED PUBUSER sqlplus@cs_dc02 (TNS V1-V3)

SQL>
再次证实了我们最初的想法—— 有人在执行了某个需要运行很久的DDL（多数是语句效率低，当然不排除遭遇bug的可能），
然后没等语句结束就异常退出了会话。

这个例子中我们在上面的跟踪文件已经找到了该会话对应的操作系统进程(SPID)，如果在其他情况下，我们如何找到这种状态为'KILLED'
的操作系统进程号（SPID）呢？
下面给出了一个方法，可以借鉴：
SQL> l
1 SELECT s.username,s.status,
2 x.ADDR,x.KSLLAPSC,x.KSLLAPSN,x.KSLLASPO,x.KSLLID1R,x.KSLLRTYP,
3 decode(bitand (x.ksuprflg,2),0,null,1)
4 FROM x$ksupr x,v$session s
5 WHERE s.paddr(+)=x.addr
6 and bitand(ksspaflg,1)!=0
7* and s.sid=37
SQL> /

USERNAME STATUS ADDR KSLLAPSC KSLLAPSN KSLLASPO KSLLID1R KS D
------------------------------ -------- ---------------- ---------- ---------- ------------ ---------- -- -
PUBUSER KILLED C000000109C831E0 41 15 16243 17

SQL>

x$ksupr.ADDR列的值对应了V$PROCESS 中的ADDR的值，知道了这个SPID的地址，找到这个操作系统进程(SPID)就简单了，例如：
SQL> select spid,pid from v$process where addr='C000000109C831E0';

SPID PID
------------ ----------
20552 26

在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.3DUMP转储文件分析定位问题

这个异常生成了转储的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 什么是进程的state object???--DSI 401中对state object中有提到，但是没有完全了解

7．队列锁的请求模式为共享（S）：mode: N, request: S

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

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

PROCESS 29:

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

SO: 6c1006740 --state object, 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。

转载：http://wenku.baidu.com/view/1edefb0fba1aa8114431d90a.html