沃趣

作者  孟庆辉

沃趣科技数据库工程师


当数据库出现严重的性能问题或者hang了的时候,我们非常需要通过systemstate dump来知道进程在做什么,在等待什么,谁是资源的持有者,谁阻塞了别人。


在出现上述问题时,及时收集systemstate dump非常有助于问题原因的分析。


systemstate dump级别简介:

1. 级别2:dump(不包括lock element)

2. 级别10:dump

3. 级别11:dump+global cache of rac

4. 级别256:short stack(函数堆栈)

5. 级别258:级别256+级别2

6. 级别266:级别256+级别10

7. 级别267:级别256+级别11


  • 注 意


1. 级别11和级别267会dump global cache,会产生较大的trace 文件,一般不推荐。


2.  一般情况下,如果进程不是太多,建议用256,因为这样可以dump出来进程的函数堆栈,可以用来分析进程在执行什么操作,但是生成short stack比较耗时,如果进程非常多,比如2000个进程,那么可能耗时30分钟以上。这种情况下,可以生成level 10 或者 level 258, level 258  比 level 10会多收集short short stack, 但比level 10少收集一些lock element data。


3. 对于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。


systemstate dump大部分时候需要手工生成,其生成方式如下:

 

1. 用sqlplus登录到数据库


$sqlplus / as sysdba

 

当数据库已经非常慢或者数据库hang到无法连接时,可使用如下方式登录:

 

$sqlplus -prelim / as sysdba

---------------------在单节点上 生成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;==>这是 生成的 文件名

---------------------在RAC上 生成systemstate dump---------------------

SQL>oradebug setmypid SQL>oradebug unlimit

SQL>oradebug -g all dump systemstate 266

等1~2分钟 

SQL>oradebug -g all dump systemstate 266

等1~2分钟

SQL>oradebug -g all dump systemstate 266

 

在我们使用prelim参数仍然无法登录数据库时,可以使用gdb调试后台进程方式生成systemstate dump,例子如下:

 

$ ps -ef|grep pmon

oracle2828810 04:42 ?00:00:00 ora_pmon_R11202

$ gdb $ORACLE_HOME/bin/oracle 28288

 

然后查看这个进程的trace文件:

 

$ more R11202_pmon_28288.trc

 

需要注意的是:虽然detach到后台进程也可以搜集到systemstate dump,但是由于有一些Bug会导致detach到的进程异常终止,所以最好不要用后台进程,因为某些后台进程的异常终止会导致数据库实例的异常终止,所以使用用户进程来做systemtate dump更稳妥一些.

 

2.使用systemstate dump处理row cache lock问题


Oracle process number: 77

Unix process pid: 10846, image: oracle@cpdb4532

* 2011-05-13 08:08:58.775

* SERVICE NAME:(ALFCMR_SERVICE) 2011-05-13 08:08:58.775

* SESSION ID:(1076.796) 2011-05-13 08:08:58.775

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

row cache enqueue: session: 0x1df57ade8, mode: N, request: S

 

trace 文件头部我们可以看到:


oracle进程在等待row cache enqueue lock 请求的row cache enqueue级别是S(共享锁)

 

所以我们能够看到77号进程在等待获取共享锁。

 

systemstate dump包含了数据库所有进程的状态信息,然后我们找到77号进程信息。

 

PROCESS 77 

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

.

.

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

SO: 0x1cdf11958, type: 50, owner: 0x17d198288, flag: INIT/-/-/0x00 

row cache enqueue: count=1 session=0x1df57ade8 object=0x1dc9a5d30, request=S savepoint=0x87b70d

row cache parent object: address=0x1dc9a5d30 cid=7(dc_users) 

.


通过上面的信息我们可以看到77号进程请求在row cache dc_users上加共享锁, 如果77号进程在等待加锁,也就意味着有其他进程在持有该资源,我们需要通过systemstate dump找出谁是最终的资源持有者。

 

最好的方式是通过object=0x1dc9a5d30去搜索systemstate dump。

 

PROCESS 218:

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

.

.

SO: 0x1cdf118f8, type: 50, owner: 0x1ceb0f178, flag: INIT/-/-/0x00

