一個RESOURCE MANAGER引起的問題分析

darren__chan發表於2018-07-28



1.分析hanganalyze日誌：

Chains most likely to have caused   the hang: 《《《最 終 阻塞源都是由於 resmgr:cpu quantum 引起。

 [a] Chain 1 Signature: ' resmgr:cpu quantum '<='buffer busy   waits'<='buffer busy waits'<='enq: TX - index contention'

     Chain 1 Signature Hash: 0xe7466825

 [b] Chain 2 Signature: ' resmgr:cpu quantum '<='buffer busy waits'

     Chain 2 Signature Hash: 0x23972dee

 [c] Chain 3 Signature: ' resmgr:cpu quantum '<='buffer busy waits'

     Chain 3 Signature Hash: 0x23972dee

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

Chain   1:

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

    Oracle session identified by:

    {

                instance: 1 (jfdb.jfdb1)

                   os id: 78941

              process id: 1240, oracle@XXX-JF-DB03

              session   id: 22 <<<< session 22

        session serial #: 32445

    }

    is waiting for 'enq: TX - index   contention' with wait info:

    {

                      p1:   'name|mode'=0x54580004

                      p2: 'usn<<16 |   slot'=0x1cb0015

                      p3: 'sequence'=0xf3fa7

            time in wait: 0.122389 sec

           timeout after: never

                 wait id: 199367

                blocking: 0 sessions

            wait history:

              * time between current wait and   wait #1: 0.000318 sec

             ………

    }

and is blocked by <<<< 被阻塞

 => Oracle session identified by:

{

                instance: 1 (jfdb.jfdb1)

                   os id: 1349

process   id: 2756, oracle@XXX-JF-DB03

session id: 3320 <<<<session 3320

        session serial #: 3849

}

which   is waiting for ‘buffer busy waits’ with wait info:

{

p1:   ‘file#’=0x8c

p2:   ‘block#’=0x286540

p3:   ‘class#’=0x1

time   in wait: 0.218850 sec

           timeout after: never

                 wait id: 51286

                blocking: 58 sessions

wait   history:

 ……….

}

     and is blocked by <<<< 被阻塞

 => Oracle session identified by:

    {

                instance: 1 (jfdb.jfdb1)

                   os id: 3182

              process id: 2975, oracle@XXX-JF-DB03

              session   id: 5658 <<<session 5658

        session serial #: 181

    }

    which is waiting for 'buffer busy waits'   with wait info:

    {

                      p1: 'file#'=0x8c

                      p2: 'block#'=0x285b1f

                      p3: 'class#'=0x1

            time in wait: 0.219271 sec

           timeout after: never

                 wait id: 38737

                blocking: 63 sessions

            wait history:

              。。。。。。

    }

    and is blocked by<<<< 被阻塞

 => Oracle session identified by:

    {

                instance: 1 (jfdb.jfdb1)

                   os id: 27602

              process id: 2384, oracle@XXX-JF-DB03

              session id: 334   《《《session 334

        session serial #: 757

    }

    which is waiting for 'resmgr:cpu quantum'   with wait info:

    {

                      p1: 'location'=0x2

                      p2: 'consumer group   id'=0x3259

                      p3: ' '=0x0

            time in wait: 0.040860 sec

           timeout after: never

                 wait id: 95941

                blocking: 114 sessions

            wait history:

            。。。。。。。

    }

 

Chain   1 Signature: 'resmgr:cpu quantum'<='buffer busy waits'<='buffer busy   waits'<='enq: TX - index contention'

Chain   1 Signature Hash: 0xe7466825

 

對 以上 hanganalyze 會 話進 行整理：

session : 334

同 時 阻塞114個會 話

阻塞了》

session : 5658

同 時 阻塞63個會 話

阻塞了》

session : 3320

同 時 阻塞 58 個會 話

阻塞了》

session id: 22

resmgr:cpu quantum

buffer busy waits

buffer busy waits

enq: TX - index contention

 

從以上 hanganalyze 日誌可以看出， enq: TX - index contention 和 buffer busy waits 的等待堆積最終的源頭是由於 resmgr:cpu quantum 等待引起，並且這些等待同時又阻塞了多個其他會話。

