問題處理

背景：

2017 / 04/02 日中午11 點 30 左右，接到 jzdb3 庫節點 1 資料庫效能差， awr 中出現嚴重的 cursor: mutex S\ cursor: mutex X 爭用。

SR 3-14602160331 : A Large number of child cursor caused the 'cursor: mutex S' and 'cursor: mutex X'

SSC 透過現場對 DB 、 RAC 、 OS 、 SQLHC 、 SQL version_rpt 等資料做了詳細的原因分析。

救援過程

1 、 AWR 報告分析

現場抓取了今天一整天的AWR 日誌，從 AWR 追溯到從凌晨 1 點 TOP Events 中開始出現cursor: mutex S 、 cursor: mutex X 爭用：

下一個半個小時的awr 開始持續處於 event 的前列：

分析造成該 event 衝高的 SQL為下面兩條 SQL導致的：

SQL ID: au0v7hv343q45\

具體的 SQL TEXT:

SQL ID : au0v7hv343q45:

select to_char(account_id),

acctbk_id,

to_char(last_balance),

to_char(current_balance),

status,

to_char(start_date, 'yyyymmddhh24miss' ),

to_char(end_date, 'yyyymmddhh24miss' ),

unit,

to_char(expire_date, 'yyyymmddhh24miss' ),

to_char(join_id),

to_char( version )

from acctbk

where account_id = to_number(:v_account_id)

and acctbk_id = :v_acctbk_id

SQL ID:

select to_char(account_id),

acctbk_id,

to_char(last_balance),

to_char(current_balance),

status,

to_char(start_date, 'yyyymmddhh24miss' ),

to_char(end_date, 'yyyymmddhh24miss' ),

unit,

to_char(expire_date, 'yyyymmddhh24miss' ),

to_char(join_id),

to_char( version )

from acctbk

where account_id = to_number(:v_account_id)

and acctbk_id = :v_acctbk_id

for update nowait

均為對acctbk 表的查詢操作。

2 、 Version Count Report 分析

分析 SQL C ount ：

au0v7hv343q45 ：

發現造成子游標不能共享的原因主要有 LANGUAGE_MISMATCH 、 ROLL_INVALID_MISMATCH 子游標數目比較高，而且一直沒有age out 出去。

於是我們使用下面命令收集統計資訊：

exec dbms_stats.gather_table_stats(ownname => 'accounting',tabname => 'acctbk',estimate_percent => 5,degree => 4,cascade => true, no_invalidate => false )

PL/SQL procedure successfully completed.

Elapsed: 00:07:47.44

該命令執行了 7 分多鍾， no_invalidate 引數設定為false ，目的是讓表 acctbk 對應的 SQL 的所有子游標立即失效，並age out 出 share pool 。

執行完該命令之後，再取awr 報告， c ursor: mutex S 、 cursor: mutex X 消失，系統恢復正常。

分析過程

該故障分析的焦點問題為：

1、大量 LANGUAGE_MISMATCH 、 ROLL_INVALID_MISMATCH 、 BIND_MISMATCH 如何產生的。

2、為什麼產生了這麼多的 mismatch 的子游標又不能及時的被age out 出去。

針對第一個問題，我們逐個做了分析：

1、產生原因

【 LANGUAGE_MISMATCH 】

LANGUAGE_MISMATCH 與環境設定 NLS_* 有關係，比如客戶端session 中使用了不同的NLS_SORT 等。

TEST CASE:

a lter system flush shared_pool;

create table X as select * from dba_tables;

set time on pages 1000 lin 200

col FIRST_LOAD_TIME format a20

col last_load_time format a20

var b1 varchar2(128);

var b2 varchar2(128);

exec :b1 := '0';

exec :b2 := '0';

nls_sort

alter session set = 'SCHINESE_RADICAL_M';

select count(*) from X where table_name=:b1 and OWNER=:b2;

--- 修改 nls_sort

alter session set nls_sort = 'SCHINESE_STROKE_M';

select count(*) from X where table_name=:b1 and OWNER=:b2;

-- 修改 nls_sort

alter session set nls_sort = 'SCHINESE_PINYIN_M';

