[20241116]大量软解析相关等待事件分析(11g).txt
--//测试看看应用程序大量软解析导致的相关等待事件，主要原因上午测试library cache bucket的muext值的前4个字节，在软解析时会
--//出现挂起的情况,其他地方也应该出现类似情况，测试看看主要出现在那里等待事件。
1.环境：
SCOTT@book> @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
2.建立测试环境：
drop table t purge ;
create table t as select rownum id ,'test' pad from dual connect by level<=2e5;
create unique index pk_t on t(id);
exec dbms_stats.gather_table_stats(user, 't', method_opt=>'for all columns size 1');
$ cat m4.txt
alter session set session_cached_cursors=0;
DECLARE
v_pad VARCHAR2 (200);
l_count PLS_INTEGER;
BEGIN
FOR i IN 1..&&1
LOOP
EXECUTE IMMEDIATE 'Select count(*) from t where id = :j ' INTO l_count USING i;
END LOOP;
END;
/
--//设置session_cached_cursors=0;,这样每次执行都是软解析。
3.测试：
$ zzdate;seq 20 | xargs -P 20 -IQ sqlplus -s -l scott/book @m4.txt 5e5 > /dev/null;zzdate
trunc(sysdate)+14/24+55/1440+35/86400
trunc(sysdate)+14/24+57/1440+11/86400
--//等待测试完成。需要2*60+11-35 = 96秒。
SYS@book> @ ashtop event,p1raw,p1,p3raw 1=1 trunc(sysdate)+14/24+55/1440+35/86400 trunc(sysdate)+14/24+57/1440+11/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW P1 P3RAW FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ---------- ----------------- ------------------- ------------------- ---------- -------- -----------
628 6.5 34% | resmgr:cpu quantum 0000000000000002 2 0000000000000000 2024-11-16 14:55:37 2024-11-16 14:57:10 21 83 81
344 3.6 18% | 2803829484 2024-11-16 14:55:37 2024-11-16 14:57:10 150 93 215
300 3.1 16% | library cache: mutex X 00000000A71F0AEC 2803829484 0000000000000055 2024-11-16 14:55:37 2024-11-16 14:57:10 20 86 20
152 1.6 8% | library cache: mutex X 00000000A71F0AEC 2803829484 000000000000006A 2024-11-16 14:55:37 2024-11-16 14:57:10 20 72 20
137 1.4 7% | 2 2024-11-16 14:55:37 2024-11-16 14:57:10 56 66 96
88 .9 5% | library cache: mutex X 00000000A71F0AEC 2803829484 0000000000000039 2024-11-16 14:55:37 2024-11-16 14:57:08 1 60 60
85 .9 5% | library cache: mutex X 0000000000010AEC 68332 000000000000003E 2024-11-16 14:55:45 2024-11-16 14:57:07 20 35 20
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
46 .5 2% | 68332 2024-11-16 14:55:45 2024-11-16 14:57:04 33 27 41
22 .2 1% | cursor: mutex S 0000000000000000 0 0000000200000000 2024-11-16 14:55:49 2024-11-16 14:57:02 1 5 5
19 .2 1% | cursor: pin S 00000000A71F0AEC 2803829484 0000000900000000 2024-11-16 14:55:40 2024-11-16 14:56:55 1 15 15
16 .2 1% | cursor: pin S 00000000A71F0AEC 2803829484 0000000500000000 2024-11-16 14:55:40 2024-11-16 14:57:06 1 12 12
14 .1 1% | cursor: mutex S 00000000A71F0AEC 2803829484 0000000100000000 2024-11-16 14:55:43 2024-11-16 14:56:47 1 7 7
10 .1 1% | 0 2024-11-16 14:55:49 2024-11-16 14:57:02 7 6 10
4 .0 0% | resmgr:cpu quantum 0000000000000003 3 0000000000000000 2024-11-16 14:55:58 2024-11-16 14:57:08 3 4 3
1 .0 0% | log file parallel write 0000000000000001 1 0000000000000001 2024-11-16 14:55:36 2024-11-16 14:55:36 1 1 1
1 .0 0% | log file sync 0000000000001486 5254 0000000000000000 2024-11-16 14:55:36 2024-11-16 14:55:36 1 1 1
1 .0 0% | 100 2024-11-16 14:57:05 2024-11-16 14:57:05 1 1 1
17 rows selected.
--//在这样的情况下library cache:mutex X成为主要等待事件，cursor: pin S，cursor: mutex S成为次要等待事件。
--//有点奇怪的地方是看不到21c的library cache: bucket mutex X。
--//如果仔细看下划线就可以发现11g把library cache: bucket mutex X归在library cache: mutex X里面。
--// 2803829484%2^17 = 68332 正好是KGL_BUCKET值。
--//在11g根本没有library cache: bucket mutex X等待事件。
SYS@book> @ ev_name "%bucket%"
no rows selected
--//这让我想起了Tanel Poder的Latch and Mutex Contention Troubleshooting in Oracle一篇文章:
library cache: mutex* wait events
1) library cache hash bucket number (if idn <= 131072)
2) idn = hash value of the library cache object under protection (if idn > 131072)
--//我当时想如果idn<= 131072一定是library cache hash bucket number吗？难道不可能是hash value。
--//看到测试，大家应该明白也可能是hash value，只不多在11g下要自己做判断分析，顺便贴一个hash_value=0的例子：
SCOTT@book> select /*+ 9 */ count(*) from dept where deptno = 93834;
COUNT(*)
----------
0
SCOTT@book> @hash
HASH_VALUE SQL_ID CHILD_NUMBER KGL_BUCKET PLAN_HASH_VALUE HASH_HEX SQL_EXEC_START SQL_EXEC_ID
---------- ------------- ------------ ---------- --------------- ---------- ------------------- -----------
3403546624 as3g00v5dw000 0 0 2236899148 cade0000 2024-11-17 15:05:27 16777216
--//另外补充说明软软解析看到主要是cursor: pin S等待事件。
4.分析library cache: mutex X等待事件(P1RAW=0000000000010AEC)：
SYS@book> @ ashtop event,p1,p2raw,p3raw "event='library cache: mutex X' and p1=68332" trunc(sysdate)+14/24+55/1440+35/86400 trunc(sysdate)+14/24+57/1440+11/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1 P2RAW P3RAW FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ---------------------- ----- ----------------- ----------------- ------------------- ------------------- ---------- -------- -----------
15 .2 18% | library cache: mutex X 68332 000000C800000000 000000000000003E 2024-11-16 14:56:11 2024-11-16 14:57:04 13 4 13
12 .1 14% | library cache: mutex X 68332 0000001000000000 000000000000003E 2024-11-16 14:56:50 2024-11-16 14:56:50 12 1 12
12 .1 14% | library cache: mutex X 68332 0000004700000000 000000000000003E 2024-11-16 14:55:50 2024-11-16 14:56:37 9 5 9
8 .1 9% | library cache: mutex X 68332 000000C700000000 000000000000003E 2024-11-16 14:56:26 2024-11-16 14:56:26 8 1 8
7 .1 8% | library cache: mutex X 68332 0000004500000000 000000000000003E 2024-11-16 14:56:13 2024-11-16 14:57:07 5 3 5
5 .1 6% | library cache: mutex X 68332 0000000000000000 000000000000003E 2024-11-16 14:55:52 2024-11-16 14:56:56 5 5 5
4 .0 5% | library cache: mutex X 68332 0000004400000000 000000000000003E 2024-11-16 14:55:45 2024-11-16 14:57:03 3 4 3
3 .0 4% | library cache: mutex X 68332 000000C500000000 000000000000003E 2024-11-16 14:55:57 2024-11-16 14:56:53 3 3 3
3 .0 4% | library cache: mutex X 68332 000000C600000000 000000000000003E 2024-11-16 14:56:27 2024-11-16 14:56:43 2 2 2
2 .0 2% | library cache: mutex X 68332 0000000E00000000 000000000000003E 2024-11-16 14:56:34 2024-11-16 14:56:34 2 1 2
2 .0 2% | library cache: mutex X 68332 0000004600000000 000000000000003E 2024-11-16 14:55:52 2024-11-16 14:56:31 2 2 2
2 .0 2% | library cache: mutex X 68332 0000008400000000 000000000000003E 2024-11-16 14:56:00 2024-11-16 14:56:44 2 2 2
2 .0 2% | library cache: mutex X 68332 0000008600000000 000000000000003E 2024-11-16 14:56:54 2024-11-16 14:56:57 2 2 2
2 .0 2% | library cache: mutex X 68332 0000008800000000 000000000000003E 2024-11-16 14:56:31 2024-11-16 14:56:31 2 1 2
1 .0 1% | library cache: mutex X 68332 0000000A00000000 000000000000003E 2024-11-16 14:56:45 2024-11-16 14:56:45 1 1 1
1 .0 1% | library cache: mutex X 68332 0000000C00000000 000000000000003E 2024-11-16 14:55:47 2024-11-16 14:55:47 1 1 1
1 .0 1% | library cache: mutex X 68332 0000000F00000000 000000000000003E 2024-11-16 14:55:57 2024-11-16 14:55:57 1 1 1
1 .0 1% | library cache: mutex X 68332 0000004900000000 000000000000003E 2024-11-16 14:55:49 2024-11-16 14:55:49 1 1 1
1 .0 1% | library cache: mutex X 68332 0000004B00000000 000000000000003E 2024-11-16 14:56:01 2024-11-16 14:56:01 1 1 1
1 .0 1% | library cache: mutex X 68332 000000C300000000 000000000000003E 2024-11-16 14:56:11 2024-11-16 14:56:11 1 1 1
20 rows selected.
--//P2raw对应阻塞的sid。
--//0x3e = 62
SYS@book> @ mutexprofx idn,hash,val,loc,maddr "ts>=trunc(sysdate)+14/24+55/1440+35/86400 and ts<=trunc(sysdate)+14/24+57/1440+11/86400 and idn=68332"
-- MutexProf by Tanel Poder (http://www.tanelpoder.com)
-- Showing profile of top 20 sleeps...
-- column info : id idn hash hash_value=>hash_value ts=>sleep_timestamp
-- req=>requesting_session blk=>blocking_session val=>mutex_value maddr=>mutex_addr
MAX_SLEEPS SLEEPS_DIFF MUTEX_TYPE IDN HASH VAL GET_LOCATION mutex_addr OBJECT_NAME
---------- ----------- --------------- ---------- ---------- ---------------- ------------ -------------------- ----------------
3229 Library Cache 68332 0000004600000000 kglhdgn1 62 000000008BF56080 (name not found)
554 Library Cache 68332 000000C800000000 kglhdgn1 62 000000008BF56080 (name not found)
449 38 Library Cache 68332 00 kglhdgn1 62 000000008BF56080 (name not found)
448 25 Library Cache 68332 0000000F00000000 kglhdgn1 62 000000008BF56080 (name not found)
438 Library Cache 68332 0000008800000000 kglhdgn1 62 000000008BF56080 (name not found)
434 Library Cache 68332 0000008700000000 kglhdgn1 62 000000008BF56080 (name not found)
434 Library Cache 68332 000000C700000000 kglhdgn1 62 000000008BF56080 (name not found)
411 Library Cache 68332 0000008600000000 kglhdgn1 62 000000008BF56080 (name not found)
383 Library Cache 68332 0000004900000000 kglhdgn1 62 000000008BF56080 (name not found)
9 rows selected.
--//mutex_addr=000000008BF56080
--//0x000000008BF56080-0x10 = 0x8bf56070
SYS@book> @ opeek 000000008BF56070 40 0
[08BF56070, 08BF56098) = 874C1040 00000000 874C1040 00000000 00000000 00000000 009896B3 00002200 00010AEC 00000000
--//0x00010AEC = 68332 hash桶号。
SYS@book> @ sharepool/shp4 '' 2803829484
HANDLE_TYPE KGLHDADR KGLHDPAR C40 KGLHDLMD KGLHDPMD KGLHDIVC KGLOBHD0 KGLOBHD6 KGLOBHS0 KGLOBHS6 KGLOBT16 N0_6_16 N20 KGLNAHSH KGLOBT03 KGLOBT09
---------------------- ---------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------------- ---------------- ---------- ---------- ---------- --------- ---------- ---------- ------------- ----------
child handle address 0000000088A57AF8 00000000874C1040 Select count(*) from t where id = :j 0 0 0 0000000085E92C78 0000000089749770 8600 8088 3086 19774 19774 2803829484 ctt2p2qmjy2rc 0
parent handle address 00000000874C1040 00000000874C1040 Select count(*) from t where id = :j 0 0 0 00000000889873C0 00 4720 0 0 4720 4720 2803829484 ctt2p2qmjy2rc 65535
--//前面两个8字节就是该sql语句的父游标句柄地址。
5.分析library cache: mutex X等待事件(p1raw=00000000A71F0AEC)：
SYS@book> @ ashtop event,p1,p2raw,p3raw "event='library cache: mutex X' and p1=2803829484" trunc(sysdate)+14/24+55/1440+35/86400 trunc(sysdate)+14/24+57/1440+11/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1 P2RAW P3RAW FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ---------------------- ---------- ----------------- ----------------- ------------------- ------------------- ---------- -------- -----------
93 1.0 17% | library cache: mutex X 2803829484 0000000000000000 0000000000000055 2024-11-16 14:55:37 2024-11-16 14:57:07 19 58 19
47 .5 9% | library cache: mutex X 2803829484 0000000000000000 0000000000000039 2024-11-16 14:55:38 2024-11-16 14:57:08 1 39 39
44 .5 8% | library cache: mutex X 2803829484 0000000000000000 000000000000006A 2024-11-16 14:55:37 2024-11-16 14:57:10 16 35 16
20 .2 4% | library cache: mutex X 2803829484 000000C700000000 0000000000000055 2024-11-16 14:55:38 2024-11-16 14:56:29 13 8 13
16 .2 3% | library cache: mutex X 2803829484 0000004B00000000 0000000000000055 2024-11-16 14:55:38 2024-11-16 14:57:05 11 9 11
15 .2 3% | library cache: mutex X 2803829484 0000008700000000 0000000000000055 2024-11-16 14:55:44 2024-11-16 14:56:18 13 6 13
14 .1 3% | library cache: mutex X 2803829484 0000004600000000 0000000000000055 2024-11-16 14:55:57 2024-11-16 14:56:56 9 7 9
13 .1 2% | library cache: mutex X 2803829484 0000004900000000 0000000000000055 2024-11-16 14:55:43 2024-11-16 14:57:10 10 6 10
13 .1 2% | library cache: mutex X 2803829484 000000C500000000 0000000000000055 2024-11-16 14:55:41 2024-11-16 14:57:01 11 7 11
12 .1 2% | library cache: mutex X 2803829484 0000000C00000000 0000000000000055 2024-11-16 14:56:03 2024-11-16 14:57:01 10 7 10
12 .1 2% | library cache: mutex X 2803829484 0000001000000000 0000000000000055 2024-11-16 14:55:48 2024-11-16 14:57:07 10 8 10
12 .1 2% | library cache: mutex X 2803829484 0000004500000000 0000000000000055 2024-11-16 14:55:40 2024-11-16 14:57:07 9 7 9
11 .1 2% | library cache: mutex X 2803829484 0000008400000000 0000000000000055 2024-11-16 14:55:37 2024-11-16 14:57:09 7 7 7
11 .1 2% | library cache: mutex X 2803829484 000000C300000000 0000000000000055 2024-11-16 14:56:24 2024-11-16 14:56:47 10 3 10
10 .1 2% | library cache: mutex X 2803829484 0000000C00000000 000000000000006A 2024-11-16 14:55:40 2024-11-16 14:56:53 6 7 6
10 .1 2% | library cache: mutex X 2803829484 0000000F00000000 0000000000000055 2024-11-16 14:55:37 2024-11-16 14:57:08 8 5 8
10 .1 2% | library cache: mutex X 2803829484 0000000F00000000 000000000000006A 2024-11-16 14:55:37 2024-11-16 14:57:08 8 9 8
10 .1 2% | library cache: mutex X 2803829484 0000008800000000 0000000000000055 2024-11-16 14:55:45 2024-11-16 14:56:59 8 8 8
9 .1 2% | library cache: mutex X 2803829484 0000008400000000 000000000000006A 2024-11-16 14:55:47 2024-11-16 14:56:59 8 7 8
8 .1 1% | library cache: mutex X 2803829484 0000000F00000000 0000000000000039 2024-11-16 14:55:37 2024-11-16 14:57:08 1 6 6
8 .1 1% | library cache: mutex X 2803829484 0000004500000000 000000000000006A 2024-11-16 14:55:40 2024-11-16 14:57:07 6 6 6
8 .1 1% | library cache: mutex X 2803829484 0000004B00000000 000000000000006A 2024-11-16 14:55:38 2024-11-16 14:57:09 7 5 7
8 .1 1% | library cache: mutex X 2803829484 000000C800000000 0000000000000055 2024-11-16 14:55:39 2024-11-16 14:56:55 6 7 6
7 .1 1% | library cache: mutex X 2803829484 0000000A00000000 0000000000000055 2024-11-16 14:56:03 2024-11-16 14:56:56 7 6 7
7 .1 1% | library cache: mutex X 2803829484 0000000E00000000 0000000000000055 2024-11-16 14:55:43 2024-11-16 14:57:07 7 6 7
7 .1 1% | library cache: mutex X 2803829484 0000004600000000 000000000000006A 2024-11-16 14:56:20 2024-11-16 14:56:56 6 3 6
6 .1 1% | library cache: mutex X 2803829484 0000004400000000 0000000000000055 2024-11-16 14:55:45 2024-11-16 14:57:07 6 5 6
6 .1 1% | library cache: mutex X 2803829484 0000008700000000 000000000000006A 2024-11-16 14:55:44 2024-11-16 14:56:46 6 3 6
6 .1 1% | library cache: mutex X 2803829484 000000C300000000 000000000000006A 2024-11-16 14:55:47 2024-11-16 14:56:47 5 3 5
6 .1 1% | library cache: mutex X 2803829484 000000C600000000 000000000000006A 2024-11-16 14:55:45 2024-11-16 14:57:05 5 4 5
30 rows selected.
--//P3raw基本都是00000000000000XX，与21c不同，21前面8位记录的hash_value
--//后面8位对应mutexprofx GET_LOCATION后面的数字。
SYS@book> @ ashtop event,p1,p3raw "event='library cache: mutex X' and p1=2803829484" trunc(sysdate)+14/24+55/1440+35/86400 trunc(sysdate)+14/24+57/1440+11/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1 P3RAW FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ---------------------- ---------- ----------------- ------------------- ------------------- ---------- -------- -----------
300 3.1 56% | library cache: mutex X 2803829484 0000000000000055 2024-11-16 14:55:37 2024-11-16 14:57:10 20 86 20
152 1.6 28% | library cache: mutex X 2803829484 000000000000006A 2024-11-16 14:55:37 2024-11-16 14:57:10 20 72 20
88 .9 16% | library cache: mutex X 2803829484 0000000000000039 2024-11-16 14:55:37 2024-11-16 14:57:08 1 60 60
SYS@book> @ ashtop to_number(substr(p3raw,9),'xxxxxxxx') "event='library cache: mutex X' and p1=2803829484" trunc(sysdate)+14/24+55/1440+35/86400 trunc(sysdate)+14/24+57/1440+11/86400
Total Distinct Distinct Distinct
Seconds AAS %This TO_NUMBER(SUBSTR(P3RAW,9),'XXXXXXXX') FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------- ------------------- ------------------- ---------- -------- -----------
300 3.1 56% | 85 2024-11-16 14:55:37 2024-11-16 14:57:10 20 86 20
152 1.6 28% | 106 2024-11-16 14:55:37 2024-11-16 14:57:10 20 72 20
88 .9 16% | 57 2024-11-16 14:55:37 2024-11-16 14:57:08 1 60 60
--//出现的数字是85,106,57.
SYS@book> @ mutexprofx idn,hash,loc,maddr "ts>=trunc(sysdate)+14/24+55/1440+35/86400 and ts<=trunc(sysdate)+14/24+57/1440+11/86400 "
-- MutexProf by Tanel Poder (http://www.tanelpoder.com)
-- Showing profile of top 20 sleeps...
-- column info : id idn hash hash_value=>hash_value ts=>sleep_timestamp
-- req=>requesting_session blk=>blocking_session val=>mutex_value maddr=>mutex_addr
MAX_SLEEPS SLEEPS_DIFF MUTEX_TYPE IDN HASH GET_LOCATION mutex_addr OBJECT_NAME
---------- ----------- --------------- ---------- ---------- --------------------------------- -------------------- -------------------------------------
3360 551 Library Cache 2803829484 2803829484 kglhdgn2 106 00000000874C1180 Select count(*) from t where id = :j
3229 2846 Library Cache 68332 kglhdgn1 62 000000008BF56080 (name not found)
3026 263 Library Cache 2803829484 2803829484 kgllkdl1 85 00000000874C1180 Select count(*) from t where id = :j
2904 Library Cache 2803829484 2803829484 kgllkc1 57 00000000874C1180 Select count(*) from t where id = :j
684 366 Cursor Pin 2803829484 2803829484 kkslce [KKSCHLPIN2] 00000000897496C8 Select count(*) from t where id = :j
657 343 Cursor Pin 2803829484 2803829484 kksLockDelete [KKSCHLPIN6] 00000000897496C8 Select count(*) from t where id = :j
539 440 hash table 2803829484 2803829484 kkshGetNextChild [KKSHBKLOC1] 0000000089749308 Select count(*) from t where id = :j
476 361 hash table 0 kkscsSearchChildList [KKSHBKLOC2] 0000000089749608 (name not found)
--//这里出现的数字定位我一直不理解为什么，不知道是否理解前面执行的函数，后面的数字对应程序行号。
SYS@book> @ mutexprofx maddr,P1raw "ts>=trunc(sysdate)+14/24+55/1440+35/86400 and ts<=trunc(sysdate)+14/24+57/1440+11/86400 and idn=2803829484"
-- MutexProf by Tanel Poder (http://www.tanelpoder.com)
-- Showing profile of top 20 sleeps...
-- column info : id idn hash hash_value=>hash_value ts=>sleep_timestamp
-- req=>requesting_session blk=>blocking_session val=>mutex_value maddr=>mutex_addr
MAX_SLEEPS SLEEPS_DIFF MUTEX_TYPE mutex_addr P1RAW OBJECT_NAME
---------- ----------- --------------- -------------------- ---------------- ------------------------------------
3360 551 Library Cache 00000000874C1180 00000000874C1040 Select count(*) from t where id = :j
3026 263 Library Cache 00000000874C1180 0000000088A57AF8 Select count(*) from t where id = :j
684 370 Cursor Pin 00000000897496C8 00 Select count(*) from t where id = :j
539 440 hash table 0000000089749308 00 Select count(*) from t where id = :j
--//要想知道mutex_addr只能查询x$mutex_sleep_history。
--//理论没有P1RAW字段，应该出现3行，实际出现4行，主要原因是tpt的脚本其他字段作为group by。
SYS@book> @ sharepool/shp4 '' 2803829484
HANDLE_TYPE KGLHDADR KGLHDPAR C40 KGLHDLMD KGLHDPMD KGLHDIVC KGLOBHD0 KGLOBHD6 KGLOBHS0 KGLOBHS6 KGLOBT16 N0_6_16 N20 KGLNAHSH KGLOBT03 KGLOBT09
---------------------- ---------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------------- ---------------- ---------- ---------- ---------- --------- ---------- ---------- ------------- ----------
child handle address 0000000088A57AF8 00000000874C1040 Select count(*) from t where id = :j 0 0 0 0000000085E92C78 0000000089749770 8600 8088 3086 19774 19774 2803829484 ctt2p2qmjy2rc 0
parent handle address 00000000874C1040 00000000874C1040 Select count(*) from t where id = :j 0 0 0 00000000889873C0 00 4720 0 0 4720 4720 2803829484 ctt2p2qmjy2rc 65535
--//P1RAW=00000000874C1040,0000000088A57AF8分别对应sql语句的父子游标句柄。
6.看看这些mutex_addr在哪里。
SYS@book> @ fchaz 00000000874C1180
GET_LOCATION KSMCHPTR KSMCHIDX KSMCHDUR KSMCHCOM KSMCHSIZ KSMCHCLS KSMCHTYP KSMCHPAR KSMCHPTR_BEGIN KSMCHPTR_END+1
--------------------------------- ---------------- ---------- ---------- ---------------- ---------- -------- ---------- ---------------- ---------------- -----------------
SGA 00000000874C1010 1 2 KGLHD 560 recr 80 00 00000000874C1010 00000000874C1240
SYS@book> @ fchaz 00000000897496C8
GET_LOCATION KSMCHPTR KSMCHIDX KSMCHDUR KSMCHCOM KSMCHSIZ KSMCHCLS KSMCHTYP KSMCHPAR KSMCHPTR_BEGIN KSMCHPTR_END+1
--------------------------------- ---------------- ---------- ---------- ---------------- ---------- -------- ---------- ---------------- ---------------- -----------------
SGA 0000000089749000 1 3 KGLH0^a71f0aec 4096 recr 4095 00000000889873C0 0000000089749000 000000008974A000
SYS@book> @ fchaz 0000000089749308
GET_LOCATION KSMCHPTR KSMCHIDX KSMCHDUR KSMCHCOM KSMCHSIZ KSMCHCLS KSMCHTYP KSMCHPAR KSMCHPTR_BEGIN KSMCHPTR_END+1
--------------------------------- ---------------- ---------- ---------- ---------------- ---------- -------- ---------- ---------------- ---------------- -----------------
SGA 0000000089749000 1 3 KGLH0^a71f0aec 4096 recr 4095 00000000889873C0 0000000089749000 000000008974A000
SYS@book> @ sharepool/shp4 '' 2803829484
HANDLE_TYPE KGLHDADR KGLHDPAR C40 KGLHDLMD KGLHDPMD KGLHDIVC KGLOBHD0 KGLOBHD6 KGLOBHS0 KGLOBHS6 KGLOBT16 N0_6_16 N20 KGLNAHSH KGLOBT03 KGLOBT09
---------------------- ---------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------------- ---------------- ---------- ---------- ---------- --------- ---------- ---------- ------------- ----------
child handle address 0000000088A57AF8 00000000874C1040 Select count(*) from t where id = :j 0 0 0 0000000085E92C78 0000000089749770 8600 8088 3086 19774 19774 2803829484 ctt2p2qmjy2rc 0
parent handle address 00000000874C1040 00000000874C1040 Select count(*) from t where id = :j 0 0 0 00000000889873C0 00 4720 0 0 4720 4720 2803829484 ctt2p2qmjy2rc 65535
--//从KSMCHPAR=00000000889873C0可以发现。00000000897496C8，0000000089749308对应的就是父游标的堆0地址。
--//前者00000000897496C8，对应Cursor Pin，loc=kkslce [KKSCHLPIN2]，kksLockDelete [KKSCHLPIN6]，如果大量执行软软解析这就是主要等待事件。
--//后者0000000089749308，对应hash table，loc=kkshGetNextChild [KKSHBKLOC1] kkscsSearchChildList [KKSHBKLOC2]
SYS@book> @ opeek 00000000897496C8 24 0
[0897496C8, 0897496E0) = 00000000 00000000 01312E46 00001A1E A71F0AEC 00000000
SYS@book> @ opeek 0000000089749308 24 0
[089749308, 089749320) = 00000000 00000000 01312D05 00000932 A71F0AEC 00000000
--//0xA71F0AEC = 2803829484
--//00000000874C1180位于父游标，KSMCHPTR_BEGIN=00000000874C1010,与父游标句柄KGLHDPAR=00000000874C1040，正好相差0x30(48字节)。
--//也就是大量软解析的主要等待事件。
--//对应Library Cache,loc=kglhdgn2 106 ,kgllkdl1 85 ,kgllkc1 57 .
SYS@book> @ opeek 00000000874C1180 24 0
[0874C1180, 0874C1198) = 00000000 00000000 02625CA2 0000E087 A71F0AEC 00000000
--// 476 361 hash table 0 kkscsSearchChildList [KKSHBKLOC2] 0000000089749608 (name not found)
SYS@book> @ fchaz 0000000089749608
GET_LOCATION KSMCHPTR KSMCHIDX KSMCHDUR KSMCHCOM KSMCHSIZ KSMCHCLS KSMCHTYP KSMCHPAR KSMCHPTR_BEGIN KSMCHPTR_END+1
--------------------------------- ---------------- ---------- ---------- ---------------- ---------- -------- ---------- ---------------- ---------------- -----------------
SGA 0000000089749000 1 3 KGLH0^a71f0aec 4096 recr 4095 00000000889873C0 0000000089749000 000000008974A000
--//在父游标的堆0地址。
SYS@book> @ opeek 0000000089749608 24 0
[089749608, 089749620) = 00000000 00000000 01312D08 000009C9 00000000 00000000
~~~~~~~~
--//下划线位置一般记录hash_value,这里记录是0.
7.简单总结：
--//应用程序大量软解析导致的相关等待事件,主要集中在library cache:mutex X,其中21c出现(library cache: bucket mutex X)在11g
--//被归在library cache:mutex X里面成为主要等待事件，cursor: pin S，cursor: mutex S成为次要等待事件。
--//主要原因发现管理数据库就存在这类现象，许多代码视乎就是死循环，不断的连接退出，而执行代码就是1次，这样大量的sql语句都
--//是软解析。开发应该改成连接1次，小量休眠，在继续执行，另外写一个程序判断这个连接是否存在，不存在启动新连接。
--//后记：
SYS@book> @ ashtop event,p1raw,p3raw "event='cursor: pin S'" trunc(sysdate)+14/24+55/1440+35/86400 trunc(sysdate)+14/24+57/1440+11/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW P3RAW FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ----------------- ------------------- ------------------- ---------- -------- -----------
19 .2 54% | cursor: pin S 00000000A71F0AEC 0000000900000000 2024-11-16 14:55:40 2024-11-16 14:56:55 1 15 15
16 .2 46% | cursor: pin S 00000000A71F0AEC 0000000500000000 2024-11-16 14:55:40 2024-11-16 14:57:06 1 12 12
SYS@book> @ ashtop event,p1raw,p3raw "event='cursor: mutex S'" trunc(sysdate)+14/24+55/1440+35/86400 trunc(sysdate)+14/24+57/1440+11/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW P3RAW FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ----------------- ------------------- ------------------- ---------- -------- -----------
22 .2 61% | cursor: mutex S 0000000000000000 0000000200000000 2024-11-16 14:55:49 2024-11-16 14:57:02 1 5 5
14 .1 39% | cursor: mutex S 00000000A71F0AEC 0000000100000000 2024-11-16 14:55:43 2024-11-16 14:56:47 1 7 7
--//这里P3raw 与mutexprofx的输出记录不同，不是对应数字。
8.附上mutexprofx.sql代码：
--//在tpt的mutexprof.sql基础上做的小量修改，
$ cat tpt/mutexprofx.sql
--------------------------------------------------------------------------------
--
-- File name: mutexprof.sql ( Mutex sleep Profiler )
--
-- Purpose: Display KGX mutex sleep history from v$mutex_sleep_history
-- along library cache object names protected by these mutexes.
-- Only top 20 rows are shown by default
--
-- Author: Tanel Poder
-- Copyright: (c) http://www.tanelpoder.com
--
-- Usage: @mutexprof <grouping columns> <filter condition>
--
-- The main grouping (and filtering) columns are:
--
-- id - mutex ID (which is the object hash value for library
-- cache object mutexes)
-- ts - timestamp of mutex sleep beginning
-- loc - code location where the waiter slept for the mutex
-- val - mutex value (shows whether mutex was held in exclusive or
-- shared mode)
-- req - requesting session SID
-- blk - blocking session SID
--
-- The filter condition allows filtering mutex sleep rows based on certain
-- criteria, such:
--
-- 1=1 - show all mutex sleeps (which are still in memory)
-- blk=123 - show only these mutex sleeps where blocking sid was 123
-- hash=2741853041 - show only these sleeps where mutex ID (KGL object hash value)
-- was 2741853041
--
--
-- Its also possible to have multiple "AND" filter conditions, as long as you keep
-- them in double quotes so that sqlplus would recognize them as one parameter
--
-- For example: "name like '%DUAL%' and blk in (115,98)"
--
-- Examples:
--
-- @mutexprof loc 1=1
-- @mutexprof id,loc,req,blk "lower(name) like 'select%from dual%'"
-- @mutexprof loc,val blk=98
-- @mutexprof id,loc,req,blk "blk in (select sid from v$session where username = 'SYS')"
--
-- Other: When the relevant object is aged out you will see (name not found)
-- as object_name.
--
-- On 10.2.0.1 the V$mutex_sleep_history does not have mutex_identifier
-- column externalized. In this case use X$mutex_sleep_history instead
--
--------------------------------------------------------------------------------
col msh_obj_name head OBJECT_NAME for a80 word_wrap
col msh_mutex_type head MUTEX_TYPE for a15 truncate
col loc head GET_LOCATION for a33 truncate
col mutexprof_gets head GETS for 9999999999999
col mutexprof_sleeps head SLEEPS_DIFF for 999999
col mutexprof_p2 head P2 for a16 wrap
col mutexprof_p3 head P3 for a16 wrap
col mutexprof_p4 head P4 for a16 wrap
col mutexprof_p5 head P5 for a20 wrap
col maddr head mutex_addr for a20 wrap
def MSH_NUMROWS=20
prompt
prompt -- MutexProf by Tanel Poder (http://www.tanelpoder.com)
prompt -- Showing profile of top &MSH_NUMROWS sleeps...
prompt -- column info : id idn hash hash_value=>hash_value ts=>sleep_timestamp
prompt -- req=>requesting_session blk=>blocking_session val=>mutex_value maddr=>mutex_addr
select * from (
select /*+ ORDERED USE_NL(o) */
-- TODO the sleep/get counting needs fixing!
MAX(sleeps) max_sleeps
--sum(sleeps) sum_sleeps
--count(*) sleeps
, decode(max(sleeps)-min(sleeps),0,to_number(null),max(sleeps)-min(sleeps)) mutexprof_sleeps -- may not be very accurate but give an idea
--, decode(max(gets)-min(gets),0,to_number(null),max(gets)-min(gets)) mutexprof_gets -- may not be very accurate but give an idea
-- avg(sleeps) sleeps
--, avg(gets) gets
, mutex_type msh_mutex_type
, &1
, replace(nvl(decode(kglnaown, null, kglnaobj, kglnaown||'.'||kglnaobj), '(name not found)'),chr(13),'') msh_obj_name
--, nvl(decode(kglnaown, null, kglnaobj, kglnaown||'.'||kglnaobj), '(name not found)') msh_obj_name
--, p1raw
--, CASE WHEN p2 < 536870912 THEN TO_CHAR(p2) ELSE TRIM(TO_CHAR(p2, 'XXXXXXXXXXXXXXXX')) END mutexprof_p2
--, CASE WHEN p3 < 536870912 THEN TO_CHAR(p3) ELSE TRIM(TO_CHAR(p3, 'XXXXXXXXXXXXXXXX')) END mutexprof_p3
--, CASE WHEN p4 < 536870912 THEN TO_CHAR(p4) ELSE TRIM(TO_CHAR(p4, 'XXXXXXXXXXXXXXXX')) END mutexprof_p4
--, p5 mutexprof_p5
from
(select
mutex_identifier id
, mutex_identifier idn
, sleep_timestamp ts
, mutex_type
, gets
, sleeps
, requesting_session req
, blocking_session blk
, location loc
, mutex_value val
, mutex_addr maddr
, p1
, p1raw
, p2
, p3
, p4
, p5
from x$mutex_sleep_history) m
, (select kglnahsh, kglnahsh hash_value, kglnahsh hash,
kglhdpar, kglhdadr, kglnaown, kglnaobj,
decode(kglnaown, null, kglnaobj, kglnaown||'.'||kglnaobj) object_name,
decode(kglnaown, null, kglnaobj, kglnaown||'.'||kglnaobj) name
from x$kglob) o
where
m.id = o.kglnahsh (+)
and (o.kglhdadr = o.kglhdpar or (o.kglhdpar is null)) -- only parent KGL objects if still in cache
and &2
group by
mutex_type
, &1
, kglnaown
, kglnaobj
, p1raw
, CASE WHEN p2 < 536870912 THEN TO_CHAR(p2) ELSE TRIM(TO_CHAR(p2, 'XXXXXXXXXXXXXXXX')) END
, CASE WHEN p3 < 536870912 THEN TO_CHAR(p3) ELSE TRIM(TO_CHAR(p3, 'XXXXXXXXXXXXXXXX')) END
, CASE WHEN p4 < 536870912 THEN TO_CHAR(p4) ELSE TRIM(TO_CHAR(p4, 'XXXXXXXXXXXXXXXX')) END
--, p5
order by
1 desc
-- sleeps desc
)
where rownum <= &MSH_NUMROWS
/