2.關於resmgr:cpu quantum等待事件解釋：

以下從文件 ID 2097889.1 可以獲得該等待事件的說明：

《 WAITEVENT: "resmgr:cpu quantum" Reference   Note ( 文件 ID 2097889.1) 》

·   Event   'resmgr: cpu quantum' is a standard event used by resource manager to control the allocation of   CPU to processes .   When a session waits for 'resmgr: cpu quantum' that session is waiting to be   allocated a quantum of CPU time.

等待事件 'resmgr ： cpu quantum' 是 資源管理器用來控制 CPU 分配給程式 的標準事件。   當會話等待 'resmgr ： cpu quantum' 時， 會話正在等待分配一個 CPU 時間額度 。

This wait occurs when the resource   manager is enabled and is throttling CPU consumption. To reduce the   occurrence of this wait event, increase the CPU allocation for the session's   current consumer   group .

當啟用資源管理器並限制 CPU 消耗時會發生此等待。 為了減少此等待事件的發生，請增加會話當前消費組的 CPU 分配 。

      該等待事件存在的意義是當resource manager控制CPU排程時，需要控制對應程式暫時不使用CPU而程式到內部執行佇列中，以保證該程式對應的consumer group(消費組)沒有消耗比指定resource manager指令更多的CPU。此時session就會以” ”的名義等待在內部執行佇列中，wait一段時間以減少對CPU的爭用，直到再次獲得CPU時該等待事件結束。

3.分析為何會出現資源管理：

《 11g: Scheduler Maintenance Tasks or Autotasks ( 文件 ID 756734.1) 》

 

      根據以上說明，可以發現在 Oracle 11g 中，在預設情況下會啟用自動化維護任務，資料庫會在工作日的每晚 22:00 到第二天的凌晨 2:00 ，週末的凌晨 6:00 到第二天的凌晨 2:00, 自動開啟自動化維護視窗對資料庫進行諸如最佳化器的統計資訊收集、自動 SQL 的最佳化。在此期間資料庫中便由 resource manager 來控制 CPU 的排程，啟用資源管理計劃主要是為了保障維護視窗內的任務有充分的資源進行使用。

      從告警日誌中可以看出， 4 月 1 日 6:00 啟動自動化維護視窗的資訊：

Current log# 6 seq# 23750 mem# 0: +DG_DATA/jfdb/onlinelog/group_6.279.909112437

Sun Apr 01 05:51:29 2018

Archived Log entry 46019 added for thread   1 sequence 23749 ID 0x4d5ab97e dest 1:

Sun Apr 01 06:00:00 2018 《《《《 6 點整開啟自動化維護視窗

Setting Resource Manager plan   SCHEDULER[0x32DF]:DEFAULT_MAINTENANCE_PLAN via scheduler window

Setting Resource Manager plan   DEFAULT_MAINTENANCE_PLAN via parameter

Sun Apr 01 06:00:00 2018

Starting background process   VKRM 《《《啟動相應的程式

Sun Apr 01 06:00:00 2018

VKRM started with pid=361, OS id=48797

     

那麼資源管理計劃是如何限制資源的呢？ 需要了解 RESOURCE MANAGER 的機制。

 

4.關於RESOURCE MANAGER的機制：

    Oracle 開啟自動維護任務是使用的資源管理計劃是 DEFAULT_MAINTENANCE_PLAN ， 這 個 資 源管理 計 劃控制CPU方法是使用是默 認 EMPHASIS 法， 這 種方法是多 級計 劃，它以百分比形式指定CPU 如何在使用者 組 之 間 分佈。CPU 佔用率的分配 級別為 從1 到8， 級別 1  的 優 先 級 最高，將CPU  資 源在 給 定 級別 按指定的百分比分配，把 給 定 級別 上沒有使用的使用者 資 源可供下一 級別 的使用者 組 使用。在當前資料 庫 中DEFAULT_MAINTENANCE_PLAN的 資 源管理 計 劃只用到了2個 級別 。

    在oracle 11g中， 實際 上CPU_P*的引數已 經 是失效了，而 應該 是MGMT_P*的引數，所以我 們 之前參考的是舊的引數,但 實際 是同 樣 效果。



