[20241121]测试软软解析遇到的疑惑.txt
[20241121]测试软软解析遇到的疑惑.txt
--//测试软软解析遇到的疑惑，就是大量软软解析以及分散执行两者的执行时间差别并不是很大，有点疑惑，展开分析看看。
1.环境：
SCOTT@book01p> @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.建立测试环境：
create table job_times (sid number, time_ela number,method varchar2(20));
drop table t purge ;
create table t as select rownum id ,'test' pad from dual connect by level<=5e5;
create unique index pk_t on t(id);
exec dbms_stats.gather_table_stats(user, 't', method_opt=>'for all columns size 1');
$ cat m9.txt
set verify off
insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,'&&2') ;
commit ;
DECLARE
l_count PLS_INTEGER;
BEGIN
FOR i IN 1..&&1
LOOP
EXECUTE IMMEDIATE 'Select /*+ &2 */ count(*) from t where id = :j ' INTO l_count USING i;
END LOOP;
END;
/
update job_times set time_ela = dbms_utility.get_time - time_ela where sid=sys_context ('userenv', 'sid') and method='&&2';
commit;
quit
3.测试：
$ zzdate;seq 20 | xargs -P 20 -IQ sqlplus -s -l scott/book@book01p @m9.txt 5e5 test > /dev/null;zzdate
trunc(sysdate)+10/24+11/1440+58/86400
trunc(sysdate)+10/24+12/1440+49/86400
--//等待测试完成。需要1*60+49-58 = 51秒。
SYS@book> @ ashtop event,p1raw,p1 1=1 trunc(sysdate)+10/24+11/1440+58/86400 trunc(sysdate)+10/24+12/1440+49/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW P1 FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ---------- ------------------- ------------------- ---------- -------- -----------
751 14.7 78% | 752002402 2024-11-21 10:12:01 2024-11-21 10:12:48 397 48 443
191 3.7 20% | cursor: pin S 000000002CD2A562 752002402 2024-11-21 10:12:01 2024-11-21 10:12:47 1 34 34
9 .2 1% | 1413697536 2024-11-21 10:11:59 2024-11-21 10:12:00 8 2 8
2 .0 0% | log file parallel write 0000000000000001 1 2024-11-21 10:12:00 2024-11-21 10:12:48 1 2 2
1 .0 0% | log file sync 000000000000065B 1627 2024-11-21 10:11:59 2024-11-21 10:11:59 1 1 1
1 .0 0% | log file sync 000000000000067D 1661 2024-11-21 10:12:00 2024-11-21 10:12:00 1 1 1
1 .0 0% | log file sync 00000000000006A6 1702 2024-11-21 10:12:48 2024-11-21 10:12:48 1 1 1
1 .0 0% | 100 2024-11-21 10:12:23 2024-11-21 10:12:23 1 1 1
1 .0 0% | 300 2024-11-21 10:12:25 2024-11-21 10:12:25 1 1 1
1 .0 0% | 65536 2024-11-21 10:12:00 2024-11-21 10:12:00 1 1 1
1 .0 0% | 2020423704 2024-11-21 10:12:48 2024-11-21 10:12:48 1 1 1
11 rows selected.
$ zzdate;seq 20 | xargs -P 20 -IQ sqlplus -s -l scott/book@book01p @m9.txt 5e5 Q > /dev/null;zzdate
trunc(sysdate)+10/24+14/1440+24/86400
trunc(sysdate)+10/24+15/1440+15/86400
--//参数2不同导致每个执行sql语句的都不相同，这样相当于分散开来。
--//等待测试完成。需要1*60+15-24 = 51秒。
SYS@book> @ ashtop event,p1raw,p1 1=1 trunc(sysdate)+10/24+14/1440+24/86400 trunc(sysdate)+10/24+15/1440+15/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW P1 FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ---------- ------------------- ------------------- ---------- -------- -----------
900 17.6 94% | 65536 2024-11-21 10:14:26 2024-11-21 10:15:14 446 49 493
48 .9 5% | 1614620816 2024-11-21 10:14:27 2024-11-21 10:15:14 26 48 42
6 .1 1% | 2020423704 2024-11-21 10:15:13 2024-11-21 10:15:14 6 2 6
2 .0 0% | 8 2024-11-21 10:14:26 2024-11-21 10:14:27 2 2 2
2 .0 0% | 100 2024-11-21 10:14:24 2024-11-21 10:14:25 1 2 2
1 .0 0% | 131072 2024-11-21 10:14:25 2024-11-21 10:14:25 1 1 1
6 rows selected.
--//看不见cursor: pin S等待时间。
--//但是前面cursor: pin S 占用191秒，相当于每个会话占用191/20 = 9.55秒，至少应该有9秒的差距。
SCOTT@book01p> Select decode(method,'test','test','Q'),count(*),round(avg(TIME_ELA),0),sum(TIME_ELA) from job_times group by decode(method,'test','test','Q') order by 3 ;
DECO COUNT(*) ROUND(AVG(TIME_ELA),0) SUM(TIME_ELA)
---- ---------- ---------------------- -------------
Q 20 4802 96036
test 20 4822 96449
--//可以发现两者几乎同时完成，根本不存在这么大的差距，为什么呢？总的快了仅仅4秒。
--//实际上ash的取样放大了cursor: pin S等待事件，原来1次sleeps可能1毫秒或者1厘秒，而取样放大1秒，这样相当于一下子放大1000
--//或者100倍。
SYS@book> @ mutexprofz idn,hash,loc,maddr "ts>=trunc(sysdate)+10/24+11/1440+58/86400 and ts<=trunc(sysdate)+10/24+12/1440+49/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 GET_LOCATION mutex_addr OBJECT_NAME
---------- -------------- --------------- ---------- ---------- --------------------------------- -------------------- --------------------------------------------------------------------------------
17 813649 Cursor Pin 752002402 752002402 kksLockDelete [KKSCHLPIN6] 0000000065F1A090 Select /*+ test */ count(*) from t where id = :j
6 249929 Cursor Pin 752002402 752002402 kksfbc [KKSCHLFSP2] 0000000065F1A090 Select /*+ test */ count(*) from t where id = :j
SYS@book> @ mutexprofz idn,hash,loc,maddr "ts>=trunc(sysdate)+10/24+14/1440+24/86400 and ts<=trunc(sysdate)+10/24+15/1440+15/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
no rows selected
--//第2次执行根本没有输出。
4.深入分析:
--//session 1:
SCOTT@book01p> @ spid
==============================
SID : 158
SERIAL# : 47699
PROCESS : 3997
SERVER : DEDICATED
SPID : 3999
PID : 45
P_SERIAL# : 8
KILL_COMMAND : alter system kill session '158,47699' immediate;
PL/SQL procedure successfully completed.
--//session 2:
SYS@book> @ opeek 0000000065F1A090 40 0
[065F1A090, 065F1A0B8) = 00000000 00000000 01312D28 000029F5 2CD2A562 00000000 00000000 00000000 00000000 00000000
--//sleeps = 0x000029F5 = 10741次。
--//2CD2A562 = 752002402对应hash_value，与前面ashtop的P1raw输出一致。
--//window 1:
$ mod_addr.sh 0000000065F1A094 0 1
0x65f1a094: 0x00000001
--//session 2:
SYS@book> @ opeek 0000000065F1A090 40 0
[065F1A090, 065F1A0B8) = 00000000 00000001 01312D28 000029F5 2CD2A562 00000000 00000000 00000000 00000000 00000000
--//人为设置sid=1阻塞其他会话执行。
--//window 2:
$ strace -f -p 3999 -y -Ttt 2>&1 | tee /tmp/test.txt
--//session 1:
SCOTT@book01p> @ m9.txt 1 test
--//执行1次，挂起。
--//window 1:
$ sleep 30
$ mod_addr.sh 0000000065F1A094 0 0
0x65f1a094: 0x00000000
--//session 1,执行完成。
$ egrep "getrusage" /tmp/test.txt
10:41:03.594664 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 155251}, ru_stime={0, 26042}, ...}) = 0 <0.000014>
10:41:03.595953 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 155274}, ru_stime={0, 26874}, ...}) = 0 <0.000007>
10:41:03.597621 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 155459}, ru_stime={0, 26906}, ...}) = 0 <0.000033>
10:41:03.597718 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 155469}, ru_stime={0, 26908}, ...}) = 0 <0.000036>
10:41:03.598342 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 155524}, ru_stime={0, 26917}, ...}) = 0 <0.000078>
10:41:03.598487 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 155545}, ru_stime={0, 26921}, ...}) = 0 <0.000030>
10:41:05.286856 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 185189}, ru_stime={0, 38160}, ...}) = 0 <0.000020> --//开始
10:41:07.289493 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 199727}, ru_stime={0, 51653}, ...}) = 0 <0.000016>
10:41:09.296674 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 220614}, ru_stime={0, 58830}, ...}) = 0 <0.000027>
10:41:11.298284 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 244750}, ru_stime={0, 74489}, ...}) = 0 <0.000011>
10:41:13.299803 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 258506}, ru_stime={0, 89377}, ...}) = 0 <0.000023>
10:41:15.301216 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 276349}, ru_stime={0, 109685}, ...}) = 0 <0.000014>
10:41:17.303491 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 291781}, ru_stime={0, 119890}, ...}) = 0 <0.000013>
10:41:19.306078 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 316665}, ru_stime={0, 136150}, ...}) = 0 <0.000008>
10:41:21.306500 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 334213}, ru_stime={0, 144566}, ...}) = 0 <0.000053>
10:41:23.307949 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 349695}, ru_stime={0, 151694}, ...}) = 0 <0.000014>
10:41:25.310481 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 361525}, ru_stime={0, 173467}, ...}) = 0 <0.000010>
10:41:27.328359 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 366235}, ru_stime={0, 187187}, ...}) = 0 <0.000015>
10:41:29.330023 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 374466}, ru_stime={0, 202904}, ...}) = 0 <0.000009>
10:41:31.332351 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 386455}, ru_stime={0, 209885}, ...}) = 0 <0.000027>
10:41:33.332952 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 411865}, ru_stime={0, 228429}, ...}) = 0 <0.000035>
10:41:35.334616 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 418807}, ru_stime={0, 249539}, ...}) = 0 <0.000014>
10:41:36.453755 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 423399}, ru_stime={0, 258256}, ...}) = 0 <0.000053>
10:41:36.906525 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 550256}, ru_stime={0, 258256}, ...}) = 0 <0.000020>
10:41:37.335758 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 550256}, ru_stime={0, 258256}, ...}) = 0 <0.000021>
10:41:39.338048 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 575565}, ru_stime={0, 267048}, ...}) = 0 <0.000029>
10:41:41.359361 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 584471}, ru_stime={0, 274751}, ...}) = 0 <0.000120>
10:41:43.362103 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 594111}, ru_stime={0, 285503}, ...}) = 0 <0.000008>
10:41:45.373997 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 604310}, ru_stime={0, 298852}, ...}) = 0 <0.000008>
10:41:47.375294 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 611920}, ru_stime={0, 325030}, ...}) = 0 <0.000060>
10:41:47.946923 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 618978}, ru_stime={0, 329564}, ...}) = 0 <0.000025>
10:41:47.948071 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 619977}, ru_stime={0, 329564}, ...}) = 0 <0.000028>
10:41:47.949953 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 619977}, ru_stime={0, 329564}, ...}) = 0 <0.000018>
10:41:47.953368 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 619977}, ru_stime={0, 329564}, ...}) = 0 <0.000029>
10:41:47.954803 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 619977}, ru_stime={0, 330810}, ...}) = 0 <0.000024>
--//基本间隔2秒出现getrusage。
$ egrep "getrusage|select" /tmp/test.txt | awk '{print $2}' | uniq -c | head -10
6 getrusage(0x1
855 select(0,
1 getrusage(0x1
678 select(0,
1 getrusage(0x1
546 select(0,
1 getrusage(0x1
844 select(0,
1 getrusage(0x1
575 select(0,
--//中间执行多次select。测试环境是虚拟机器，感觉性能不太稳定，如果真实的服务器我记忆里在11g下同样的参数环境下，没有其他
--//业务的情况下,select次数非常稳定基本都是18X次，感觉这次很多，仔细看以前笔记，发现休眠的时间发生了变化，11g下每次
--//select调用1厘秒(10毫秒)，在getrusage调用2秒的间隔内出现181次.
--//我猜测在21c下如果是真实服务器，没有其他业务的情况下，select次数估计可以达到17XX，18XX次。
$ egrep "select" /tmp/test.txt | head -10
10:41:03.599064 select(0, [], [], [], {0, 1000}) = 0 (Timeout) <0.001461>
10:41:03.600622 select(0, [], [], [], {0, 1000}) = 0 (Timeout) <0.001835>
10:41:03.602569 select(0, [], [], [], {0, 1000}) = 0 (Timeout) <0.001885>
10:41:03.604577 select(0, [], [], [], {0, 1000}) = 0 (Timeout) <0.002752>
10:41:03.607499 select(0, [], [], [], {0, 1000}) = 0 (Timeout) <0.001795>
10:41:03.609419 select(0, [], [], [], {0, 1000}) = 0 (Timeout) <0.001731>
10:41:03.611348 select(0, [], [], [], {0, 1000}) = 0 (Timeout) <0.001845>
10:41:03.613303 select(0, [], [], [], {0, 1000}) = 0 (Timeout) <0.001874>
10:41:03.615272 select(0, [], [], [], {0, 1000}) = 0 (Timeout) <0.001856>
10:41:03.617224 select(0, [], [], [], {0, 1000}) = 0 (Timeout) <0.001858>
--//每次select相当于sleep {0, 1000}里面的1000单位是微秒，相当于1毫秒。
--//21c下select仅仅1毫秒
--//sleeps = 0x000029F5 = 10741次。这个测试我重复几次基本在0x27XX-0x29XX之间。
--//10741*0.001050 = 11.27805秒 占11.3秒.
--//10741*0.001100 = 11.8151 占11.8秒.
--//我估计上select调用+加上其他消耗总共占用11.3-11.8秒。
--//说明：我每次调用select没有选择0.0018(最后显示的时间)，我感觉使用strace跟踪大大影响调用select次数。
--//我仅仅大致估计select调用完成需要0.001050-0.001100秒之间。
SCOTT@book01p> Select decode(method,'test','test','Q'),count(*),round(avg(TIME_ELA),0),sum(TIME_ELA) from job_times group by decode(method,'test','test','Q') order by 3 ;
DECO COUNT(*) ROUND(AVG(TIME_ELA),0) SUM(TIME_ELA)
---- ---------- ---------------------- -------------
Q 20 4802 96036
test 20 4822 96449
--//这里的时间单位是厘秒，总的执行时间集中模式比分散模式慢了(96449-96036)/100 = 4.13/100秒，存在
--//11.3-4.13 = 7.17, 11.8-4.13 = 7.67 差不多7秒的差距。
--//集中模式存在2次硬解析(1次存储过程1次sql语句)，而分散模式存在40次硬解析(20次存储过程29次sql语句).
SCOTT@book01p> delete from JOB_TIMES ;
62 rows deleted.
SCOTT@book01p> commit ;
Commit complete.
$ zzdate;seq 20 | xargs -P 20 -IQ sqlplus -s -l scott/book@book01p @m9.txt 1 TEST > /dev/null;zzdate
trunc(sysdate)+16/24+25/1440+25/86400
trunc(sysdate)+16/24+25/1440+26/86400
$ zzdate;seq 20 | xargs -P 20 -IQ sqlplus -s -l scott/book@book01p @m9.txt 1 Q > /dev/null;zzdate
trunc(sysdate)+16/24+25/1440+33/86400
trunc(sysdate)+16/24+25/1440+34/86400
--//相当于仅仅执行1次。
COTT@book01p> Select decode(method,'TEST','TEST','Q'),count(*),round(avg(TIME_ELA),2),sum(TIME_ELA) from job_times group by decode(method,'TEST','TEST','Q') order by 3 ;
DECO COUNT(*) ROUND(AVG(TIME_ELA),2) SUM(TIME_ELA)
---- ---------- ---------------------- -------------
Q 20 2.3 46
TEST 20 3.15 63
--//仅仅相差 (63-46)/100 = 0.17秒。还有7秒的误差不知道问题在哪里。
--//重复测试
--//delete from JOB_TIMES ;
--//commit ;
$ zzdate;seq 20 | xargs -P 20 -IQ sqlplus -s -l scott/book@book01p @m9.txt 5e5 TEST > /dev/null;zzdate
trunc(sysdate)+16/24+34/1440+59/86400
trunc(sysdate)+16/24+35/1440+50/86400
$ zzdate;seq 20 | xargs -P 20 -IQ sqlplus -s -l scott/book@book01p @m9.txt 5e5 Q > /dev/null;zzdate
trunc(sysdate)+16/24+35/1440+59/86400
trunc(sysdate)+16/24+36/1440+49/86400
SYS@book> @ ashtop event,p1raw,p1,p3raw 1=1 trunc(sysdate)+16/24+34/1440+59/86400 trunc(sysdate)+16/24+35/1440+50/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW P1 P3RAW FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------- ----------------- ---------- ----------------- ------------------- ------------------- ---------- -------- -----------
748 14.7 77% | 3173923829 2024-11-22 16:35:01 2024-11-22 16:35:49 407 49 455
118 2.3 12% | cursor: pin S 00000000BD2E3BF5 3173923829 0000000900000000 2024-11-22 16:35:01 2024-11-22 16:35:49 1 33 33
70 1.4 7% | cursor: pin S 00000000BD2E3BF5 3173923829 0000000300000000 2024-11-22 16:35:04 2024-11-22 16:35:45 1 30 30
32 .6 3% | 12 2024-11-22 16:35:01 2024-11-22 16:35:47 15 31 26
2 .0 0% | 1413697536 2024-11-22 16:35:01 2024-11-22 16:35:01 2 1 2
1 .0 0% | 131072 2024-11-22 16:35:00 2024-11-22 16:35:00 1 1 1
6 rows selected.
SYS@book> @ mutexprofz idn,hash,loc,maddr "ts>=trunc(sysdate)+16/24+34/1440+59/86400 and ts<=trunc(sysdate)+16/24+35/1440+50/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 GET_LOCATION mutex_addr OBJECT_NAME
---------- -------------- --------------- ---------- ---------- --------------------------------- -------------------- --------------------------------------------------------------------------------
7 297757 Cursor Pin 3173923829 3173923829 kksLockDelete [KKSCHLPIN6] 0000000067EA8210 Select /*+ TEST */ count(*) from t where id = :j
3 810203 Cursor Pin 3173923829 3173923829 kksfbc [KKSCHLFSP2] 0000000067EA8210 Select /*+ TEST */ count(*) from t where id = :j
SYS@book> @ opeek 0000000067EA8210 40 0
[067EA8210, 067EA8238) = 00000000 00000000 01312D20 00002789 BD2E3BF5 00000000 00000000 00000000 00000000 00000000
--//0x00002789 = 10121
--//10121*0.00105 = 10.62705
SCOTT@book01p> Select decode(method,'TEST','TEST','Q'),count(*),round(avg(TIME_ELA),2),sum(TIME_ELA) from job_times group by decode(method,'TEST','TEST','Q') order by 3 ;
DECO COUNT(*) ROUND(AVG(TIME_ELA),2) SUM(TIME_ELA)
---- ---------- ---------------------- -------------
Q 20 4819.35 96387
TEST 20 4867.4 97348
--//(97348-96387)/100 = 9.61
--//这次算是比较接近的1次。
--//总之大量相同sql语句软软解析密集执行ash记录cursor: pin S的时间由于1秒取样的原因被放大了，在我的测试里相当于仅仅看到1/20.
--//192/20 = 9.6
--//我不知道真实的环境是否到达这样的执行强度，我估计连接的会话数更多，但我总觉得分散带来的好处很小。
--//感觉虚拟机器太不稳定了，今天的测试
SYS@book> @ ashtop event,p1raw 1=1 trunc(sysdate)+16/24+24/1440+25/86400 trunc(sysdate)+16/24+25/1440+15/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ------------------- ------------------- ---------- -------- -----------
421 8.4 44% | resmgr:cpu quantum 0000000000000002 2024-11-24 16:24:26 2024-11-24 16:25:14 1 49 49
297 5.9 31% | 2024-11-24 16:24:26 2024-11-24 16:25:14 170 49 210
198 4.0 21% | resmgr:cpu quantum 0000000000000003 2024-11-24 16:24:27 2024-11-24 16:25:13 21 40 21
39 .8 4% | cursor: pin S 00000000132C35C0 2024-11-24 16:24:27 2024-11-24 16:25:14 1 22 22
--//测试cursor: pin S 占39秒，不知道为什么今天的测试cursor: pin S占用偏小。
--//不知道是否与出现resmgr:cpu quantum事件有关。
--//有机会在11g下重复测试看看。
5.mod_addr.sh 代码如下：
$ cat mod_addr.sh
#/bin/bash
# modify address value
# arg1=address arg2=offset (default 0) arg3=value (default 0)
offset=${2:-0}
value=${3:-0}
gdb -q -batch -p $(pgrep -f ora_mmon_${ORACLE_SID}) -ex "set *( int *)(0x${1}+0x${offset})=0x${value}" -ex "x /wx 0x${1}+0x${offset}" -ex "quit" | grep "^0x" | grep -v "^0x0"
--//测试软软解析遇到的疑惑，就是大量软软解析以及分散执行两者的执行时间差别并不是很大，有点疑惑，展开分析看看。
1.环境：
SCOTT@book01p> @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.建立测试环境：
create table job_times (sid number, time_ela number,method varchar2(20));
drop table t purge ;
create table t as select rownum id ,'test' pad from dual connect by level<=5e5;
create unique index pk_t on t(id);
exec dbms_stats.gather_table_stats(user, 't', method_opt=>'for all columns size 1');
$ cat m9.txt
set verify off
insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,'&&2') ;
commit ;
DECLARE
l_count PLS_INTEGER;
BEGIN
FOR i IN 1..&&1
LOOP
EXECUTE IMMEDIATE 'Select /*+ &2 */ count(*) from t where id = :j ' INTO l_count USING i;
END LOOP;
END;
/
update job_times set time_ela = dbms_utility.get_time - time_ela where sid=sys_context ('userenv', 'sid') and method='&&2';
commit;
quit
3.测试：
$ zzdate;seq 20 | xargs -P 20 -IQ sqlplus -s -l scott/book@book01p @m9.txt 5e5 test > /dev/null;zzdate
trunc(sysdate)+10/24+11/1440+58/86400
trunc(sysdate)+10/24+12/1440+49/86400
--//等待测试完成。需要1*60+49-58 = 51秒。
SYS@book> @ ashtop event,p1raw,p1 1=1 trunc(sysdate)+10/24+11/1440+58/86400 trunc(sysdate)+10/24+12/1440+49/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW P1 FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ---------- ------------------- ------------------- ---------- -------- -----------
751 14.7 78% | 752002402 2024-11-21 10:12:01 2024-11-21 10:12:48 397 48 443
191 3.7 20% | cursor: pin S 000000002CD2A562 752002402 2024-11-21 10:12:01 2024-11-21 10:12:47 1 34 34
9 .2 1% | 1413697536 2024-11-21 10:11:59 2024-11-21 10:12:00 8 2 8
2 .0 0% | log file parallel write 0000000000000001 1 2024-11-21 10:12:00 2024-11-21 10:12:48 1 2 2
1 .0 0% | log file sync 000000000000065B 1627 2024-11-21 10:11:59 2024-11-21 10:11:59 1 1 1
1 .0 0% | log file sync 000000000000067D 1661 2024-11-21 10:12:00 2024-11-21 10:12:00 1 1 1
1 .0 0% | log file sync 00000000000006A6 1702 2024-11-21 10:12:48 2024-11-21 10:12:48 1 1 1
1 .0 0% | 100 2024-11-21 10:12:23 2024-11-21 10:12:23 1 1 1
1 .0 0% | 300 2024-11-21 10:12:25 2024-11-21 10:12:25 1 1 1
1 .0 0% | 65536 2024-11-21 10:12:00 2024-11-21 10:12:00 1 1 1
1 .0 0% | 2020423704 2024-11-21 10:12:48 2024-11-21 10:12:48 1 1 1
11 rows selected.
$ zzdate;seq 20 | xargs -P 20 -IQ sqlplus -s -l scott/book@book01p @m9.txt 5e5 Q > /dev/null;zzdate
trunc(sysdate)+10/24+14/1440+24/86400
trunc(sysdate)+10/24+15/1440+15/86400
--//参数2不同导致每个执行sql语句的都不相同，这样相当于分散开来。
--//等待测试完成。需要1*60+15-24 = 51秒。
SYS@book> @ ashtop event,p1raw,p1 1=1 trunc(sysdate)+10/24+14/1440+24/86400 trunc(sysdate)+10/24+15/1440+15/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW P1 FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ---------- ------------------- ------------------- ---------- -------- -----------
900 17.6 94% | 65536 2024-11-21 10:14:26 2024-11-21 10:15:14 446 49 493
48 .9 5% | 1614620816 2024-11-21 10:14:27 2024-11-21 10:15:14 26 48 42
6 .1 1% | 2020423704 2024-11-21 10:15:13 2024-11-21 10:15:14 6 2 6
2 .0 0% | 8 2024-11-21 10:14:26 2024-11-21 10:14:27 2 2 2
2 .0 0% | 100 2024-11-21 10:14:24 2024-11-21 10:14:25 1 2 2
1 .0 0% | 131072 2024-11-21 10:14:25 2024-11-21 10:14:25 1 1 1
6 rows selected.
--//看不见cursor: pin S等待时间。
--//但是前面cursor: pin S 占用191秒，相当于每个会话占用191/20 = 9.55秒，至少应该有9秒的差距。
SCOTT@book01p> Select decode(method,'test','test','Q'),count(*),round(avg(TIME_ELA),0),sum(TIME_ELA) from job_times group by decode(method,'test','test','Q') order by 3 ;
DECO COUNT(*) ROUND(AVG(TIME_ELA),0) SUM(TIME_ELA)
---- ---------- ---------------------- -------------
Q 20 4802 96036
test 20 4822 96449
--//可以发现两者几乎同时完成，根本不存在这么大的差距，为什么呢？总的快了仅仅4秒。
--//实际上ash的取样放大了cursor: pin S等待事件，原来1次sleeps可能1毫秒或者1厘秒，而取样放大1秒，这样相当于一下子放大1000
--//或者100倍。
SYS@book> @ mutexprofz idn,hash,loc,maddr "ts>=trunc(sysdate)+10/24+11/1440+58/86400 and ts<=trunc(sysdate)+10/24+12/1440+49/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 GET_LOCATION mutex_addr OBJECT_NAME
---------- -------------- --------------- ---------- ---------- --------------------------------- -------------------- --------------------------------------------------------------------------------
17 813649 Cursor Pin 752002402 752002402 kksLockDelete [KKSCHLPIN6] 0000000065F1A090 Select /*+ test */ count(*) from t where id = :j
6 249929 Cursor Pin 752002402 752002402 kksfbc [KKSCHLFSP2] 0000000065F1A090 Select /*+ test */ count(*) from t where id = :j
SYS@book> @ mutexprofz idn,hash,loc,maddr "ts>=trunc(sysdate)+10/24+14/1440+24/86400 and ts<=trunc(sysdate)+10/24+15/1440+15/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
no rows selected
--//第2次执行根本没有输出。
4.深入分析:
--//session 1:
SCOTT@book01p> @ spid
==============================
SID : 158
SERIAL# : 47699
PROCESS : 3997
SERVER : DEDICATED
SPID : 3999
PID : 45
P_SERIAL# : 8
KILL_COMMAND : alter system kill session '158,47699' immediate;
PL/SQL procedure successfully completed.
--//session 2:
SYS@book> @ opeek 0000000065F1A090 40 0
[065F1A090, 065F1A0B8) = 00000000 00000000 01312D28 000029F5 2CD2A562 00000000 00000000 00000000 00000000 00000000
--//sleeps = 0x000029F5 = 10741次。
--//2CD2A562 = 752002402对应hash_value，与前面ashtop的P1raw输出一致。
--//window 1:
$ mod_addr.sh 0000000065F1A094 0 1
0x65f1a094: 0x00000001
--//session 2:
SYS@book> @ opeek 0000000065F1A090 40 0
[065F1A090, 065F1A0B8) = 00000000 00000001 01312D28 000029F5 2CD2A562 00000000 00000000 00000000 00000000 00000000
--//人为设置sid=1阻塞其他会话执行。
--//window 2:
$ strace -f -p 3999 -y -Ttt 2>&1 | tee /tmp/test.txt
--//session 1:
SCOTT@book01p> @ m9.txt 1 test
--//执行1次，挂起。
--//window 1:
$ sleep 30
$ mod_addr.sh 0000000065F1A094 0 0
0x65f1a094: 0x00000000
--//session 1,执行完成。
$ egrep "getrusage" /tmp/test.txt
10:41:03.594664 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 155251}, ru_stime={0, 26042}, ...}) = 0 <0.000014>
10:41:03.595953 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 155274}, ru_stime={0, 26874}, ...}) = 0 <0.000007>
10:41:03.597621 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 155459}, ru_stime={0, 26906}, ...}) = 0 <0.000033>
10:41:03.597718 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 155469}, ru_stime={0, 26908}, ...}) = 0 <0.000036>
10:41:03.598342 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 155524}, ru_stime={0, 26917}, ...}) = 0 <0.000078>
10:41:03.598487 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 155545}, ru_stime={0, 26921}, ...}) = 0 <0.000030>
10:41:05.286856 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 185189}, ru_stime={0, 38160}, ...}) = 0 <0.000020> --//开始
10:41:07.289493 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 199727}, ru_stime={0, 51653}, ...}) = 0 <0.000016>
10:41:09.296674 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 220614}, ru_stime={0, 58830}, ...}) = 0 <0.000027>
10:41:11.298284 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 244750}, ru_stime={0, 74489}, ...}) = 0 <0.000011>
10:41:13.299803 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 258506}, ru_stime={0, 89377}, ...}) = 0 <0.000023>
10:41:15.301216 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 276349}, ru_stime={0, 109685}, ...}) = 0 <0.000014>
10:41:17.303491 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 291781}, ru_stime={0, 119890}, ...}) = 0 <0.000013>
10:41:19.306078 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 316665}, ru_stime={0, 136150}, ...}) = 0 <0.000008>
10:41:21.306500 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 334213}, ru_stime={0, 144566}, ...}) = 0 <0.000053>
10:41:23.307949 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 349695}, ru_stime={0, 151694}, ...}) = 0 <0.000014>
10:41:25.310481 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 361525}, ru_stime={0, 173467}, ...}) = 0 <0.000010>
10:41:27.328359 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 366235}, ru_stime={0, 187187}, ...}) = 0 <0.000015>
10:41:29.330023 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 374466}, ru_stime={0, 202904}, ...}) = 0 <0.000009>
10:41:31.332351 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 386455}, ru_stime={0, 209885}, ...}) = 0 <0.000027>
10:41:33.332952 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 411865}, ru_stime={0, 228429}, ...}) = 0 <0.000035>
10:41:35.334616 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 418807}, ru_stime={0, 249539}, ...}) = 0 <0.000014>
10:41:36.453755 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 423399}, ru_stime={0, 258256}, ...}) = 0 <0.000053>
10:41:36.906525 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 550256}, ru_stime={0, 258256}, ...}) = 0 <0.000020>
10:41:37.335758 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 550256}, ru_stime={0, 258256}, ...}) = 0 <0.000021>
10:41:39.338048 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 575565}, ru_stime={0, 267048}, ...}) = 0 <0.000029>
10:41:41.359361 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 584471}, ru_stime={0, 274751}, ...}) = 0 <0.000120>
10:41:43.362103 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 594111}, ru_stime={0, 285503}, ...}) = 0 <0.000008>
10:41:45.373997 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 604310}, ru_stime={0, 298852}, ...}) = 0 <0.000008>
10:41:47.375294 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 611920}, ru_stime={0, 325030}, ...}) = 0 <0.000060>
10:41:47.946923 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 618978}, ru_stime={0, 329564}, ...}) = 0 <0.000025>
10:41:47.948071 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 619977}, ru_stime={0, 329564}, ...}) = 0 <0.000028>
10:41:47.949953 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 619977}, ru_stime={0, 329564}, ...}) = 0 <0.000018>
10:41:47.953368 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 619977}, ru_stime={0, 329564}, ...}) = 0 <0.000029>
10:41:47.954803 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 619977}, ru_stime={0, 330810}, ...}) = 0 <0.000024>
--//基本间隔2秒出现getrusage。
$ egrep "getrusage|select" /tmp/test.txt | awk '{print $2}' | uniq -c | head -10
6 getrusage(0x1
855 select(0,
1 getrusage(0x1
678 select(0,
1 getrusage(0x1
546 select(0,
1 getrusage(0x1
844 select(0,
1 getrusage(0x1
575 select(0,
--//中间执行多次select。测试环境是虚拟机器，感觉性能不太稳定，如果真实的服务器我记忆里在11g下同样的参数环境下，没有其他
--//业务的情况下,select次数非常稳定基本都是18X次，感觉这次很多，仔细看以前笔记，发现休眠的时间发生了变化，11g下每次
--//select调用1厘秒(10毫秒)，在getrusage调用2秒的间隔内出现181次.
--//我猜测在21c下如果是真实服务器，没有其他业务的情况下，select次数估计可以达到17XX，18XX次。
$ egrep "select" /tmp/test.txt | head -10
10:41:03.599064 select(0, [], [], [], {0, 1000}) = 0 (Timeout) <0.001461>
10:41:03.600622 select(0, [], [], [], {0, 1000}) = 0 (Timeout) <0.001835>
10:41:03.602569 select(0, [], [], [], {0, 1000}) = 0 (Timeout) <0.001885>
10:41:03.604577 select(0, [], [], [], {0, 1000}) = 0 (Timeout) <0.002752>
10:41:03.607499 select(0, [], [], [], {0, 1000}) = 0 (Timeout) <0.001795>
10:41:03.609419 select(0, [], [], [], {0, 1000}) = 0 (Timeout) <0.001731>
10:41:03.611348 select(0, [], [], [], {0, 1000}) = 0 (Timeout) <0.001845>
10:41:03.613303 select(0, [], [], [], {0, 1000}) = 0 (Timeout) <0.001874>
10:41:03.615272 select(0, [], [], [], {0, 1000}) = 0 (Timeout) <0.001856>
10:41:03.617224 select(0, [], [], [], {0, 1000}) = 0 (Timeout) <0.001858>
--//每次select相当于sleep {0, 1000}里面的1000单位是微秒，相当于1毫秒。
--//21c下select仅仅1毫秒
--//sleeps = 0x000029F5 = 10741次。这个测试我重复几次基本在0x27XX-0x29XX之间。
--//10741*0.001050 = 11.27805秒 占11.3秒.
--//10741*0.001100 = 11.8151 占11.8秒.
--//我估计上select调用+加上其他消耗总共占用11.3-11.8秒。
--//说明：我每次调用select没有选择0.0018(最后显示的时间)，我感觉使用strace跟踪大大影响调用select次数。
--//我仅仅大致估计select调用完成需要0.001050-0.001100秒之间。
SCOTT@book01p> Select decode(method,'test','test','Q'),count(*),round(avg(TIME_ELA),0),sum(TIME_ELA) from job_times group by decode(method,'test','test','Q') order by 3 ;
DECO COUNT(*) ROUND(AVG(TIME_ELA),0) SUM(TIME_ELA)
---- ---------- ---------------------- -------------
Q 20 4802 96036
test 20 4822 96449
--//这里的时间单位是厘秒，总的执行时间集中模式比分散模式慢了(96449-96036)/100 = 4.13/100秒，存在
--//11.3-4.13 = 7.17, 11.8-4.13 = 7.67 差不多7秒的差距。
--//集中模式存在2次硬解析(1次存储过程1次sql语句)，而分散模式存在40次硬解析(20次存储过程29次sql语句).
SCOTT@book01p> delete from JOB_TIMES ;
62 rows deleted.
SCOTT@book01p> commit ;
Commit complete.
$ zzdate;seq 20 | xargs -P 20 -IQ sqlplus -s -l scott/book@book01p @m9.txt 1 TEST > /dev/null;zzdate
trunc(sysdate)+16/24+25/1440+25/86400
trunc(sysdate)+16/24+25/1440+26/86400
$ zzdate;seq 20 | xargs -P 20 -IQ sqlplus -s -l scott/book@book01p @m9.txt 1 Q > /dev/null;zzdate
trunc(sysdate)+16/24+25/1440+33/86400
trunc(sysdate)+16/24+25/1440+34/86400
--//相当于仅仅执行1次。
COTT@book01p> Select decode(method,'TEST','TEST','Q'),count(*),round(avg(TIME_ELA),2),sum(TIME_ELA) from job_times group by decode(method,'TEST','TEST','Q') order by 3 ;
DECO COUNT(*) ROUND(AVG(TIME_ELA),2) SUM(TIME_ELA)
---- ---------- ---------------------- -------------
Q 20 2.3 46
TEST 20 3.15 63
--//仅仅相差 (63-46)/100 = 0.17秒。还有7秒的误差不知道问题在哪里。
--//重复测试
--//delete from JOB_TIMES ;
--//commit ;
$ zzdate;seq 20 | xargs -P 20 -IQ sqlplus -s -l scott/book@book01p @m9.txt 5e5 TEST > /dev/null;zzdate
trunc(sysdate)+16/24+34/1440+59/86400
trunc(sysdate)+16/24+35/1440+50/86400
$ zzdate;seq 20 | xargs -P 20 -IQ sqlplus -s -l scott/book@book01p @m9.txt 5e5 Q > /dev/null;zzdate
trunc(sysdate)+16/24+35/1440+59/86400
trunc(sysdate)+16/24+36/1440+49/86400
SYS@book> @ ashtop event,p1raw,p1,p3raw 1=1 trunc(sysdate)+16/24+34/1440+59/86400 trunc(sysdate)+16/24+35/1440+50/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW P1 P3RAW FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------- ----------------- ---------- ----------------- ------------------- ------------------- ---------- -------- -----------
748 14.7 77% | 3173923829 2024-11-22 16:35:01 2024-11-22 16:35:49 407 49 455
118 2.3 12% | cursor: pin S 00000000BD2E3BF5 3173923829 0000000900000000 2024-11-22 16:35:01 2024-11-22 16:35:49 1 33 33
70 1.4 7% | cursor: pin S 00000000BD2E3BF5 3173923829 0000000300000000 2024-11-22 16:35:04 2024-11-22 16:35:45 1 30 30
32 .6 3% | 12 2024-11-22 16:35:01 2024-11-22 16:35:47 15 31 26
2 .0 0% | 1413697536 2024-11-22 16:35:01 2024-11-22 16:35:01 2 1 2
1 .0 0% | 131072 2024-11-22 16:35:00 2024-11-22 16:35:00 1 1 1
6 rows selected.
SYS@book> @ mutexprofz idn,hash,loc,maddr "ts>=trunc(sysdate)+16/24+34/1440+59/86400 and ts<=trunc(sysdate)+16/24+35/1440+50/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 GET_LOCATION mutex_addr OBJECT_NAME
---------- -------------- --------------- ---------- ---------- --------------------------------- -------------------- --------------------------------------------------------------------------------
7 297757 Cursor Pin 3173923829 3173923829 kksLockDelete [KKSCHLPIN6] 0000000067EA8210 Select /*+ TEST */ count(*) from t where id = :j
3 810203 Cursor Pin 3173923829 3173923829 kksfbc [KKSCHLFSP2] 0000000067EA8210 Select /*+ TEST */ count(*) from t where id = :j
SYS@book> @ opeek 0000000067EA8210 40 0
[067EA8210, 067EA8238) = 00000000 00000000 01312D20 00002789 BD2E3BF5 00000000 00000000 00000000 00000000 00000000
--//0x00002789 = 10121
--//10121*0.00105 = 10.62705
SCOTT@book01p> Select decode(method,'TEST','TEST','Q'),count(*),round(avg(TIME_ELA),2),sum(TIME_ELA) from job_times group by decode(method,'TEST','TEST','Q') order by 3 ;
DECO COUNT(*) ROUND(AVG(TIME_ELA),2) SUM(TIME_ELA)
---- ---------- ---------------------- -------------
Q 20 4819.35 96387
TEST 20 4867.4 97348
--//(97348-96387)/100 = 9.61
--//这次算是比较接近的1次。
--//总之大量相同sql语句软软解析密集执行ash记录cursor: pin S的时间由于1秒取样的原因被放大了，在我的测试里相当于仅仅看到1/20.
--//192/20 = 9.6
--//我不知道真实的环境是否到达这样的执行强度，我估计连接的会话数更多，但我总觉得分散带来的好处很小。
--//感觉虚拟机器太不稳定了，今天的测试
SYS@book> @ ashtop event,p1raw 1=1 trunc(sysdate)+16/24+24/1440+25/86400 trunc(sysdate)+16/24+25/1440+15/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ------------------- ------------------- ---------- -------- -----------
421 8.4 44% | resmgr:cpu quantum 0000000000000002 2024-11-24 16:24:26 2024-11-24 16:25:14 1 49 49
297 5.9 31% | 2024-11-24 16:24:26 2024-11-24 16:25:14 170 49 210
198 4.0 21% | resmgr:cpu quantum 0000000000000003 2024-11-24 16:24:27 2024-11-24 16:25:13 21 40 21
39 .8 4% | cursor: pin S 00000000132C35C0 2024-11-24 16:24:27 2024-11-24 16:25:14 1 22 22
--//测试cursor: pin S 占39秒，不知道为什么今天的测试cursor: pin S占用偏小。
--//不知道是否与出现resmgr:cpu quantum事件有关。
--//有机会在11g下重复测试看看。
5.mod_addr.sh 代码如下：
$ cat mod_addr.sh
#/bin/bash
# modify address value
# arg1=address arg2=offset (default 0) arg3=value (default 0)
offset=${2:-0}
value=${3:-0}
gdb -q -batch -p $(pgrep -f ora_mmon_${ORACLE_SID}) -ex "set *( int *)(0x${1}+0x${offset})=0x${value}" -ex "x /wx 0x${1}+0x${offset}" -ex "quit" | grep "^0x" | grep -v "^0x0"
