用Oracle跟蹤診斷掛起的會話

1.簡介

本文透過例子簡要介紹瞭如何利用Oracle的跟蹤以及內部資料字典表診斷某些掛起的會話。

--測試指令碼

conn test/test

create orreplace procedure sp_test

as

begin

dbms_lock.sleep(seconds=>600);

end;

/

假定以下的場景：

Client A以test使用者登陸到資料庫中執行過程sp_test

sql>execsp_test;

幾秒後Client B以test使用者登陸到資料庫中執行批次complie儲存過程的操作，在執行

sql>alterprocedure sp_test compile;

的時候發現程式掛起，下面示例如何診斷掛起的會話。

2.透過SYSTEMSTATE跟蹤

設定跟蹤：

sql>conntest/test

sql>ALTERSESSION SET EVENTS 'IMMEDIATE TRACE NAME SYSTEMSTATE LEVEL 8';

獲取跟蹤檔案為：_ora_676046.trc

由於分析跟蹤檔案需要知道會話的pid，透過以下查詢獲取：

sql> columnsql_text format a60

sql> selectt1.sid,t1.status,t2.sql_text

2fromv$session t1,v$sqlarea t2

3where t1.sql_hash_value = t2.hash_value

4andt1.username = 'TEST'a

5andsql_text like '%compile%'

6/

SID STATUSSQL_TEXT

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

66 INACTIVE alter procedure sp_test compile

獲取pid：

sql> SELECTPID FROM V$PROCESS

2WHERE ADDR =

3(SELECT PADDR FROM V$SESSION WHERE SID=&sid)

4/

輸入sid的值:66

原值3: (SELECT PADDR FROMV$SESSION WHERE SID=&sid)

新值3: (SELECT PADDR FROMV$SESSION WHERE SID=66)

PID

----------

58

在跟蹤檔案中查詢process 58

PROCESS 58:

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

SO: 70000006f2a2140, type: 2, owner: 0, flag:INIT/-/-/0x00

(process) Oracle pid=58, calls cur/top:700000071023710/700000071023710, flag: (0) -

int error: 0, call error: 0, sesserror: 0, txn error 0

(post info) last post received: 0 0 4

last post received-location:kslpsr

last process to post me:70000006f291340 1 6

last post sent: 0 0 16

last post sent-location: ksasnd

last process posted by me:70000006f291340 1 6

(latch info) wait_event=0 bits=0

Process Group: DEFAULT, pseudo proc:70000006f2beda0

O/S info: user: oracle, term: UNKNOWN,ospid: 2089002

OSD pid info: Unix process pid: 2089002,image: oracle@ecx (TNS V1-V3)

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

SO: 70000006fee0798, type: 8, owner:70000006f2a2140, flag: INIT/-/-/0x00

(FOB) flags=2 fib ptr=6ffaa408 incno=0pending i/o cnt=0

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

SO: 70000006fee0628, type: 8, owner:70000006f2a2140, flag: INIT/-/-/0x00

(FOB) flags=2 fib ptr=6ffa0e78 incno=1pending i/o cnt=0

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

SO: 70000006f2efae0, type: 4, owner:70000006f2a2140, flag: INIT/-/-/0x00

(session) trans: 70000007023b2f8, creator:70000006f2a2140, flag: (100041) USR/- BSY/-/-/-/-/-

DID: 0001-003A-0000153E,short-term DID: 0000-0000-00000000

txn branch: 0

oct: 0, prv: 0, sql:7000000688721e0, psql: 70000007d7c38e8, user: 68/TEST

O/S info: user: hxd, term: HEXIAODONG,ospid: 2144:1804, machine: FORESEE\HEXIAODONG

program: sqlplus.exe

application name: SQL*Plus, hashvalue=3669949024

waiting for'library cache pin' blocking sess=0x0 seq=96 wait_time=0

handleaddress=7000000689304c0, pin address=700000074021108,100*mode+namespace=12d