select count(*) from X where table_name=:b1 and OWNER=:b2;

-- 查詢 SQL id ：

09:12:41 SQL> select sql_id from v$sql where sql_text='select count(*) from X where table_name=:b1 and OWNER=:b2';

SQL_ID

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

1uk1h0wuzcuaf

09:14:53 SQL> select sql_id,child_address,language_mismatch,roll_invalid_mismatch,BIND_MISMATCH from v$sql_shared_cursor where sql_id='1uk1h0wuzcuaf';

SQL_ID CHILD_ADDRESS L R B

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

1uk1h0wuzcuaf 00000000750EDBB0 N N N

1uk1h0wuzcuaf 0000000079F0C748 Y N N

1uk1h0wuzcuaf 0000000075F5F6A0 Y N N

【 ROLL_INVALID_MISMATCH 】

在統計資訊收集的時候，預設情況下 dbms_stats 的 no_invalidate 引數為 auto_invalidate ，意思是收集完統計資訊之後，不立即失效統計物件相關的cursor ，而是採用滾動失效的方式。這種做法是為了避免統計資訊收集之後產生大量的硬解析。資料庫會隨機的取一個小於_optimizer_invalidation_period 值來判斷子游標的 INVALIDATE 時間，預設情況下是 18000 秒，即 5 個小時。

18000s 並不是從統計資訊收集開始（下圖中的 T0 ），而是從統計資訊收集之後該 SQL 的第一次解析時間開始（ T1 ），然後隨機的取一個時間，該時間小於_optimizer_invalidation_period 設定的時間，我們可以定義為下圖的 T max 。

下次執行的時候（ T2 ），如果 T2 小於 T max ，就會複用以前的子游標，如果 T2 大於 T max ，則會執行硬解析。

TEST CASE:

alter system flush shared_pool;

create table X as select * from dba_tables;

set time on pages 1000 lin 200

col FIRST_LOAD_TIME format a20

col last_load_time format a20

alter system set "_optimizer_invalidation_period"=120;

09:38:56 SQL> select child_number,parse_calls,executions,first_load_time, last_load_time,last_active_time from v$sql where sql_id='95rckg79jgshh';

CHILD_NUMBER PARSE_CALLS EXECUTIONS FIRST_LOAD_TIME LAST_LOAD_TIME LAST_ACTIVE_TIME

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

0 3 3 2017-04-06/09:35:47 2017-04-06/09:35:47 06/04/2017 09:38:55

09:39:00 SQL> exec dbms_stats.gather_table_stats(null,'X');

PL/SQL procedure successfully completed.

09:39:23 SQL> select last_analyzed from dba_tables where table_name='X';

LAST_ANALYZED

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

06/04/2017 09:39:23

09:39:38 SQL> select count(*) from X;

COUNT(*)

----------

2341

09:43:58 SQL> select child_number,parse_calls,executions,first_load_time, last_load_time,last_active_time from v$sql where sql_id='95rckg79jgshh';

CHILD_NUMBER PARSE_CALLS EXECUTIONS FIRST_LOAD_TIME LAST_LOAD_TIME LAST_ACTIVE_TIME

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

0 4 4 2017-04-06/09:35:47 2017-04-06/09:35:47 06/04/2017 09:39:46

1 1 1 2017-04-06/09:35:47 2017-04-06/09:43:57 06/04/2017 09:43:57

09:44:01 SQL> select sql_id,child_address,language_mismatch,roll_invalid_mismatch,BIND_MISMATCH from v$sql_shared_cursor where sql_id='95rckg79jgshh';

SQL_ID CHILD_ADDRESS L R B

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

95rckg79jgshh 00000000748609A0 N N N

95rckg79jgshh 00000000751A7820 N Y N

【 BIND_MISMATCH 】

一般是由於bind value 的長度不同導致 bind buffer 無法重用，最終導致 cursor 無法重用。

2 、為什麼不被清理

經過分析和多輪測試發現：

