[20241018]21c x$mutex_sleep_history記錄的變化.txt

[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
/