[20250207]21c library cache mutex的深入探究13.txt

[20250207]21c library cache mutex的深入探究13.txt

--//探究library cache mutex阻塞导致的相关等待事件,分析_mutex_wait_scheme=2的情况下修改mutext值的0-3字节。
--//关于mutex的结构,我的测试的结果如下:
--// 0- 7 字节是muext的值。
--// 8-11 字节是mutex gets的数量。
--//12-15 字节是mutex sleep的数量。
--//16-19 字节是Bucket桶号。
--//20-23 字节是转储看到的6.

--//我前面的测试仅仅修改mutex值的sid部分(4-7字节),也就是mutex结构里面0-7字节的4-7部分,没有尝试0-3字节的信息,该信息记
--//录的是持有该mutex的数量,尝试修改两部分信息看看会出现怎么情况。

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.

SYS@book> @ hidez ^_mutex
 NUM N_HEX NAME               DESCRIPTION       DEFAULT_VALUE SESSION_VALUE SYSTEM_VALUE ISSES ISSYS_MOD
---- ----- ------------------ ----------------- ------------- ------------- ------------ ----- ---------
3553   DE1 _mutex_wait_time   Mutex wait time   TRUE          1             1            FALSE IMMEDIATE
3554   DE2 _mutex_spin_count  Mutex spin count  TRUE          255           255          FALSE IMMEDIATE
3555   DE3 _mutex_wait_scheme Mutex wait scheme TRUE          2             2            FALSE IMMEDIATE

--//缺省_mutex_wait_time=1,时间单位与_mutex_wait_scheme相关,_mutex_wait_scheme=2时时间单位是厘秒,而
--//_mutex_wait_scheme=0,1时,单位时毫秒。
--//_mutex_wait_scheme =2时,_mutex_wait_time>1时sleeps的时间会出现指数回退.

--//缺省_mutex_wait_scheme =2.

--//网上找了一段资料:
* _mutex_spin_count (Integer)
- This sets the number of times to spin before yielding/waiting.

* _mutex_wait_scheme (Integer)
- In 11.2 this controls which wait scheme to use. It can be set to one of the three wait schemes described above thus:
_mutex_wait_scheme = 0                        – Always YIELD
_mutex_wait_scheme = 1 & _mutex_wait_time = t – Always SLEEP for t milli-seconds
_mutex_wait_scheme = 2 & _mutex_wait_time = t – EXP BACKOFF with maximum sleep (default)

2.测试前准备:
SYS@book> oradebug setmypid
Statement processed.
SYS@book> oradebug dump library_cache 4
Statement processed.

$ grep "^Bucket:" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_10770.trc | head -4
Bucket: #=0 Mutex=0x6cfa1400(1125281431552, 9, 0, 6)
Bucket: #=5 Mutex=0x6cfa14f0(1125281431552, 4, 0, 6)
Bucket: #=17 Mutex=0x6cfa1730(1125281431552, 8, 0, 6)
Bucket: #=39 Mutex=0x6cfa1b50(1125281431552, 4, 0, 6)
--//以上是前面测试的结果,直接找Bucket: #=0 Mutex=0x6cfa1400的语句测试。
--//该sql语句select /*+ 9 */ count(*) from dept where deptno = 93834;的bucket=0.
--//Bucket: #=0 Mutex=0x6cfa1400
--//0x6cfa1400-0x10 = 0x6cfa13f0

3.测试:
--//节省篇幅,操作细节不再贴出,直接给出测试结果。

(gdb) x /8wx 0x6cfa1400
0x6cfa1400:     0x00000000      0x00000000      0x00000006      0x00000000
0x6cfa1410:     0x00000000      0x00000000      0x66a10bb8      0x00000000

(gdb) set *(int *)0x6cfa1404=0x9999
(gdb) set *(int *)0x6cfa1400=0x1

(gdb) x /8wx 0x6cfa1400
0x6cfa1400:     0x00000001      0x00009999      0x00000006      0x00000000
0x6cfa1410:     0x00000000      0x00000000      0x66a10bb8      0x00000000

(gdb) set *(int *)0x6cfa1404=0x0
(gdb) set *(int *)0x6cfa1400=0x0
(gdb) x /8wx 0x6cfa1400
0x6cfa1400:     0x00000000      0x00000000      0x00000007      0x00000d01
0x6cfa1410:     0x00000000      0x00000000      0x66a10bb8      0x00000000
--//sleeps=0x00000d01=3329,gets-> 0x6->0x7