row cache enqueue: count=1 session=0x1da54cf68 object=0x1dc9a5d30, request=X savepoint=0x11e

row cache parent object: address=0x1dc9a5d30 cid=7(dc_users)

 

上面的搜索结果中,我们发现218号进程在请求对object=0x1dc9a5d30添加排他锁,这往往意味着他处于资源等待队列的第一位,其他的资源请求都是排在他的后面,所以我们需要找到是谁锁住了这个进程。


PROCESS 164:

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

.

.

O/S info: user: u1m, term: , ospid: 1234, machine: cpc44711 program:

last wait for 'SQL*Net message from client' blocking sess=0x(nil) seq=36289 wait_t ime=6943 seconds since wait started=2539

driver id=54435000, #bytes=1, =0

SO: 0x1cdf11418, type: 50, owner: 0x1ccc26120, flag: INIT/-/-/0x00

row cache enqueue: count=2 session=0x1df578318 object=0x1dc9a5d30, mode=S savepoint=0xb1bd8e

row cache parent object: address=0x1dc9a5d30 cid=7(dc_users) hash=fc968070 typ=11 transaction=(nil) flags=00000002

own=0x1dc9a5e00[0x1cdf11448,0x1cdf11448] wat=0x1dc9a5e10[0x1cdf11928,0x17d5192e0] mode=S

 

我们根据object=0x1dc9a5d30最终找到上面部分内容,根据信息我们可以看到164进程以共享模式持有object:0x1dc9a5d30,因此阻塞了想要以排他模式持有该资源的进程218,而且可以看到164进程是持有CPU资源的(可以根据进程信息显示last wait for 'SQL*Net message from client'  而不是waiting for 'SQL*Net message from client'看出), 而且持有CPU时间为2539(根据seconds since wait started=2539看出),接下来我们就可以围绕该进程排查。

 

3.使用systemstate dump处理library cache lock问题


首先我们可以通过SQL找出任意一个目前正在处于library cache lock的进程,从该进程着手排查。

 

select pid from v$process where addr=

(select paddr from v$session where event='library cache lock' );

 

然后我们根据查到的进程号到systemstate dump文件中查找:


PROCESS 20:

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

SO: 0x7d2bd820, type: 2, owner: (nil), flag: INIT/-/-/0x00

(process) Oracle pid=20, calls cur/top: 0x7d3d62d0/0x7d3d85dc, 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: 7d2b8d94 1 6

last post sent: 0 0 24 

last post sent-location: ksasnd

last process posted by me: 7d2b8d94 1 6 (latch info) wait_event=0 bits=0

Process Group: DEFAULT, pseudo proc: 0x7d2ed5dc

O/S info: user: oracle, term: pts/7, ospid: 19759

OSD pid info: Unix process pid: 19759, image: goblin.forgotten.realms (TNS V1-V3)

<cut>

(session) sid: 141 trans: (nil), creator: 0x7d2bd820, flag: (41) USR/- BSY/-/-/-/-/-

DID: 0001-0014-00000668, short-term DID: 0000-0000-00000000 

txn branch: (nil) 

oct: 6, prv: 0, sql: 0x62d01c34, psql: 0x7c20f24c, user: 542/SCOTT

service name: SYS$USERS

O/S info: user: oracle, term: pts/7, ospid: 19758, machine: goblin.forgotten.realm s

program: sqlplus@goblin.forgotten.realms (TNS V1-V3)

application name: SQL*Plus, hash value=3669949024

waiting for 'library cache lock' blocking sess=0x(nil) seq=36 wait_time=0 seconds since wait started=11

handle address=62d064dc, lock address=79f88a68, 100*mode+namespace=c9

 

可以看到20号进程在等待library cache lock,我们可以根据handle address=62d064dc查找阻塞者。

 

根据handle address我们可以查询到18号进程目前正在以排他模式(mode=X)持有该锁。然后我们可以使用v$session及v$process视图进一步排查该进程。


参考资料

1.Troubleshooting: "WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! "(文档 ID 278316.1)


2.How to Find which Session is Holding a Particular Library Cache Lock(文档 ID 122793.1)

 

返回