注意‘waiting for 'library cache pin' blocking’部分，表明該Session正在等待，然後我可以透過‘handle address=7000000689304c0’獲取blocking程式。在跟蹤檔案中查詢7000000689304c0可以發現：

PROCESS 63:

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

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

SO: 70000007400fb18, type: 51, owner:70000006f2fe340, flag: INIT/-/-/0x00

LIBRARY OBJECT LOCK: lock=70000007400fb18handle=7000000689304c0 mode=N

call pin=70000007d35bca0 session pin=0

htl=70000007400fb88[70000007300a620,70000007300a620]htb=70000007300a620

user=70000006f2fe340session=70000006f2fe340 count=1 flags=PNC/[04] savepoint=102

the rest of the object was already dumped

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

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

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

SO: 70000006f2de840, type: 4, owner:700000072019cc0, flag: INIT/-/-/0x00

(session) trans: 0, creator: 0, flag: (2)-/REC -/-/-/-/-/-

DID: 0000-0000-00000000,short-term DID: 0000-0000-00000000

txn branch: 0

oct: 0, prv: 0, sql:700000072d96c58, psql: 700000072d96c58, user: 0/SYS

temporary object counter: 0

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

SO:7000000719f1080, type: 52, owner: 700000072019cc0, flag: INIT/-/-/0x00

LIBRARY OBJECT PIN: pin=7000000719f1080handle=700000072e28340 mode=S lock=70000007110e968

user=70000006f2fe340session=70000006f2fe340 count=2 mask=0011 savepoint=102 flags=[00]

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

SO: 70000007d35bca0, type: 52, owner:700000072019cc0, flag: INIT/-/-/0x00

LIBRARY OBJECT PIN: pin=70000007d35bca0handle=7000000689304c0 mode=S lock=70000007400fb18

user=70000006f2fe340 session=70000006f2fe340 count=3 mask=0011savepoint=102 flags=[00]

可以看到該程式鎖定了‘某些’資源。透過以下查詢獲得相應的Session正在執行的sql語句：

sql> columnsql_text format a60

sql> selectt1.sid,t1.status,t2.sql_text

2fromv$session t1,v$sqlarea t2,v$process t3

3where t1.sql_hash_value = t2.hash_value

4andt1.paddr = t3.addr

5andt3.pid = &pid

6/

輸入pid的值:63

原值5: and t3.pid = &pid

新值5: and t3.pid = 63

SID STATUSSQL_TEXT

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

88 ACTIVEBEGIN sp_test; END;

該Session正在執行過程sp_test，從而阻塞了其他Session編譯該過程。

3.透過HANGANALYZE跟蹤

HANGANALYZE跟蹤給出了當前系統一個宏觀的檢視。

--以sysdba登陸執行

sql> showuser

USER為"SYS"

sql> oradebughanganalyze 3

Hang Analysis in/data/app/oracle/admin/query/udump/query_ora_2236466.trc

sql>

--以下為生成的跟蹤檔案

/data/app/oracle/admin/query/udump/query_ora_1613868.trc

Oracle9iEnterprise Edition Release 9.2.0.5.0 - 64bit Production

With thePartitioning, OLAP and Oracle Data Mining options

JServer Release9.2.0.5.0 - Production

ORACLE_HOME =/data/app/oracle/product/9.2.0

System name:AIX

Node name:ecx

Release:2

Version:5

Machine:00580DAD4C00

Instance name:query

Redo threadmounted by this instance: 1

Oracle processnumber: 67

Unix processpid: 1613868, image: oracle@ecx (TNS V1-V3)

*** SESSIONID:(27.60605) 2004-12-14 13:58:56.861

*** 2004-12-1413:58:56.861

==============

HANG ANALYSIS:

==============

Open chainsfound:

Chain 1 : :

<0/88/64186/0x6f2a3a40/475250/PL/SQL lock timer>

--<0/66/28252/0x6f2a2140/2089002/library cache pin>

Other chainsfound:

Chain 2 : :

