[20241018]21c x$mutex_sleep_history记录的变化.txt
--//mutex很少会成为主要等待事件，如果遇到多数情况非常特别，比如bug。mutex本身和保护对象是一体的,不像latch一样有单独的
--//latch,而且mutex本身占内存也更小,mutex没有等待和持有队列,所以没有排队机制,mutex具有共享和排它两种模式.
--//正是mutex的特点，很分散，oracle使用x$mutex_sleep_history记录(某个内存区域)，即使get数量很高，只要不进入sleep状态，就
--//不会记录。而且一旦进入sleep将其值，sleeps数量，gets数量一并，我以前自己写的脚本有问题，采用sum(gets)，sum(sleeps)显
--//示，这样无形放大gets，sleeps的数量，换一句话讲以前记录更像是流水帐。
--//今天在使用tpt里面mutexprof.sql脚本时遇到的问题，我发现里面的SLEEPS不再是累积，而是实时修改，这样mutexprof.sql的脚本
--//执行存在问题。
1.环境：
SYS@book> @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 m2.txt
DECLARE
v_pad VARCHAR2 (200);
l_count PLS_INTEGER;
BEGIN
FOR i IN 1..&&1
LOOP
--EXECUTE IMMEDIATE 'select pad from t where id = :j ' INTO v_pad USING i;
--EXECUTE IMMEDIATE 'select count(distinct pad) from t where id = :j ' INTO l_count USING i;
--EXECUTE IMMEDIATE 'select count(*) from t where id = :j ' INTO l_count USING i;
SELECT COUNT(*) INTO L_COUNT FROM T WHERE ID = 1 ;
END LOOP;
END;
/
--//PL SQL的里面sql语句自动转换成大写执行。
$ cat m3.txt
column p1 noprint
column p2 noprint
column p3 noprint
column p4 noprint
column p5 noprint
column p1raw noprint
column MUTEX_TYPE format a13
select * from x$mutex_sleep_history where mutex_identifier=287837530;
SCOTT@book01p> SELECT COUNT(*) FROM T WHERE ID = 1 ;
COUNT(*)
----------
1
SCOTT@book01p> @ hash
HASH_VALUE SQL_ID CHILD_NUMBER KGL_BUCKET PLAN_HASH_VALUE HASH_HEX SQL_EXEC_START SQL_EXEC_ID
---------- ------------- ------------ ---------- --------------- ---------- ------------------- -----------
287837530 5mr67th8kh3au 1 3418 916843435 11280d5a 2024-10-18 16:14:38 19771968
--//记下sql=5mr67th8kh3au，hash_value=287837530，然后避开其他因素，我重启数据库测试。
3.测试：
$ \zzdate;seq 20 | xargs -IQ -P 20 sqlplus scott/book@book01p @ m1.txt 1e6 > /dev/null;\zzdate
trunc(sysdate)+16/24+20/1440+47/86400 == 2024/10/18 16:20:47 === 2024-10-18 16:20:47== "timestamp'2024-10-18 16:20:47'"
trunc(sysdate)+16/24+22/1440+07/86400 == 2024/10/18 16:22:07 === 2024-10-18 16:22:07== "timestamp'2024-10-18 16:22:07'"
SYS@book> @ m3.txt
ADDR INDX INST_ID CON_ID MUTEX_ADDR MUTEX_IDENTIFIER SLEEP_TIMESTAMP MUTEX_TYPE MUTEX_TYPE_ID GETS SLEEPS REQUESTING_SESSION BLOCKING_SESSION LOCATION_ID LOCATION MUTEX_VALUE
---------------- ---- ------- ------ ---------------- ---------------- -------------------------- ---------- ------------- -------- ------ ------------------ ---------------- ----------- ------------------------------ ----------------
00007FBA49A99B28 9 1 0 00000000649AD2B8 287837530 2024-10-18 16:22:06.906324 Cursor Pin 7 39844604 1 151 281 9 kksLockDelete [KKSCHLPIN6] 0000011900000004
00007FBA49A99C60 10 1 0 00000000649AD2B8 287837530 2024-10-18 16:22:06.871089 Cursor Pin 7 39828068 1 150 26 3 kksfbc [KKSCHLFSP2] 0000001A00000001
00007FBA49A99D98 11 1 0 00000000649AD2B8 287837530 2024-10-18 16:22:06.973587 Cursor Pin 7 39876924 1 149 398 9 kksLockDelete [KKSCHLPIN6] 0000018E00000004
00007FBA49A99ED0 12 1 0 00000000649AD2B8 287837530 2024-10-18 16:22:05.974210 Cursor Pin 7 39381458 1 148 398 9 kksLockDelete [KKSCHLPIN6] 0000018E00000008
00007FBA49A9A008 13 1 0 00000000649AD2B8 287837530 2024-10-18 16:22:06.503297 Cursor Pin 7 39646099 1 147 29 9 kksLockDelete [KKSCHLPIN6] 0000001D00000006
00007FBA49A998B8 20 1 0 00000000649AD2B8 287837530 2024-10-18 16:22:07.248338 Cursor Pin 7 39985982 1 281 26 3 kksfbc [KKSCHLFSP2] 0000001A00000001
00007FBA49A999F0 21 1 0 00000000649AD2B8 287837530 2024-10-18 16:22:05.926493 Cursor Pin 7 39356946 1 280 148 9 kksLockDelete [KKSCHLPIN6] 000000940000000C
00007FBA49A99B28 22 1 0 00000000649AD2B8 287837530 2024-10-18 16:22:05.974183 Cursor Pin 7 39381458 1 279 398 3 kksfbc [KKSCHLFSP2] 0000018E00000008
00007FBA49A99C60 23 1 0 00000000649AD2B8 287837530 2024-10-18 16:22:06.659299 Cursor Pin 7 39723202 1 278 29 9 kksLockDelete [KKSCHLPIN6] 0000001D00000008
00007FBA49A99D98 24 1 0 00000000649AD2B8 287837530 2024-10-18 16:22:07.278975 Cursor Pin 7 39992938 1 277 26 3 kksfbc [KKSCHLFSP2] 0000001A00000000
00007FBA49A99B28 33 1 0 00000000649AD2B8 287837530 2024-10-18 16:22:06.906319 Cursor Pin 7 39844604 1 403 281 3 kksfbc [KKSCHLFSP2] 0000011900000004
00007FBA49A99C60 34 1 0 00000000649AD2B8 287837530 2024-10-18 16:22:04.246499 Cursor Pin 7 38504224 2 402 150 9 kksLockDelete [KKSCHLPIN6] 000000960000000C
00007FBA49A99D98 35 1 0 00000000649AD2B8 287837530 2024-10-18 16:22:06.472489 Cursor Pin 7 39631542 1 401 29 3 kksfbc [KKSCHLFSP2] 0000001D00000006
00007FBA49A99ED0 36 1 0 00000000649AD2B8 287837530 2024-10-18 16:22:05.140514 Cursor Pin 7 38959831 1 399 149 9 kksLockDelete [KKSCHLPIN6] 000000950000000E
00007FBA49A9A008 37 1 0 00000000649AD2B8 287837530 2024-10-18 16:22:07.056237 Cursor Pin 7 39917943 1 398 149 9 kksLockDelete [KKSCHLPIN6] 0000009500000004
00007FBA49A999F0 58 1 0 00000000649AD2B8 287837530 2024-10-18 16:22:06.786873 Cursor Pin 7 39786415 1 29 0 9 kksLockDelete [KKSCHLPIN6] 0000000000000005
00007FBA49A99B28 59 1 0 00000000649AD2B8 287837530 2024-10-18 16:22:06.104102 Cursor Pin 7 39445671 1 28 24 9 kksLockDelete [KKSCHLPIN6] 0000001800000009
00007FBA49A99C60 60 1 0 00000000649AD2B8 287837530 2024-10-18 16:22:07.236079 Cursor Pin 7 39981963 1 26 281 3 kksfbc [KKSCHLFSP2] 0000011900000002
00007FBA49A99D98 61 1 0 00000000649AD2B8 287837530 2024-10-18 16:22:05.623212 Cursor Pin 7 39204684 1 25 0 9 kksLockDelete [KKSCHLPIN6] 0000000000000010
00007FBA49A99ED0 62 1 0 00000000649AD2B8 287837530 2024-10-18 16:22:06.755218 Cursor Pin 7 39771165 1 24 277 3 kksfbc [KKSCHLFSP2] 0000011500000005
20 rows selected.
--//正好20个行，感觉应该出现40行才对，估计运行时间不够。
--//注意看sleeps列，仅仅出现1，2数值，而只有gets列是累积增加的。我没有按照SLEEP_TIMESTAMP排序。
--//而且看SLEEP_TIMESTAMP时间，基本接近程序结束的时间2024/10/18 16:22:07。
--//换一句话将以前x$mutex_sleep_history记录的信息更像是流水账，而现在实时更新里面的信息。
--//顺便提一下我以前自己写的脚本有问题，采用sum(gets)，sum(sleeps)，这样无形放大了gets，sleeps的数量。
--//再次运行测试：
$ \zzdate;seq 20 | xargs -IQ -P 20 sqlplus scott/book@book01p @ m1.txt 1e6 > /dev/null;\zzdate
trunc(sysdate)+16/24+31/1440+31/86400 == 2024/10/18 16:31:31 === 2024-10-18 16:31:31== "timestamp'2024-10-18 16:31:31'"
trunc(sysdate)+16/24+32/1440+51/86400 == 2024/10/18 16:32:51 === 2024-10-18 16:32:51== "timestamp'2024-10-18 16:32:51'"
SYS@book> @ m3.txt
ADDR INDX INST_ID CON_ID MUTEX_ADDR MUTEX_IDENTIFIER SLEEP_TIMESTAMP MUTEX_TYPE MUTEX_TYPE_ID GETS SLEEPS REQUESTING_SESSION BLOCKING_SESSION LOCATION_ID LOCATION MUTEX_VALUE
---------------- ---- ------- ------ ---------------- ---------------- -------------------------- ---------- ------------- -------- ------ ------------------ ---------------- ----------- ------------------------------ ----------------
00007FBA49A999F0 9 1 0 00000000649AD2B8 287837530 2024-10-18 16:32:50.272496 Cursor Pin 7 79622561 1 152 282 3 kksfbc [KKSCHLFSP2] 0000011A0000000A
00007FBA49A99B28 10 1 0 00000000649AD2B8 287837530 2024-10-18 16:32:50.533450 Cursor Pin 7 79753891 1 151 29 3 kksfbc [KKSCHLFSP2] 0000001D00000006
00007FBA49A99C60 11 1 0 00000000649AD2B8 287837530 2024-10-18 16:32:51.204528 Cursor Pin 7 80011129 1 150 280 3 kksfbc [KKSCHLFSP2] 0000011800000001
00007FBA49A99D98 12 1 0 00000000649AD2B8 287837530 2024-10-18 16:22:06.973587 Cursor Pin 7 39876924 1 149 398 9 kksLockDelete [KKSCHLPIN6] 0000018E00000004
00007FBA49A99ED0 13 1 0 00000000649AD2B8 287837530 2024-10-18 16:32:50.737053 Cursor Pin 7 79853824 1 148 280 9 kksLockDelete [KKSCHLPIN6] 0000011800000006
00007FBA49A9A008 14 1 0 00000000649AD2B8 287837530 2024-10-18 16:32:50.419470 Cursor Pin 7 79697742 1 147 278 9 kksLockDelete [KKSCHLPIN6] 0000011600000009
00007FBA49A99780 21 1 0 00000000649AD2B8 287837530 2024-10-18 16:32:50.674697 Cursor Pin 7 79824064 1 282 148 3 kksfbc [KKSCHLFSP2] 0000009400000007
00007FBA49A998B8 22 1 0 00000000649AD2B8 287837530 2024-10-18 16:32:49.972562 Cursor Pin 7 79471290 2 281 29 9 kksLockDelete [KKSCHLPIN6] 0000001D0000000A
00007FBA49A999F0 23 1 0 00000000649AD2B8 287837530 2024-10-18 16:32:51.140114 Cursor Pin 7 79995303 1 280 150 9 kksLockDelete [KKSCHLPIN6] 0000009600000002
00007FBA49A99B28 24 1 0 00000000649AD2B8 287837530 2024-10-18 16:32:50.456973 Cursor Pin 7 79716120 1 279 282 9 kksLockDelete [KKSCHLPIN6] 0000011A00000006
00007FBA49A99C60 25 1 0 00000000649AD2B8 287837530 2024-10-18 16:32:50.904891 Cursor Pin 7 79929552 1 278 280 3 kksfbc [KKSCHLFSP2] 0000011800000002
00007FBA49A99D98 26 1 0 00000000649AD2B8 287837530 2024-10-18 16:22:07.278975 Cursor Pin 7 39992938 1 277 26 3 kksfbc [KKSCHLFSP2] 0000001A00000000
00007FBA49A999F0 35 1 0 00000000649AD2B8 287837530 2024-10-18 16:32:49.545363 Cursor Pin 7 79259791 2 403 29 9 kksLockDelete [KKSCHLPIN6] 0000001D00000008
00007FBA49A99B28 36 1 0 00000000649AD2B8 287837530 2024-10-18 16:32:50.065868 Cursor Pin 7 79517951 1 402 278 3 kksfbc [KKSCHLFSP2] 0000011600000009
00007FBA49A99C60 37 1 0 00000000649AD2B8 287837530 2024-10-18 16:32:50.904885 Cursor Pin 7 79929552 1 401 280 9 kksLockDelete [KKSCHLPIN6] 0000011800000002
00007FBA49A99D98 38 1 0 00000000649AD2B8 287837530 2024-10-18 16:32:50.815225 Cursor Pin 7 79891822 1 400 280 3 kksfbc [KKSCHLFSP2] 0000011800000004
00007FBA49A99ED0 39 1 0 00000000649AD2B8 287837530 2024-10-18 16:32:49.844326 Cursor Pin 7 79407915 1 399 402 9 kksLockDelete [KKSCHLPIN6] 000001920000000B
00007FBA49A9A008 40 1 0 00000000649AD2B8 287837530 2024-10-18 16:22:07.056237 Cursor Pin 7 39917943 1 398 149 9 kksLockDelete [KKSCHLPIN6] 0000009500000004
00007FBA49A998B8 62 1 0 00000000649AD2B8 287837530 2024-10-18 16:32:50.491494 Cursor Pin 7 79732732 1 29 152 9 kksLockDelete [KKSCHLPIN6] 0000009800000008
00007FBA49A999F0 63 1 0 00000000649AD2B8 287837530 2024-10-18 16:32:49.545387 Cursor Pin 7 79259791 1 28 29 9 kksLockDelete [KKSCHLPIN6] 0000001D00000008
00007FBA49A99B28 64 1 0 00000000649AD2B8 287837530 2024-10-18 16:32:50.814495 Cursor Pin 7 79891456 1 27 0 9 kksLockDelete [KKSCHLPIN6] 0000000000000004
00007FBA49A99C60 65 1 0 00000000649AD2B8 287837530 2024-10-18 16:22:07.236079 Cursor Pin 7 39981963 1 26 281 3 kksfbc [KKSCHLFSP2] 0000011900000002
00007FBA49A99D98 66 1 0 00000000649AD2B8 287837530 2024-10-18 16:32:49.413471 Cursor Pin 7 79194407 1 25 279 3 kksfbc [KKSCHLFSP2] 0000011700000009
00007FBA49A99ED0 67 1 0 00000000649AD2B8 287837530 2024-10-18 16:32:48.393100 Cursor Pin 7 78680357 1 24 28 3 kksfbc [KKSCHLFSP2] 0000001C0000000D
24 rows selected.
--//看SLEEP_TIMESTAMP时间,正是接近结束的时间2024/10/18 16:32:51。
--//这样tpt的mutexprof.sql脚本有点不再适用。
SYS@book> @ mutexprof id,loc "id=287837530"
-- MutexProf by Tanel Poder (http://www.tanelpoder.com)
-- Showing profile of top 20 sleeps...
SLEEPS SLEEPS MUTEX_TYPE ID GET_LOCATION OBJECT_NAME
---------- ------- --------------- ---------- --------------------------------- --------------------------------------------
2 1 Cursor Pin 287837530 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 kksfbc [KKSCHLFSP2] SELECT COUNT(*) FROM T WHERE ID = 1
--//看到sleeps仅仅2，1.我当时仅仅觉得奇怪，并没有怀疑，当我在更加1个gets字段时，发现问题。
SYS@book> @ mutexprof id,gets,loc "id=287837530"
-- MutexProf by Tanel Poder (http://www.tanelpoder.com)
-- Showing profile of top 20 sleeps...
SLEEPS SLEEPS MUTEX_TYPE ID GETS GET_LOCATION OBJECT_NAME
---------- ------- --------------- ---------- ---------- --------------------------------- -------------------------------------
2 Cursor Pin 287837530 79471290 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
2 1 Cursor Pin 287837530 79259791 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 79622561 kksfbc [KKSCHLFSP2] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 79753891 kksfbc [KKSCHLFSP2] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 80011129 kksfbc [KKSCHLFSP2] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 39876924 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 79853824 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 79697742 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 79824064 kksfbc [KKSCHLFSP2] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 79995303 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 79716120 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 79929552 kksfbc [KKSCHLFSP2] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 39992938 kksfbc [KKSCHLFSP2] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 79517951 kksfbc [KKSCHLFSP2] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 79929552 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 79891822 kksfbc [KKSCHLFSP2] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 79407915 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 39917943 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 79732732 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 79891456 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
20 rows selected.
--//看到sleeps比前面的多，这才发现问题，21c的x$mutex_sleep_history视图记录的信息已经发生了变化，不能在使用max(sleeps)的
--//显示，这样看到也许永远时1，2，而是改写sum(sleeps),比较准确。
--//我做了修改，并且加入了mutex_addr地址显示，取消如下注解。
, decode(max(gets)-min(gets),0,to_number(null),max(gets)-min(gets)) mutexprof_gets -- may not be very accurate but give an idea
SYS@book> @ mutexprof id,loc "id=287837530"
-- MutexProf by Tanel Poder (http://www.tanelpoder.com)
-- Showing profile of top 20 sleeps...
SLEEPS SLEEPS MUTEX_TYPE ID GET_LOCATION OBJECT_NAME
---------- ------- --------------- ---------- --------------------------------- ------------------------------------
2 1 Cursor Pin 287837530 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 kksfbc [KKSCHLFSP2] SELECT COUNT(*) FROM T WHERE ID = 1
SYS@book> @ mutexprofz id,loc "id=287837530"
-- MutexProf by Tanel Poder (http://www.tanelpoder.com)
-- Showing profile of top 20 sleeps...
SUM_SLEEPS GETS MUTEX_TYPE ID GET_LOCATION OBJECT_NAME
---------- -------------- --------------- ---------- --------------------------------- -----------------------------------
15 40118379 Cursor Pin 287837530 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
11 40029166 Cursor Pin 287837530 kksfbc [KKSCHLFSP2] SELECT COUNT(*) FROM T WHERE ID = 1
--//这样看到sleeps也是仅仅作为参考，因为前面的记录已经不存在了。显示max(gets)-min(gets)也是作为参考。
--//注意看即使这样，看到的SUM_SLEEPS也是非常小，根据这个判断有可能存在问题。
SYS@book> @ mutexprofz id,gets,loc "id=287837530"
-- MutexProf by Tanel Poder (http://www.tanelpoder.com)
-- Showing profile of top 20 sleeps...
SUM_SLEEPS GETS MUTEX_TYPE ID GETS GET_LOCATION OBJECT_NAME
---------- -------------- --------------- ---------- ---------- --------------------------------- ------------------------------------
3 Cursor Pin 287837530 79259791 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
2 Cursor Pin 287837530 79471290 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 79622561 kksfbc [KKSCHLFSP2] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 79753891 kksfbc [KKSCHLFSP2] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 80011129 kksfbc [KKSCHLFSP2] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 39876924 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
1 Cursor Pin 287837530 79853824 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 79697742 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 79824064 kksfbc [KKSCHLFSP2] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 79995303 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 79716120 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 79929552 kksfbc [KKSCHLFSP2] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 39992938 kksfbc [KKSCHLFSP2] SELECT COUNT(*) FROM T WHERE ID = 1
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
1 Cursor Pin 287837530 79517951 kksfbc [KKSCHLFSP2] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 79929552 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 79891822 kksfbc [KKSCHLFSP2] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 79407915 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 39917943 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 79732732 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
1 Cursor Pin 287837530 79891456 kksLockDelete [KKSCHLPIN6] SELECT COUNT(*) FROM T WHERE ID = 1
20 rows selected.
--//第2列的gets显示为null实际是0，前面SUM_SLEEPS非常小。
--//是否可以以第2列desc排序显示，我发现也不行，看下划线行gets比其它小很多。
--//这样导致前面看到gets很多，如果没有下划线2行，第2列gets的数量会很小，也就是不能以gets的变化作为判断。
--//也许查询加入ts>= sysdate -1 /1440 之类的条件对于诊断有一定的帮助。
--//另外我加入mutex_addr列，能够具体知道mutex的位置。
SYS@book> @ mutexprofz id,maddr "id=287837530"
-- MutexProf by Tanel Poder (http://www.tanelpoder.com)
-- Showing profile of top 20 sleeps...
SUM_SLEEPS GETS MUTEX_TYPE ID mutex_addr OBJECT_NAME
---------- -------------- --------------- ---------- -------------------- --------------------------------------------------------------------------------
26 40134205 Cursor Pin 287837530 00000000649AD2B8 SELECT COUNT(*) FROM T WHERE ID = 1
SYS@book> @ fchaz 00000000649AD2B8
GET_LOCATION KSMCHPTR KSMCHIDX KSMCHDUR KSMCHCOM KSMCHSIZ KSMCHCLS KSMCHTYP KSMCHPAR KSMCHPTR_BEGIN KSMCHPTR_END+1
--------------------------------- ---------------- ---------- ---------- ---------------- ---------- -------- ---------- ---------------- ---------------- -----------------
SGA 00000000649ACB08 1 1 KGLH0^11280d5a 4096 recr 4095 00000000649ADB78 00000000649ACB08 00000000649ADB08
SYS@book> @ sharepool/shp4 '' 287837530
HANDLE_TYPE KGLHDADR KGLHDPAR C40 KGLHDLMD KGLHDPMD KGLHDIVC KGLOBHD0 KGLOBHD6 KGLOBHS0 KGLOBHS6 KGLOBT16 N0_6_16 N20 KGLNAHSH KGLOBT03 KGLOBT09
---------------------- ---------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------------- ---------------- ---------- ---------- ---------- --------- ---------- ---------- ------------- ----------
child handle address 00000000649AC5D8 00000000649ADD38 SELECT COUNT(*) FROM T WHERE ID = 1 0 0 0 00000000649AC418 00000000649AD360 8128 12128 3301 23557 23557 287837530 5mr67th8kh3au 0
parent handle address 00000000649ADD38 00000000649ADD38 SELECT COUNT(*) FROM T WHERE ID = 1 0 0 0 00000000649ADB78 00 4064 0 0 4064 4064 287837530 5mr67th8kh3au 65535
SYS@book> @ ksmsp 00000000649ADB78 ''
GET_LOCATION KSMCHPTR KSMCHIDX KSMCHDUR KSMCHCOM KSMCHSIZ KSMCHCLS KSMCHTYP KSMCHPAR KSMCHPTR_BEGIN KSMCHPTR_END+1 HEAP_DESC
--------------------------------- ---------------- ---------- ---------- ---------------- ---------- -------- ---------- ---------------- ---------------- ----------------- -------------------------
SGA 00000000649ADB08 1 1 KGLDA 512 freeabl 0 00 00000000649ADB08 00000000649ADD08
SGA 00000000649ACB08 1 1 KGLH0^11280d5a 4096 recr 4095 00000000649ADB78 00000000649ACB08 00000000649ADB08 KSMCHPAR=00000000649ADB78
--//可以发现mutex_addr=00000000649AD2B8在父堆0里面。
SYS@book> select max(gets) from x$mutex_sleep_history where MUTEX_IDENTIFIER =287837530;
MAX(GETS)
----------
80011129
--//80011129 = 0x4c4df79
SYS@book> @ opeek 00000000649AD2B8 32 1
New tracefile_identifier = /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_4208_0001.trc
Statement processed.
[0649AD2B8, 0649AD2D8) = 00000000 00000000 04C55EAC 0000D2E8 11280D5A 00000000 00000000 00000000
--//而现在记录在mutex结构里面的明显是x04C55EAC = 80043692。不知道那个是sleep字段，以前的可以猜测出来。
--//而记录在x$mutex_sleep是汇总信息。
SYS@book> select * from x$mutex_sleep;
ADDR INDX INST_ID CON_ID MUTEX_TYPE MUTEX_TYPE_ID LOCATION_ID LOCATION SLEEPS WAIT_TIME
---------------- ---------- ---------- ---------- ------------- ------------- ----------- ------------------------------ ---------- ----------
00007FBA495BEF58 0 1 0 Row Cache 3 19 [19] kqrpre 1 2124
00007FBA495BEFF0 1 1 0 Row Cache 3 14 [14] kqrScan 1 10
00007FBA495BF088 2 1 0 Row Cache 3 10 [10] kqreqd 1 4
00007FBA495BED90 3 1 0 Library Cache 4 119 kglUpgradeLock 119 1 27
00007FBA495BEE28 4 1 0 Library Cache 4 106 kglhdgn2 106 1 8
00007FBA495BEEC0 5 1 0 Library Cache 4 90 kglpnal1 90 1 6
00007FBA495BEF58 6 1 0 Library Cache 4 57 kgllkc1 57 1 10
00007FBA495BEFF0 7 1 0 Library Cache 4 4 kglpin1 4 1 10
00007FBA495BF088 8 1 0 Library Cache 4 2 kglget2 2 1 695
00007FBA495BEF58 9 1 0 Cursor Pin 7 9 kksLockDelete [KKSCHLPIN6] 35250 524978637
00007FBA495BEFF0 10 1 0 Cursor Pin 7 5 kkslce [KKSCHLPIN2] 191 543489
00007FBA495BF088 11 1 0 Cursor Pin 7 3 kksfbc [KKSCHLFSP2] 18728 282584102
12 rows selected.
--//D2E8 = 53992
--//35250+18728 = 317816 = 0x4d978,我记忆sleeps记录仅仅2个字节，前面的4溢出。
SYS@book> oradebug poke 0x00000000649AD2B8 8 0x0000012700000127
ORA-32519: insufficient privileges to execute ORADEBUG command: execution of ORADEBUG commands is disabled for this instance
SYS@book01p> @ ashtop event,sid,sql_id,p1hex,p2hex,p3hex "event like 'cursor%'" trunc(sysdate)+16/24+31/1440+31/86400 trunc(sysdate)+16/24+32/1440+51/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT SID SQL_ID P1HEX P2HEX P3HEX FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------- ------ ------------- ----------------- ----------------- ----------------- ------------------- ------------------- ---------- -------- -----------
2 .0 0% | cursor: pin S 25 0000000011280D5A 0000011A0000000E 0000000900000000 2024-10-18 16:32:17 2024-10-18 16:32:31 1 2 2
2 .0 0% | cursor: pin S 25 0000000011280D5A 000001900000000F 0000000900000000 2024-10-18 16:32:23 2024-10-18 16:32:34 1 2 2
2 .0 0% | cursor: pin S 147 5mr67th8kh3au 0000000011280D5A 000001910000000D 0000000300000000 2024-10-18 16:32:23 2024-10-18 16:32:40 1 2 2
2 .0 0% | cursor: pin S 148 5mr67th8kh3au 0000000011280D5A 0000001D00000008 0000000300000000 2024-10-18 16:32:49 2024-10-18 16:32:50 1 2 2
2 .0 0% | cursor: pin S 151 0000000011280D5A 0000011A0000000E 0000000900000000 2024-10-18 16:32:17 2024-10-18 16:32:31 1 2 2
2 .0 0% | cursor: pin S 152 0000000011280D5A 0000011A0000000E 0000000900000000 2024-10-18 16:32:17 2024-10-18 16:32:31 1 2 2
2 .0 0% | cursor: pin S 278 0000000011280D5A 000000980000000F 0000000900000000 2024-10-18 16:31:34 2024-10-18 16:32:00 1 2 2
2 .0 0% | cursor: pin S 278 0000000011280D5A 0000011A0000000E 0000000900000000 2024-10-18 16:32:17 2024-10-18 16:32:31 1 2 2
2 .0 0% | cursor: pin S 279 0000000011280D5A 0000011A0000000E 0000000900000000 2024-10-18 16:32:17 2024-10-18 16:32:31 1 2 2
2 .0 0% | cursor: pin S 279 0000000011280D5A 000001900000000A 0000000900000000 2024-10-18 16:32:04 2024-10-18 16:32:16 1 2 2
2 .0 0% | cursor: pin S 400 5mr67th8kh3au 0000000011280D5A 0000011A0000000E 0000000300000000 2024-10-18 16:32:26 2024-10-18 16:32:31 1 2 2
2 .0 0% | cursor: pin S 400 0000000011280D5A 000000970000000C 0000000900000000 2024-10-18 16:32:39 2024-10-18 16:32:48 1 2 2
2 .0 0% | cursor: pin S 401 0000000011280D5A 000000930000000D 0000000900000000 2024-10-18 16:31:55 2024-10-18 16:32:27 1 2 2
2 .0 0% | cursor: pin S 401 0000000011280D5A 0000011600000010 0000000900000000 2024-10-18 16:32:15 2024-10-18 16:32:34 1 2 2
2 .0 0% | cursor: pin S 402 0000000011280D5A 000000000000000D 0000000900000000 2024-10-18 16:32:01 2024-10-18 16:32:25 1 2 2
2 .0 0% | cursor: pin S 402 0000000011280D5A 0000011A0000000E 0000000900000000 2024-10-18 16:32:17 2024-10-18 16:32:31 1 2 2
2 .0 0% | cursor: pin S 403 5mr67th8kh3au 0000000011280D5A 000000180000000D 0000000300000000 2024-10-18 16:31:50 2024-10-18 16:32:11 1 2 2
1 .0 0% | cursor: pin S 24 5mr67th8kh3au 0000000011280D5A 0000001B0000000B 0000000300000000 2024-10-18 16:32:20 2024-10-18 16:32:20 1 1 1
1 .0 0% | cursor: pin S 24 5mr67th8kh3au 0000000011280D5A 0000001C00000009 0000000300000000 2024-10-18 16:31:51 2024-10-18 16:31:51 1 1 1
1 .0 0% | cursor: pin S 24 5mr67th8kh3au 0000000011280D5A 0000001C0000000F 0000000300000000 2024-10-18 16:32:12 2024-10-18 16:32:12 1 1 1
1 .0 0% | cursor: pin S 24 5mr67th8kh3au 0000000011280D5A 000000940000000A 0000000300000000 2024-10-18 16:31:44 2024-10-18 16:31:44 1 1 1
1 .0 0% | cursor: pin S 24 5mr67th8kh3au 0000000011280D5A 000001180000000C 0000000300000000 2024-10-18 16:31:43 2024-10-18 16:31:43 1 1 1
1 .0 0% | cursor: pin S 24 5mr67th8kh3au 0000000011280D5A 0000011A0000000E 0000000300000000 2024-10-18 16:32:17 2024-10-18 16:32:17 1 1 1
1 .0 0% | cursor: pin S 24 5mr67th8kh3au 0000000011280D5A 0000011A0000000F 0000000300000000 2024-10-18 16:32:26 2024-10-18 16:32:26 1 1 1
1 .0 0% | cursor: pin S 24 5mr67th8kh3au 0000000011280D5A 000001910000000C 0000000300000000 2024-10-18 16:31:50 2024-10-18 16:31:50 1 1 1
1 .0 0% | cursor: pin S 24 0000000011280D5A 000000190000000D 0000000900000000 2024-10-18 16:32:27 2024-10-18 16:32:27 1 1 1
1 .0 0% | cursor: pin S 24 0000000011280D5A 0000001B0000000A 0000000900000000 2024-10-18 16:31:52 2024-10-18 16:31:52 1 1 1
1 .0 0% | cursor: pin S 24 0000000011280D5A 0000001C0000000D 0000000900000000 2024-10-18 16:32:14 2024-10-18 16:32:14 1 1 1
1 .0 0% | cursor: pin S 24 0000000011280D5A 0000001D00000012 0000000900000000 2024-10-18 16:31:54 2024-10-18 16:31:54 1 1 1
1 .0 0% | cursor: pin S 24 0000000011280D5A 000000940000000F 0000000900000000 2024-10-18 16:31:46 2024-10-18 16:31:46 1 1 1
30 rows selected.
--//也许使用ashtop更好分析诊断。
SYS@book01p> @ ashtop event 1=1 trunc(sysdate)+16/24+31/1440+31/86400 trunc(sysdate)+16/24+32/1440+51/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ------------------- ------------------- ---------- -------- -----------
1052 13.2 68% | 2024-10-18 16:31:31 2024-10-18 16:32:50 572 80 647
503 6.3 32% | cursor: pin S 2024-10-18 16:31:33 2024-10-18 16:32:50 1 74 74
2 .0 0% | log file sync 2024-10-18 16:31:31 2024-10-18 16:31:31 1 1 1
1 .0 0% | library cache lock 2024-10-18 16:31:31 2024-10-18 16:31:31 1 1 1
4.附上我修改的脚本：
$ 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 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...
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
, 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
/