ROLL_INVALID_MISMATCH 為 Y 的子遊標，在統計資訊收集之後，如果使用預設的NO_INVALIDATE= AUTO_INVALIDATE ，過一段時間之後，會被置為 invalidations ，並有特定的機制保證它及時的age out 出去。在 12 c 中，未發現無法清理的bug 存在，假設有，那麼acctbk 表所涉及到的所有 SQL 都應該會出現該問題，從記賬庫 3 查詢的情況來看，是可以排除該可能性的。

、 BIND_MISMATCH 為客戶端編碼導致的，當一個子遊標的LANGUAGE_MISMATCH/ BIND_MISMATCH 被標記成 Y 之後，在的object_status 就一直為valid 狀態，資料庫認為他還是有可能被重新複用的，只有當該物件在統計資訊收集的時候，使用NO_INVALIDATE=>false 引數，該狀態才能變成INVALID_UNAUTH ，在下次 SQL 被執行之後才能 age out 出去。

另外從目前記賬庫上查詢的情況來看，大部分子 cursor 的 ROLL_INVALID_MISMATCH 、 LANGUAGE_MISMATCH 欄位同時為 Y ， V $SQL 的 object_status 為 valid ，這就能解釋了 ROLL_INVALID_MISMATCH 不能被age out 的原因：

SQL>select sql_id,child_address,language_mismatch,roll_invalid_mismatch,BIND_MISMATCH from v$sql_shared_cursor where sql_id='6uvmkxmcvbc6t';

SQL_ID CHILD_ADDRESS LANGUAGE_MISMATCH ROLL_INVALID_MISMATCH BIND_MISMATCH

6uvmkxmcvbc6t C000002357553CE8 Y N Y

6uvmkxmcvbc6t C00000235749AC10 Y N Y

6uvmkxmcvbc6t C000002353906DA0 Y N Y

6uvmkxmcvbc6t C000002354557798 Y N Y

6uvmkxmcvbc6t C0000021BFEDCC50 Y Y N

6uvmkxmcvbc6t C0000021BF661238 Y Y N

6uvmkxmcvbc6t C0000021BE4973D8 Y Y Y

6uvmkxmcvbc6t C0000021BDF0F488 Y Y N

6uvmkxmcvbc6t C0000020DBE75628 Y Y N

6uvmkxmcvbc6t C0000020DB9FA1A8 Y Y N

6uvmkxmcvbc6t C0000020DB9F2FC8 Y Y N

6uvmkxmcvbc6t C0000020DB7E7C60 Y Y N

6uvmkxmcvbc6t C00000226B498B18 Y Y N

6uvmkxmcvbc6t C000001FEC10BE90 Y Y N

6uvmkxmcvbc6t C000002269971508 Y Y N

6uvmkxmcvbc6t C000002265912D38 Y Y N

6uvmkxmcvbc6t C0000020D32857D8 Y Y N

6uvmkxmcvbc6t C0000020D3C625B8 Y Y Y

6uvmkxmcvbc6t C0000020D01DF1D0 Y Y N

6uvmkxmcvbc6t C0000020CFE39790 Y Y N

6uvmkxmcvbc6t C00000226A5A8D80 Y Y N

6uvmkxmcvbc6t C00000226B529B90 Y Y N

6uvmkxmcvbc6t C00000226B53B440 Y Y N

6uvmkxmcvbc6t C000002268732578 Y Y N

6uvmkxmcvbc6t C0000020CD03B6C8 Y Y Y

6uvmkxmcvbc6t C0000020C6D79578 Y Y N

6uvmkxmcvbc6t C000002351AFBB78 Y Y Y

6uvmkxmcvbc6t C0000020C4E37F08 Y Y N

SQL>select child_number,LAST_ACTIVE_TIME,LAST_LOAD_TIME,OBJECT_STATUS from v$sql where sql_id='6uvmkxmcvbc6t' order by LAST_ACTIVE_TIME;

CHILD_NUMBER LAST_ACTIVE_TIME LAST_LOAD_TIME OBJECT_STATUS

1 2017/4/1 17:04:57 2017-04-01/17:04:57 VALID

2 2017/4/2 9:01:35 2017-04-01/17:06:01 VALID

3 2017/4/2 9:02:27 2017-04-01/17:06:01 VALID

