[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 /
[20241018]21c x$mutex_sleep_history记录的变化.txt
来源:这里教程网
时间:2026-03-03 20:44:10
作者:
编辑推荐:
- [20241018]21c x$mutex_sleep_history记录的变化.txt03-03
- Oracle 数据库发版时间表03-03
- 音视频技术原理及应用03-03
- 掌握HTTP请求:GET、POST、PUT、DELETE的妙用03-03
- 大规模数据处理中的数据分片技巧03-03
- [20240930]建立ocol.sh脚本查询字段.txt03-03
- Bitmap 和 布隆过滤器傻傻分不清?你这不应该啊03-03
- python实现基本的正则表达式匹配03-03
下一篇:
相关推荐
-
雷神推出 MIX PRO II 迷你主机:基于 Ultra 200H,玻璃上盖 + ARGB 灯效
2 月 9 日消息,雷神 (THUNDEROBOT) 现已宣布推出基于英
-
制造商 Musnap 推出彩色墨水屏电纸书 Ocean C:支持手写笔、第三方安卓应用
2 月 10 日消息,制造商 Musnap 现已在海外推出一款 Oce
热文推荐
- Oracle 数据库归档缺失,介质恢复失败,如何处理?
Oracle 数据库归档缺失,介质恢复失败,如何处理?
26-03-03 - Oracle 数据库发版时间表
Oracle 数据库发版时间表
26-03-03 - 音视频技术原理及应用
音视频技术原理及应用
26-03-03 - Bitmap 和 布隆过滤器傻傻分不清?你这不应该啊
Bitmap 和 布隆过滤器傻傻分不清?你这不应该啊
26-03-03 - 从误删文件说说数据库的DRA
从误删文件说说数据库的DRA
26-03-03 - 敲开IPO大门,闪送要飞?
敲开IPO大门,闪送要飞?
26-03-03 - GoldenGate 状态监控及自启动脚本分享
GoldenGate 状态监控及自启动脚本分享
26-03-03 - 高效 Selenium 测试技巧:轻松控制已开启
高效 Selenium 测试技巧:轻松控制已开启
26-03-03 - oracle数据恢复—Oracle数据库文件出现坏块的数据恢复案例
oracle数据恢复—Oracle数据库文件出现坏块的数据恢复案例
26-03-03 - Workspace E1016P08用户在云桌面里使用耳机录音录到的音频有杂音
