用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

来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/6906/viewspace-21673/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/6906/viewspace-21673/