[20241115]大量软解析相关等待事件分析(21c).txt
--//测试看看应用程序大量软解析导致的相关等待事件，主要原因上午测试library cache bucket的muext值的前4个字节，在软解析时会
--//出现挂起的情况,其他地方也应该出现类似情况，测试看看主要出现在那里等待事件。
1.环境：
SCOTT@book01p> @ ver2
==============================
PORT_STRING : x86_64/Linux 2.4.xx
VERSION : 21.0.0.0.0
BANNER : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
BANNER_FULL : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
Version 21.3.0.0.0
BANNER_LEGACY : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
CON_ID : 0
PL/SQL procedure successfully completed.
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@book01p @m4.txt 5e5 > /dev/null;zzdate
trunc(sysdate)+15/24+19/1440+19/86400
trunc(sysdate)+15/24+21/1440+03/86400
--//等待测试完成。需要2*60+3-19 = 104秒。
SYS@book> @ ashtop event,p1raw,p1,p3raw 1=1 trunc(sysdate)+15/24+19/1440+19/86400 trunc(sysdate)+15/24+21/1440+03/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW P1 P3RAW FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ----------------------------- ----------------- ---------- ----------------- ------------------- ------------------- ---------- -------- -----------
765 7.4 37% | 1607470161 2024-11-15 15:19:20 2024-11-15 15:21:02 282 102 377
527 5.1 26% | library cache: mutex X 000000005FD00C51 1607470161 5FD00C5100000055 2024-11-15 15:19:21 2024-11-15 15:21:02 1 100 100
246 2.4 12% | library cache: mutex X 000000005FD00C51 1607470161 5FD00C510000006A 2024-11-15 15:19:20 2024-11-15 15:21:02 20 92 20
134 1.3 7% | library cache: mutex X 000000005FD00C51 1607470161 5FD00C5100000039 2024-11-15 15:19:21 2024-11-15 15:21:02 1 80 80
104 1.0 5% | 3153 2024-11-15 15:19:20 2024-11-15 15:21:02 46 44 76
99 1.0 5% | library cache: bucket mutex X 0000000000000C51 3153 000000000000003E 2024-11-15 15:19:23 2024-11-15 15:20:58 20 39 20
54 .5 3% | cursor: pin S 000000005FD00C51 1607470161 0000000500000000 2024-11-15 15:19:23 2024-11-15 15:21:01 1 22 22
30 .3 1% | cursor: pin S 000000005FD00C51 1607470161 0000000900000000 2024-11-15 15:19:23 2024-11-15 15:20:57 1 14 14
24 .2 1% | 0 2024-11-15 15:19:34 2024-11-15 15:20:59 14 14 22
19 .2 1% | cursor: mutex S 000000005FD00C51 1607470161 0000000100000000 2024-11-15 15:19:24 2024-11-15 15:19:55 1 3 3
18 .2 1% | cursor: mutex S 0000000000000000 0 0000000200000000 2024-11-15 15:19:26 2024-11-15 15:21:00 1 8 8
11 .1 1% | 12 2024-11-15 15:19:20 2024-11-15 15:19:59 7 11 11
3 .0 0% | 1 2024-11-15 15:20:15 2024-11-15 15:20:18 1 3 3
3 .0 0% | 1413697536 2024-11-15 15:19:20 2024-11-15 15:19:20 3 1 3
2 .0 0% | db file sequential read 0000000000000001 1 0000000000000001 2024-11-15 15:20:13 2024-11-15 15:20:17 1 2 2
2 .0 0% | 131072 2024-11-15 15:19:19 2024-11-15 15:19:19 1 1 1
1 .0 0% | 3 2024-11-15 15:20:12 2024-11-15 15:20:12 1 1 1
1 .0 0% | 20 2024-11-15 15:19:44 2024-11-15 15:19:44 1 1 1
1 .0 0% | 100 2024-11-15 15:20:29 2024-11-15 15:20:29 1 1 1
1 .0 0% | 262144 2024-11-15 15:20:14 2024-11-15 15:20:14 1 1 1
20 rows selected.
--//在这样的情况下library cache:mutex X,library cache: bucket mutex X成为主要等待事件，cursor: pin S，cursor: mutex S成为次要等待事件。
--//11g下没有library cache: bucket mutex X等待事件，归类在library cache: mutex X，另外注意21c下P3RAW值前面8位对应hash_value.
--//而11g下前面8位位00000000.
--//另外补充说明软软解析看到主要是cursor: pin S。
4.分析library cache: bucket mutex X等待事件：
--//1607470161%2^17 = 3153等于KGL_BUCKET,P3=0x3e=62.
SYS@book> @ ashtop event,p1,p2raw,p3raw "event='library cache: bucket mutex X'" trunc(sysdate)+15/24+19/1440+19/86400 trunc(sysdate)+15/24+21/1440+03/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1 P2RAW P3RAW FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ----------------------------- ----- ----------------- ----------------- ------------------- ------------------- ---------- -------- -----------
18 .2 18% | library cache: bucket mutex X 3153 0000019B00000000 000000000000003E 2024-11-15 15:19:53 2024-11-15 15:20:51 15 6 15
14 .1 14% | library cache: bucket mutex X 3153 0000019500000000 000000000000003E 2024-11-15 15:19:27 2024-11-15 15:19:32 13 2 13
11 .1 11% | library cache: bucket mutex X 3153 0000001A00000000 000000000000003E 2024-11-15 15:19:28 2024-11-15 15:20:46 10 6 10
9 .1 9% | library cache: bucket mutex X 3153 0000010E00000000 000000000000003E 2024-11-15 15:19:24 2024-11-15 15:20:24 8 2 8
7 .1 7% | library cache: bucket mutex X 3153 0000009A00000000 000000000000003E 2024-11-15 15:19:27 2024-11-15 15:20:18 7 2 7
6 .1 6% | library cache: bucket mutex X 3153 0000001C00000000 000000000000003E 2024-11-15 15:20:12 2024-11-15 15:20:15 5 2 5
5 .0 5% | library cache: bucket mutex X 3153 0000019000000000 000000000000003E 2024-11-15 15:19:27 2024-11-15 15:20:58 5 3 5
3 .0 3% | library cache: bucket mutex X 3153 0000000000000000 000000000000003E 2024-11-15 15:19:51 2024-11-15 15:20:40 3 3 3
3 .0 3% | library cache: bucket mutex X 3153 0000001200000000 000000000000003E 2024-11-15 15:19:38 2024-11-15 15:20:00 2 2 2
3 .0 3% | library cache: bucket mutex X 3153 000000A200000000 000000000000003E 2024-11-15 15:20:02 2024-11-15 15:20:52 3 3 3
3 .0 3% | library cache: bucket mutex X 3153 0000011500000000 000000000000003E 2024-11-15 15:20:20 2024-11-15 15:20:40 2 3 2
3 .0 3% | library cache: bucket mutex X 3153 0000018D00000000 000000000000003E 2024-11-15 15:19:28 2024-11-15 15:19:45 3 2 3
2 .0 2% | library cache: bucket mutex X 3153 0000001500000000 000000000000003E 2024-11-15 15:19:41 2024-11-15 15:20:23 2 2 2
2 .0 2% | library cache: bucket mutex X 3153 0000002300000000 000000000000003E 2024-11-15 15:19:23 2024-11-15 15:20:19 2 2 2
2 .0 2% | library cache: bucket mutex X 3153 0000009700000000 000000000000003E 2024-11-15 15:19:24 2024-11-15 15:19:53 2 2 2
2 .0 2% | library cache: bucket mutex X 3153 0000009900000000 000000000000003E 2024-11-15 15:19:34 2024-11-15 15:19:43 2 2 2
2 .0 2% | library cache: bucket mutex X 3153 0000009B00000000 000000000000003E 2024-11-15 15:20:10 2024-11-15 15:20:42 2 2 2
2 .0 2% | library cache: bucket mutex X 3153 0000019A00000000 000000000000003E 2024-11-15 15:20:03 2024-11-15 15:20:42 2 2 2
1 .0 1% | library cache: bucket mutex X 3153 0000001B00000000 000000000000003E 2024-11-15 15:19:38 2024-11-15 15:19:38 1 1 1
1 .0 1% | library cache: bucket mutex X 3153 0000011200000000 000000000000003E 2024-11-15 15:19:38 2024-11-15 15:19:38 1 1 1
20 rows selected.
--//P2raw对应阻塞的sid。
--//P1=3153对应buckect number。 1607470161%2^17 = 3153
SYS@book> @ mutexprofz idn,hash,val,loc,maddr "ts>=trunc(sysdate)+15/24+19/1440+19/86400 and ts<=trunc(sysdate)+15/24+21/1440+03/86400 and idn=3153"
-- 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
SUM_SLEEPS GETS_DIFF MUTEX_TYPE IDN HASH VAL GET_LOCATION mutex_addr OBJECT_NAME
---------- -------------- --------------- ---------- ---------- ---------------- --------------------------------- -------------------- -----------------
7 186297 Library Cache 3153 0000009700000000 kglhdgn1 62 0000000073BFB440 (name not found)
4 Library Cache 3153 0000001500000000 kglhdgn1 62 0000000073BFB440 (name not found)
2 Library Cache 3153 000000A200000000 kglhdgn1 62 0000000073BFB440 (name not found)
2 Library Cache 3153 0000001B00000000 kglhdgn1 62 0000000073BFB440 (name not found)
2 86887 Library Cache 3153 0000009900000000 kglhdgn1 62 0000000073BFB440 (name not found)
1 Library Cache 3153 0000019A00000000 kglhdgn1 62 0000000073BFB440 (name not found)
1 Library Cache 3153 00 kglhdgn1 62 0000000073BFB440 (name not found)
1 Library Cache 3153 0000001A00000000 kglhdgn1 62 0000000073BFB440 (name not found)
8 rows selected.
--//理论P2RAW=0000019B00000000应该很多，实际上很少，因为查询x$mutex_sleep_history记录不再sleeps累积，而是记录流水账。
--//mutex_addr=0000000073BFB440，就是library cache bucket地址。
--//0x0000000073BFB440-0x10 = 0x73bfb430
SYS@book> @ opeek 73BFB430 48 0
[073BFB430, 073BFB460) = 684A3740 00000000 684A3740 00000000 00000000 00000000 009896A9 000036F1 00000C51 00000000 61858120 00000000
--//0x00000C51 = 3153, hash桶号。
SYS@book> @ sharepool/shp4 '' 1607470161
HANDLE_TYPE KGLHDADR KGLHDPAR C40 KGLHDLMD KGLHDPMD KGLHDIVC KGLOBHD0 KGLOBHD6 KGLOBHS0 KGLOBHS6 KGLOBT16 N0_6_16 N20 KGLNAHSH KGLOBT03 KGLOBT09
---------------------- ---------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------------- ---------------- ---------- ---------- ---------- --------- ---------- ---------- ------------- ----------
child handle address 0000000065CDA030 00000000684A3740 select count(*) from t where id = :j 0 0 0 00000000619B3AF0 00000000684A2F68 8128 16176 3318 27622 27622 1607470161 3qa9k69gx032j 0
parent handle address 00000000684A3740 00000000684A3740 select count(*) from t where id = :j 0 0 0 0000000061ABB960 00 4064 0 0 4064 4064 1607470161 3qa9k69gx032j 65535
--//前面两个8字节就是该sql语句的父游标句柄地址。
5.分析library cache: mutex X等待事件：
SYS@book> @ ashtop event,p1,p2raw,p3raw "event='library cache: mutex X'" trunc(sysdate)+15/24+19/1440+19/86400 trunc(sysdate)+15/24+21/1440+03/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1 P2RAW P3RAW FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ---------------------- ---------- ----------------- ----------------- ------------------- ------------------- ---------- -------- -----------
54 .5 6% | library cache: mutex X 1607470161 0000000000000000 5FD00C5100000055 2024-11-15 15:19:22 2024-11-15 15:21:01 1 46 46
40 .4 4% | library cache: mutex X 1607470161 0000010F00000000 5FD00C5100000055 2024-11-15 15:19:21 2024-11-15 15:20:56 1 14 14
36 .3 4% | library cache: mutex X 1607470161 0000001A00000000 5FD00C5100000055 2024-11-15 15:19:23 2024-11-15 15:20:54 1 16 16
34 .3 4% | library cache: mutex X 1607470161 0000000000000000 5FD00C5100000039 2024-11-15 15:19:24 2024-11-15 15:20:55 1 28 28
30 .3 3% | library cache: mutex X 1607470161 0000002300000000 5FD00C5100000055 2024-11-15 15:19:28 2024-11-15 15:21:02 1 14 14
30 .3 3% | library cache: mutex X 1607470161 0000011200000000 5FD00C5100000055 2024-11-15 15:19:25 2024-11-15 15:20:55 1 16 16
29 .3 3% | library cache: mutex X 1607470161 0000018D00000000 5FD00C5100000055 2024-11-15 15:19:22 2024-11-15 15:20:54 1 17 17
26 .3 3% | library cache: mutex X 1607470161 0000001B00000000 5FD00C5100000055 2024-11-15 15:19:35 2024-11-15 15:20:28 1 7 7
25 .2 3% | library cache: mutex X 1607470161 0000011500000000 5FD00C5100000055 2024-11-15 15:19:49 2024-11-15 15:20:40 1 8 8
25 .2 3% | library cache: mutex X 1607470161 0000019000000000 5FD00C5100000055 2024-11-15 15:19:22 2024-11-15 15:20:59 1 16 16
24 .2 3% | library cache: mutex X 1607470161 0000001500000000 5FD00C5100000055 2024-11-15 15:19:31 2024-11-15 15:20:56 1 13 13
24 .2 3% | library cache: mutex X 1607470161 0000019A00000000 5FD00C5100000055 2024-11-15 15:19:44 2024-11-15 15:21:02 1 10 10
23 .2 3% | library cache: mutex X 1607470161 0000000000000000 5FD00C510000006A 2024-11-15 15:19:20 2024-11-15 15:20:55 15 21 15
23 .2 3% | library cache: mutex X 1607470161 0000001200000000 5FD00C5100000055 2024-11-15 15:19:22 2024-11-15 15:20:58 1 11 11
22 .2 2% | library cache: mutex X 1607470161 0000009A00000000 5FD00C5100000055 2024-11-15 15:19:29 2024-11-15 15:21:01 1 13 13
22 .2 2% | library cache: mutex X 1607470161 000000A200000000 5FD00C5100000055 2024-11-15 15:19:23 2024-11-15 15:20:56 1 14 14
20 .2 2% | library cache: mutex X 1607470161 0000002300000000 5FD00C510000006A 2024-11-15 15:19:23 2024-11-15 15:21:00 11 10 11
20 .2 2% | library cache: mutex X 1607470161 0000009B00000000 5FD00C5100000055 2024-11-15 15:19:30 2024-11-15 15:20:59 1 11 11
20 .2 2% | library cache: mutex X 1607470161 0000019500000000 5FD00C5100000055 2024-11-15 15:19:40 2024-11-15 15:20:54 1 14 14
17 .2 2% | library cache: mutex X 1607470161 0000009700000000 5FD00C5100000055 2024-11-15 15:19:26 2024-11-15 15:20:55 1 11 11
17 .2 2% | library cache: mutex X 1607470161 0000009900000000 5FD00C5100000055 2024-11-15 15:19:25 2024-11-15 15:21:01 1 14 14
16 .2 2% | library cache: mutex X 1607470161 0000001C00000000 5FD00C5100000055 2024-11-15 15:19:27 2024-11-15 15:21:01 1 11 11
16 .2 2% | library cache: mutex X 1607470161 0000018D00000000 5FD00C510000006A 2024-11-15 15:19:29 2024-11-15 15:21:00 10 10 10
15 .1 2% | library cache: mutex X 1607470161 0000001A00000000 5FD00C510000006A 2024-11-15 15:19:26 2024-11-15 15:20:48 11 10 11
15 .1 2% | library cache: mutex X 1607470161 0000009A00000000 5FD00C510000006A 2024-11-15 15:19:33 2024-11-15 15:20:51 9 12 9
14 .1 2% | library cache: mutex X 1607470161 0000010E00000000 5FD00C5100000055 2024-11-15 15:19:24 2024-11-15 15:20:51 1 11 11
14 .1 2% | library cache: mutex X 1607470161 0000010F00000000 5FD00C510000006A 2024-11-15 15:19:21 2024-11-15 15:20:56 10 7 10
13 .1 1% | library cache: mutex X 1607470161 0000001500000000 5FD00C510000006A 2024-11-15 15:19:25 2024-11-15 15:20:44 8 11 8
13 .1 1% | library cache: mutex X 1607470161 0000001B00000000 5FD00C510000006A 2024-11-15 15:19:35 2024-11-15 15:20:56 8 9 8
13 .1 1% | library cache: mutex X 1607470161 0000009B00000000 5FD00C510000006A 2024-11-15 15:19:25 2024-11-15 15:20:59 10 13 10
30 rows selected.
--//P3raw基本都是5FD00C51000000XX，前面8位0x5FD00C51 = 1607470161，正好等于sql语句的hash_value.
--//后面8位对应mutexprofz GET_LOCATION后面的数字。
SYS@book> @ ashtop event,p1,p3raw "event='library cache: mutex X'" trunc(sysdate)+15/24+19/1440+19/86400 trunc(sysdate)+15/24+21/1440+03/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1 P3RAW FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ---------------------- ---------- ----------------- ------------------- ------------------- ---------- -------- -----------
527 5.1 58% | library cache: mutex X 1607470161 5FD00C5100000055 2024-11-15 15:19:21 2024-11-15 15:21:02 1 100 100
246 2.4 27% | library cache: mutex X 1607470161 5FD00C510000006A 2024-11-15 15:19:20 2024-11-15 15:21:02 20 92 20
134 1.3 15% | library cache: mutex X 1607470161 5FD00C5100000039 2024-11-15 15:19:21 2024-11-15 15:21:02 1 80 80
YS@book> @ ashtop to_number(substr(p3raw,9),'xxxxxxxx') "event='library cache: mutex X'" trunc(sysdate)+15/24+19/1440+19/86400 trunc(sysdate)+15/24+21/1440+03/86400
Total Distinct Distinct Distinct
Seconds AAS %This TO_NUMBER(SUBSTR(P3RAW,9),'XXXXXXXX') FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------- ------------------- ------------------- ---------- -------- -----------
527 5.1 58% | 85 2024-11-15 15:19:21 2024-11-15 15:21:02 1 100 100
246 2.4 27% | 106 2024-11-15 15:19:20 2024-11-15 15:21:02 20 92 20
134 1.3 15% | 57 2024-11-15 15:19:21 2024-11-15 15:21:02 1 80 80
--//出现的数字是85,106,57.
SYS@book> @ mutexprofz idn,hash,loc,maddr "ts>=trunc(sysdate)+15/24+19/1440+19/86400 and ts<=trunc(sysdate)+15/24+21/1440+03/86400 and idn=1607470161"
-- 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
SUM_SLEEPS GETS_DIFF MUTEX_TYPE IDN HASH GET_LOCATION mutex_addr OBJECT_NAME
---------- -------------- --------------- ---------- ---------- --------------------------------- -------------------- ------------------------------------
19 919120 Library Cache 1607470161 1607470161 kgllkdl1 85 00000000684A3898 select count(*) from t where id = :j
17 806316 hash table 1607470161 1607470161 kkshGetNextChild [KKSHBKLOC1] 00000000684A2CD0 select count(*) from t where id = :j
8 359935 Cursor Pin 1607470161 1607470161 kkslce [KKSCHLPIN2] 00000000684A2EC0 select count(*) from t where id = :j
7 493831 Cursor Pin 1607470161 1607470161 kksLockDelete [KKSCHLPIN6] 00000000684A2EC0 select count(*) from t where id = :j
6 398527 Library Cache 1607470161 1607470161 kglhdgn2 106 00000000684A3898 select count(*) from t where id = :j
1 Library Cache 1607470161 1607470161 kgllkc1 57 00000000684A3898 select count(*) from t where id = :j
6 rows selected.
SYS@book> @ mutexprofz idn,hash,loc,maddr "ts>=trunc(sysdate)+15/24+19/1440+19/86400 and ts<=trunc(sysdate)+15/24+21/1440+03/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
SUM_SLEEPS GETS_DIFF MUTEX_TYPE IDN HASH GET_LOCATION mutex_addr OBJECT_NAME
---------- -------------- --------------- ---------- ---------- --------------------------------- -------------------- ------------------------------------
20 233346 Library Cache 3153 kglhdgn1 62 0000000073BFB440 (name not found)
19 919120 Library Cache 1607470161 1607470161 kgllkdl1 85 00000000684A3898 select count(*) from t where id = :j
17 806316 hash table 1607470161 1607470161 kkshGetNextChild [KKSHBKLOC1] 00000000684A2CD0 select count(*) from t where id = :j
15 677965 hash table 0 kkscsSearchChildList [KKSHBKLOC2] 00000000684A2DD0 (name not found)
--//补充发现遗漏行，idn=0.
8 359935 Cursor Pin 1607470161 1607470161 kkslce [KKSCHLPIN2] 00000000684A2EC0 select count(*) from t where id = :j
6 493831 Cursor Pin 1607470161 1607470161 kksLockDelete [KKSCHLPIN6] 00000000684A2EC0 select count(*) from t where id = :j
6 398527 Library Cache 1607470161 1607470161 kglhdgn2 106 00000000684A3898 select count(*) from t where id = :j
1 Library Cache 1607470161 1607470161 kgllkc1 57 00000000684A3898 select count(*) from t where id = :j
8 rows selected.
--//提醒注意21c下查询x$mutex_sleep_history记录不再sleeps累积，而是记录流水账，后面的sleeps覆盖前面的值，所以看到sleeps很
--//小。
--//这里出现的数字定位我一直不理解为什么，不知道是否理解前面执行的函数，后面的数字对应程序行号。
SYS@book> @ mutexprofz maddr,p1raw "ts>=trunc(sysdate)+15/24+19/1440+19/86400 and ts<=trunc(sysdate)+15/24+21/1440+03/86400 and idn=1607470161"
-- 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
SUM_SLEEPS GETS_DIFF MUTEX_TYPE mutex_addr P1RAW OBJECT_NAME
---------- -------------- --------------- -------------------- ---------------- -------------------------------------
20 919120 Library Cache 00000000684A3898 0000000065CDA030 select count(*) from t where id = :j
17 806316 hash table 00000000684A2CD0 00 select count(*) from t where id = :j
14 493831 Cursor Pin 00000000684A2EC0 00 select count(*) from t where id = :j
6 398527 Library Cache 00000000684A3898 00000000684A3740 select count(*) from t where id = :j
--//要想知道mutex_addr只能查询x$mutex_sleep_history。
--//理论没有P1RAW字段，应该出现3行，实际出现4行，主要原因是tpt的脚本其他字段作为group by。
--//P1RAW=0000000065CDA030,00000000684A3740分别对应sql语句的子父游标句柄。
6.看看这些mutex_addr在哪里。
SYS@book> @ fchaz 00000000684A3898
GET_LOCATION KSMCHPTR KSMCHIDX KSMCHDUR KSMCHCOM KSMCHSIZ KSMCHCLS KSMCHTYP KSMCHPAR KSMCHPTR_BEGIN KSMCHPTR_END+1
--------------------------------- ---------------- ---------- ---------- ---------------- ---------- -------- ---------- ---------------- ---------------- -----------------
SGA 00000000684A3710 1 1 KGLHD 816 recr 80 00 00000000684A3710 00000000684A3A40
SYS@book> @ fchaz 00000000684A2CD0
GET_LOCATION KSMCHPTR KSMCHIDX KSMCHDUR KSMCHCOM KSMCHSIZ KSMCHCLS KSMCHTYP KSMCHPAR KSMCHPTR_BEGIN KSMCHPTR_END+1
--------------------------------- ---------------- ---------- ---------- ---------------- ---------- -------- ---------- ---------------- ---------------- -----------------
SGA 00000000684A2710 1 1 KGLH0^5fd00c51 4096 recr 4095 0000000061ABB960 00000000684A2710 00000000684A3710
SYS@book> @ fchaz 00000000684A2EC0
GET_LOCATION KSMCHPTR KSMCHIDX KSMCHDUR KSMCHCOM KSMCHSIZ KSMCHCLS KSMCHTYP KSMCHPAR KSMCHPTR_BEGIN KSMCHPTR_END+1
--------------------------------- ---------------- ---------- ---------- ---------------- ---------- -------- ---------- ---------------- ---------------- -----------------
SGA 00000000684A2710 1 1 KGLH0^5fd00c51 4096 recr 4095 0000000061ABB960 00000000684A2710 00000000684A3710
SYS@book> @ sharepool/shp4 '' 1607470161
HANDLE_TYPE KGLHDADR KGLHDPAR C40 KGLHDLMD KGLHDPMD KGLHDIVC KGLOBHD0 KGLOBHD6 KGLOBHS0 KGLOBHS6 KGLOBT16 N0_6_16 N20 KGLNAHSH KGLOBT03 KGLOBT09
---------------------- ---------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------------- ---------------- ---------- ---------- ---------- --------- ---------- ---------- ------------- ----------
child handle address 0000000065CDA030 00000000684A3740 select count(*) from t where id = :j 0 0 0 00000000619B3AF0 00000000684A2F68 8128 16176 3318 27622 27622 1607470161 3qa9k69gx032j 0
parent handle address 00000000684A3740 00000000684A3740 select count(*) from t where id = :j 0 0 0 0000000061ABB960 00 4064 0 0 4064 4064 1607470161 3qa9k69gx032j 65535
--//从KSMCHPAR=0000000061ABB960可以发现。00000000684A2CD0，00000000684A2EC0对应的就是父游标的堆0地址。
--//前者00000000684A2CD0，对应hash table探查，loc=kkshGetNextChild [KKSHBKLOC1]。
--//后者00000000684A2EC0，对应Cursor Pin，loc=kkslce [KKSCHLPIN2]，kksLockDelete [KKSCHLPIN6] ，如果大量执行软软解析这就
--//是主要等待事件,视乎比软软解析多了1个loc定位。
SYS@book> @ opeek 00000000684A2CD0 24 0
[0684A2CD0, 0684A2CE8) = 00000000 00000000 01312D05 00000700 5FD00C51 00000000
SYS@book> @ opeek 00000000684A2EC0 24 0
[0684A2EC0, 0684A2ED8) = 00000000 00000000 01312FEC 00000FCC 5FD00C51 00000000
--//0x5FD00C51 = 1607470161
--//00000000684A3898位于父游标，KSMCHPTR_BEGIN=00000000684A3710,与父游标句柄KGLHDPAR=00000000684A3740，正好相差0x30(48字节)。
--//也就是大量软解析的主要等待事件。
--//对应Library Cache,loc=kgllkdl1 85,kglhdgn2 106,kgllkc1 57.
SYS@book> @ opeek 00000000684A3898 24 0
[0684A3898, 0684A38B0) = 00000000 00000000 02625FF9 00014AC7 5FD00C51 00000000
--// 15 677965 hash table 0 kkscsSearchChildList [KKSHBKLOC2] 00000000684A2DD0 (name not found)
SYS@book> @ fchaz 00000000684A2DD0
GET_LOCATION KSMCHPTR KSMCHIDX KSMCHDUR KSMCHCOM KSMCHSIZ KSMCHCLS KSMCHTYP KSMCHPAR KSMCHPTR_BEGIN KSMCHPTR_END+1
--------------------------------- ---------------- ---------- ---------- ---------------- ---------- -------- ---------- ---------------- ---------------- -----------------
SGA 00000000684A2710 1 1 KGLH0^5fd00c51 4096 recr 4095 0000000061ABB960 00000000684A2710 00000000684A3710
--//在父游标的堆0地址。
SYS@book> @opeek 00000000684A2DD0 24 0
[0684A2DD0, 0684A2DE8) = 00000000 00000000 01312D0C 00000844 00000000 00000000
~~~~~~~~
--//下划线位置一般记录hash_value,这里记录是0.
7.简单总结：
--//应用程序大量软解析导致的相关等待事件,主要集中在library cache:mutex X,library cache: bucket mutex X成为主要等待事件，
--//cursor: pin S，cursor: mutex S成为次要等待事件。
--//主要原因发现管理数据库就存在这类现象，许多代码视乎就是死循环，不断的连接退出，而执行代码就是1次，这样大量的sql语句都
--//是软解析。开发应该改成连接1次，小量休眠，在继续执行，另外写一个程序判断这个连接是否存在，不存在启动新连接。
--//library cache: mutex X,P3raw前8位记录sql语句 的hash_value。
--//后记：
SYS@book> @ ashtop event,p1raw,p3raw "event='cursor: pin S'" trunc(sysdate)+15/24+19/1440+19/86400 trunc(sysdate)+15/24+21/1440+03/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW P3RAW FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ----------------- ------------------- ------------------- ---------- -------- -----------
54 .5 64% | cursor: pin S 000000005FD00C51 0000000500000000 2024-11-15 15:19:23 2024-11-15 15:21:01 1 22 22
30 .3 36% | cursor: pin S 000000005FD00C51 0000000900000000 2024-11-15 15:19:23 2024-11-15 15:20:57 1 14 14
SYS@book> @ ashtop event,p1raw,p3raw "event='cursor: mutex S'" trunc(sysdate)+15/24+19/1440+19/86400 trunc(sysdate)+15/24+21/1440+03/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW P3RAW FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ----------------- ------------------- ------------------- ---------- -------- -----------
19 .2 51% | cursor: mutex S 000000005FD00C51 0000000100000000 2024-11-15 15:19:24 2024-11-15 15:19:55 1 3 3
18 .2 49% | cursor: mutex S 0000000000000000 0000000200000000 2024-11-15 15:19:26 2024-11-15 15:21:00 1 8 8
--//这里P3raw 与mutexprofz的输出记录不同，不是对应数字。
8.附上mutexprofz.sql代码：
--//在tpt的mutexprof.sql基础上做的小量修改，
$ cat mutexprofz.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_DIFF for 9999999999999
col mutexprof_sleeps head SLEEPS 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) 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
/