Oracle資料庫效能障礙分析利器：SYSTEMSTATE DUMP介紹

作者  孟慶輝

沃趣科技資料庫工程師

當資料庫出現嚴重的效能問題或者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)