[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'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+14/1440+24/86400 and ts=trunc(sysdate)+16/24+34/1440+59/86400 and ts |
