[20250204]21c library cache mutex的深入探究8(_mutex_wait_time>1)

来源:这里教程网 时间:2026-03-03 21:33:18 作者:

[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秒。

相关推荐