0 2017/4/2 11:19:38 2017-04-01/17:04:57 VALID

6 2017/4/3 1:53:15 2017-04-02/11:20:01 VALID

5 2017/4/3 1:54:21 2017-04-02/09:55:21 VALID

7 2017/4/3 3:48:58 2017-04-02/12:39:23 VALID

4 2017/4/3 6:00:42 2017-04-02/09:02:28 VALID

11 2017/4/3 23:16:10 2017-04-03/06:17:07 VALID

10 2017/4/4 0:30:47 2017-04-03/05:16:42 VALID

9 2017/4/4 0:42:46 2017-04-03/02:57:43 VALID

8 2017/4/4 2:08:32 2017-04-03/01:54:22 VALID

14 2017/4/4 23:08:15 2017-04-04/01:14:50 VALID

12 2017/4/4 23:08:15 2017-04-04/00:30:47 VALID

15 2017/4/5 1:44:24 2017-04-04/02:08:56 VALID

13 2017/4/5 1:45:39 2017-04-04/01:08:46 VALID

17 2017/4/5 23:31:41 2017-04-05/00:32:06 VALID

16 2017/4/6 0:33:06 2017-04-05/00:32:06 VALID

18 2017/4/6 2:26:54 2017-04-05/01:45:39 VALID

19 2017/4/6 2:27:46 2017-04-05/03:34:29 VALID

20 2017/4/6 23:26:48 2017-04-06/00:33:07 VALID

23 2017/4/6 23:46:55 2017-04-06/03:31:30 VALID

21 2017/4/7 0:34:21 2017-04-06/02:19:02 VALID

22 2017/4/7 1:54:16 2017-04-06/02:27:47 VALID

24 2017/4/7 1:55:31 2017-04-06/23:49:10 VALID

27 2017/4/7 10:34:12 2017-04-07/02:15:01 VALID

25 2017/4/7 10:37:39 2017-04-07/00:34:21 VALID

26 2017/4/7 10:39:15 2017-04-07/01:55:32 VALID

故障分析總結

基於上述分析，客戶端環境變數、遊標使用不規範導致了mismatch 的子游標過多，進而導致了 cursor: mutex S 、 cursor: mutex X 爭用，效能出現問題，因為客戶端環境比較複雜，修改起來需要一個過程，目前資料庫端能做的workaround 有如下：

1、定期監控遊標過多的 SQL ，子游標超過 200 的，收集統計資訊的時候使用 no_invalidate=false 引數。

或者為有上述問題的表特別的指定統計資訊收集屬性，設定 no_invalidate => false ，方法如下：

SQL> SELECT DBMS_STATS.GET_PREFS('NO_INVALIDATE','SYS','X') FROM DUAL;

DBMS_STATS.GET_PREFS('NO_INVALIDATE','SYS','X')

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

DBMS_STATS.AUTO_INVALIDATE

SQL>

PL/SQL procedure successfully completed.

SQL> SELECT DBMS_STATS.GET_PREFS('NO_INVALIDATE','SYS','X') FROM DUAL;

DBMS_STATS.GET_PREFS('NO_INVALIDATE','SYS','X')

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

FALSE

2、當出現子游標過多的時候，執行如下命令將該 SQL 的所有子游標清除出去

SQL> alter session set events '5614566 trace name context forever' --oracle10g 需要執行

SQL>select address,hash_value,executions,parse_calls from v$sql where sql_id='3yr4fwqux2buz';

SQL> . e('00000000749AF8B8,3050385247','C');

- - 引數 1 ： SQL address ；引數 2 ： hash_value ；引數 3 ： C 表示 PURGE 的物件是 CURSOR

3、修改每個 sql 允許生成子游標的總個數（ 12 c 版本預設值為 1024 ）

SQL>alter system set " _cursor_obsolete_threshold "=200;

子游標過多導致大量mutex爭用故障分析

問題處理

救援過程

分析過程

故障分析總結

相關文章

子游標過多導致大量mutex爭用故障分析

問題處理

救援 過程

分析過程

故障 分析 總結

相關文章

救援過程

故障分析總結