一次library cache pin故障的解決過程

dawn009發表於2015-03-09
在dbsnake 上看到的這篇文章,轉過來。 主要還是學習解決問題的一個思路。這個往往比問題的解決更重要。

       原文連結如下:

      


內容如下:


       今天接到同事的電話,說他的一個儲存過程已經run了一個多小時了,還在繼續run,他覺得極不正常,按道理說不應該run這麼長時間。

我說那我去看一下吧。

這個庫是一個AIX上的10.2.0.4,我採集了一下問題時間段的AWR報告:

Begin Snap:

13302

11-Jun-10 12:00:56

109

4.7

End Snap:

13303

11-Jun-10 13:00:02

97

4.9

Elapsed:


59.10 (mins)



DB Time:


113.98 (mins)



Top 5事件為:

Event

Waits

Time(s)

Avg Wait(ms)

% Total Call Time

Wait Class

library cache pin

1,252

3,656

2,920

53.5

Concurrency

library cache lock

989

2,890

2,922

42.3

Concurrency

CPU time


219


3.2


db file sequential read

5,694

12

2

.2

User I/O

log file parallel write

1,467

11

8

.2

System I/O

從AWR報告結果裡我們可以看出在出問題的時間段,系統在經歷嚴重的library cache pin以及library cache lock等待。

從Load Profile中我們又可以看到:


Per Second

Per Transaction

Parses:

12.83

65.83

Hard parses:

0.05

0.25

也就是說導致上述library cache pinlibrary cache lock的並不是hard parse

對於library cache pin等待來說,AWR報告的作用有限,最有效的方式就是找到持有library cache pin以及等待library cache pinsession,然後看看他們在做什麼


SQL> SELECT s.sid, kglpnmod "Mode", kglpnreq "Req", SPID "OS Process"

  2  FROM v$session_wait w, x$kglpn p, v$session s ,v$process o

  3  WHERE p.kglpnuse=s.saddr

  4  AND kglpnhdl=w.p1raw

  5  and w.event like '%library cache pin%'

  6  and s.paddr=o.addr

  7  /

       SID       Mode        Req OS Process

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

       396          0          2 6381970

       396          0          2 6381970

       396          0          2 6381970

       396          0          2 6381970

       341          2          0 4092132

       341          2          0 4092132

       341          2          0 4092132

       341          2          0 4092132

       363          0          2 3514690

       363          0          2 3514690

       363          0          2 3514690

       363          0          2 3514690

       304          0          2 3977478

       304          0          2 3977478

       304          0          2 3977478

       304          0          2 3977478

       354          0          3 3137874

       354          0          3 3137874

       354          0          3 3137874

       354          0          3 3137874

20 rows selected

其中:

KGLPNHDL --- Library Cache Handle Address

KGLPNADR --- Library Cache Pin Address.

KGLPNSES --- 識別鎖住此pin 的session

KGLPNREQ --- Pin 請求

KGNMODE --- Pin 鎖


我 那位run儲存過程的同事所在的session是396,從上述結果裡我們可以看出來396現在想以Share模式(即Req=2)去持有library cache pin,同時現在持有上述library cache pin的是session 341,且341的持有模式也是Share(即Mode=2)。

本來ShareShare是可以共享的,但不幸的是在396之前,session 354想以Exclusive模式(即Req=3)去持有上述library cache pin,這直接導致了396需要處於等待的Queue中,同時處於Queue中的還有363和304。

我為什麼這麼說呢,因為oracle對library cache pin的解釋中有一句非常經典的話:

An X request (3) will be blocked by any pins held S mode (2) on the object.
An S request (2) will be blocked by any X mode (3) pin held, or may queue behind some other X request.

所以從AWR報告和上述查詢結果中我們可以得出如下結論:

1、  我那位run儲存過程的同事為什麼run了1個多小時還沒有run完是因為這個儲存過程正在經歷嚴重的library cache pin等待;

2、  而 為什麼會導致嚴重的library cache pin等待是因為session 341和354聯手達到了這一效果,即341以Share模式持有library cache pin,接著354想以Exclusive模式持有,這直接導致所有的後續請求全部被處於等待的Queue中。也就是說341阻塞了354,而354又間接阻塞了396

既然知道了原因,那我們去看一下session 341在做什麼事情:

SQL> select decode(sql_hash_value,0,prev_hash_value,sql_hash_value) from v$session where sid=341;

DECODE(SQL_HASH_VALUE,0,PREV_H

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

                     784727971

間隔10秒鐘後再次執行:

SQL> select decode(sql_hash_value,0,prev_hash_value,sql_hash_value) from v$session where sid=341;

DECODE(SQL_HASH_VALUE,0,PREV_H

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

                     784727971

間隔10秒鐘後再次執行:

SQL> select decode(sql_hash_value,0,prev_hash_value,sql_hash_value) from v$session where sid=341;

DECODE(SQL_HASH_VALUE,0,PREV_H

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

                     784727971

SQL> select sql_text from v$sqltext where hash_value=784727971 order by piece;

SQL_TEXT

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

begin   -- Call the procedure   p_adj_rrp_main(o_vc_flag => _vc_flag); end;

從結果裡可以看到341一直在run一個儲存過程。

給持有341的那位大姐打電話,問她在做什麼,她告訴我說她從昨晚就開始run這個儲存過程,今早來看發現死掉了,所以她就沒管了。

知道原因後處理起來還是很容易的,當我把session 341幹掉後,整個系統的library cache pin一下子就降下來了,接著我那位同事的run了一個多小時的儲存過程過了沒多久就run完了。

來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/29119536/viewspace-1453596/,如需轉載,請註明出處,否則將追究法律責任。

相關文章