[20250211]更正11g x$mutex_sleep_history记录的一些疑问.txt
[20250211]更正11g x$mutex_sleep_history记录的一些疑问.txt
--//在11g下测试遇到的问题,看了以前的链接:[20241018]21c x$mutex_sleep_history记录的变化.txt,实际上当时自己的理解也存在
--//错误,有必要在11g下重复验证自己以前混乱的概念。
--//实际上第一次学习就存在遇到这个问题,将自己写的脚本将gets,sleeps数量做sum汇总,当时就发生gets数量不对,想当然认为
--//sleeps数量也是类似情况,实际上gets数量理解是对的,但是sleeps的理解是错误的,还有一些理解不对的地方,通过真实的例子说
--//明问题。
1.环境:
SCOTT@book> @ver1
PORT_STRING VERSION BANNER
------------------- ---------- ----------------------------------------------------------------------------
x86_64/Linux 2.4.xx 11.2.0.4.0 Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
2.测试环境建立:
drop table t purge ;
create table t as select rownum id ,'test' pad from dual connect by level<=2e5;
create unique index pk_t on t(id);
exec dbms_stats.gather_table_stats(user, 't', method_opt=>'for all columns size 1');
$ cat 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 MUTEX_ADDR,MUTEX_IDENTIFIER,SLEEP_TIMESTAMP,MUTEX_TYPE,GETS,
SLEEPS,REQUESTING_SESSION,BLOCKING_SESSION,LOCATION,MUTEX_VALUE
FROM x$mutex_sleep_history
WHERE mutex_identifier = 287837530
ORDER BY SLEEP_TIMESTAMP;
--//注意设置按SLEEP_TIMESTAMP排序,便于后面观察。
SCOTT@book> SELECT COUNT(*) FROM T WHERE ID = 1 ;
COUNT(*)
----------
1
SCOTT@book> @ 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 2025-02-11 09:09:58 19849416
--//记下sql=5mr67th8kh3au,hash_value=287837530,然后避开其他因素,重启数据库测试。
3.测试:
$ zzdate;seq 10 | xargs -IQ -P 10 sqlplus scott/book @ m2.txt 1e6 > /dev/null;zzdate
trunc(sysdate)+10/24+53/1440+35/86400 -1739242415.181859957
trunc(sysdate)+10/24+54/1440+14/86400 1739242454.048513370
--//在执行过程中执行m3.txt.
SYS@book> @ m3.txt
no rows selected
SYS@book> @ m3.txt
MUTEX_ADDR MUTEX_IDENTIFIER SLEEP_TIMESTAMP MUTEX_TYPE GETS SLEEPS REQUESTING_SESSION BLOCKING_SESSION LOCATION MUTEX_VALUE
---------------- ---------------- -------------------------- ---------- -------- ------ ------------------ ---------------- -------------------------- ----------------
00000000877906C8 287837530 2025-02-11 10:53:37.062648 Cursor Pin 760418 22 12 10 kksLockDelete [KKSCHLPIN6] 0000000A00000004
00000000877906C8 287837530 2025-02-11 10:53:37.321700 Cursor Pin 898059 41 135 199 kksfbc [KKSCHLFSP2] 000000C700000004
00000000877906C8 287837530 2025-02-11 10:53:37.321706 Cursor Pin 898059 32 133 199 kksfbc [KKSCHLFSP2] 000000C700000004
00000000877906C8 287837530 2025-02-11 10:53:37.351523 Cursor Pin 913868 41 197 135 kksLockDelete [KKSCHLPIN6] 0000008700000006
00000000877906C8 287837530 2025-02-11 10:53:37.351534 Cursor Pin 913868 34 195 135 kksfbc [KKSCHLFSP2] 0000008700000006
00000000877906C8 287837530 2025-02-11 10:53:37.351541 Cursor Pin 913870 49 69 135 kksfbc [KKSCHLFSP2] 0000000000000004
00000000877906C8 287837530 2025-02-11 10:53:37.360631 Cursor Pin 918601 17 10 133 kksLockDelete [KKSCHLPIN6] 0000000000000005
00000000877906C8 287837530 2025-02-11 10:53:37.360633 Cursor Pin 918599 27 8 133 kksfbc [KKSCHLFSP2] 0000008500000004
00000000877906C8 287837530 2025-02-11 10:53:37.360634 Cursor Pin 918599 35 199 133 kksfbc [KKSCHLFSP2] 0000008500000004
00000000877906C8 287837530 2025-02-11 10:53:37.360653 Cursor Pin 918600 55 71 133 kksfbc [KKSCHLFSP2] 0000000000000004
10 rows selected.
SYS@book> @ m3.txt
MUTEX_ADDR MUTEX_IDENTIFIER SLEEP_TIMESTAMP MUTEX_TYPE GETS SLEEPS REQUESTING_SESSION BLOCKING_SESSION LOCATION MUTEX_VALUE
---------------- ---------------- -------------------------- ---------- -------- ------ ------------------ ---------------- -------------------------- ----------------
00000000877906C8 287837530 2025-02-11 10:54:02.083479 Cursor Pin 13950008 469 8 195 kksLockDelete [KKSCHLPIN6] 0000000000000006
00000000877906C8 287837530 2025-02-11 10:54:02.184960 Cursor Pin 14003353 503 69 199 kksLockDelete [KKSCHLPIN6] 000000C700000007
00000000877906C8 287837530 2025-02-11 10:54:02.260661 Cursor Pin 14043662 458 133 8 kksfbc [KKSCHLFSP2] 0000000800000005
00000000877906C8 287837530 2025-02-11 10:54:02.260662 Cursor Pin 14043662 436 12 8 kksfbc [KKSCHLFSP2] 0000000800000005
00000000877906C8 287837530 2025-02-11 10:54:02.260663 Cursor Pin 14043663 450 197 8 kksLockDelete [KKSCHLPIN6] 0000000000000005
00000000877906C8 287837530 2025-02-11 10:54:02.314660 Cursor Pin 14072550 528 71 135 kksLockDelete [KKSCHLPIN6] 0000008700000007
00000000877906C8 287837530 2025-02-11 10:54:02.346910 Cursor Pin 14089645 534 135 71 kksfbc [KKSCHLFSP2] 0000004700000008
00000000877906C8 287837530 2025-02-11 10:54:02.346916 Cursor Pin 14089645 436 195 71 kksLockDelete [KKSCHLPIN6] 0000004700000008
00000000877906C8 287837530 2025-02-11 10:54:02.346924 Cursor Pin 14089645 415 199 71 kksLockDelete [KKSCHLPIN6] 0000004700000008
00000000877906C8 287837530 2025-02-11 10:54:02.346924 Cursor Pin 14089647 452 10 71 kksfbc [KKSCHLFSP2] 0000000000000007
10 rows selected.
--//全部结束后,执行如下:
SYS@book> @ m3.txt
MUTEX_ADDR MUTEX_IDENTIFIER SLEEP_TIMESTAMP MUTEX_TYPE GETS SLEEPS REQUESTING_SESSION BLOCKING_SESSION LOCATION MUTEX_VALUE
---------------- ---------------- -------------------------- ---------- -------- ------ ------------------ ---------------- -------------------------- ----------------
00000000877906C8 287837530 2025-02-11 10:54:11.936582 Cursor Pin 19142324 705 135 12 kksLockDelete [KKSCHLPIN6] 0000000000000006
00000000877906C8 287837530 2025-02-11 10:54:12.276535 Cursor Pin 19317941 595 197 69 kksfbc [KKSCHLFSP2] 0000004500000006
00000000877906C8 287837530 2025-02-11 10:54:12.569631 Cursor Pin 19471875 662 69 195 kksfbc [KKSCHLFSP2] 0000000000000003
00000000877906C8 287837530 2025-02-11 10:54:12.703461 Cursor Pin 19541631 633 12 133 kksfbc [KKSCHLFSP2] 0000000000000005
00000000877906C8 287837530 2025-02-11 10:54:12.709637 Cursor Pin 19544898 694 71 195 kksLockDelete [KKSCHLPIN6] 0000000000000004
00000000877906C8 287837530 2025-02-11 10:54:13.054674 Cursor Pin 19724415 601 195 10 kksfbc [KKSCHLFSP2] 0000000A00000002
00000000877906C8 287837530 2025-02-11 10:54:13.141620 Cursor Pin 19770180 643 8 195 kksfbc [KKSCHLFSP2] 000000C300000003
00000000877906C8 287837530 2025-02-11 10:54:13.575564 Cursor Pin 19931013 641 10 199 kksfbc [KKSCHLFSP2] 000000C700000000
00000000877906C8 287837530 2025-02-11 10:54:13.575566 Cursor Pin 19931013 671 133 199 kksfbc [KKSCHLFSP2] 000000C700000000
00000000877906C8 287837530 2025-02-11 10:54:13.587096 Cursor Pin 19933718 607 199 0 kksfbc [KKSCHLFSP2] 00
--//Sum = 6452
10 rows selected.
--//gets记录的最大值是19933718。
--//仔细gets的变化顺着SLEEP_TIMESTAMP变化,不断累积的。
SYS@book> @ opeek 00000000877906C8 24 0
[0877906C8, 0877906E0) = 00000000 00000000 01312D00 00001934 11280D5A 00000000
--//0x11280D5A = 287837530,正好等于bucket桶号,也就是hash_value.
--//gets 0x01312D00 = 20000000,总共执行10*1000000 = 10000000,有2个LOCATION出现kksLockDelete [KKSCHLPIN6],kksfbc [KKSCHLFSP2] 。
--//这样gets=执行次数*2,完全能对上。而m3.txt脚本查询最大的gets=19933718,因为后面没有sleeps,就不做记录,与20000000非常接近。
--//sleeps =0x00001934 = 6452。将最后的输出sleeps结果累积
--//705+595+662+633+694+601+643+641+671+607 = 6452,正好等于opeek.sql脚本输出看到的结果。
--//另外注意输出的记录每次都是10行,说明10个会话在执行(我以前的理解存在错误),实际上相当于取样每个REQUESTING_SESSION,对于每个
--//REQUESTING_SESSION讲sleeps的次数是不断累积的,相当于snapshot当时的情况。最后sum(sleeps)就是实际sleeps的数量。
--//另外注意一个前提就是出现sleeps在x$mutex_sleep_history视图才会有记录。
--//另外注意一个细节最后一行MUTEX_VALUE=00,因为其他会话已经退出,无法抓取到MUTEX_VALUE值。
$ zzdate;seq 10 | xargs -IQ -P 10 sqlplus scott/book @ m2.txt 1e6 > /dev/null;zzdate
trunc(sysdate)+11/24+13/1440+41/86400 -1739243621.004123399
trunc(sysdate)+11/24+14/1440+22/86400 1739243662.918034260
--//注意这次执行修改m2.txt ,结尾加入host sleep 3再退出。
SYS@book> @ m3.txt
MUTEX_ADDR MUTEX_IDENTIFIER SLEEP_TIMESTAMP MUTEX_TYPE GETS SLEEPS REQUESTING_SESSION BLOCKING_SESSION LOCATION MUTEX_VALUE
---------------- ---------------- -------------------------- ---------- -------- ------ ------------------ ---------------- -------------------------- ----------------
00000000877906C8 287837530 2025-02-11 10:54:11.936582 Cursor Pin 19142324 705 135 12 kksLockDelete [KKSCHLPIN6] 0000000000000006
00000000877906C8 287837530 2025-02-11 10:54:12.276535 Cursor Pin 19317941 595 197 69 kksfbc [KKSCHLFSP2] 0000004500000006
00000000877906C8 287837530 2025-02-11 10:54:12.569631 Cursor Pin 19471875 662 69 195 kksfbc [KKSCHLFSP2] 0000000000000003
00000000877906C8 287837530 2025-02-11 10:54:12.709637 Cursor Pin 19544898 694 71 195 kksLockDelete [KKSCHLPIN6] 0000000000000004
00000000877906C8 287837530 2025-02-11 10:54:13.141620 Cursor Pin 19770180 643 8 195 kksfbc [KKSCHLFSP2] 000000C300000003
00000000877906C8 287837530 2025-02-11 10:54:13.575564 Cursor Pin 19931013 641 10 199 kksfbc [KKSCHLFSP2] 000000C700000000
00000000877906C8 287837530 2025-02-11 10:54:13.587096 Cursor Pin 19933718 607 199 0 kksfbc [KKSCHLFSP2] 00
00000000877906C8 287837530 2025-02-11 11:14:16.431549 Cursor Pin 38381754 569 73 195 kksfbc [KKSCHLFSP2] 000000C300000007
00000000877906C8 287837530 2025-02-11 11:14:16.912629 Cursor Pin 38636326 612 136 195 kksfbc [KKSCHLFSP2] 0000000000000004
00000000877906C8 287837530 2025-02-11 11:14:18.354618 Cursor Pin 39388791 658 200 12 kksLockDelete [KKSCHLPIN6] 0000000C00000008
00000000877906C8 287837530 2025-02-11 11:14:18.772595 Cursor Pin 39608095 1147 12 11 kksLockDelete [KKSCHLPIN6] 0000000000000005
00000000877906C8 287837530 2025-02-11 11:14:18.878636 Cursor Pin 39664305 642 134 12 kksLockDelete [KKSCHLPIN6] 0000000000000005
00000000877906C8 287837530 2025-02-11 11:14:19.019570 Cursor Pin 39738675 643 11 70 kksLockDelete [KKSCHLPIN6] 0000004600000003
00000000877906C8 287837530 2025-02-11 11:14:19.141432 Cursor Pin 39801441 1267 195 0 kksLockDelete [KKSCHLPIN6] 0000000000000003
00000000877906C8 287837530 2025-02-11 11:14:19.426140 Cursor Pin 39913625 657 198 133 kksfbc [KKSCHLFSP2] 0000008500000001
00000000877906C8 287837530 2025-02-11 11:14:19.522707 Cursor Pin 39937671 1334 133 70 kksfbc [KKSCHLFSP2] 0000004600000001
00000000877906C8 287837530 2025-02-11 11:14:19.554008 Cursor Pin 39945620 619 70 133 kksLockDelete [KKSCHLPIN6] 0000000000000002
--//Sum = 12695
17 rows selected.
--//这次看到不是10行正常的,因为sid发生了变化,前面SLEEP_TIMESTAMP=2025-02-11 10:54占7行。第2次执行仅仅3个会话的sid与前
--//面相同,可以发现3条记录的sleep大于1000。
SYS@book> @ opeek 00000000877906C8 24 0
[0877906C8, 0877906E0) = 00000000 00000000 02625A02 00003197 11280D5A 00000000
--//0x02625A02 = 40000002
--//0x00003197 = 12695,与记录的完全一致,两者相减就是这次sleeps的数量12695-6452 = 6243。
--//我不知道x$mutex_sleep_history占用的内存区域多大,这些信息保存多久,如果记录不全,sum(sleeps)会存在误差。
--//注意这次的最后的MUTEX_VALUE不再是00.
--//再次执行:
$ zzdate;seq 10 | xargs -IQ -P 10 sqlplus scott/book @ m2.txt 1e6 > /dev/null;zzdate
trunc(sysdate)+11/24+30/1440+57/86400 -1739244657.163923990
trunc(sysdate)+11/24+31/1440+38/86400 1739244698.618742061
SYS@book> @ m3.txt
MUTEX_ADDR MUTEX_IDENTIFIER SLEEP_TIMESTAMP MUTEX_TYPE GETS SLEEPS REQUESTING_SESSION BLOCKING_SESSION LOCATION MUTEX_VALUE
---------------- ---------------- -------------------------- ---------- -------- ------ ------------------ ---------------- -------------------------- ----------------
00000000877906C8 287837530 2025-02-11 10:54:11.936582 Cursor Pin 19142324 705 135 12 kksLockDelete [KKSCHLPIN6] 0000000000000006
00000000877906C8 287837530 2025-02-11 10:54:12.276535 Cursor Pin 19317941 595 197 69 kksfbc [KKSCHLFSP2] 0000004500000006
00000000877906C8 287837530 2025-02-11 10:54:12.569631 Cursor Pin 19471875 662 69 195 kksfbc [KKSCHLFSP2] 0000000000000003
00000000877906C8 287837530 2025-02-11 10:54:12.709637 Cursor Pin 19544898 694 71 195 kksLockDelete [KKSCHLPIN6] 0000000000000004
00000000877906C8 287837530 2025-02-11 10:54:13.587096 Cursor Pin 19933718 607 199 0 kksfbc [KKSCHLFSP2] 00
00000000877906C8 287837530 2025-02-11 11:14:18.354618 Cursor Pin 39388791 658 200 12 kksLockDelete [KKSCHLPIN6] 0000000C00000008
00000000877906C8 287837530 2025-02-11 11:14:19.019570 Cursor Pin 39738675 643 11 70 kksLockDelete [KKSCHLPIN6] 0000004600000003
00000000877906C8 287837530 2025-02-11 11:31:34.098471 Cursor Pin 59257937 1894 133 198 kksLockDelete [KKSCHLPIN6] 0000000000000007
00000000877906C8 287837530 2025-02-11 11:31:34.906244 Cursor Pin 59679684 1723 12 134 kksfbc [KKSCHLFSP2] 0000008600000005
00000000877906C8 287837530 2025-02-11 11:31:35.113291 Cursor Pin 59788336 1250 134 73 kksLockDelete [KKSCHLPIN6] 0000004900000003
00000000877906C8 287837530 2025-02-11 11:31:35.113304 Cursor Pin 59788337 1194 136 73 kksfbc [KKSCHLFSP2] 0000000000000003
00000000877906C8 287837530 2025-02-11 11:31:35.133611 Cursor Pin 59798956 1321 198 134 kksfbc [KKSCHLFSP2] 0000008600000005
00000000877906C8 287837530 2025-02-11 11:31:35.133612 Cursor Pin 59798956 1919 195 134 kksLockDelete [KKSCHLPIN6] 0000008600000005
00000000877906C8 287837530 2025-02-11 11:31:35.338611 Cursor Pin 59906303 1253 8 198 kksfbc [KKSCHLFSP2] 000000C600000002
00000000877906C8 287837530 2025-02-11 11:31:35.443080 Cursor Pin 59960673 1279 70 73 kksLockDelete [KKSCHLPIN6] 0000004900000003
00000000877906C8 287837530 2025-02-11 11:31:35.513651 Cursor Pin 59986883 1076 73 8 kksfbc [KKSCHLFSP2] 0000000000000001
00000000877906C8 287837530 2025-02-11 11:31:35.517620 Cursor Pin 59988393 1169 10 8 kksfbc [KKSCHLFSP2] 0000000800000002
--//Sum = 18642
17 rows selected.
SYS@book> @ opeek 00000000877906C8 24 0
[0877906C8, 0877906E0) = 00000000 00000000 03938702 000048D2 11280D5A 00000000
--//03938702 = 60000002
--//000048D2 = 18642
--//与opeek脚本的输出完全一致。
SYS@book> @ mutexprofz idn,hash,loc,maddr "idn=287837530"
-- 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
---------- -------------- --------------- ---------- ---------- --------------------------------- -------------------- -----------------------------------
9600 40670452 Cursor Pin 287837530 287837530 kksfbc [KKSCHLFSP2] 00000000877906C8 SELECT COUNT(*) FROM T WHERE ID = 1
9042 40818349 Cursor Pin 287837530 287837530 kksLockDelete [KKSCHLPIN6] 00000000877906C8 SELECT COUNT(*) FROM T WHERE ID = 1
SYS@book> @ mutexprofz idn,hash "idn=287837530"
-- 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 OBJECT_NAME
---------- -------------- --------------- ---------- ---------- -----------------------------------
18642 40846069 Cursor Pin 287837530 287837530 SELECT COUNT(*) FROM T WHERE ID = 1
4.补充21c的情况:
--//在21c情况就不同了,记录sleeps很小,就是当时sleeps的实际数量。
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.
--//直接贴出测试结果:
$ zzdate;seq 10 | xargs -IQ -P 10 sqlplus scott/book@book01p @ m2.txt 1e6 > /dev/null;zzdate
trunc(sysdate)+15/24+30/1440+35/86400 1739259035.666690247
trunc(sysdate)+15/24+31/1440+16/86400 1739259076.844448490
SYS@book> @ m3.txt
MUTEX_ADDR MUTEX_IDENTIFIER SLEEP_TIMESTAMP MUTEX_TYPE GETS SLEEPS REQUESTING_SESSION BLOCKING_SESSION LOCATION MUTEX_VALUE
---------------- ---------------- -------------------------- ---------- -------- ------ ------------------ ---------------- -------------------------- ----------------
000000006353C498 287837530 2025-02-11 15:30:45.611297 Cursor Pin 5069176 1 141 22 kksLockDelete [KKSCHLPIN6] 0000001600000006
000000006353C498 287837530 2025-02-11 15:30:45.611310 Cursor Pin 5069176 1 20 22 kksLockDelete [KKSCHLPIN6] 0000001600000006
000000006353C498 287837530 2025-02-11 15:30:45.619614 Cursor Pin 5073068 1 273 0 kksfbc [KKSCHLFSP2] 0000000000000008
000000006353C498 287837530 2025-02-11 15:30:45.651220 Cursor Pin 5088852 1 142 20 kksLockDelete [KKSCHLPIN6] 0000001400000005
000000006353C498 287837530 2025-02-11 15:30:45.651231 Cursor Pin 5088852 1 276 20 kksfbc [KKSCHLFSP2] 0000001400000005
000000006353C498 287837530 2025-02-11 15:30:45.704251 Cursor Pin 5117720 1 274 397 kksLockDelete [KKSCHLPIN6] 0000018D00000008
000000006353C498 287837530 2025-02-11 15:30:45.774112 Cursor Pin 5156081 1 397 274 kksfbc [KKSCHLFSP2] 0000011200000005
000000006353C498 287837530 2025-02-11 15:30:45.812144 Cursor Pin 5176762 1 22 397 kksLockDelete [KKSCHLPIN6] 0000018D00000005
000000006353C498 287837530 2025-02-11 15:30:45.836287 Cursor Pin 5189902 1 146 273 kksfbc [KKSCHLFSP2] 0000011100000007
000000006353C498 287837530 2025-02-11 15:30:45.836292 Cursor Pin 5189902 1 399 273 kksLockDelete [KKSCHLPIN6] 0000011100000007
10 rows selected.
--//看到gets是逐步累积,而sleeps很小,仅仅1.
--//执行脚本结束后执行:
SYS@book> @ m3.txt
MUTEX_ADDR MUTEX_IDENTIFIER SLEEP_TIMESTAMP MUTEX_TYPE GETS SLEEPS REQUESTING_SESSION BLOCKING_SESSION LOCATION MUTEX_VALUE
---------------- ---------------- -------------------------- ---------- -------- ------ ------------------ ---------------- -------------------------- ----------------
000000006353C498 287837530 2025-02-11 15:31:12.394131 Cursor Pin 19376968 3 276 397 kksLockDelete [KKSCHLPIN6] 0000018D00000009
000000006353C498 287837530 2025-02-11 15:31:12.841261 Cursor Pin 19616716 1 20 142 kksLockDelete [KKSCHLPIN6] 0000008E00000006
000000006353C498 287837530 2025-02-11 15:31:13.011625 Cursor Pin 19708179 3 146 399 kksfbc [KKSCHLFSP2] 0000018F00000006
000000006353C498 287837530 2025-02-11 15:31:13.126153 Cursor Pin 19770339 1 22 273 kksfbc [KKSCHLFSP2] 0000011100000005
000000006353C498 287837530 2025-02-11 15:31:13.126154 Cursor Pin 19770339 1 397 273 kksLockDelete [KKSCHLPIN6] 0000011100000005
000000006353C498 287837530 2025-02-11 15:31:13.153332 Cursor Pin 19785004 1 142 399 kksfbc [KKSCHLFSP2] 0000018F00000006
000000006353C498 287837530 2025-02-11 15:31:13.182297 Cursor Pin 19800904 1 141 397 kksfbc [KKSCHLFSP2] 0000018D00000007
000000006353C498 287837530 2025-02-11 15:31:13.346246 Cursor Pin 19882900 1 273 399 kksfbc [KKSCHLFSP2] 0000018F00000000
000000006353C498 287837530 2025-02-11 15:31:13.507455 Cursor Pin 19944940 1 274 273 kksLockDelete [KKSCHLPIN6] 0000011100000002
000000006353C498 287837530 2025-02-11 15:31:13.507458 Cursor Pin 19944940 1 399 273 kksLockDelete [KKSCHLPIN6] 0000011100000002
10 rows selected.
SYS@book> @ opeek 000000006353C498 24 0
[06353C498, 06353C4B0) = 00000000 00000000 01312D00 00001547 11280D5A 00000000
--//0x11280D5A = 287837530 bucket桶号。
--//gets = 0x01312D00 = 20000000
--//sleeps = 0x00001547 = 5447,从x$mutex_sleep_history的输出看就无法判断sleeps的数量。
SYS@book> @ mutexprofz idn,hash,loc,maddr "idn=287837530"
-- 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
---------- --------- ---------- ---------- ---------- -------------------------- ---------------- -----------------------------------
7 174721 Cursor Pin 287837530 287837530 kksfbc [KKSCHLFSP2] 000000006353C498 SELECT COUNT(*) FROM T WHERE ID = 1
7 567972 Cursor Pin 287837530 287837530 kksLockDelete [KKSCHLPIN6] 000000006353C498 SELECT COUNT(*) FROM T WHERE ID = 1
--//最后sum_sleeps仅仅是7,两者相加也就是14.
--//gets的数量是累积的,但是sleeps就是当时sleeps的实际数量,总之该值不是累积的,感觉21c这样改进存在问题。
--//换一句讲11g看到sleeps高可能是之前的记录就很高,要比较就先后执行2次看看两者的差值。而21c下直接看SUM_SLEEPS值,而且只
--//能作为参考,包括GETS_DIFF值。不过多数情况mutex不会成为主要等待事件。
--//原始的tpt版本,sleeps取的是最大值,实际上感觉还是使用自己改写的版本更加科学一些。
5.附上opeek.sql脚本:
$ cat opeek.sql
-- Copyright 2023 lfree. All rights reserved.
-- Licensed under the Apache License, Version 2.0. See LICENSE.txt for terms and conditions.
--------------------------------------------------------------------------------
--
-- Name: opeek.sql
-- Purpose: oradebug peek
-- Author: lfree
-- Usage:
-- @ opeek <addr> <length> <1|0>
-- argv3 : 1 -- write tracename and display 0 -- display
--------------------------------------------------------------------------------
set term off
col 1 new_value 1
select replace(lower('&&1'),'x','') "1" from dual;
column tt new_value var
select decode(&&3,1,'ti','zero') tt from dual;
oradebug setmypid
set term on
@ &var.
--@ ti
oradebug peek 0x&1 &2 &3
prompt
$ cat tpt/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
/
--//在11g下测试遇到的问题,看了以前的链接:[20241018]21c x$mutex_sleep_history记录的变化.txt,实际上当时自己的理解也存在
--//错误,有必要在11g下重复验证自己以前混乱的概念。
--//实际上第一次学习就存在遇到这个问题,将自己写的脚本将gets,sleeps数量做sum汇总,当时就发生gets数量不对,想当然认为
--//sleeps数量也是类似情况,实际上gets数量理解是对的,但是sleeps的理解是错误的,还有一些理解不对的地方,通过真实的例子说
--//明问题。
1.环境:
SCOTT@book> @ver1
PORT_STRING VERSION BANNER
------------------- ---------- ----------------------------------------------------------------------------
x86_64/Linux 2.4.xx 11.2.0.4.0 Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
2.测试环境建立:
drop table t purge ;
create table t as select rownum id ,'test' pad from dual connect by level<=2e5;
create unique index pk_t on t(id);
exec dbms_stats.gather_table_stats(user, 't', method_opt=>'for all columns size 1');
$ cat 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 MUTEX_ADDR,MUTEX_IDENTIFIER,SLEEP_TIMESTAMP,MUTEX_TYPE,GETS,
SLEEPS,REQUESTING_SESSION,BLOCKING_SESSION,LOCATION,MUTEX_VALUE
FROM x$mutex_sleep_history
WHERE mutex_identifier = 287837530
ORDER BY SLEEP_TIMESTAMP;
--//注意设置按SLEEP_TIMESTAMP排序,便于后面观察。
SCOTT@book> SELECT COUNT(*) FROM T WHERE ID = 1 ;
COUNT(*)
----------
1
SCOTT@book> @ 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 2025-02-11 09:09:58 19849416
--//记下sql=5mr67th8kh3au,hash_value=287837530,然后避开其他因素,重启数据库测试。
3.测试:
$ zzdate;seq 10 | xargs -IQ -P 10 sqlplus scott/book @ m2.txt 1e6 > /dev/null;zzdate
trunc(sysdate)+10/24+53/1440+35/86400 -1739242415.181859957
trunc(sysdate)+10/24+54/1440+14/86400 1739242454.048513370
--//在执行过程中执行m3.txt.
SYS@book> @ m3.txt
no rows selected
SYS@book> @ m3.txt
MUTEX_ADDR MUTEX_IDENTIFIER SLEEP_TIMESTAMP MUTEX_TYPE GETS SLEEPS REQUESTING_SESSION BLOCKING_SESSION LOCATION MUTEX_VALUE
---------------- ---------------- -------------------------- ---------- -------- ------ ------------------ ---------------- -------------------------- ----------------
00000000877906C8 287837530 2025-02-11 10:53:37.062648 Cursor Pin 760418 22 12 10 kksLockDelete [KKSCHLPIN6] 0000000A00000004
00000000877906C8 287837530 2025-02-11 10:53:37.321700 Cursor Pin 898059 41 135 199 kksfbc [KKSCHLFSP2] 000000C700000004
00000000877906C8 287837530 2025-02-11 10:53:37.321706 Cursor Pin 898059 32 133 199 kksfbc [KKSCHLFSP2] 000000C700000004
00000000877906C8 287837530 2025-02-11 10:53:37.351523 Cursor Pin 913868 41 197 135 kksLockDelete [KKSCHLPIN6] 0000008700000006
00000000877906C8 287837530 2025-02-11 10:53:37.351534 Cursor Pin 913868 34 195 135 kksfbc [KKSCHLFSP2] 0000008700000006
00000000877906C8 287837530 2025-02-11 10:53:37.351541 Cursor Pin 913870 49 69 135 kksfbc [KKSCHLFSP2] 0000000000000004
00000000877906C8 287837530 2025-02-11 10:53:37.360631 Cursor Pin 918601 17 10 133 kksLockDelete [KKSCHLPIN6] 0000000000000005
00000000877906C8 287837530 2025-02-11 10:53:37.360633 Cursor Pin 918599 27 8 133 kksfbc [KKSCHLFSP2] 0000008500000004
00000000877906C8 287837530 2025-02-11 10:53:37.360634 Cursor Pin 918599 35 199 133 kksfbc [KKSCHLFSP2] 0000008500000004
00000000877906C8 287837530 2025-02-11 10:53:37.360653 Cursor Pin 918600 55 71 133 kksfbc [KKSCHLFSP2] 0000000000000004
10 rows selected.
SYS@book> @ m3.txt
MUTEX_ADDR MUTEX_IDENTIFIER SLEEP_TIMESTAMP MUTEX_TYPE GETS SLEEPS REQUESTING_SESSION BLOCKING_SESSION LOCATION MUTEX_VALUE
---------------- ---------------- -------------------------- ---------- -------- ------ ------------------ ---------------- -------------------------- ----------------
00000000877906C8 287837530 2025-02-11 10:54:02.083479 Cursor Pin 13950008 469 8 195 kksLockDelete [KKSCHLPIN6] 0000000000000006
00000000877906C8 287837530 2025-02-11 10:54:02.184960 Cursor Pin 14003353 503 69 199 kksLockDelete [KKSCHLPIN6] 000000C700000007
00000000877906C8 287837530 2025-02-11 10:54:02.260661 Cursor Pin 14043662 458 133 8 kksfbc [KKSCHLFSP2] 0000000800000005
00000000877906C8 287837530 2025-02-11 10:54:02.260662 Cursor Pin 14043662 436 12 8 kksfbc [KKSCHLFSP2] 0000000800000005
00000000877906C8 287837530 2025-02-11 10:54:02.260663 Cursor Pin 14043663 450 197 8 kksLockDelete [KKSCHLPIN6] 0000000000000005
00000000877906C8 287837530 2025-02-11 10:54:02.314660 Cursor Pin 14072550 528 71 135 kksLockDelete [KKSCHLPIN6] 0000008700000007
00000000877906C8 287837530 2025-02-11 10:54:02.346910 Cursor Pin 14089645 534 135 71 kksfbc [KKSCHLFSP2] 0000004700000008
00000000877906C8 287837530 2025-02-11 10:54:02.346916 Cursor Pin 14089645 436 195 71 kksLockDelete [KKSCHLPIN6] 0000004700000008
00000000877906C8 287837530 2025-02-11 10:54:02.346924 Cursor Pin 14089645 415 199 71 kksLockDelete [KKSCHLPIN6] 0000004700000008
00000000877906C8 287837530 2025-02-11 10:54:02.346924 Cursor Pin 14089647 452 10 71 kksfbc [KKSCHLFSP2] 0000000000000007
10 rows selected.
--//全部结束后,执行如下:
SYS@book> @ m3.txt
MUTEX_ADDR MUTEX_IDENTIFIER SLEEP_TIMESTAMP MUTEX_TYPE GETS SLEEPS REQUESTING_SESSION BLOCKING_SESSION LOCATION MUTEX_VALUE
---------------- ---------------- -------------------------- ---------- -------- ------ ------------------ ---------------- -------------------------- ----------------
00000000877906C8 287837530 2025-02-11 10:54:11.936582 Cursor Pin 19142324 705 135 12 kksLockDelete [KKSCHLPIN6] 0000000000000006
00000000877906C8 287837530 2025-02-11 10:54:12.276535 Cursor Pin 19317941 595 197 69 kksfbc [KKSCHLFSP2] 0000004500000006
00000000877906C8 287837530 2025-02-11 10:54:12.569631 Cursor Pin 19471875 662 69 195 kksfbc [KKSCHLFSP2] 0000000000000003
00000000877906C8 287837530 2025-02-11 10:54:12.703461 Cursor Pin 19541631 633 12 133 kksfbc [KKSCHLFSP2] 0000000000000005
00000000877906C8 287837530 2025-02-11 10:54:12.709637 Cursor Pin 19544898 694 71 195 kksLockDelete [KKSCHLPIN6] 0000000000000004
00000000877906C8 287837530 2025-02-11 10:54:13.054674 Cursor Pin 19724415 601 195 10 kksfbc [KKSCHLFSP2] 0000000A00000002
00000000877906C8 287837530 2025-02-11 10:54:13.141620 Cursor Pin 19770180 643 8 195 kksfbc [KKSCHLFSP2] 000000C300000003
00000000877906C8 287837530 2025-02-11 10:54:13.575564 Cursor Pin 19931013 641 10 199 kksfbc [KKSCHLFSP2] 000000C700000000
00000000877906C8 287837530 2025-02-11 10:54:13.575566 Cursor Pin 19931013 671 133 199 kksfbc [KKSCHLFSP2] 000000C700000000
00000000877906C8 287837530 2025-02-11 10:54:13.587096 Cursor Pin 19933718 607 199 0 kksfbc [KKSCHLFSP2] 00
--//Sum = 6452
10 rows selected.
--//gets记录的最大值是19933718。
--//仔细gets的变化顺着SLEEP_TIMESTAMP变化,不断累积的。
SYS@book> @ opeek 00000000877906C8 24 0
[0877906C8, 0877906E0) = 00000000 00000000 01312D00 00001934 11280D5A 00000000
--//0x11280D5A = 287837530,正好等于bucket桶号,也就是hash_value.
--//gets 0x01312D00 = 20000000,总共执行10*1000000 = 10000000,有2个LOCATION出现kksLockDelete [KKSCHLPIN6],kksfbc [KKSCHLFSP2] 。
--//这样gets=执行次数*2,完全能对上。而m3.txt脚本查询最大的gets=19933718,因为后面没有sleeps,就不做记录,与20000000非常接近。
--//sleeps =0x00001934 = 6452。将最后的输出sleeps结果累积
--//705+595+662+633+694+601+643+641+671+607 = 6452,正好等于opeek.sql脚本输出看到的结果。
--//另外注意输出的记录每次都是10行,说明10个会话在执行(我以前的理解存在错误),实际上相当于取样每个REQUESTING_SESSION,对于每个
--//REQUESTING_SESSION讲sleeps的次数是不断累积的,相当于snapshot当时的情况。最后sum(sleeps)就是实际sleeps的数量。
--//另外注意一个前提就是出现sleeps在x$mutex_sleep_history视图才会有记录。
--//另外注意一个细节最后一行MUTEX_VALUE=00,因为其他会话已经退出,无法抓取到MUTEX_VALUE值。
$ zzdate;seq 10 | xargs -IQ -P 10 sqlplus scott/book @ m2.txt 1e6 > /dev/null;zzdate
trunc(sysdate)+11/24+13/1440+41/86400 -1739243621.004123399
trunc(sysdate)+11/24+14/1440+22/86400 1739243662.918034260
--//注意这次执行修改m2.txt ,结尾加入host sleep 3再退出。
SYS@book> @ m3.txt
MUTEX_ADDR MUTEX_IDENTIFIER SLEEP_TIMESTAMP MUTEX_TYPE GETS SLEEPS REQUESTING_SESSION BLOCKING_SESSION LOCATION MUTEX_VALUE
---------------- ---------------- -------------------------- ---------- -------- ------ ------------------ ---------------- -------------------------- ----------------
00000000877906C8 287837530 2025-02-11 10:54:11.936582 Cursor Pin 19142324 705 135 12 kksLockDelete [KKSCHLPIN6] 0000000000000006
00000000877906C8 287837530 2025-02-11 10:54:12.276535 Cursor Pin 19317941 595 197 69 kksfbc [KKSCHLFSP2] 0000004500000006
00000000877906C8 287837530 2025-02-11 10:54:12.569631 Cursor Pin 19471875 662 69 195 kksfbc [KKSCHLFSP2] 0000000000000003
00000000877906C8 287837530 2025-02-11 10:54:12.709637 Cursor Pin 19544898 694 71 195 kksLockDelete [KKSCHLPIN6] 0000000000000004
00000000877906C8 287837530 2025-02-11 10:54:13.141620 Cursor Pin 19770180 643 8 195 kksfbc [KKSCHLFSP2] 000000C300000003
00000000877906C8 287837530 2025-02-11 10:54:13.575564 Cursor Pin 19931013 641 10 199 kksfbc [KKSCHLFSP2] 000000C700000000
00000000877906C8 287837530 2025-02-11 10:54:13.587096 Cursor Pin 19933718 607 199 0 kksfbc [KKSCHLFSP2] 00
00000000877906C8 287837530 2025-02-11 11:14:16.431549 Cursor Pin 38381754 569 73 195 kksfbc [KKSCHLFSP2] 000000C300000007
00000000877906C8 287837530 2025-02-11 11:14:16.912629 Cursor Pin 38636326 612 136 195 kksfbc [KKSCHLFSP2] 0000000000000004
00000000877906C8 287837530 2025-02-11 11:14:18.354618 Cursor Pin 39388791 658 200 12 kksLockDelete [KKSCHLPIN6] 0000000C00000008
00000000877906C8 287837530 2025-02-11 11:14:18.772595 Cursor Pin 39608095 1147 12 11 kksLockDelete [KKSCHLPIN6] 0000000000000005
00000000877906C8 287837530 2025-02-11 11:14:18.878636 Cursor Pin 39664305 642 134 12 kksLockDelete [KKSCHLPIN6] 0000000000000005
00000000877906C8 287837530 2025-02-11 11:14:19.019570 Cursor Pin 39738675 643 11 70 kksLockDelete [KKSCHLPIN6] 0000004600000003
00000000877906C8 287837530 2025-02-11 11:14:19.141432 Cursor Pin 39801441 1267 195 0 kksLockDelete [KKSCHLPIN6] 0000000000000003
00000000877906C8 287837530 2025-02-11 11:14:19.426140 Cursor Pin 39913625 657 198 133 kksfbc [KKSCHLFSP2] 0000008500000001
00000000877906C8 287837530 2025-02-11 11:14:19.522707 Cursor Pin 39937671 1334 133 70 kksfbc [KKSCHLFSP2] 0000004600000001
00000000877906C8 287837530 2025-02-11 11:14:19.554008 Cursor Pin 39945620 619 70 133 kksLockDelete [KKSCHLPIN6] 0000000000000002
--//Sum = 12695
17 rows selected.
--//这次看到不是10行正常的,因为sid发生了变化,前面SLEEP_TIMESTAMP=2025-02-11 10:54占7行。第2次执行仅仅3个会话的sid与前
--//面相同,可以发现3条记录的sleep大于1000。
SYS@book> @ opeek 00000000877906C8 24 0
[0877906C8, 0877906E0) = 00000000 00000000 02625A02 00003197 11280D5A 00000000
--//0x02625A02 = 40000002
--//0x00003197 = 12695,与记录的完全一致,两者相减就是这次sleeps的数量12695-6452 = 6243。
--//我不知道x$mutex_sleep_history占用的内存区域多大,这些信息保存多久,如果记录不全,sum(sleeps)会存在误差。
--//注意这次的最后的MUTEX_VALUE不再是00.
--//再次执行:
$ zzdate;seq 10 | xargs -IQ -P 10 sqlplus scott/book @ m2.txt 1e6 > /dev/null;zzdate
trunc(sysdate)+11/24+30/1440+57/86400 -1739244657.163923990
trunc(sysdate)+11/24+31/1440+38/86400 1739244698.618742061
SYS@book> @ m3.txt
MUTEX_ADDR MUTEX_IDENTIFIER SLEEP_TIMESTAMP MUTEX_TYPE GETS SLEEPS REQUESTING_SESSION BLOCKING_SESSION LOCATION MUTEX_VALUE
---------------- ---------------- -------------------------- ---------- -------- ------ ------------------ ---------------- -------------------------- ----------------
00000000877906C8 287837530 2025-02-11 10:54:11.936582 Cursor Pin 19142324 705 135 12 kksLockDelete [KKSCHLPIN6] 0000000000000006
00000000877906C8 287837530 2025-02-11 10:54:12.276535 Cursor Pin 19317941 595 197 69 kksfbc [KKSCHLFSP2] 0000004500000006
00000000877906C8 287837530 2025-02-11 10:54:12.569631 Cursor Pin 19471875 662 69 195 kksfbc [KKSCHLFSP2] 0000000000000003
00000000877906C8 287837530 2025-02-11 10:54:12.709637 Cursor Pin 19544898 694 71 195 kksLockDelete [KKSCHLPIN6] 0000000000000004
00000000877906C8 287837530 2025-02-11 10:54:13.587096 Cursor Pin 19933718 607 199 0 kksfbc [KKSCHLFSP2] 00
00000000877906C8 287837530 2025-02-11 11:14:18.354618 Cursor Pin 39388791 658 200 12 kksLockDelete [KKSCHLPIN6] 0000000C00000008
00000000877906C8 287837530 2025-02-11 11:14:19.019570 Cursor Pin 39738675 643 11 70 kksLockDelete [KKSCHLPIN6] 0000004600000003
00000000877906C8 287837530 2025-02-11 11:31:34.098471 Cursor Pin 59257937 1894 133 198 kksLockDelete [KKSCHLPIN6] 0000000000000007
00000000877906C8 287837530 2025-02-11 11:31:34.906244 Cursor Pin 59679684 1723 12 134 kksfbc [KKSCHLFSP2] 0000008600000005
00000000877906C8 287837530 2025-02-11 11:31:35.113291 Cursor Pin 59788336 1250 134 73 kksLockDelete [KKSCHLPIN6] 0000004900000003
00000000877906C8 287837530 2025-02-11 11:31:35.113304 Cursor Pin 59788337 1194 136 73 kksfbc [KKSCHLFSP2] 0000000000000003
00000000877906C8 287837530 2025-02-11 11:31:35.133611 Cursor Pin 59798956 1321 198 134 kksfbc [KKSCHLFSP2] 0000008600000005
00000000877906C8 287837530 2025-02-11 11:31:35.133612 Cursor Pin 59798956 1919 195 134 kksLockDelete [KKSCHLPIN6] 0000008600000005
00000000877906C8 287837530 2025-02-11 11:31:35.338611 Cursor Pin 59906303 1253 8 198 kksfbc [KKSCHLFSP2] 000000C600000002
00000000877906C8 287837530 2025-02-11 11:31:35.443080 Cursor Pin 59960673 1279 70 73 kksLockDelete [KKSCHLPIN6] 0000004900000003
00000000877906C8 287837530 2025-02-11 11:31:35.513651 Cursor Pin 59986883 1076 73 8 kksfbc [KKSCHLFSP2] 0000000000000001
00000000877906C8 287837530 2025-02-11 11:31:35.517620 Cursor Pin 59988393 1169 10 8 kksfbc [KKSCHLFSP2] 0000000800000002
--//Sum = 18642
17 rows selected.
SYS@book> @ opeek 00000000877906C8 24 0
[0877906C8, 0877906E0) = 00000000 00000000 03938702 000048D2 11280D5A 00000000
--//03938702 = 60000002
--//000048D2 = 18642
--//与opeek脚本的输出完全一致。
SYS@book> @ mutexprofz idn,hash,loc,maddr "idn=287837530"
-- 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
---------- -------------- --------------- ---------- ---------- --------------------------------- -------------------- -----------------------------------
9600 40670452 Cursor Pin 287837530 287837530 kksfbc [KKSCHLFSP2] 00000000877906C8 SELECT COUNT(*) FROM T WHERE ID = 1
9042 40818349 Cursor Pin 287837530 287837530 kksLockDelete [KKSCHLPIN6] 00000000877906C8 SELECT COUNT(*) FROM T WHERE ID = 1
SYS@book> @ mutexprofz idn,hash "idn=287837530"
-- 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 OBJECT_NAME
---------- -------------- --------------- ---------- ---------- -----------------------------------
18642 40846069 Cursor Pin 287837530 287837530 SELECT COUNT(*) FROM T WHERE ID = 1
4.补充21c的情况:
--//在21c情况就不同了,记录sleeps很小,就是当时sleeps的实际数量。
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.
--//直接贴出测试结果:
$ zzdate;seq 10 | xargs -IQ -P 10 sqlplus scott/book@book01p @ m2.txt 1e6 > /dev/null;zzdate
trunc(sysdate)+15/24+30/1440+35/86400 1739259035.666690247
trunc(sysdate)+15/24+31/1440+16/86400 1739259076.844448490
SYS@book> @ m3.txt
MUTEX_ADDR MUTEX_IDENTIFIER SLEEP_TIMESTAMP MUTEX_TYPE GETS SLEEPS REQUESTING_SESSION BLOCKING_SESSION LOCATION MUTEX_VALUE
---------------- ---------------- -------------------------- ---------- -------- ------ ------------------ ---------------- -------------------------- ----------------
000000006353C498 287837530 2025-02-11 15:30:45.611297 Cursor Pin 5069176 1 141 22 kksLockDelete [KKSCHLPIN6] 0000001600000006
000000006353C498 287837530 2025-02-11 15:30:45.611310 Cursor Pin 5069176 1 20 22 kksLockDelete [KKSCHLPIN6] 0000001600000006
000000006353C498 287837530 2025-02-11 15:30:45.619614 Cursor Pin 5073068 1 273 0 kksfbc [KKSCHLFSP2] 0000000000000008
000000006353C498 287837530 2025-02-11 15:30:45.651220 Cursor Pin 5088852 1 142 20 kksLockDelete [KKSCHLPIN6] 0000001400000005
000000006353C498 287837530 2025-02-11 15:30:45.651231 Cursor Pin 5088852 1 276 20 kksfbc [KKSCHLFSP2] 0000001400000005
000000006353C498 287837530 2025-02-11 15:30:45.704251 Cursor Pin 5117720 1 274 397 kksLockDelete [KKSCHLPIN6] 0000018D00000008
000000006353C498 287837530 2025-02-11 15:30:45.774112 Cursor Pin 5156081 1 397 274 kksfbc [KKSCHLFSP2] 0000011200000005
000000006353C498 287837530 2025-02-11 15:30:45.812144 Cursor Pin 5176762 1 22 397 kksLockDelete [KKSCHLPIN6] 0000018D00000005
000000006353C498 287837530 2025-02-11 15:30:45.836287 Cursor Pin 5189902 1 146 273 kksfbc [KKSCHLFSP2] 0000011100000007
000000006353C498 287837530 2025-02-11 15:30:45.836292 Cursor Pin 5189902 1 399 273 kksLockDelete [KKSCHLPIN6] 0000011100000007
10 rows selected.
--//看到gets是逐步累积,而sleeps很小,仅仅1.
--//执行脚本结束后执行:
SYS@book> @ m3.txt
MUTEX_ADDR MUTEX_IDENTIFIER SLEEP_TIMESTAMP MUTEX_TYPE GETS SLEEPS REQUESTING_SESSION BLOCKING_SESSION LOCATION MUTEX_VALUE
---------------- ---------------- -------------------------- ---------- -------- ------ ------------------ ---------------- -------------------------- ----------------
000000006353C498 287837530 2025-02-11 15:31:12.394131 Cursor Pin 19376968 3 276 397 kksLockDelete [KKSCHLPIN6] 0000018D00000009
000000006353C498 287837530 2025-02-11 15:31:12.841261 Cursor Pin 19616716 1 20 142 kksLockDelete [KKSCHLPIN6] 0000008E00000006
000000006353C498 287837530 2025-02-11 15:31:13.011625 Cursor Pin 19708179 3 146 399 kksfbc [KKSCHLFSP2] 0000018F00000006
000000006353C498 287837530 2025-02-11 15:31:13.126153 Cursor Pin 19770339 1 22 273 kksfbc [KKSCHLFSP2] 0000011100000005
000000006353C498 287837530 2025-02-11 15:31:13.126154 Cursor Pin 19770339 1 397 273 kksLockDelete [KKSCHLPIN6] 0000011100000005
000000006353C498 287837530 2025-02-11 15:31:13.153332 Cursor Pin 19785004 1 142 399 kksfbc [KKSCHLFSP2] 0000018F00000006
000000006353C498 287837530 2025-02-11 15:31:13.182297 Cursor Pin 19800904 1 141 397 kksfbc [KKSCHLFSP2] 0000018D00000007
000000006353C498 287837530 2025-02-11 15:31:13.346246 Cursor Pin 19882900 1 273 399 kksfbc [KKSCHLFSP2] 0000018F00000000
000000006353C498 287837530 2025-02-11 15:31:13.507455 Cursor Pin 19944940 1 274 273 kksLockDelete [KKSCHLPIN6] 0000011100000002
000000006353C498 287837530 2025-02-11 15:31:13.507458 Cursor Pin 19944940 1 399 273 kksLockDelete [KKSCHLPIN6] 0000011100000002
10 rows selected.
SYS@book> @ opeek 000000006353C498 24 0
[06353C498, 06353C4B0) = 00000000 00000000 01312D00 00001547 11280D5A 00000000
--//0x11280D5A = 287837530 bucket桶号。
--//gets = 0x01312D00 = 20000000
--//sleeps = 0x00001547 = 5447,从x$mutex_sleep_history的输出看就无法判断sleeps的数量。
SYS@book> @ mutexprofz idn,hash,loc,maddr "idn=287837530"
-- 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
---------- --------- ---------- ---------- ---------- -------------------------- ---------------- -----------------------------------
7 174721 Cursor Pin 287837530 287837530 kksfbc [KKSCHLFSP2] 000000006353C498 SELECT COUNT(*) FROM T WHERE ID = 1
7 567972 Cursor Pin 287837530 287837530 kksLockDelete [KKSCHLPIN6] 000000006353C498 SELECT COUNT(*) FROM T WHERE ID = 1
--//最后sum_sleeps仅仅是7,两者相加也就是14.
--//gets的数量是累积的,但是sleeps就是当时sleeps的实际数量,总之该值不是累积的,感觉21c这样改进存在问题。
--//换一句讲11g看到sleeps高可能是之前的记录就很高,要比较就先后执行2次看看两者的差值。而21c下直接看SUM_SLEEPS值,而且只
--//能作为参考,包括GETS_DIFF值。不过多数情况mutex不会成为主要等待事件。
--//原始的tpt版本,sleeps取的是最大值,实际上感觉还是使用自己改写的版本更加科学一些。
5.附上opeek.sql脚本:
$ cat opeek.sql
-- Copyright 2023 lfree. All rights reserved.
-- Licensed under the Apache License, Version 2.0. See LICENSE.txt for terms and conditions.
--------------------------------------------------------------------------------
--
-- Name: opeek.sql
-- Purpose: oradebug peek
-- Author: lfree
-- Usage:
-- @ opeek <addr> <length> <1|0>
-- argv3 : 1 -- write tracename and display 0 -- display
--------------------------------------------------------------------------------
set term off
col 1 new_value 1
select replace(lower('&&1'),'x','') "1" from dual;
column tt new_value var
select decode(&&3,1,'ti','zero') tt from dual;
oradebug setmypid
set term on
@ &var.
--@ ti
oradebug peek 0x&1 &2 &3
prompt
$ cat tpt/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
/
【推荐】编程新体验,更懂你的AI,立即体验豆包MarsCode编程助手
【推荐】凌霞软件回馈社区,博客园 & 1Panel & Halo 联合会员上线
【推荐】抖音旗下AI助手豆包,你的智能百科全书,全免费不限次数
【推荐】博客园社区专享云产品让利特惠,阿里云新客6.5折上折
【推荐】轻量又高性能的 SSH 工具 IShell:AI 加持,快人一步
· 一个费力不讨好的项目,让我损失了近一半的绩效!
· 清华大学推出第四讲使用 DeepSeek + DeepResearch 让科研像聊天一样简单!
· 实操Deepseek接入个人知识库
· CSnakes vs Python.NET:高效嵌入与灵活互通的跨语言方案对比
· Plotly.NET 一个为 .NET 打造的强大开源交互式图表库
2021-02-18 [20210218]shared latch spin count 5.txt