<0/8/15/0x6f293b40/241800/wakeup timemanager>

Chain 3 : :

<0/27/60605/0x6f2a4e40/1613868/NoWait>

Chain 4 : :

<0/140/64779/0x6f2a9440/2117764/NoWait>

Extrainformation that will be dumped at higher levels:

[level4] :1 node dumps -- [REMOTE_WT] [LEAF] [LEAF_NW]

[level5] :3 node dumps -- [SINGLE_NODE] [SINGLE_NODE_NW] [IGN_DMP]

[level6] :1 node dumps -- [NLEAF]

[level 10]:76 node dumps -- [IGN]

State of nodes

([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor):

[0]/0/1/1/0x6f2c4c50/282766/IGN/1/2//none

[1]/0/2/1/0x6f2c56e0/286864/IGN/3/4//none

[2]/0/3/1/0x6f2c6170/278666/IGN/5/6//none

[3]/0/4/1/0x6f2c6c00/237708/IGN/7/8//none

[4]/0/5/1/0x6f2c7690/245896/IGN/9/10//none

[5]/0/6/1/0x6f2c8120/307352/IGN/11/12//none

[6]/0/7/1/0x6f2c8bb0/299158/IGN/13/14//none

[7]/0/8/15/0x6f2c9640/241800/SINGLE_NODE/15/16//none

[8]/0/9/16437/0x6f2ca0d0//IGN/17/18//none

[9]/0/10/57955/0x6f2cab60/966866/IGN/19/20//none

[11]/0/12/18499/0x6f2cc080/798812/IGN/21/22//none

[12]/0/13/22777/0x6f2ccb10/655582/IGN/23/24//none

[13]/0/14/29669/0x6f2cd5a0/995546/IGN/25/26//none

[15]/0/16/39305/0x6f2ceac0/762106/IGN/27/28//none

[16]/0/17/41716/0x6f2cf550/1282088/IGN/29/30//none

[17]/0/18/18405/0x6f2cffe0/1765548/IGN/31/32//none

[19]/0/20/50960/0x6f2d1500/594074/IGN/33/34//none

[20]/0/21/1037/0x6f2d1f90/1347680/IGN/35/36//none

[21]/0/22/64906/0x6f2d2a20/667806/IGN/37/38//none

[22]/0/23/58042/0x6f2d34b0//IGN/39/40//none

[23]/0/24/44630/0x6f2d3f40/561236/IGN/41/42//none

[24]/0/25/27987/0x6f2d49d0/913526/IGN/43/44//none

[25]/0/26/23641/0x6f2d5460//IGN/45/46//none

[26]/0/27/60605/0x6f2d5ef0/1613868/SINGLE_NODE_NW/47/48//none

[27]/0/28/6814/0x6f2d6980/2252902/IGN/49/50//none

[29]/0/30/38893/0x6f2d7ea0/2117764/IGN/51/52//none

[30]/0/31/4083/0x6f2d8930//IGN/53/54//none

[31]/0/32/591/0x6f2d93c0/2084874/IGN/55/56//none

[32]/0/33/25228/0x6f2d9e50/2146418/IGN/57/58//none

[33]/0/34/19839/0x6f2da8e0/757874/IGN/59/60//none

[34]/0/35/52004/0x6f2db370/2314262/IGN/61/62//none

[36]/0/37/20217/0x6f2dc890/1343694/IGN/63/64//none

[37]/0/38/37361/0x6f2dd320/426096/IGN/65/66//none

[38]/0/39/62842/0x6f2dddb0/979190/IGN/67/68//none

[40]/0/41/36124/0x6f2df2d0/974900/IGN/69/70//none

[41]/0/42/52280/0x6f2dfd60/868410/IGN/71/72//none

[42]/0/43/32767/0x6f2e07f0/1056914/IGN/73/74//none

[43]/0/44/56466/0x6f2e1280/573512/IGN/75/76//none

[44]/0/45/39703/0x6f2e1d10/815272/IGN/77/78//none

[45]/0/46/58422/0x6f2e27a0/2236466/IGN/79/80//none

[46]/0/47/38349/0x6f2e3230/1933528/IGN/81/82//none

[47]/0/48/7314/0x6f2e3cc0/2056290/IGN/83/84//none

[48]/0/49/45536/0x6f2e4750/483434/IGN/85/86//none

[49]/0/50/11157/0x6f2e51e0/2318564/IGN/87/88//none

[50]/0/51/45405/0x6f2e5c70/708838/IGN/89/90//none

[51]/0/52/3753/0x6f2e6700/1679438/IGN/91/92//none

[52]/0/53/65049/0x6f2e7190/991338/IGN/93/94//none

[53]/0/54/47799/0x6f2e7c20/585760/IGN/95/96//none

[56]/0/57/61869/0x6f2e9bd0/1069080/IGN/97/98//none

[57]/0/58/25525/0x6f2ea660/2293878/IGN/99/100//none

[58]/0/59/51692/0x6f2eb0f0/2334944/IGN/101/102//none

[60]/0/61/21926/0x6f2ec610/1245364/IGN/103/104//none

[62]/0/63/3648/0x6f2edb30/1020084/IGN/105/106//none

[63]/0/64/20755/0x6f2ee5c0//IGN/107/108//none

[64]/0/65/57016/0x6f2ef050//IGN/109/110//none

[65]/0/66/28252/0x6f2efae0/2089002/NLEAF/111/114/[87]/none

[66]/0/67/9980/0x6f2f0570/2281662/IGN/115/116//none

[68]/0/69/13320/0x6f2f1a90/659626/IGN/117/118//none

[69]/0/70/47485/0x6f2f2520/2097404/IGN/119/120//none

[72]/0/73/4628/0x6f2f44d0/1032362/IGN/121/122//none

[73]/0/74/16535/0x6f2f4f60/970800/IGN/123/124//none

[74]/0/75/35508/0x6f2f59f0/1011894/IGN/125/126//none

[75]/0/76/13639/0x6f2f6480/1572996/IGN/127/128//none

[76]/0/77/24426/0x6f2f6f10/487514/IGN/129/130//none

[78]/0/79/33586/0x6f2f8430/1081504/IGN/131/132//none

[81]/0/82/35351/0x6f2fa3e0/491738/IGN/133/134//none

[82]/0/83/24257/0x6f2fae70/581672/IGN/135/136//none

[83]/0/84/18408/0x6f2fb900/2154508/IGN/137/138//none

[84]/0/85/7723/0x6f2fc390/766196/IGN/139/140//none

[86]/0/87/4841/0x6f2fd8b0/2023476/IGN/141/142//none

[87]/0/88/64186/0x6f2fe340/475250/LEAF/112/113//65

[88]/0/89/556/0x6f2fedd0/954576/IGN/143/144//none

[89]/0/90/5502/0x6f2ff860/1724668/IGN/145/146//none

[97]/0/98/30290/0x6f304ce0/639148/IGN/147/148//none

[98]/0/99/22667/0x6f305770/463022/IGN/149/150//none

[120]/0/121/5289/0x6f313fd0/839808/IGN/151/152//none

[122]/0/123/28636/0x6f3154f0/1310798/IGN/153/154//none

[124]/0/125/36699/0x6f316a10/1159176/IGN/155/156//none

[128]/0/129/19465/0x6f319450/925860/IGN/157/158//none

[139]/0/140/64779/0x6f320880/2117764/SINGLE_NODE_NW/159/160//none

[152]/0/153/64790/0x6f3291d0/880808/IGN/161/162//none

====================

END OF HANGANALYSIS

從Chain 1部分，我們看到SID為66的會話在等待SID為88的會話。

4.小結

透過設定跟蹤可以很容易定位會話掛起背後的原因，本例只是簡單的介紹了透過跟蹤如何診斷資料庫中出現的問題，其他‘高階’用法有待進一步的挖掘。

5.參考文件

metalink

google