​[20201203]探究library cache mutex X 3.txt

[20201203]探究library cache mutex X 3.txt

--//生產系統經常遇到library cache: mutex X等待事件，我實際上已經估計到大量呼叫PL/SQL包導致的問題(防水牆產品)，還是分析看
--//看:

             Snap Id  Snap Time               Sessions Cursors/Session  Instances
Begin Snap:  53273    25-Nov-20 09:00:28      5745     2.4              2
End Snap:    53274    25-Nov-20 10:00:01      6377     2.4              2
Elapsed:              59.55 (mins)                                                             
DB Time:              607.20 (mins)            
Top 10 Foreground Events by Total Wait Time
--//db time已經接近10個小時。以前上線exadata是業務高峰僅僅2個小時。實在無心做這方面的最佳化....

Event                           Waits       Total Wait Time (sec)  Wait Avg(ms)  % DB time   Wait Class
DB CPU                                      32.8K                                90.0         
cell single block physical read 1,056,585   1413                   1             3.9         User I/O
SQL*Net more data to client     19,247,659  406.2                  0             1.1         Network
library cache: mutex X          96,416      216.5                  2             .6          Concurrency
log file sync                   304,792     180.5                  1             .5          Commit
--//library cache: mutex X 佔用216秒/每小時。

> @ ashtop sql_id "event='library cache: mutex X'" trunc(sysdate) sysdate
    Total
  Seconds     AAS %This   SQL_ID        FIRST_SEEN          LAST_SEEN
--------- ------- ------- ------------- ------------------- -------------------
       36      .0    7% | 9mb3vstumytc8 2020-11-25 07:36:32 2020-11-25 10:56:15
       33      .0    6% | 5wnky979drmys 2020-11-25 07:36:32 2020-11-25 10:55:56
       23      .0    4% | 2dapgszyhwhks 2020-11-25 07:00:10 2020-11-25 11:02:09
       19      .0    4% | 5x0u0ftb8sv53 2020-11-25 08:19:45 2020-11-25 11:05:58
       18      .0    3% | 9s6xvf5bcg13s 2020-11-25 07:52:09 2020-11-25 11:04:44
       17      .0    3% | f16tcy0s7f73s 2020-11-25 07:54:28 2020-11-25 10:58:53
       15      .0    3% | 305qy2uu2q5gp 2020-11-25 07:56:38 2020-11-25 11:04:42
       13      .0    2% | 2zzar56rrsqm6 2020-11-25 07:54:15 2020-11-25 10:56:51
...
--//注意ashtop僅僅查詢v$active_session_history檢視的資訊，這樣我時間範圍再大，也不會改變，從FIRST_SEEN最小是2020-11-25
--//07:00:10也可以看出來。可以使用dashtop查詢，這樣準確性差一些，total Seconds佔用更大。

> @ tpt/sqlid 9mb3vstumytc8 '%'
Show SQL text, child cursors and execution stats for SQLID 9mb3vstumytc8 child nvl('%','%')
HASH_VALUE PLAN_HASH_VALUE  CH# SQL_TEXT
---------- --------------- ---- ---------------------------------------
1967089032      1995374031    0 SELECT KSMC From GY_KSDM Where KSDM =:1

 CH# PARENT_HANDLE    OBJECT_HANDLE     PLAN_HASH     PARSES   H_PARSES EXECUTIONS    FETCHES ROWS_PROCESSED ROWS_PER_FETCH    CPU_SEC CPU_SEC_EXEC    ELA_SEC ELA_SEC_EXEC       LIOS  LIOS_EXEC       PIOS      SORTS USERS_EXECUTING
---- ---------------- ---------------- ---------- ---------- ---------- ---------- ---------- -------------- -------------- ---------- ------------ ---------- ------------ ---------- ---------- ---------- ---------- ---------------
   0 000000131F6B0A80 000000131F6B0820 1995374031      26736          8      26736      26736          13137     .491359964  15.671637   .000586162  16.555437   .000619219      41073 1.53624327          0          0               0
   1 000000131F6B0A80 000000131A4BA9D8 1995374031  161531319          3  161537872  161539459       61003887     .377640778 101640.927   .000629208 105705.048   .000654367  208242574  1.2891254          0          0               0
--//也就是2個子游標。為什麼高密集的執行會出現library cache: mutex X呢？
--//有問題語句出現的很離散，並不集中出現在特定的sql語句。
--//做一個簡單跟蹤看看：

1.環境：
> @ ver1
PORT_STRING                    VERSION        BANNER
------------------------------ -------------- --------------------------------------------------------------------------------
x86_64/Linux 2.4.xx            11.2.0.4.0     Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production

> @ d_buffer 9mb3vstumytc8 60
EXECUTIONS1 BUFFER_GETS1 ELAPSED_TIME1 ROWS_PROCESSED1
----------- ------------ ------------- ---------------
    4814941      6334542    2987615357         1854411

... sleep 60 , waiting ....

EXECUTIONS2 BUFFER_GETS2 ELAPSED_TIME2 ROWS_PROCESSED2
----------- ------------ ------------- ---------------
    4820469      6341581    2991504285         1856458

總buffer_gets 每次buffer_gets   執行次數 總執行時間 每次執行時間 總處理記錄數 平均處理記錄數
------------- --------------- ---------- ---------- ------------ ------------ --------------
         7039      1.27333575       5528    3888928   703.496382         2047     .370296671

--//總執行次數在1分鐘內高達5528次。奇怪竟然有查詢不到科室名稱的情況(平均處理記錄數＝.370296671)，什麼垃圾程式碼,理論講不該出現這種情況。
--//原來輸入值有帶入NULL值的情況，無語。

