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

来源：这里教程网时间：2026-03-03 16:17:16 作者：

[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); --//先暂时放一下，再观察观察。