[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.

[20190321]測試相同語句遇到導致cursor pin S的疑問.txt

相關文章