[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);
--//先暂时放一下，再观察观察。
来自 “ ITPUB博客 ” ，链接：https://blog.itpub.net/267265/viewspace-2738969/ ，如需转载，请注明出处，否则将追究法律责任。
最新文章
- [20261008]验证Shared Memory Segments key以及Semaphore Arrays Key(11g).txt
- [20261008]gdb引入结构体是否可行.txt
- [20261008]bpftrace定义结构体例子.txt
- [20261007]关于oracle sskgph2函数.txt
- [20261007]oracle Semaphore Arrays Key值的冲突.txt
- [20261004]oracle sskgph2函数等价c以及python脚本.txt
- [20261004]bpftrace查看oracle函数调用堆栈问题.txt
- [20261002]验证sskgphpjw函数参与运算的字符串是否存在规律.txt
- [20261002]oracle Semaphore Arrays Key值的计算2.txt
- [20261001]oracle Semaphore Arrays Key值的计算.txt