> @ bind_cap 9mb3vstumytc8 ''
C200
---------------------------------------
SELECT KSMC From GY_KSDM Where KSDM =:1

SQL_ID        CHILD_NUMBER WAS NAME  POSITION MAX_LENGTH LAST_CAPTURED       DATATYPE_STRING VALUE_STRING C30
------------- ------------ --- ----- -------- ---------- ------------------- --------------- ------------ ------------
9mb3vstumytc8            0 YES :1           1         22 2020-11-27 08:55:36 NUMBER          NULL
--//竟然有抓到NULL的情況,我服了，沒做變數檢查嗎，真心服了一幫開發人員。

alter session set current_schema=XXXXXX_YYY;
variable v_ksdm number;
@ 10046on 12
exec :v_ksdm := 1;
SELECT KSMC From GY_KSDM Where KSDM =:v_ksdm;
@ 10046off

--//看不出問題，注我的指令碼是透過sys使用者執行。直接跟蹤會話看看：
alter system set events 'sql_trace [sql:sql_id=9mb3vstumytc8] bind=true, wait=false';

--//看到如下程式碼：
=====================
PARSING IN CURSOR #140510064751448 len=52 dep=1 uid=131 oct=47 lid=131 tim=1606699683522893 hv=3354287527 ad='130f7c3f28' sqlid='190q1sz3ywrd7'
begin :con := "TASSETACL"."QUERYACL"(:sn, :on); end;
END OF STMT
PARSE #140510064751448:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=0,tim=1606699683522890
BINDS #140510064751448:
 Bind#0
  oacdty=01 mxl=4000(4000) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=0001 frm=01 csi=852 siz=4000 off=0
  kxsbbbfp=7fcb0c540750  bln=4000  avl=00  flg=05
 Bind#1
  oacdty=01 mxl=32(10) mxlc=00 mal=00 scl=00 pre=00
  oacflg=10 fl2=0001 frm=01 csi=852 siz=32 off=0
  kxsbbbfp=7fff63bb2d6e  bln=32  avl=10  flg=09
  value="XXXXXX_YYY"
 Bind#2
  oacdty=01 mxl=32(07) mxlc=00 mal=00 scl=00 pre=00
  oacflg=10 fl2=0001 frm=01 csi=852 siz=32 off=0
  kxsbbbfp=7fff63bb2da2  bln=32  avl=07  flg=09
  value="GY_KSDM"
=====================

--//噢明白了，普通使用者會透過防水牆每次執行都會遞迴呼叫上面的語句。實際上也就是密集調入這個儲存過程導致出現library cache: mutex X等
--//待事件.而等待事件library cache: mutex X算在該語句上出現，並沒有記錄在begin :con := "TASSETACL"."QUERYACL"(:sn, :on); end;語句上。

> @ dashtop sql_id "event='library cache: mutex X' and sql_id='190q1sz3ywrd7'" trunc(sysdate)-10 sysdate
%This  SQL_ID        TotalSeconds FIRST_SEEN          LAST_SEEN
------ ------------- ------------ ------------------- -------------------
 100%  190q1sz3ywrd7           10 2020-11-30 08:48:28 2020-11-30 08:48:28
--//這麼長時間段，僅僅在2020-11-30 08:48:28抓到1次(dashtop指令碼看到的時間放大10倍)。這也是我困惑的原因。

=====================
PARSING IN CURSOR #140510064750504 len=40 dep=0 uid=103 oct=3 lid=103 tim=1606699683524359 hv=1967089032 ad='131f6b0a80' sqlid='9mb3vstumytc8'
SELECT KSMC From GY_KSDM Where KSDM =:1
END OF STMT
BINDS #140510064750504:
 Bind#0
  oacdty=02 mxl=22(00) mxlc=00 mal=00 scl=00 pre=00
  oacflg=01 fl2=1000000 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=7fcb0c4eafa8  bln=22  avl=00  flg=05
EXEC #140510064750504:c=1000,e=440,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1995374031,tim=1606699683524467
FETCH #140510064750504:c=0,e=6,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1995374031,tim=1606699683524518
STAT #140510064750504 id=1 cnt=0 pid=0 pos=1 obj=94032 op='TABLE ACCESS BY INDEX ROWID GY_KSDM (cr=0 pr=0 pw=0 time=4 us cost=1 size=18 card=1)'
STAT #140510064750504 id=2 cnt=0 pid=1 pos=1 obj=94033 op='INDEX UNIQUE SCAN PK_GY_KSDM (cr=0 pr=0 pw=0 time=3 us cost=0 size=0 card=1)'
CLOSE #140510064750504:c=0,e=3,dep=0,type=0,tim=1606699683528032
--//竟然出現沒有定義變數的情況。這種情況在特殊情況下很可怕，可能會導致執行計劃畸形。
--//參考連結：http://blog.itpub.net/267265/viewspace-2682641/

> alter system set events 'sql_trace off';
System altered.

#  grep value ZZZZ1_ora_106472.trc | sort |uniq -c
     20   value=420
    991   value=66
     60   value=70
   7712   value="GY_KSDM"
   7712   value="XXXXXX_YYY"
--//執行NULL值的次數有這麼多嗎？

總結：
--//今年2月分一直在做使用dbms_shared_pool.markhot包做熱標識物件的測試，相當然以為library cache: mutex X等待出現在呼叫TASSETACL的情況。
--//現在困惑我是否應該使用dbms_shared_pool.markhot標識熱物件，感覺為了216.5秒做這件事情，風險有點大。
--//實際上我已經在一個小的測試環境做了測試，我發現無法回頭執行如下會卡住。
exec dbms_shared_pool.unmarkhot('XXXX','TAUDIT',1);
--//先暫時放一下，再觀察觀察。