SYS@book> @ ashtop event,p1,p1raw,p2raw,p3raw 1=1 "'2025/02/07 15:26:06'" "'2025/02/07 15:27:11'"

    Total                                                                                                                                                                       Distinct Distinct    Distinct
  Seconds     AAS %This   EVENT                                              P1 P1RAW             P2RAW             P3RAW             FIRST_SEEN          LAST_SEEN           Execs Seen  Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ---------- ----------------- ----------------- ----------------- ------------------- ------------------- ---------- -------- -----------
       54      .8   70% | library cache: bucket mutex X                       0 0000000000000000  0000999900000001  000000000000003E  2025-02-07 15:26:07 2025-02-07 15:27:00          1       54          54
        8      .1   10% | library cache: bucket mutex X                       0 0000000000000000  0000000000000001  000000000000003E  2025-02-07 15:27:01 2025-02-07 15:27:09          1        8           8
        4      .1    5% |                                                    20                                                       2025-02-07 15:26:07 2025-02-07 15:26:58          1        4           4
        4      .1    5% |                                                   100                                                       2025-02-07 15:26:07 2025-02-07 15:26:46          1        4           4
        2      .0    3% | LGWR all worker groups                              0 0000000000000000  0000000000000000  0000000000000000  2025-02-07 15:26:07 2025-02-07 15:26:08          1        2           2
        2      .0    3% | log file parallel write                             1 0000000000000001  0000000000000001  0000000000000001  2025-02-07 15:26:07 2025-02-07 15:26:08          1        2           2
        1      .0    1% |                                                     0                                                       2025-02-07 15:27:03 2025-02-07 15:27:03          1        1           1
        1      .0    1% |                                                   300                                                       2025-02-07 15:26:17 2025-02-07 15:26:17          1        1           1
        1      .0    1% |                                            1932464120                                                       2025-02-07 15:26:31 2025-02-07 15:26:31          1        1           1
9 rows selected.
--//注意P2RAW的变化,开始0000999900000001,0000000000000001。

SYS@book> @ mutexprofz idn,hash,maddr,loc "ts>=trunc(sysdate)+15/24+26/1440+06/86400"

-- 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 mutex_addr           GET_LOCATION OBJECT_NAME
---------- -------------- --------------- ---------- ---------- -------------------- ------------ --------------------------------------------------------------------------------
      3329                Library Cache            0            000000006CFA1400     kglhdgn1  62 (name not found)
         3                Library Cache   2276283790 2276283790 00000000662B96A0     kglhdgn2 106 SELECT /*+ NO_STATEMENT_QUEUING RESULT_CACHE (SYSOBJ=TRUE) */
                                                                                                  "OBJ#","CLASS_OID","JOB_FLAGS","RUN_TIME","PRIORITY","JOB_STATUS","RUNNING_INSTA
                                                                                                  NCE","SCHEDULE_LIMIT","JOB_WEIGHT","INSTANCE_ID","AFFINITY","DATABASE_ROLE"
                                                                                                  FROM "SYS"."SCHEDULER$_JOB_REFRESH" "SCHEDULER$_JOB_REFRESH" WHERE 1=1
--//3329 = 0xd01.