以下當前資源管理計劃所使用 MGMT_P* 的 情況：

    在 這 個 資 源管理 計 劃DEFAULT_MAINTENANCE_PLAN中，主要存在四個CPU使用 組 ： 1. ORA$AUTOTASK_SUB_PLAN 和 ORA$DIAGNOSTICS 實際 是用於自 動維護 任 務的。

2. SYS_GROUP 是 SYS 和 SYSTEM 用 戶 的初始使用者 組，組中的會話都是 sys 或 system 賬號建立的會話。

3. OTHER_GROUPS 用於在活 動資 源 計 劃之外的所有使用者 組擁 有的會 話，即使其他業務使用者及個人使用者的會話。

    資 源管理 計 劃中MGMT_P* 設 置的百分比 值 並不是一個固定限制的 值 是一個在 資 源 緊張時 的限制 值 ，但在 資 源空 閒時 有可能超出 這 個 值 。

    例如，在DEFAULT_MAINTENANCE_PLAN中ORA$AUTOTASK_SUB_PLAN分配了25%，但此 時 如果資料 庫 比 較 空 閒 ，SYS_GROUP和OTHER_GROUPS等其他 組 沒有什麼 資 源佔用，ORA$AUTOTASK_SUB_PLAN 則 可能增 長 到50%，但如果此 時資 源比 較緊張 OTHER_GROUPS 且已 經 佔用50%以上，ORA$AUTOTASK_SUB_PLAN 則 需下降到25%。

    因此，在 這 個 資 源管理 計 劃中，ORA$AUTOTASK_SUB_PLAN和ORA$DIAGNOSTICS 設 了MAX_UTILIZATION_LIMIT最大使用限制 為 90 。 這樣 即使cpu是空 閒 的， 該組 或 計 劃也不能分配90%以上的cpu 資 源。

對 於 資 源 計 劃而言， 為 某個消耗 組 或者子 計 劃分配的份 額 若沒有使用，就可以被其他的消耗 組 或子 計 劃使用。

 

再次分析 這 個 資 源管理 計 劃DEFAULT_MAINTENANCE_PLAN，SYS_GROUP 優 先 級 最高在 級別 1 ，分配75%，在當 時 的情況，sys或system 賬 號 創 建的會 話 佔用的CPU 資 源並不一定達到了75%，其剩餘的 資 源 則 分配 給級別 2 。在 級別 2 中ORA$AUTOTASK_SUB_PLAN和ORA$DIAGNOSTICS的自 動維護 任 務 在 資 源 緊張 的情況下用了30%，而其餘70% 則 分配 給 了OTHER_GROUPS的 業務 會 話 。

資 源管理 計 劃中MGMT_P* 設 置的百分比 值 可以理解 為 依據CPU個數的百分比來 計 算， 這 CPU 個數 則 來自CPU_COUNT引數 設 置的 值 。


5.發現CPU_COUNT引數異常：

    在排查的過程中，發現當前資料庫的CPU_COUNT僅設定為8，而實際上這臺主機有32個CPU 核數，64個邏輯CPU。

CPU_COUNT:

實際CPU Cores及邏輯cpu個數：


在oracle 官方文件中已說明CPU_COUNT是依據CPU cores 的數量來指定的，並且也說明很多元件包括Resource Manager都是依靠這個cpu個數的。

一個RESOURCE MANAGER引起的問題分析

這說明了，在資源管理計劃開啟時，受CPU_COUNT 為8的限制，資料庫只能使用到了主機 32個CPU 核數中的8個，即為1/4。

分析故障期間主機的CPU 使用情況，發現在資源管理計劃開啟後，CPU使用率逐漸升高，但始終不超過25%，直到9:30後手工禁用了資源管理計劃，CPU資源被放開，CPU使用率則立即上升到45%左右。



     因此，可以看出，資 源管理 計 劃 開啟期間，由於CPU_COUNT的設定過小，導致了資料庫只能最多使用到了主機25%的CPU資源，並且受以上資源管理計劃控制CPU機制的影響，業務會話可能只能用到這25% CPU資源中的70%，這就是導致資料庫在4月1日高峰期時資料庫達到了CPU了資源瓶頸的原因。

 



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

相關文章