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

[20190322]测试相同语句遇到导致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.