$ egrep "getrusage" 0207mutexb.txt
15:26:07.150476 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 347135}, ru_stime={0, 33692}, ...}) = 0 <0.000015>
15:26:07.150587 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 347177}, ru_stime={0, 33696}, ...}) = 0 <0.000012>
15:26:08.856385 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 348149}, ru_stime={0, 37665}, ...}) = 0 <0.000046>
15:26:10.911100 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 351302}, ru_stime={0, 39944}, ...}) = 0 <0.000124>
15:26:12.915692 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 354508}, ru_stime={0, 42252}, ...}) = 0 <0.000029>
15:26:14.912085 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 358084}, ru_stime={0, 44760}, ...}) = 0 <0.000228>
15:26:16.916171 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 361168}, ru_stime={0, 49060}, ...}) = 0 <0.000011>
15:26:18.915817 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 364606}, ru_stime={0, 52235}, ...}) = 0 <0.000238>
15:26:20.917717 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 366301}, ru_stime={0, 54421}, ...}) = 0 <0.000150>
15:26:22.920764 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 369432}, ru_stime={0, 57888}, ...}) = 0 <0.000018>
15:26:24.927205 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 373480}, ru_stime={0, 60677}, ...}) = 0 <0.000018>
15:26:26.942295 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 379902}, ru_stime={0, 62089}, ...}) = 0 <0.000009>
15:26:28.934122 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 381876}, ru_stime={0, 63469}, ...}) = 0 <0.000021>
15:26:30.936776 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 386159}, ru_stime={0, 65070}, ...}) = 0 <0.000096>
15:26:32.942150 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 393274}, ru_stime={0, 67326}, ...}) = 0 <0.000035>
15:26:34.952065 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 396936}, ru_stime={0, 71491}, ...}) = 0 <0.000029>
15:26:36.950711 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 403350}, ru_stime={0, 73140}, ...}) = 0 <0.000011>
15:26:38.949480 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 406376}, ru_stime={0, 75655}, ...}) = 0 <0.000029>
15:26:40.953517 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 411364}, ru_stime={0, 77738}, ...}) = 0 <0.000032>
15:26:42.953218 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 416651}, ru_stime={0, 79207}, ...}) = 0 <0.000014>
15:26:44.957684 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 421671}, ru_stime={0, 83023}, ...}) = 0 <0.000028>
15:26:46.973537 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 425903}, ru_stime={0, 86063}, ...}) = 0 <0.000037>
15:26:48.962069 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 428810}, ru_stime={0, 91730}, ...}) = 0 <0.000054>
15:26:50.966768 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 433422}, ru_stime={0, 96067}, ...}) = 0 <0.000015>
15:26:52.963272 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 436899}, ru_stime={0, 99959}, ...}) = 0 <0.000015>
15:26:54.971342 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 441843}, ru_stime={0, 100573}, ...}) = 0 <0.000070>
15:26:56.978882 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 446572}, ru_stime={0, 102529}, ...}) = 0 <0.000017>
15:26:58.981386 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 450588}, ru_stime={0, 107228}, ...}) = 0 <0.000026>
15:27:00.981732 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 452718}, ru_stime={0, 109749}, ...}) = 0 <0.000072>
--//以上基本2秒间隔。
--//2025-02-07 15:27:01,set *(int *)0x6cfa1404=0x0.
15:27:01.906844 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 455381}, ru_stime={0, 110117}, ...}) = 0 <0.000018>
15:27:02.507095 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 524171}, ru_stime={0, 145603}, ...}) = 0 <0.000032>
15:27:02.977242 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 613417}, ru_stime={0, 160914}, ...}) = 0 <0.000007>
15:27:03.020355 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 623319}, ru_stime={0, 161481}, ...}) = 0 <0.000006>
15:27:03.533703 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 700621}, ru_stime={0, 185209}, ...}) = 0 <0.000007>
15:27:04.045811 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 744292}, ru_stime={0, 209496}, ...}) = 0 <0.000008>
15:27:04.559666 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 811104}, ru_stime={0, 234625}, ...}) = 0 <0.000007>
15:27:04.980668 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 877326}, ru_stime={0, 267244}, ...}) = 0 <0.000007>
15:27:05.083171 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 889736}, ru_stime={0, 270556}, ...}) = 0 <0.000008>
15:27:05.596662 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 890103}, ru_stime={0, 274617}, ...}) = 0 <0.000028>
15:27:06.110036 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 975686}, ru_stime={0, 308338}, ...}) = 0 <0.000005>
15:27:06.622168 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={1, 52302}, ru_stime={0, 337591}, ...}) = 0 <0.000013>
15:27:06.978185 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={1, 99112}, ru_stime={0, 354831}, ...}) = 0 <0.000085>
15:27:07.135351 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={1, 128844}, ru_stime={0, 360498}, ...}) = 0 <0.000006>
15:27:07.663219 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={1, 220534}, ru_stime={0, 382071}, ...}) = 0 <0.000006>
15:27:08.175760 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={1, 282472}, ru_stime={0, 410056}, ...}) = 0 <0.000024>
15:27:08.693119 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={1, 296474}, ru_stime={0, 412372}, ...}) = 0 <0.000028>
15:27:08.985687 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={1, 340967}, ru_stime={0, 420797}, ...}) = 0 <0.000016>
15:27:09.206344 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={1, 371415}, ru_stime={0, 436874}, ...}) = 0 <0.000006>
15:27:09.723266 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={1, 457950}, ru_stime={0, 450432}, ...}) = 0 <0.000006>
15:27:10.236054 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={1, 515126}, ru_stime={0, 477863}, ...}) = 0 <0.000005>
15:27:10.750786 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={1, 602139}, ru_stime={0, 499834}, ...}) = 0 <0.000006>
15:27:10.986176 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={1, 635316}, ru_stime={0, 509629}, ...}) = 0 <0.000005>
15:27:11.008831 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={1, 638633}, ru_stime={0, 511753}, ...}) = 0 <0.000006>
--//似乎后面2个都在继续调用getrusage。存在2个间隔都是2秒。

