[20190321]测试相同语句遇到导致cursor pin S的疑问.txt

来源：这里教程网时间：2026-03-03 13:08:07 作者：

[20190321]测试相同语句遇到导致cursor pin S的疑问.txt --//昨天测试遇到的情况,链接:http://blog.itpub.net/267265/viewspace-2638857/ --//我一直认为打散sql语句,避开cursor: pin S等待事件,能够提高执行效率.而测试结果有点出乎意料. --//反而是测试2快于测试1,很难理解为什么会出现这样的情况,今天继续探究看看. 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)); $ cat m1.txt set verify off insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,'&&2') ; commit ; declare v_id number; v_d date; begin for i in 1 .. &&1 loop select /*+ &&3 */ 1 into v_id from dual ; --select /*+ &&3 */ sysdate into v_d from dual ; 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 $ cat m2.txt set verify off insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,'&&2') ; commit ; declare v_id number; v_d date; begin for i in 1 .. &&1 loop select 1 into v_id from dual ; --//select sysdate into v_d from dual ; 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,产生每个会话执行语句不同,对比看看.昨天的测试第2种情况快于第1种情况,不理解,我再次重复测试: 3.测试: --//测试最好避开整点的awr生成以及其它对数据库的操作, seq 1 40 | xargs -I {} echo 'seq {} | xargs -I %# -P {} bash -c "sqlplus -s -l scott/book @m1.txt 1e6 m1_{} %# >/dev/null"' | bash seq 1 40 | xargs -I {} echo 'seq {} | xargs -I %# -P {} bash -c "sqlplus -s -l scott/book @m2.txt 1e6 m2_{} %# >/dev/null"' | bash $ sqlplus -s -l scott/book <<< "select method,count(*),round(avg(TIME_ELA),0),sum(TIME_ELA) from job_times where method like 'm%' group by method order by to_number(substr(method,4)),4;" | egrep "^|m1_.*$" METHOD COUNT(*) ROUND(AVG(TIME_ELA),0) SUM(TIME_ELA) ------ -------- ---------------------- ------------- m2_1 1 1802 1802 m1_1 1 1841 1841 m1_2 2 1677 3354 m2_2 2 1697 3393 m2_3 3 1660 4981 m1_3 3 1691 5074 m1_4 4 1672 6688 m2_4 4 1704 6816 m1_5 5 1588 7941 m2_5 5 1717 8586 m1_6 6 1584 9505 m2_6 6 1655 9931 m1_7 7 1595 11162 m2_7 7 1628 11395 m1_8 8 1599 12790 m2_8 8 1758 14067 m1_9 9 1600 14400 m2_9 9 1659 14935 m1_10 10 1595 15953 m2_10 10 1670 16701 m1_11 11 1584 17429 m2_11 11 1696 18653 m1_12 12 1586 19029 m2_12 12 1710 20519 m1_13 13 1683 21877 m2_13 13 1834 23844 m1_14 14 1757 24596 m2_14 14 1913 26777 m1_15 15 1832 27473 m2_15 15 2061 30919 m1_16 16 1913 30600 m2_16 16 2078 33247 m1_17 17 1975 33568 m2_17 17 2130 36203 m1_18 18 2057 37023 m2_18 18 2245 40418 m1_19 19 2131 40485 m2_19 19 2332 44301 m1_20 20 2246 44913 m2_20 20 2397 47932 m1_21 21 2318 48674 m2_21 21 2537 53285 m1_22 22 2430 53456 m2_22 22 2646 58218 m1_23 23 2538 58365 m2_23 23 2735 62906 m1_24 24 2664 63927 m2_24 24 2866 68789 m1_25 25 2795 69875 m2_25 25 2998 74952 m1_26 26 2835 73716 m2_26 26 3134 81489 m1_27 27 2967 80114 m2_27 27 3239 87444 m1_28 28 3088 86477 m2_28 28 3371 94391 m1_29 29 3172 91990 m2_29 29 3536 102550 m1_30 30 3303 99083 m2_30 30 3660 109802 m1_31 31 3377 104679 m2_31 31 3979 123359 m1_32 32 3560 113920 m2_32 32 4179 133740 m1_33 33 3608 119055 m2_33 33 4335 143050 m1_34 34 3732 126880 m2_34 34 4404 149722 m1_35 35 3760 131615 m2_35 35 4277 149679 m1_36 36 3948 142134 m2_36 36 4714 169701 m1_37 37 4098 151626 m2_37 37 4889 180908 m1_38 38 4066 154523 m2_38 38 5033 191253 m1_39 39 4153 161969 m2_39 39 5149 200827 m1_40 40 4394 175767 m2_40 40 5182 207291 80 rows selected. --//大部分情况下都是测试1快于测试2.设置grep支持彩色.比较好观察.还有一种方法在vim下:set hls,查询/^m1.*$,这样也可以. $ sqlplus -s -l scott/book <<< "select method,count(*),round(avg(TIME_ELA),0),sum(TIME_ELA) from job_times where method like 'm%' group by method order by to_number(substr(method,4)),4;" | egrep "^|m1_.*$" --//也就是我前面的测试有问题??? 如果执行如下: --//注:我注解select /*+ &&3 */ 1 into v_id from dual ;改为执行select /*+ &&3 */ sysdate into v_d from dual ; seq 150 | xargs -I %# -P 150 bash -c "sqlplus -s -l scott/book @m1.txt 1e6 X1_150 %# >/dev/null" seq 150 | xargs -I %# -P 150 bash -c "sqlplus -s -l scott/book @m2.txt 1e6 X2_150 %# >/dev/null" SCOTT@book> select method,count(*),round(avg(TIME_ELA),0),sum(TIME_ELA) from job_times where method like 'X%' group by method order by to_number(substr(method,4)),3; METHOD COUNT(*) ROUND(AVG(TIME_ELA),0) SUM(TIME_ELA) -------------------- ---------- ---------------------- ------------- X2_150 150 19268 2890191 X1_150 150 19768 2965136 --//为什么呢?并发用户多了吗?我仔细想想,问题估计在开始阶段,测试1 150个连接开始执行大量的非绑定变量语句要硬解析,这样开始出现大量 --//latch: shared pool等待事件,而引起的这样的情况,如果开始脚本加入适当的延迟,测试才比较准确.修改脚本如下: $ cat m1.txt set verify off insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,'&&2') ; commit ; host sleep $(echo &&3/50 | bc -l ) declare v_id number; v_d date; begin for i in 1 .. &&1 loop select /*+ &&3 */ 1 into v_id from dual ; --select /*+ &&3 */ sysdate into v_d from dual ; 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 $ cat m2.txt set verify off insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,'&&2') ; commit ; host sleep $(echo &&3/50| bc -l ) declare v_id number; v_d date; begin for i in 1 .. &&1 loop select 1 into v_id from dual ; --select sysdate into v_d from dual ; 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 $ seq 150 | xargs -I %# -P 150 bash -c "sqlplus -s -l scott/book @m1.txt 1e6 A1_150 %# >/dev/null" $ seq 150 | xargs -I %# -P 150 bash -c "sqlplus -s -l scott/book @m2.txt 1e6 A2_150 %# >/dev/null" --//实际上我在测试时还犯了一个严重错误,实际上到一定时间,看latch: shared pool的等待事件最后SECONDS_IN_WAIT是不变的, --//实际上v$session记录的最后1个等待事件,非常容易存在疑惑. SCOTT@book> @ wait P1RAW P2RAW P3RAW P1 P2 P3 SID SERIAL# SEQ# EVENT STATUS STATE WAIT_TIME_MICRO SECONDS_IN_WAIT WAIT_CLASS ---------------- ---------------- ----- ---------- --- -- --- ------- ---- --------------------------- -------- ----------------- --------------- --------------- ------------ ... 0000000062657100 0000000000000001 00 1650815232 1 0 333 95 28 SQL*Net message from client ACTIVE WAITED KNOWN TIME 305362 144 Idle 000000006010D860 0000000000000150 00 1611716704 336 0 6 145 30 latch: shared pool ACTIVE WAITED KNOWN TIME 34009 138 Concurrency 000000006010D860 0000000000000150 00 1611716704 336 0 21 131 30 latch: shared pool ACTIVE WAITED KNOWN TIME 30997 138 Concurrency 000000006010D860 0000000000000150 00 1611716704 336 0 67 115 31 latch: shared pool ACTIVE WAITED KNOWN TIME 31987 138 Concurrency 000000006010D860 0000000000000150 00 1611716704 336 0 132 87 30 latch: shared pool ACTIVE WAITED SHORT TIME 17 141 Concurrency 000000006010D860 0000000000000150 00 1611716704 336 0 170 719 31 latch: shared pool ACTIVE WAITED KNOWN TIME 33078 138 Concurrency 000000006010D860 0000000000000150 00 1611716704 336 0 246 89 33 latch: shared pool ACTIVE WAITED KNOWN TIME 28119 138 Concurrency 000000006010D860 0000000000000150 00 1611716704 336 0 320 57 30 latch: shared pool ACTIVE WAITED KNOWN TIME 35783 138 Concurrency 000000006010D860 0000000000000150 00 1611716704 336 0 255 789 31 latch: shared pool ACTIVE WAITED KNOWN TIME 28109 138 Concurrency 000000006010D860 0000000000000150 00 1611716704 336 0 257 157 33 latch: shared pool ACTIVE WAITED KNOWN TIME 34000 138 Concurrency 000000006010D860 0000000000000150 00 1611716704 336 0 262 125 30 latch: shared pool ACTIVE WAITED KNOWN TIME 30084 138 Concurrency 000000006010D860 0000000000000150 00 1611716704 336 0 284 111 30 latch: shared pool ACTIVE WAITED KNOWN TIME 26152 138 Concurrency 000000006010D860 0000000000000150 00 1611716704 336 0 290 33 32 latch: shared pool ACTIVE WAITED KNOWN TIME 31020 138 Concurrency 000000006010D860 0000000000000150 00 1611716704 336 0 298 403 30 latch: shared pool ACTIVE WAITED KNOWN TIME 35788 138 Concurrency 000000006010D860 0000000000000150 00 1611716704 336 0 247 121 30 latch: shared pool ACTIVE WAITED KNOWN TIME 32958 138 Concurrency 150 rows selected. SCOTT@book> select method,count(*),round(avg(TIME_ELA),0),sum(TIME_ELA) from job_times where method like 'A%' group by method order by to_number(substr(method,4)),3; METHOD COUNT(*) ROUND(AVG(TIME_ELA),0) SUM(TIME_ELA) -------------------- ---------- ---------------------- ------------- A1_150 150 16718 2507696 A2_150 150 18234 2735046 --//这样测试1就快于测试2. --//改成执行select sysdate into v_d from dual ;代码看看. $ seq 150 | xargs -I %# -P 150 bash -c "sqlplus -s -l scott/book @m1.txt 1e6 B1_150 %# >/dev/null" $ seq 150 | xargs -I %# -P 150 bash -c "sqlplus -s -l scott/book @m2.txt 1e6 B2_150 %# >/dev/null" SCOTT@book> select method,count(*),round(avg(TIME_ELA),0),sum(TIME_ELA) from job_times group by method order by method; METHOD COUNT(*) ROUND(AVG(TIME_ELA),0) SUM(TIME_ELA) -------------------- ---------- ---------------------- ------------- A1_150 150 16718 2507696 A2_150 150 18234 2735046 B1_150 150 17613 2641914 B2_150 150 21185 3177713 --//你可以可以看出sql语句分散后大概提高10%上下. --//另外我的测试还加入了sleep, $ seq 150 | xargs | tr ' ' + | bc -l 11325 --//11325/50 = 226.5秒,排除这个因素.平均每个扣除226.5/150 = 1.51秒.哎!!脚本写的有问题,考虑欠缺,应该sleep在前面,再次重复测试: --//从这次测试也看出,自己的测试设计不严谨,没有考虑一些细节问题,从另外一个方面也可以看出不使用绑定变量对数据库的危害,特别是oltp系统. --//补充: $ cat m1.txt set verify off host sleep $(echo &&3/50 | bc -l ) insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,'&&2') ; commit ; declare v_id number; v_d date; begin for i in 1 .. &&1 loop --select /*+ &&3 */ 1 into v_id from dual ; select /*+ &&3 */ sysdate into v_d from dual ; 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 $ cat m2.txt set verify off host sleep $(echo &&3/50| bc -l ) insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,'&&2') ; commit ; declare v_id number; v_d date; begin for i in 1 .. &&1 loop --select 1 into v_id from dual ; select sysdate into v_d from dual ; 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 $ seq 150 | xargs -I %# -P 150 bash -c "sqlplus -s -l scott/book @m1.txt 1e6 C1_150 %# >/dev/null" $ seq 150 | xargs -I %# -P 150 bash -c "sqlplus -s -l scott/book @m2.txt 1e6 C2_150 %# >/dev/null" SCOTT@book> select method,count(*),round(avg(TIME_ELA),0),sum(TIME_ELA) from job_times group by method order by method; METHOD COUNT(*) ROUND(AVG(TIME_ELA),0) SUM(TIME_ELA) -------------------- ---------- ---------------------- ------------- A1_150 150 16718 2507696 A2_150 150 18234 2735046 B1_150 150 17613 2641914 B2_150 150 21185 3177713 C1_150 150 16024 2403599 C2_150 150 21062 3159275 6 rows selected.