【故障處理】佇列等待之enq IV - contention案例

【故障處理】佇列等待之enq IV - contention案例

1.1 BLOG文件結構圖

1.2 前言部分

1.2.1 導讀和注意事項

各位技術愛好者，看完本文後，你可以掌握如下的技能，也可以學到一些其它你所不知道的知識，~O(∩_∩)O~：

① 佇列等待之enq IV - contention案例（重點）

Tips：

① 本文在itpub（http://blog.itpub.net/26736162）、部落格園(http://www.cnblogs.com/lhrbest)和微信公眾號（xiaomaimiaolhr）上有同步更新。

② 文章中用到的所有程式碼、相關軟體、相關資料及本文的pdf版本都請前往小麥苗的雲盤下載，小麥苗的雲盤地址見：http://blog.itpub.net/26736162/viewspace-1624453/。

③ 若網頁文章程式碼格式有錯亂，請下載pdf格式的文件來閱讀。

④ 在本篇BLOG中，程式碼輸出部分一般放在一行一列的表格中。

本文如有錯誤或不完善的地方請大家多多指正，ITPUB留言或QQ皆可，您的批評指正是我寫作的最大動力。

1.3 故障分析及解決過程

1.3.1 資料庫環境介紹

專案	source db
db 型別	RAC
db version	12.1.0.2.0
db 儲存	ASM
OS版本及kernel版本	SuSE Linux Enterprise Server（SLES 11） 64位

1.3.2 AWR分析

這裡簡單分析一下Up Time(hrs)，其它幾個指標都很熟悉了。表中的“Up Time(hrs)”代表自資料庫例項啟動到本次快照結束這段時間的小時數。例如，該AWR中資料庫例項1的啟動時間為“2016-08-11 20:51”，快照結束時間為“2016-12-14 21:00”，故“Up Time(hrs)”約為125.006天，轉換為小時約為3000.14小時，如下所示：

SYS@lhrdb> SELECT trunc(UP_TIME_D,3), trunc(trunc(UP_TIME_D,3)*24,2) UP_TIME_HRS FROM (SELECT (TO_DATE('2016-12-14 21:00', 'YYYY-MM-DD HH24:MI') - TO_DATE('2016-08-11 20:51', 'YYYY-MM-DD HH24:MI')) UP_TIME_D FROM DUAL);

TRUNC(UP_TIME_D,3) UP_TIME_HRS

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

125.006 3000.14

可以看到節點1的負載較大，而ADDM中，特殊類的等待事件較多。接下來檢視等待事件的部分：

可以看到enq: IV - contention和DFS lock handle等待較為嚴重。這裡需要說一下enq: IV - contention這個名稱。在AWR中，IV和-的前後都是1個空格，而在資料庫中記錄的是-之後有2個空格，如下：

所以，採用搜尋的時候需要注意。

根據ASH中的p1引數的值獲得：

SYS@lhrdb> SELECT CHR(BITAND(1230372867, -16777216) / 16777215) ||

2 CHR(BITAND(1230372867, 16711680) / 65535) "LOCK",

3 BITAND(1230372867, 65535) "MODE"

4 FROM DUAL;

LO MODE

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

IV 3

1.3.3 enq: IV - contention解決

SELECT *

FROM V$EVENT_NAME A

WHERE A.NAME LIKE '%enq: IV - contention%';

該等待事件為12c特有，12c相比11g多了大約500多個等待事件。該問題參考MOS：12c RAC DDL Performance Issue: High "enq: IV - contention" etc if CPU Count is Different (文件 ID 2028503.1)

The fix will be included in future PSU, patch exists for certain platform/version.

The workaround is to set the following parameter to the highest value in the cluster and restart:

_ges_server_processes

To find out the highest value, run the following grep on each node:

ps -ef| grep lmd

該等待事件主要是由於12c RAC的2個節點上的cpu_count這個變數不一致導致的。

從AWR中可以看出節點1的CPU為48，而節點2的CPU為96。

從dba_hist_parameter中可以看到CPU_COUNT這個引數的變化歷史：

SQL> SHOW PARAMETER CPU

NAME TYPE VALUE

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

cpu_count integer 96

parallel_threads_per_cpu integer 2

resource_manager_cpu_allocation integer 96

SQL> select snap_id, INSTANCE_NUMBER,PARAMETER_NAME,VALUE from dba_hist_parameter where PARAMETER_NAME='cpu_count' order by snap_id;

SNAP_ID INSTANCE_NUMBER PARAMETER_NAME VALUE

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

。。。。。。。。。。。。。。。。。。。。。。。。。。。

3368 1 cpu_count 48

3369 1 cpu_count 48

3369 2 cpu_count 48

3370 1 cpu_count 48

3371 1 cpu_count 48

3372 1 cpu_count 48

3373 1 cpu_count 48

3374 1 cpu_count 48

3375 2 cpu_count 96

3375 1 cpu_count 48

3376 1 cpu_count 48

3376 2 cpu_count 96

3377 1 cpu_count 48

3377 2 cpu_count 96

3378 2 cpu_count 96

3378 1 cpu_count 48

3379 1 cpu_count 48

3379 2 cpu_count 96

。。。。。。。。。。。。。。。。。。。。

查詢告警日誌：more alert*|grep -i Cpu 也可以獲取CPU的變化。

詢問客戶可知，是他們調整過系統的CPU資源，所以導致節點2上的CPU_COUNT自動變化，引起了enq: IV - contention等待。

若主機的CPU個數變化，那麼當主機重啟後資料庫的cpu_count引數的值會隨之變化，該引數屬於作業系統依賴引數。

調整主機的CPU個數之後，該等待事件消失。

1.4 MOS

1.4.1 12c RAC DDL Performance Issue: High "enq: IV - contention" etc if CPU Count is Different (文件 ID 2028503.1)

In this Document

Symptoms

Cause

Solution

References

APPLIES TO:

Oracle Database - Enterprise Edition - Version 12.1.0.1 to 12.1.0.2 [Release 12.1]
Information in this document applies to any platform.

SYMPTOMS

12c RAC database seeing high "enq: IV - contention":

From awr report:

Top 10 Foreground Events by Total Wait Time
===================================
Event Waits Total Wait Time (sec) Wait Avg(ms) % DB time Wait Class
enq: IV - contention 52,914 1688.4 31.91 42.8 Other
row cache lock 44,865 896.8 19.99 22.7 Concurrency

tkprof of 10046 trace of SQL statement shows the same event in the top:

Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
enq: IV - contention 6017 0.32 287.68
row cache lock 957 0.20 7.48
library cache lock 631 0.13 15.10
library cache pin 616 0.11 14.54

CAUSE

Cluster nodes have different CPU count resulting in different number of LMD processes, on one node it has two while on the other it has three.

The issue is due to the following bug:

BUG 21293056 - PERFORMANCE DEGRADATION OF GRANT STATEMENT AFTER 12C UPGRADE

Which is closed as duplicate of:

BUG 21395269 - ASYMMETRICAL LMDS CONFIGURATION IN A CLUSTER LEADS TO POOR MESSAGE TRANSFER

SOLUTION