$ awk '{print $2}' 0207mutexb.txt |egrep "semtimedop|getrusage|sched_yield|select" | uniq -c | head -12
      2 getrusage(0x1
      2 sched_yield()
     71 semtimedop(98304,
      1 getrusage(0x1
     92 semtimedop(98304,
      1 getrusage(0x1
     83 semtimedop(98304,
      1 getrusage(0x1
    117 semtimedop(98304,
      1 getrusage(0x1
    118 semtimedop(98304,
      1 getrusage(0x1
--//开始调用1次sched_yield(),semtimedop多次,2秒之后调用getrusage。

$ awk '/^15.27./{print $2}' 0207mutexb.txt |egrep "semtimedop|getrusage|sched_yield|select" | uniq -c | head -14
     57 semtimedop(98304,
      1 getrusage(0x1
     56 semtimedop(98304,
      1 getrusage(0x1
     99 sched_yield()
      1 select(0,
     99 sched_yield()
      1 select(0,
     99 sched_yield()
      1 select(0,
     99 sched_yield()
      1 select(0,
     99 sched_yield()
      1 select(0,
--//99次sched_yield,1次select。遇到getrusage分开,相加次数还是99次,如此反复循环。

$ awk '{print $2}' 0207mutexb.txt |egrep "semtimedop|getrusage|sched_yield|select" | sort | uniq -c
     53 getrusage(0x1
 129989 sched_yield()
   1313 select(0,
   3099 semtimedop(98304,

--//sleeps =  129989+1313+3099 = 134401,远远大于3329,实际上单次sleeps最大的sleeps的保存是0xffff,
--//134401 = 0x20d01, 16进制后4位是0x0d01 = 3329,与opeek,mutexprofz的输出一致。

SYS@book> @opeek 0x6cfa13f0 48 0
[06CFA13F0, 06CFA1420) = 67DCBD20 00000000 67DCBD20 00000000 00000000 00000000 00000008 00000D01 00000000 00000000 66A10BB8 00000000

$ egrep "semtimedop" 0207mutexb.txt | head -4
15:26:07.150907 semtimedop(98304, {{46, -1, 0}}, 1, {0, 10000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.010787>
15:26:07.161795 semtimedop(98304, {{46, -1, 0}}, 1, {0, 10000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.030185>
15:26:07.192224 semtimedop(98304, {{46, -1, 0}}, 1, {0, 10000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.020344>
15:26:07.212747 semtimedop(98304, {{46, -1, 0}}, 1, {0, 10000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.010422>
--//{0, 10000000} 前面参数的时间单位是秒,后面参数的时间单位是纳秒。10000000/10^9 = .01,相当于10毫秒

$ egrep "select" 0207mutexb.txt | head -4
15:27:01.913128 select(0, [], [], [], {0, 1000}) = 0 (Timeout) <0.001389>
15:27:01.920727 select(0, [], [], [], {0, 1000}) = 0 (Timeout) <0.001606>
15:27:01.928416 select(0, [], [], [], {0, 1000}) = 0 (Timeout) <0.004600>
15:27:01.939098 select(0, [], [], [], {0, 1000}) = 0 (Timeout) <0.001875>
--//休眠的时间单位微秒(1/10^6秒),1000微秒= 1000/10^6  = .001秒。

posted @   lfree  阅读(2)  评论(0编辑  收藏  举报
相关博文:
阅读排行:
· 一个费力不讨好的项目,让我损失了近一半的绩效!
· 清华大学推出第四讲使用 DeepSeek + DeepResearch 让科研像聊天一样简单!
· 实操Deepseek接入个人知识库
· CSnakes vs Python.NET:高效嵌入与灵活互通的跨语言方案对比
· Plotly.NET 一个为 .NET 打造的强大开源交互式图表库
历史上的今天:
2024-02-19 [20240219]建立完善sql_idx.sh脚本.txt
2019-02-19 [20190219]那个更快(11g).txt
点击右上角即可分享
微信分享提示