[20241123]测试软软解析遇到的疑惑3.txt
[20241123]测试软软解析遇到的疑惑3.txt
--//测试软软解析遇到的疑惑，就是大量软软解析以及分散执行两者的执行时间差别并不是很大，有点疑惑，发现调用select休眠的时间
--//是1毫秒，而11g是1厘秒。而ash取样是1秒，这样在21c下相当于方法1000倍，11g下仅仅100倍。
--//前面测试21c下的情况，在11g下重复测试看看。
1.环境：
SCOTT@book> @ver1
PORT_STRING VERSION BANNER
------------------------------ -------------- --------------------------------------------------------------------------------
x86_64/Linux 2.4.xx 11.2.0.4.0 Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
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
variable v_method varchar2(20)
exec :v_method := '&&2';
--insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,'&&2') ;
insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,:v_method) ;
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= :v_method;
commit;
quit
3.测试1：
$ zzdate;seq 20 | xargs -P 20 -IQ sqlplus -s -l scott/book @m9.txt 5e5 BBBB > /dev/null;zzdate
trunc(sysdate)+09/24+32/1440+14/86400
trunc(sysdate)+09/24+33/1440+01/86400
--//等待测试完成。需要61-14 = 47秒
SYS@book> @ ashtop event,p1raw 1=1 trunc(sysdate)+09/24+32/1440+14/86400 trunc(sysdate)+09/24+33/1440+01/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ------------------- ------------------- ---------- -------- -----------
464 9.9 52% | resmgr:cpu quantum 0000000000000002 2024-11-23 09:32:15 2024-11-23 09:33:00 1 45 45
261 5.6 29% | 2024-11-23 09:32:14 2024-11-23 09:33:00 156 46 196
94 2.0 11% | resmgr:cpu quantum 0000000000000003 2024-11-23 09:32:17 2024-11-23 09:32:56 20 32 20
71 1.5 8% | cursor: pin S 00000000228F13A7 2024-11-23 09:32:14 2024-11-23 09:32:59 1 29 29
3 .1 0% | ADR block file read 0000000000000000 2024-11-23 09:32:14 2024-11-23 09:32:14 3 1 3
--//cursor: pin S占71秒，明显比21c下测试要小，11g下调用select休眠10毫秒，仅仅放大100倍。
SYS@book> @ mutexprofx idn,hash,loc,maddr,p1raw "ts>=trunc(sysdate)+09/24+32/1440+14/86400 and ts<=trunc(sysdate)+09/24+33/1440+01/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
MAX_SLEEPS SLEEPS_DIFF MUTEX_TYPE IDN HASH GET_LOCATION mutex_addr P1RAW OBJECT_NAME
---------- ----------- --------------- ---------- ---------- --------------------------------- -------------------- ---------------- --------------------------------------------------------------------------------
630 366 Cursor Pin 579802023 579802023 kksLockDelete [KKSCHLPIN6] 0000000084ED26C8 00 Select /*+ BBBB */ count(*) from t where id = :j
299 11 Cursor Pin 579802023 579802023 kksfbc [KKSCHLFSP2] 0000000084ED26C8 00 Select /*+ BBBB */ count(*) from t where id = :j
SYS@book> @ opeek 0000000084ED26C8 24 0
[084ED26C8, 084ED26E0) = 00000000 00000000 01312D20 00001616 228F13A7 00000000
--//sleeps次数0x1616 = 5654，5654*0.01 = 56.54秒。检测到sleeps次数减少1半。
4.测试2：
$ zzdate;seq 20 | xargs -P 20 -IQ sqlplus -s -l scott/book @m9.txt 5e5 Q > /dev/null;zzdate
trunc(sysdate)+09/24+39/1440+56/86400
trunc(sysdate)+09/24+40/1440+43/86400
--//参数2带入Q，相当于分散sql语句执行，等待测试完成。需要43+60-56 = 47秒.
SYS@book> @ ashtop event,p1raw,p3raw 1=1 trunc(sysdate)+09/24+39/1440+56/86400 trunc(sysdate)+09/24+40/1440+43/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW P3RAW FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ----------------- ------------------- ------------------- ---------- -------- -----------
635 13.5 71% | resmgr:cpu quantum 0000000000000003 0000000000000000 2024-11-23 09:39:57 2024-11-23 09:40:42 5 46 5
236 5.0 26% | 2024-11-23 09:39:57 2024-11-23 09:40:42 125 46 161
19 .4 2% | resmgr:cpu quantum 0000000000000002 0000000000000000 2024-11-23 09:39:57 2024-11-23 09:40:42 6 7 12
5 .1 1% | ADR block file read 0000000000000000 0000000000000000 2024-11-23 09:39:57 2024-11-23 09:39:57 5 1 5
1 .0 0% | log file sync 0000000000000D79 0000000000000000 2024-11-23 09:40:41 2024-11-23 09:40:41 1 1 1
--//sql语句分散了，看不见cursor: pin S等待事件。
SCOTT@book> Select decode(method,'BBBB','BBBB','Q'),count(*),round(avg(TIME_ELA),0),sum(TIME_ELA) from job_times group by decode(method,'BBBB','BBBB','Q') order by 3 ;
DECO COUNT(*) ROUND(AVG(TIME_ELA),0) SUM(TIME_ELA)
---- ---------- ---------------------- -------------
Q 20 4404 88087
BBBB 20 4476 89524
--//分散模式仅仅比集中模式总的快了89524-88087 = 1437，相当于快了14秒。
--//我仅仅认为这类问题，密集执行不是非常非常大，没有必要分散，有点多余。
--//ash取样放大了cursor: pin S的等待时间，特别在21c下select时间更短看到看到的等待时间更大，11g下还有点效果。
--//测试软软解析遇到的疑惑，就是大量软软解析以及分散执行两者的执行时间差别并不是很大，有点疑惑，发现调用select休眠的时间
--//是1毫秒，而11g是1厘秒。而ash取样是1秒，这样在21c下相当于方法1000倍，11g下仅仅100倍。
--//前面测试21c下的情况，在11g下重复测试看看。
1.环境：
SCOTT@book> @ver1
PORT_STRING VERSION BANNER
------------------------------ -------------- --------------------------------------------------------------------------------
x86_64/Linux 2.4.xx 11.2.0.4.0 Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
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
variable v_method varchar2(20)
exec :v_method := '&&2';
--insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,'&&2') ;
insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,:v_method) ;
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= :v_method;
commit;
quit
3.测试1：
$ zzdate;seq 20 | xargs -P 20 -IQ sqlplus -s -l scott/book @m9.txt 5e5 BBBB > /dev/null;zzdate
trunc(sysdate)+09/24+32/1440+14/86400
trunc(sysdate)+09/24+33/1440+01/86400
--//等待测试完成。需要61-14 = 47秒
SYS@book> @ ashtop event,p1raw 1=1 trunc(sysdate)+09/24+32/1440+14/86400 trunc(sysdate)+09/24+33/1440+01/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ------------------- ------------------- ---------- -------- -----------
464 9.9 52% | resmgr:cpu quantum 0000000000000002 2024-11-23 09:32:15 2024-11-23 09:33:00 1 45 45
261 5.6 29% | 2024-11-23 09:32:14 2024-11-23 09:33:00 156 46 196
94 2.0 11% | resmgr:cpu quantum 0000000000000003 2024-11-23 09:32:17 2024-11-23 09:32:56 20 32 20
71 1.5 8% | cursor: pin S 00000000228F13A7 2024-11-23 09:32:14 2024-11-23 09:32:59 1 29 29
3 .1 0% | ADR block file read 0000000000000000 2024-11-23 09:32:14 2024-11-23 09:32:14 3 1 3
--//cursor: pin S占71秒，明显比21c下测试要小，11g下调用select休眠10毫秒，仅仅放大100倍。
SYS@book> @ mutexprofx idn,hash,loc,maddr,p1raw "ts>=trunc(sysdate)+09/24+32/1440+14/86400 and ts<=trunc(sysdate)+09/24+33/1440+01/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
MAX_SLEEPS SLEEPS_DIFF MUTEX_TYPE IDN HASH GET_LOCATION mutex_addr P1RAW OBJECT_NAME
---------- ----------- --------------- ---------- ---------- --------------------------------- -------------------- ---------------- --------------------------------------------------------------------------------
630 366 Cursor Pin 579802023 579802023 kksLockDelete [KKSCHLPIN6] 0000000084ED26C8 00 Select /*+ BBBB */ count(*) from t where id = :j
299 11 Cursor Pin 579802023 579802023 kksfbc [KKSCHLFSP2] 0000000084ED26C8 00 Select /*+ BBBB */ count(*) from t where id = :j
SYS@book> @ opeek 0000000084ED26C8 24 0
[084ED26C8, 084ED26E0) = 00000000 00000000 01312D20 00001616 228F13A7 00000000
--//sleeps次数0x1616 = 5654，5654*0.01 = 56.54秒。检测到sleeps次数减少1半。
4.测试2：
$ zzdate;seq 20 | xargs -P 20 -IQ sqlplus -s -l scott/book @m9.txt 5e5 Q > /dev/null;zzdate
trunc(sysdate)+09/24+39/1440+56/86400
trunc(sysdate)+09/24+40/1440+43/86400
--//参数2带入Q，相当于分散sql语句执行，等待测试完成。需要43+60-56 = 47秒.
SYS@book> @ ashtop event,p1raw,p3raw 1=1 trunc(sysdate)+09/24+39/1440+56/86400 trunc(sysdate)+09/24+40/1440+43/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW P3RAW FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ----------------- ------------------- ------------------- ---------- -------- -----------
635 13.5 71% | resmgr:cpu quantum 0000000000000003 0000000000000000 2024-11-23 09:39:57 2024-11-23 09:40:42 5 46 5
236 5.0 26% | 2024-11-23 09:39:57 2024-11-23 09:40:42 125 46 161
19 .4 2% | resmgr:cpu quantum 0000000000000002 0000000000000000 2024-11-23 09:39:57 2024-11-23 09:40:42 6 7 12
5 .1 1% | ADR block file read 0000000000000000 0000000000000000 2024-11-23 09:39:57 2024-11-23 09:39:57 5 1 5
1 .0 0% | log file sync 0000000000000D79 0000000000000000 2024-11-23 09:40:41 2024-11-23 09:40:41 1 1 1
--//sql语句分散了，看不见cursor: pin S等待事件。
SCOTT@book> Select decode(method,'BBBB','BBBB','Q'),count(*),round(avg(TIME_ELA),0),sum(TIME_ELA) from job_times group by decode(method,'BBBB','BBBB','Q') order by 3 ;
DECO COUNT(*) ROUND(AVG(TIME_ELA),0) SUM(TIME_ELA)
---- ---------- ---------------------- -------------
Q 20 4404 88087
BBBB 20 4476 89524
--//分散模式仅仅比集中模式总的快了89524-88087 = 1437，相当于快了14秒。
--//我仅仅认为这类问题，密集执行不是非常非常大，没有必要分散，有点多余。
--//ash取样放大了cursor: pin S的等待时间，特别在21c下select时间更短看到看到的等待时间更大，11g下还有点效果。
