[20250204]21c library cache mutex的深入探究8(_mutex_wait_scheme=2 _mutex_wait_time大于1).txt
[20250204]21c library cache mutex的深入探究8(_mutex_wait_scheme=2 _mutex_wait_time大于1).txt
--//探究library cache mutex阻塞导致的相关等待事件,分析_mutex_wait_scheme=2,_mutex_wait_time>1的情况的相关细节。
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)
--//本文的目的测试看看当_mutex_wait_scheme = 2 & _mutex_wait_time = t ,t=1时每次调用semtimedop都是0.01秒。
--//并没有出现EXP BACKOFF with maximum sleep的情况。
--//测试_mutex_wait_time >1的情况下,是否出现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
--//为了避免前面测试的干扰,重启数据库,并设置_mutex_wait_time=200看看。
SYS@book> alter system set "_mutex_wait_time"=200 scope=memory;
System altered.
--//相当于2秒。
3.测试:
--//session 2:
SYS@book> @opeek 0x6cfa13f0 48 0
[06CFA13F0, 06CFA1420) = 6CFA13F0 00000000 6CFA13F0 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
--//前面2个8字节等于0x6cfa13f0,说明没有对象使用该library cache mutex。
--//session 1:
SCOTT@book01p> @ spid
==============================
SID : 395
SERIAL# : 63864
PROCESS : 4933
SERVER : DEDICATED
SPID : 4935
PID : 51
P_SERIAL# : 4
KILL_COMMAND : alter system kill session '395,63864' immediate;
PL/SQL procedure successfully completed.
SCOTT@book01p> alter session set session_cached_cursors=0 ;
Session altered.
--//主要目的避免光标缓存,保证每次执行library cache mutex gets增加。
SCOTT@book01p> select /*+ 9 */ count(*) from dept where deptno = 93834;
COUNT(*)
----------
0
--//执行多次。
SCOTT@book01p> @ hash
HASH_VALUE SQL_ID CHILD_NUMBER KGL_BUCKET PLAN_HASH_VALUE HASH_HEX SQL_EXEC_START SQL_EXEC_ID
---------- ------------- ------------ ---------- --------------- ---------- ------------------- -----------
3403546624 as3g00v5dw000 0 0 2236899148 cade0000 2025-02-04 16:02:24 16777218
--//session 2:
SYS@book> @opeek 0x6cfa13f0 48 0
[06CFA13F0, 06CFA1420) = 6743A7A8 00000000 6743A7A8 00000000 00000000 00000000 00000009 00000000 00000000 00000000 66F022A8 00000000
4.继续测试:
--//由于目前版本21c不支持oradebug poke内存信息,采用gdb操作。
--//session 3:
SYS@book> @ spid
==============================
SID : 17
SERIAL# : 53159
PROCESS : 4956
SERVER : DEDICATED
SPID : 4957
PID : 64
P_SERIAL# : 2
KILL_COMMAND : alter system kill session '17,53159' immediate;
PL/SQL procedure successfully completed.
--//window 1:
$ rlgdb -f -p 4957
...
(gdb) x /8wx 0x6cfa1400
0x6cfa1400: 0x00000000 0x00000000 0x00000009 0x00000000
0x6cfa1410: 0x00000000 0x00000000 0x66f022a8 0x00000000
--//当前gets=0x9.
(gdb) set *(int *)0x6cfa1404=0x8888
(gdb) x /8wx 0x6cfa1400
0x6cfa1400: 0x00000000 0x00008888 0x00000009 0x00000000
0x6cfa1410: 0x00000000 0x00000000 0x66f022a8 0x00000000
--//windows 2,跟踪session 1进程:
$ strace -Ttt -y -f -p 4935 2>&1 | tee mutex0204b.txt
--//session 1:
SCOTT@book01p> select /*+ 9 */ count(*) from dept where deptno = 93834;
--//挂起,等4X秒。
--//window 1:
(gdb) set *(int *)0x6cfa1404=0x0
--//session 1:
SCOTT@book01p> select /*+ 9 */ count(*) from dept where deptno = 93834;
COUNT(*)
----------
0
--//执行完成。
--//session 2:
SYS@book> @opeek 0x6cfa13f0 48 0
[06CFA13F0, 06CFA1420) = 6743A7A8 00000000 6743A7A8 00000000 00000000 00000000 0000000A 00000025 00000000 00000000 66F022A8 00000000
--//对比前面的gets从0x9->0xA. 增加1次,sleeps次数从0x0->0x25 =37,增加37次。
$ egrep "sched_yield|getrusage" mutex0204b.txt
16:07:35.366022 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 289933}, ru_stime={0, 18908}, ...}) = 0 <0.000015>
16:07:35.366136 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 289979}, ru_stime={0, 18911}, ...}) = 0 <0.000013>
16:07:35.366232 sched_yield() = 0 <0.000032>
16:07:35.366330 sched_yield() = 0 <0.000016>
16:07:36.954171 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 290460}, ru_stime={0, 18943}, ...}) = 0 <0.000031>
16:07:40.336531 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 290563}, ru_stime={0, 18949}, ...}) = 0 <0.000199>
16:07:42.364438 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 290670}, ru_stime={0, 18956}, ...}) = 0 <0.000089>
16:07:44.415681 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 290841}, ru_stime={0, 18967}, ...}) = 0 <0.000031>
16:07:46.424966 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 290914}, ru_stime={0, 18972}, ...}) = 0 <0.000037>
16:07:48.432955 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 290965}, ru_stime={0, 18976}, ...}) = 0 <0.000030>
16:07:50.436952 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 291140}, ru_stime={0, 18987}, ...}) = 0 <0.000076>
16:07:52.449685 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 291244}, ru_stime={0, 18994}, ...}) = 0 <0.000082>
16:07:54.451323 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 291298}, ru_stime={0, 18997}, ...}) = 0 <0.000029>
16:07:56.463819 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 291349}, ru_stime={0, 19001}, ...}) = 0 <0.000128>
16:07:58.464690 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 291428}, ru_stime={0, 19006}, ...}) = 0 <0.000045>
16:08:00.468074 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 291597}, ru_stime={0, 19006}, ...}) = 0 <0.000087>
16:08:02.477534 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 291653}, ru_stime={0, 19006}, ...}) = 0 <0.000065>
16:08:04.494453 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 291770}, ru_stime={0, 19006}, ...}) = 0 <0.000029>
16:08:06.500738 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 291878}, ru_stime={0, 19006}, ...}) = 0 <0.000130>
16:08:08.502009 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 291948}, ru_stime={0, 19006}, ...}) = 0 <0.000030>
16:08:10.504447 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 292016}, ru_stime={0, 19006}, ...}) = 0 <0.000088>
16:08:12.513079 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 292265}, ru_stime={0, 19006}, ...}) = 0 <0.000032>
16:08:14.518111 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 292364}, ru_stime={0, 19006}, ...}) = 0 <0.000028>
16:08:16.520604 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 292458}, ru_stime={0, 19006}, ...}) = 0 <0.000029>
16:08:18.524013 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 292513}, ru_stime={0, 19008}, ...}) = 0 <0.000014>
16:08:20.524774 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 292717}, ru_stime={0, 19021}, ...}) = 0 <0.000031>
16:08:22.529713 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 292909}, ru_stime={0, 19021}, ...}) = 0 <0.000024>
16:08:24.535057 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 292973}, ru_stime={0, 19021}, ...}) = 0 <0.000029>
16:08:26.542336 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 293058}, ru_stime={0, 19021}, ...}) = 0 <0.000047>
16:08:28.549802 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 293159}, ru_stime={0, 19021}, ...}) = 0 <0.000039>
16:08:30.552271 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 293256}, ru_stime={0, 19021}, ...}) = 0 <0.000060>
16:08:32.566288 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 293364}, ru_stime={0, 19021}, ...}) = 0 <0.000047>
16:08:32.568322 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 293364}, ru_stime={0, 20011}, ...}) = 0 <0.000058>
--//注意看时间间隔,开始sched_yield2次之后2秒调用1次getrusage。除了第1,2次间隔36.954171-35.366136 = 1.588035,
--//40.336531-36.954171 = 3.38236秒。出现这样的情况与设置_mutex_wait_time=200有关,看下面semtimedop的休眠时间就可以知道
--//为什么?
$ awk '{print $2}' mutex0204b.txt |egrep "semtimedop|getrusage|sched_yield|select" | uniq -c|head
2 getrusage(0x1
2 sched_yield()
7 semtimedop(262144,
1 getrusage(0x1
2 semtimedop(262144,
1 getrusage(0x1
1 semtimedop(262144,
1 getrusage(0x1
1 semtimedop(262144,
1 getrusage(0x1
--//可以看出规律,开始2次sched_yield,接着调用semtimedop,2秒之后调用1次getrusage,如此重复。
$ egrep "semtimedop|getrusage" mutex0204b.txt | head -16
16:07:35.366022 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 289933}, ru_stime={0, 18908}, ...}) = 0 <0.000015>
16:07:35.366136 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 289979}, ru_stime={0, 18911}, ...}) = 0 <0.000013>
16:07:35.366380 semtimedop(262144, {{55, -1, 0}}, 1, {0, 10000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.014299>
16:07:35.380786 semtimedop(262144, {{55, -1, 0}}, 1, {0, 20000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.032584>
16:07:35.413455 semtimedop(262144, {{55, -1, 0}}, 1, {0, 40000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.048156>
16:07:35.461738 semtimedop(262144, {{55, -1, 0}}, 1, {0, 80000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.105115>
16:07:35.567193 semtimedop(262144, {{55, -1, 0}}, 1, {0, 170000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.189166>
16:07:35.756537 semtimedop(262144, {{55, -1, 0}}, 1, {0, 340000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.438653>
16:07:36.195344 semtimedop(262144, {{55, -1, 0}}, 1, {0, 690000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.758518>
--// 1+2+4+8+17+34+69 = 135,小于2秒,这里出现调用getrusage小于2秒的间歇。
16:07:36.954171 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 290460}, ru_stime={0, 18943}, ...}) = 0 <0.000031>
16:07:36.954382 semtimedop(262144, {{55, -1, 0}}, 1, {1, 380000000}) = -1 EAGAIN (Resource temporarily unavailable) <1.379731>
16:07:38.334248 semtimedop(262144, {{55, -1, 0}}, 1, {2, 0}) = -1 EAGAIN (Resource temporarily unavailable) <2.002140>
--// 1.38+2 = 3.38,大于2秒,这里出现调用getrusage大于2秒的间歇。
16:07:40.336531 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 290563}, ru_stime={0, 18949}, ...}) = 0 <0.000199>
16:07:40.336970 semtimedop(262144, {{55, -1, 0}}, 1, {2, 0}) = -1 EAGAIN (Resource temporarily unavailable) <2.027328>
16:07:42.364438 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 290670}, ru_stime={0, 18956}, ...}) = 0 <0.000089>
16:07:42.364621 semtimedop(262144, {{55, -1, 0}}, 1, {2, 0}) = -1 EAGAIN (Resource temporarily unavailable) <2.050807>
$ grep semtimedop mutex0204b.txt | awk '{print $8}'| uniq -c
1 10000000})
1 20000000})
1 40000000})
1 80000000})
1 170000000})
1 340000000})
1 690000000})
1 380000000})
27 0}) --//27次2秒调用。
$ grep semtimedop mutex0204b.txt | awk '{print $8}'| wc
35 35 200
--//调用semtimedop 35次,加上2次sched_yield(),sleeps合计37,与opeek看到的结果0x0000025=37一致。
--//注意看semtimedop调用时间上的变化:
--//0,10000000->0,20000000->0.40000000->0,80000000->0,170000000->0,340000000->0,690000000->1,380000000->2,0->2,0->...
--//出现EXP BACKOFF with maximum sleep 现象,翻译就是指数回退现象。
SYS@book> @ mutexprofz id,loc "ts>=trunc(sysdate)+16/24+07/1440+34/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 ID GET_LOCATION OBJECT_NAME
---------- -------------- --------------- ---------- --------------------------------- --------------------------
37 Library Cache 0 kglhdgn1 62 (name not found)
--//记录的sleeps次数也是37次。GET_LOCATION 对应的数字62 与前面ashtop 看到的p2 0x3e对应,注意id=0表示bucket桶号。
$ ./lookup.awk kglhdgn1
(kglhdgn)1 : kernel generic library cache management object handle get handle, if it doesn't exist, create it ??
5.补充说明:
--//如果设置_mutex_wait_time很大,没有实际意义,这时候getrusage时间间歇不再是2秒,最后是12秒。
SYS@book> alter system set "_mutex_wait_time"=1200 scope=memory;
System altered.
$ strace -Ttt -y -f -p 4935 2>&1 | tee mutex0204c.txt
Process 4935 attached
16:33:07.351687 read(16<socket:[30585]>, "\0\0\1\240\6\0\0\0\0\0\21iA\376\377\377\377\377\377\377\377\1\0\0\0\0\0\0\0\6\0\0"..., 8208) = 416 <1.667917>
16:33:09.019922 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 293364}, ru_stime={0, 20011}, ...}) = 0 <0.000009>
16:33:09.020021 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 293364}, ru_stime={0, 20011}, ...}) = 0 <0.000007>
16:33:09.020090 sched_yield() = 0 <0.000052>
16:33:09.020187 sched_yield() = 0 <0.000019>
16:33:09.020233 semtimedop(262144, {{55, -1, 0}}, 1, {0, 10000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.010288>
16:33:09.030594 semtimedop(262144, {{55, -1, 0}}, 1, {0, 20000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.026353>
16:33:09.057015 semtimedop(262144, {{55, -1, 0}}, 1, {0, 40000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.045969>
16:33:09.103124 semtimedop(262144, {{55, -1, 0}}, 1, {0, 90000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.094419>
16:33:09.197673 semtimedop(262144, {{55, -1, 0}}, 1, {0, 190000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.193284>
16:33:09.391115 semtimedop(262144, {{55, -1, 0}}, 1, {0, 380000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.382748>
16:33:09.773980 semtimedop(262144, {{55, -1, 0}}, 1, {0, 760000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.846228>
16:33:10.620387 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 293492}, ru_stime={0, 20058}, ...}) = 0 <0.000018>
16:33:10.620474 semtimedop(262144, {{55, -1, 0}}, 1, {1, 520000000}) = -1 EAGAIN (Resource temporarily unavailable) <1.537400>
16:33:12.157947 semtimedop(262144, {{55, -1, 0}}, 1, {3, 50000000}) = -1 EAGAIN (Resource temporarily unavailable) <3.054631>
16:33:15.212714 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 293630}, ru_stime={0, 20068}, ...}) = 0 <0.000013>
16:33:15.212803 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.005837>
16:33:18.218701 semtimedop(262144, {{55, -1, 0}}, 1, {3, 104101000}) = -1 EAGAIN (Resource temporarily unavailable) <3.107612>
16:33:21.326406 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 293738}, ru_stime={0, 20075}, ...}) = 0 <0.000014>
16:33:21.326494 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <2.999727>
16:33:24.326282 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.000130>
16:33:27.326546 semtimedop(262144, {{55, -1, 0}}, 1, {5, 999954000}) = -1 EAGAIN (Resource temporarily unavailable) <6.010356>
16:33:33.337011 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 293971}, ru_stime={0, 20091}, ...}) = 0 <0.000014>
16:33:33.337115 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.010616>
16:33:36.347971 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.017368>
16:33:39.365672 semtimedop(262144, {{55, -1, 0}}, 1, {5, 971485000}) = -1 EAGAIN (Resource temporarily unavailable) <5.989490>
16:33:45.355288 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 294125}, ru_stime={0, 20102}, ...}) = 0 <0.000019>
16:33:45.355435 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.010445>
SYS@book> alter system set "_mutex_wait_time"=5000 scope=memory;
System altered.
$ strace -Ttt -y -f -p 4935 2>&1 | tee mutex0204d.txt
Process 4935 attached
16:40:42.509184 read(16<socket:[30585]>, "\0\0\1\240\6\0\0\0\0\0\21iD\376\377\377\377\377\377\377\377\1\0\0\0\0\0\0\0\7\0\0"..., 8208) = 416 <1.604775>
16:40:44.114178 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 296728}, ru_stime={0, 23397}, ...}) = 0 <0.000008>
16:40:44.114319 sched_yield() = 0 <0.000047>
16:40:44.114503 sched_yield() = 0 <0.000119>
16:40:44.114689 semtimedop(262144, {{55, -1, 0}}, 1, {0, 10000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.011245>
16:40:44.126018 semtimedop(262144, {{55, -1, 0}}, 1, {0, 20000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.029844>
16:40:44.155924 semtimedop(262144, {{55, -1, 0}}, 1, {0, 40000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.040734>
16:40:44.196738 semtimedop(262144, {{55, -1, 0}}, 1, {0, 90000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.094686>
16:40:44.291502 semtimedop(262144, {{55, -1, 0}}, 1, {0, 190000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.207473>
16:40:44.499158 semtimedop(262144, {{55, -1, 0}}, 1, {0, 390000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.390151>
16:40:44.889457 semtimedop(262144, {{55, -1, 0}}, 1, {0, 780000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.790779>
16:40:45.680396 semtimedop(262144, {{55, -1, 0}}, 1, {1, 570000000}) = -1 EAGAIN (Resource temporarily unavailable) <1.569574>
16:40:47.250064 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 297301}, ru_stime={0, 23443}, ...}) = 0 <0.000014>
16:40:47.250153 semtimedop(262144, {{55, -1, 0}}, 1, {3, 150000000}) = -1 EAGAIN (Resource temporarily unavailable) <3.151710>
16:40:50.401941 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 297376}, ru_stime={0, 23449}, ...}) = 0 <0.000014>
16:40:50.402037 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001986>
16:40:53.404088 semtimedop(262144, {{55, -1, 0}}, 1, {3, 307950000}) = -1 EAGAIN (Resource temporarily unavailable) <3.308673>
16:40:56.712914 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 297487}, ru_stime={0, 23457}, ...}) = 0 <0.000113>
16:40:56.713135 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.000733>
16:40:59.713976 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.010793>
16:41:02.724890 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.016674>
16:41:05.741684 semtimedop(262144, {{55, -1, 0}}, 1, {3, 591435000}) = -1 EAGAIN (Resource temporarily unavailable) <3.607961>
16:41:09.349742 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 297900}, ru_stime={0, 23490}, ...}) = 0 <0.000040>
16:41:09.349960 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.017286>
16:41:12.367397 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001125>
16:41:15.368643 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.017873>
16:41:18.386641 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001640>
16:41:21.388405 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.000991>
16:41:24.389518 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001038>
16:41:27.390677 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001919>
16:41:30.392801 semtimedop(262144, {{55, -1, 0}}, 1, {4, 197159000}) = -1 EAGAIN (Resource temporarily unavailable) <4.201812>
16:41:34.594822 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 298756}, ru_stime={0, 23557}, ...}) = 0 <0.000035>
16:41:34.595027 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.004639>
16:41:37.599778 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.006057>
16:41:40.605956 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001773>
16:41:43.607987 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.012962>
16:41:46.621072 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.012515>
16:41:49.633726 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.003316>
16:41:52.637193 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.000112>
16:41:55.637444 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.012365>
16:41:58.649941 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.013924>
16:42:01.663988 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.003015>
16:42:04.667188 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.004693>
16:42:07.672005 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.002168>
16:42:10.674295 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.000473>
16:42:13.674887 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.004575>
16:42:16.679692 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.010170>
16:42:19.690043 semtimedop(262144, {{55, -1, 0}}, 1, {4, 904989000}) = -1 EAGAIN (Resource temporarily unavailable) <4.920992>
16:42:24.611135 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 299627}, ru_stime={0, 23626}, ...}) = 0 <0.000029>
16:42:24.611239 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.007973>
16:42:27.619312 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.002894>
16:42:30.622329 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.009767>
16:42:33.632219 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.014810>
16:42:36.647207 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <2.999745>
16:42:39.647074 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.000077>
16:42:42.647328 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.009985>
16:42:45.657433 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.005072>
16:42:48.662626 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.003804>
16:42:51.666523 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.009973>
16:42:54.676613 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <2.999223>
16:42:57.675978 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.021504>
16:43:00.697660 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.006737>
16:43:03.704521 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.008046>
16:43:06.712688 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.007068>
16:43:09.719877 semtimedop(262144, {{55, -1, 0}}, 1, {4, 891360000}) = -1 EAGAIN (Resource temporarily unavailable) <4.908715>
16:43:14.628730 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 300538}, ru_stime={0, 23698}, ...}) = 0 <0.000025>
--//oracle拆分为许多3秒,不足补齐,15*3+5 = 50.
--//调用getrusage的间隔不再是2秒,最大50秒。
--//探究library cache mutex阻塞导致的相关等待事件,分析_mutex_wait_scheme=2,_mutex_wait_time>1的情况的相关细节。
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)
--//本文的目的测试看看当_mutex_wait_scheme = 2 & _mutex_wait_time = t ,t=1时每次调用semtimedop都是0.01秒。
--//并没有出现EXP BACKOFF with maximum sleep的情况。
--//测试_mutex_wait_time >1的情况下,是否出现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
--//为了避免前面测试的干扰,重启数据库,并设置_mutex_wait_time=200看看。
SYS@book> alter system set "_mutex_wait_time"=200 scope=memory;
System altered.
--//相当于2秒。
3.测试:
--//session 2:
SYS@book> @opeek 0x6cfa13f0 48 0
[06CFA13F0, 06CFA1420) = 6CFA13F0 00000000 6CFA13F0 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
--//前面2个8字节等于0x6cfa13f0,说明没有对象使用该library cache mutex。
--//session 1:
SCOTT@book01p> @ spid
==============================
SID : 395
SERIAL# : 63864
PROCESS : 4933
SERVER : DEDICATED
SPID : 4935
PID : 51
P_SERIAL# : 4
KILL_COMMAND : alter system kill session '395,63864' immediate;
PL/SQL procedure successfully completed.
SCOTT@book01p> alter session set session_cached_cursors=0 ;
Session altered.
--//主要目的避免光标缓存,保证每次执行library cache mutex gets增加。
SCOTT@book01p> select /*+ 9 */ count(*) from dept where deptno = 93834;
COUNT(*)
----------
0
--//执行多次。
SCOTT@book01p> @ hash
HASH_VALUE SQL_ID CHILD_NUMBER KGL_BUCKET PLAN_HASH_VALUE HASH_HEX SQL_EXEC_START SQL_EXEC_ID
---------- ------------- ------------ ---------- --------------- ---------- ------------------- -----------
3403546624 as3g00v5dw000 0 0 2236899148 cade0000 2025-02-04 16:02:24 16777218
--//session 2:
SYS@book> @opeek 0x6cfa13f0 48 0
[06CFA13F0, 06CFA1420) = 6743A7A8 00000000 6743A7A8 00000000 00000000 00000000 00000009 00000000 00000000 00000000 66F022A8 00000000
4.继续测试:
--//由于目前版本21c不支持oradebug poke内存信息,采用gdb操作。
--//session 3:
SYS@book> @ spid
==============================
SID : 17
SERIAL# : 53159
PROCESS : 4956
SERVER : DEDICATED
SPID : 4957
PID : 64
P_SERIAL# : 2
KILL_COMMAND : alter system kill session '17,53159' immediate;
PL/SQL procedure successfully completed.
--//window 1:
$ rlgdb -f -p 4957
...
(gdb) x /8wx 0x6cfa1400
0x6cfa1400: 0x00000000 0x00000000 0x00000009 0x00000000
0x6cfa1410: 0x00000000 0x00000000 0x66f022a8 0x00000000
--//当前gets=0x9.
(gdb) set *(int *)0x6cfa1404=0x8888
(gdb) x /8wx 0x6cfa1400
0x6cfa1400: 0x00000000 0x00008888 0x00000009 0x00000000
0x6cfa1410: 0x00000000 0x00000000 0x66f022a8 0x00000000
--//windows 2,跟踪session 1进程:
$ strace -Ttt -y -f -p 4935 2>&1 | tee mutex0204b.txt
--//session 1:
SCOTT@book01p> select /*+ 9 */ count(*) from dept where deptno = 93834;
--//挂起,等4X秒。
--//window 1:
(gdb) set *(int *)0x6cfa1404=0x0
--//session 1:
SCOTT@book01p> select /*+ 9 */ count(*) from dept where deptno = 93834;
COUNT(*)
----------
0
--//执行完成。
--//session 2:
SYS@book> @opeek 0x6cfa13f0 48 0
[06CFA13F0, 06CFA1420) = 6743A7A8 00000000 6743A7A8 00000000 00000000 00000000 0000000A 00000025 00000000 00000000 66F022A8 00000000
--//对比前面的gets从0x9->0xA. 增加1次,sleeps次数从0x0->0x25 =37,增加37次。
$ egrep "sched_yield|getrusage" mutex0204b.txt
16:07:35.366022 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 289933}, ru_stime={0, 18908}, ...}) = 0 <0.000015>
16:07:35.366136 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 289979}, ru_stime={0, 18911}, ...}) = 0 <0.000013>
16:07:35.366232 sched_yield() = 0 <0.000032>
16:07:35.366330 sched_yield() = 0 <0.000016>
16:07:36.954171 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 290460}, ru_stime={0, 18943}, ...}) = 0 <0.000031>
16:07:40.336531 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 290563}, ru_stime={0, 18949}, ...}) = 0 <0.000199>
16:07:42.364438 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 290670}, ru_stime={0, 18956}, ...}) = 0 <0.000089>
16:07:44.415681 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 290841}, ru_stime={0, 18967}, ...}) = 0 <0.000031>
16:07:46.424966 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 290914}, ru_stime={0, 18972}, ...}) = 0 <0.000037>
16:07:48.432955 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 290965}, ru_stime={0, 18976}, ...}) = 0 <0.000030>
16:07:50.436952 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 291140}, ru_stime={0, 18987}, ...}) = 0 <0.000076>
16:07:52.449685 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 291244}, ru_stime={0, 18994}, ...}) = 0 <0.000082>
16:07:54.451323 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 291298}, ru_stime={0, 18997}, ...}) = 0 <0.000029>
16:07:56.463819 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 291349}, ru_stime={0, 19001}, ...}) = 0 <0.000128>
16:07:58.464690 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 291428}, ru_stime={0, 19006}, ...}) = 0 <0.000045>
16:08:00.468074 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 291597}, ru_stime={0, 19006}, ...}) = 0 <0.000087>
16:08:02.477534 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 291653}, ru_stime={0, 19006}, ...}) = 0 <0.000065>
16:08:04.494453 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 291770}, ru_stime={0, 19006}, ...}) = 0 <0.000029>
16:08:06.500738 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 291878}, ru_stime={0, 19006}, ...}) = 0 <0.000130>
16:08:08.502009 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 291948}, ru_stime={0, 19006}, ...}) = 0 <0.000030>
16:08:10.504447 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 292016}, ru_stime={0, 19006}, ...}) = 0 <0.000088>
16:08:12.513079 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 292265}, ru_stime={0, 19006}, ...}) = 0 <0.000032>
16:08:14.518111 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 292364}, ru_stime={0, 19006}, ...}) = 0 <0.000028>
16:08:16.520604 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 292458}, ru_stime={0, 19006}, ...}) = 0 <0.000029>
16:08:18.524013 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 292513}, ru_stime={0, 19008}, ...}) = 0 <0.000014>
16:08:20.524774 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 292717}, ru_stime={0, 19021}, ...}) = 0 <0.000031>
16:08:22.529713 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 292909}, ru_stime={0, 19021}, ...}) = 0 <0.000024>
16:08:24.535057 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 292973}, ru_stime={0, 19021}, ...}) = 0 <0.000029>
16:08:26.542336 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 293058}, ru_stime={0, 19021}, ...}) = 0 <0.000047>
16:08:28.549802 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 293159}, ru_stime={0, 19021}, ...}) = 0 <0.000039>
16:08:30.552271 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 293256}, ru_stime={0, 19021}, ...}) = 0 <0.000060>
16:08:32.566288 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 293364}, ru_stime={0, 19021}, ...}) = 0 <0.000047>
16:08:32.568322 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 293364}, ru_stime={0, 20011}, ...}) = 0 <0.000058>
--//注意看时间间隔,开始sched_yield2次之后2秒调用1次getrusage。除了第1,2次间隔36.954171-35.366136 = 1.588035,
--//40.336531-36.954171 = 3.38236秒。出现这样的情况与设置_mutex_wait_time=200有关,看下面semtimedop的休眠时间就可以知道
--//为什么?
$ awk '{print $2}' mutex0204b.txt |egrep "semtimedop|getrusage|sched_yield|select" | uniq -c|head
2 getrusage(0x1
2 sched_yield()
7 semtimedop(262144,
1 getrusage(0x1
2 semtimedop(262144,
1 getrusage(0x1
1 semtimedop(262144,
1 getrusage(0x1
1 semtimedop(262144,
1 getrusage(0x1
--//可以看出规律,开始2次sched_yield,接着调用semtimedop,2秒之后调用1次getrusage,如此重复。
$ egrep "semtimedop|getrusage" mutex0204b.txt | head -16
16:07:35.366022 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 289933}, ru_stime={0, 18908}, ...}) = 0 <0.000015>
16:07:35.366136 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 289979}, ru_stime={0, 18911}, ...}) = 0 <0.000013>
16:07:35.366380 semtimedop(262144, {{55, -1, 0}}, 1, {0, 10000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.014299>
16:07:35.380786 semtimedop(262144, {{55, -1, 0}}, 1, {0, 20000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.032584>
16:07:35.413455 semtimedop(262144, {{55, -1, 0}}, 1, {0, 40000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.048156>
16:07:35.461738 semtimedop(262144, {{55, -1, 0}}, 1, {0, 80000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.105115>
16:07:35.567193 semtimedop(262144, {{55, -1, 0}}, 1, {0, 170000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.189166>
16:07:35.756537 semtimedop(262144, {{55, -1, 0}}, 1, {0, 340000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.438653>
16:07:36.195344 semtimedop(262144, {{55, -1, 0}}, 1, {0, 690000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.758518>
--// 1+2+4+8+17+34+69 = 135,小于2秒,这里出现调用getrusage小于2秒的间歇。
16:07:36.954171 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 290460}, ru_stime={0, 18943}, ...}) = 0 <0.000031>
16:07:36.954382 semtimedop(262144, {{55, -1, 0}}, 1, {1, 380000000}) = -1 EAGAIN (Resource temporarily unavailable) <1.379731>
16:07:38.334248 semtimedop(262144, {{55, -1, 0}}, 1, {2, 0}) = -1 EAGAIN (Resource temporarily unavailable) <2.002140>
--// 1.38+2 = 3.38,大于2秒,这里出现调用getrusage大于2秒的间歇。
16:07:40.336531 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 290563}, ru_stime={0, 18949}, ...}) = 0 <0.000199>
16:07:40.336970 semtimedop(262144, {{55, -1, 0}}, 1, {2, 0}) = -1 EAGAIN (Resource temporarily unavailable) <2.027328>
16:07:42.364438 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 290670}, ru_stime={0, 18956}, ...}) = 0 <0.000089>
16:07:42.364621 semtimedop(262144, {{55, -1, 0}}, 1, {2, 0}) = -1 EAGAIN (Resource temporarily unavailable) <2.050807>
$ grep semtimedop mutex0204b.txt | awk '{print $8}'| uniq -c
1 10000000})
1 20000000})
1 40000000})
1 80000000})
1 170000000})
1 340000000})
1 690000000})
1 380000000})
27 0}) --//27次2秒调用。
$ grep semtimedop mutex0204b.txt | awk '{print $8}'| wc
35 35 200
--//调用semtimedop 35次,加上2次sched_yield(),sleeps合计37,与opeek看到的结果0x0000025=37一致。
--//注意看semtimedop调用时间上的变化:
--//0,10000000->0,20000000->0.40000000->0,80000000->0,170000000->0,340000000->0,690000000->1,380000000->2,0->2,0->...
--//出现EXP BACKOFF with maximum sleep 现象,翻译就是指数回退现象。
SYS@book> @ mutexprofz id,loc "ts>=trunc(sysdate)+16/24+07/1440+34/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 ID GET_LOCATION OBJECT_NAME
---------- -------------- --------------- ---------- --------------------------------- --------------------------
37 Library Cache 0 kglhdgn1 62 (name not found)
--//记录的sleeps次数也是37次。GET_LOCATION 对应的数字62 与前面ashtop 看到的p2 0x3e对应,注意id=0表示bucket桶号。
$ ./lookup.awk kglhdgn1
(kglhdgn)1 : kernel generic library cache management object handle get handle, if it doesn't exist, create it ??
5.补充说明:
--//如果设置_mutex_wait_time很大,没有实际意义,这时候getrusage时间间歇不再是2秒,最后是12秒。
SYS@book> alter system set "_mutex_wait_time"=1200 scope=memory;
System altered.
$ strace -Ttt -y -f -p 4935 2>&1 | tee mutex0204c.txt
Process 4935 attached
16:33:07.351687 read(16<socket:[30585]>, "\0\0\1\240\6\0\0\0\0\0\21iA\376\377\377\377\377\377\377\377\1\0\0\0\0\0\0\0\6\0\0"..., 8208) = 416 <1.667917>
16:33:09.019922 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 293364}, ru_stime={0, 20011}, ...}) = 0 <0.000009>
16:33:09.020021 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 293364}, ru_stime={0, 20011}, ...}) = 0 <0.000007>
16:33:09.020090 sched_yield() = 0 <0.000052>
16:33:09.020187 sched_yield() = 0 <0.000019>
16:33:09.020233 semtimedop(262144, {{55, -1, 0}}, 1, {0, 10000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.010288>
16:33:09.030594 semtimedop(262144, {{55, -1, 0}}, 1, {0, 20000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.026353>
16:33:09.057015 semtimedop(262144, {{55, -1, 0}}, 1, {0, 40000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.045969>
16:33:09.103124 semtimedop(262144, {{55, -1, 0}}, 1, {0, 90000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.094419>
16:33:09.197673 semtimedop(262144, {{55, -1, 0}}, 1, {0, 190000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.193284>
16:33:09.391115 semtimedop(262144, {{55, -1, 0}}, 1, {0, 380000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.382748>
16:33:09.773980 semtimedop(262144, {{55, -1, 0}}, 1, {0, 760000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.846228>
16:33:10.620387 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 293492}, ru_stime={0, 20058}, ...}) = 0 <0.000018>
16:33:10.620474 semtimedop(262144, {{55, -1, 0}}, 1, {1, 520000000}) = -1 EAGAIN (Resource temporarily unavailable) <1.537400>
16:33:12.157947 semtimedop(262144, {{55, -1, 0}}, 1, {3, 50000000}) = -1 EAGAIN (Resource temporarily unavailable) <3.054631>
16:33:15.212714 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 293630}, ru_stime={0, 20068}, ...}) = 0 <0.000013>
16:33:15.212803 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.005837>
16:33:18.218701 semtimedop(262144, {{55, -1, 0}}, 1, {3, 104101000}) = -1 EAGAIN (Resource temporarily unavailable) <3.107612>
16:33:21.326406 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 293738}, ru_stime={0, 20075}, ...}) = 0 <0.000014>
16:33:21.326494 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <2.999727>
16:33:24.326282 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.000130>
16:33:27.326546 semtimedop(262144, {{55, -1, 0}}, 1, {5, 999954000}) = -1 EAGAIN (Resource temporarily unavailable) <6.010356>
16:33:33.337011 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 293971}, ru_stime={0, 20091}, ...}) = 0 <0.000014>
16:33:33.337115 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.010616>
16:33:36.347971 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.017368>
16:33:39.365672 semtimedop(262144, {{55, -1, 0}}, 1, {5, 971485000}) = -1 EAGAIN (Resource temporarily unavailable) <5.989490>
16:33:45.355288 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 294125}, ru_stime={0, 20102}, ...}) = 0 <0.000019>
16:33:45.355435 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.010445>
SYS@book> alter system set "_mutex_wait_time"=5000 scope=memory;
System altered.
$ strace -Ttt -y -f -p 4935 2>&1 | tee mutex0204d.txt
Process 4935 attached
16:40:42.509184 read(16<socket:[30585]>, "\0\0\1\240\6\0\0\0\0\0\21iD\376\377\377\377\377\377\377\377\1\0\0\0\0\0\0\0\7\0\0"..., 8208) = 416 <1.604775>
16:40:44.114178 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 296728}, ru_stime={0, 23397}, ...}) = 0 <0.000008>
16:40:44.114319 sched_yield() = 0 <0.000047>
16:40:44.114503 sched_yield() = 0 <0.000119>
16:40:44.114689 semtimedop(262144, {{55, -1, 0}}, 1, {0, 10000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.011245>
16:40:44.126018 semtimedop(262144, {{55, -1, 0}}, 1, {0, 20000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.029844>
16:40:44.155924 semtimedop(262144, {{55, -1, 0}}, 1, {0, 40000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.040734>
16:40:44.196738 semtimedop(262144, {{55, -1, 0}}, 1, {0, 90000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.094686>
16:40:44.291502 semtimedop(262144, {{55, -1, 0}}, 1, {0, 190000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.207473>
16:40:44.499158 semtimedop(262144, {{55, -1, 0}}, 1, {0, 390000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.390151>
16:40:44.889457 semtimedop(262144, {{55, -1, 0}}, 1, {0, 780000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.790779>
16:40:45.680396 semtimedop(262144, {{55, -1, 0}}, 1, {1, 570000000}) = -1 EAGAIN (Resource temporarily unavailable) <1.569574>
16:40:47.250064 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 297301}, ru_stime={0, 23443}, ...}) = 0 <0.000014>
16:40:47.250153 semtimedop(262144, {{55, -1, 0}}, 1, {3, 150000000}) = -1 EAGAIN (Resource temporarily unavailable) <3.151710>
16:40:50.401941 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 297376}, ru_stime={0, 23449}, ...}) = 0 <0.000014>
16:40:50.402037 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001986>
16:40:53.404088 semtimedop(262144, {{55, -1, 0}}, 1, {3, 307950000}) = -1 EAGAIN (Resource temporarily unavailable) <3.308673>
16:40:56.712914 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 297487}, ru_stime={0, 23457}, ...}) = 0 <0.000113>
16:40:56.713135 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.000733>
16:40:59.713976 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.010793>
16:41:02.724890 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.016674>
16:41:05.741684 semtimedop(262144, {{55, -1, 0}}, 1, {3, 591435000}) = -1 EAGAIN (Resource temporarily unavailable) <3.607961>
16:41:09.349742 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 297900}, ru_stime={0, 23490}, ...}) = 0 <0.000040>
16:41:09.349960 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.017286>
16:41:12.367397 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001125>
16:41:15.368643 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.017873>
16:41:18.386641 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001640>
16:41:21.388405 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.000991>
16:41:24.389518 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001038>
16:41:27.390677 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001919>
16:41:30.392801 semtimedop(262144, {{55, -1, 0}}, 1, {4, 197159000}) = -1 EAGAIN (Resource temporarily unavailable) <4.201812>
16:41:34.594822 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 298756}, ru_stime={0, 23557}, ...}) = 0 <0.000035>
16:41:34.595027 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.004639>
16:41:37.599778 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.006057>
16:41:40.605956 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001773>
16:41:43.607987 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.012962>
16:41:46.621072 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.012515>
16:41:49.633726 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.003316>
16:41:52.637193 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.000112>
16:41:55.637444 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.012365>
16:41:58.649941 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.013924>
16:42:01.663988 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.003015>
16:42:04.667188 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.004693>
16:42:07.672005 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.002168>
16:42:10.674295 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.000473>
16:42:13.674887 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.004575>
16:42:16.679692 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.010170>
16:42:19.690043 semtimedop(262144, {{55, -1, 0}}, 1, {4, 904989000}) = -1 EAGAIN (Resource temporarily unavailable) <4.920992>
16:42:24.611135 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 299627}, ru_stime={0, 23626}, ...}) = 0 <0.000029>
16:42:24.611239 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.007973>
16:42:27.619312 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.002894>
16:42:30.622329 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.009767>
16:42:33.632219 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.014810>
16:42:36.647207 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <2.999745>
16:42:39.647074 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.000077>
16:42:42.647328 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.009985>
16:42:45.657433 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.005072>
16:42:48.662626 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.003804>
16:42:51.666523 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.009973>
16:42:54.676613 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <2.999223>
16:42:57.675978 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.021504>
16:43:00.697660 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.006737>
16:43:03.704521 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.008046>
16:43:06.712688 semtimedop(262144, {{55, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.007068>
16:43:09.719877 semtimedop(262144, {{55, -1, 0}}, 1, {4, 891360000}) = -1 EAGAIN (Resource temporarily unavailable) <4.908715>
16:43:14.628730 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 300538}, ru_stime={0, 23698}, ...}) = 0 <0.000025>
--//oracle拆分为许多3秒,不足补齐,15*3+5 = 50.
--//调用getrusage的间隔不再是2秒,最大50秒。
【推荐】编程新体验,更懂你的AI,立即体验豆包MarsCode编程助手
【推荐】凌霞软件回馈社区,博客园 & 1Panel & Halo 联合会员上线
【推荐】抖音旗下AI助手豆包,你的智能百科全书,全免费不限次数
【推荐】博客园社区专享云产品让利特惠,阿里云新客6.5折上折
【推荐】轻量又高性能的 SSH 工具 IShell:AI 加持,快人一步
· 一个费力不讨好的项目,让我损失了近一半的绩效!
· 清华大学推出第四讲使用 DeepSeek + DeepResearch 让科研像聊天一样简单!
· 实操Deepseek接入个人知识库
· CSnakes vs Python.NET:高效嵌入与灵活互通的跨语言方案对比
· Plotly.NET 一个为 .NET 打造的强大开源交互式图表库
2024-02-19 [20240219]建立完善sql_idx.sh脚本.txt
2019-02-19 [20190219]那个更快(11g).txt