[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下还有点效果。