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

作者:lfree原文地址:https://www.cnblogs.com/lfree/p/18486587

%s 个评论

要回复文章请先登录注册