[20190401]那個更快的疑問.txt

[20190401]那個更快的疑問.txt

--//前一陣子,做了11g於10g下,單表單條記錄唯一索引掃描的測試,摘要如下:

--//參考連結:

http://blog.itpub.net/267265/viewspace-2636321/

http://blog.itpub.net/267265/viewspace-2636342/

1.環境:

--//當時的測試,在11g下測試結果如下:

SCOTT@book> select method,count(*),round(avg(TIME_ELA),0),sum(TIME_ELA) from job_times group by method order by 3 ;

METHOD                 COUNT(*) ROUND(AVG(TIME_ELA),0) SUM(TIME_ELA)

-------------------- ---------- ---------------------- -------------

result_cache                 50                   8611        430536

id=1_unique_index            50                   9494        474714

null                         50                  10664        533197

id=1_index                   50                  28160       1407987

notnull                      50                  29279       1463928

--//在10g下測試結果如下:

SCOTT@test> select method,count(*),round(avg(TIME_ELA),0),sum(TIME_ELA) from job_times group by method order by 3 ;

METHOD                 COUNT(*) ROUND(AVG(TIME_ELA),0) SUM(TIME_ELA)

-------------------- ---------- ---------------------- -------------

id=1_unique_index            50                   4864        243192

notnull                      50                  34134       1706713

id=1_index                   50                  34703       1735173

null                         50                  37234       1861717

--//我的測試環境伺服器硬體相同,os版本一樣,對比可以發現id=1_unique_index的情況下,10g比11g快了1倍(指id=1_unique_index的情況).

--//而其他方式下11g都明顯快於10g,而10g下除了id=1_unique_index下其他執行方式都可以看到大量cbc latch等待事件.

--//而11g僅僅在id=1_index,notnull下看到大量cbc latch等待時間,null方式下(全表掃描)的情況下反而看不到cbc 

--//latch等待事件.

--//我一直再想,我是不是測試方法存在什麼問題,或者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

create table t as select rownum id from dual ;

create unique index pk_t on t(id);

create table job_times (sid number, time_ela number,method varchar2(20));

--//分析表略.

$ 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 */ count (*) into v_id from t where id=1;

        --//select /*+ &&3 */ count (*) into v_id from t ;

        --//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

$ sqlplus -s -l scott/book @m1.txt 1e6 id=1_unique_index 0 >/dev/null

SCOTT@book> Select method,count(*),round(avg(TIME_ELA),0),sum(TIME_ELA) from job_times group by method order by 3 ;

METHOD                 COUNT(*) ROUND(AVG(TIME_ELA),0) SUM(TIME_ELA)

-------------------- ---------- ---------------------- -------------

id=1_unique_index             1                   2615          2615

--//在10g環境下重複上面的步驟略.環境:

SCOTT@test> @ &r/ver1

PORT_STRING                    VERSION        BANNER

------------------------------ -------------- ----------------------------------------------------------------

x86_64/Linux 2.4.xx            10.2.0.4.0     Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bi

$ sqlplus -s -l scott/btbtms @m1.txt 1e6 id=1_unique_index 0 >/dev/null

SCOTT@test> select method,count(*),round(avg(TIME_ELA),0),sum(TIME_ELA) from job_times group by method order by 3 ;

METHOD                 COUNT(*) ROUND(AVG(TIME_ELA),0) SUM(TIME_ELA)

-------------------- ---------- ---------------------- -------------

id=1_unique_index             1                   1535          1535

--//可以看出即使我單個使用者執行相似的sql語句情況下,唯一索引查詢10g下明顯快於11g.

2.使用strace跟蹤看看:

--//執行1e6次有點慢,改成1e5看看.

--//11g的測試:

$ strace -f -c sqlplus -s -l scott/book @m1.txt 1e5 id=1_unique_index 0 >/dev/null

...

% time     seconds  usecs/call     calls    errors syscall

------ ----------- ----------- --------- --------- ----------------

 72.78    0.043919           0    700708           getrusage

 19.80    0.011947           0    200179           times

  6.67    0.004024         671         6         3 wait4

  0.24    0.000147          29         5           clone

  0.18    0.000106           0       375         2 read

  0.16    0.000096           0       264       106 open

...

------ ----------- ----------- --------- --------- ----------------

100.00    0.060341                902967       206 total

--//10g的測試:

$ strace -f -c sqlplus -s -l scott/btbtms @m1.txt 1e5 id=1_unique_index 0 >/dev/null

% time     seconds  usecs/call     calls    errors syscall

------ ----------- ----------- --------- --------- ----------------

 72.00    0.056425           0    700486           getrusage

 24.98    0.019573        2796         7         2 wait4

  0.91    0.000714           3       236           read

  0.74    0.000582          97         6           clone

  0.73    0.000572         286         2           shmdt

  0.23    0.000177           1       302       189 open

  0.16    0.000122           1       145       108 stat

  0.05    0.000042           1        65           write

..

  0.03    0.000025           0       116           times

------ ----------- ----------- --------- --------- ----------------

100.00    0.097352                702291       347 total

--//差異在於10g很少做times的系統呼叫上.10g下僅僅116次.而11g高達200179.

--//如果再次執行跟蹤如下,11g: 

$ strace -f  -p 57003

times({tms_utime=1948, tms_stime=328, tms_cutime=0, tms_cstime=0}) = 10865304314

times({tms_utime=1948, tms_stime=328, tms_cutime=0, tms_cstime=0}) = 10865304314

getrusage(RUSAGE_SELF, {ru_utime={19, 483038}, ru_stime={3, 285500}, ...}) = 0

getrusage(RUSAGE_SELF, {ru_utime={19, 483038}, ru_stime={3, 285500}, ...}) = 0

getrusage(RUSAGE_SELF, {ru_utime={19, 483038}, ru_stime={3, 285500}, ...}) = 0

getrusage(RUSAGE_SELF, {ru_utime={19, 483038}, ru_stime={3, 285500}, ...}) = 0

getrusage(RUSAGE_SELF, {ru_utime={19, 483038}, ru_stime={3, 285500}, ...}) = 0

getrusage(RUSAGE_SELF, {ru_utime={19, 483038}, ru_stime={3, 285500}, ...}) = 0

getrusage(RUSAGE_SELF, {ru_utime={19, 483038}, ru_stime={3, 285500}, ...}) = 0

times({tms_utime=1948, tms_stime=328, tms_cutime=0, tms_cstime=0}) = 10865304314

times({tms_utime=1948, tms_stime=328, tms_cutime=0, tms_cstime=0}) = 10865304314

getrusage(RUSAGE_SELF, {ru_utime={19, 483038}, ru_stime={3, 285500}, ...}) = 0

getrusage(RUSAGE_SELF, {ru_utime={19, 483038}, ru_stime={3, 285500}, ...}) = 0

getrusage(RUSAGE_SELF, {ru_utime={19, 483038}, ru_stime={3, 285500}, ...}) = 0

getrusage(RUSAGE_SELF, {ru_utime={19, 483038}, ru_stime={3, 285500}, ...}) = 0

getrusage(RUSAGE_SELF, {ru_utime={19, 483038}, ru_stime={3, 285500}, ...}) = 0

getrusage(RUSAGE_SELF, {ru_utime={19, 483038}, ru_stime={3, 285500}, ...}) = 0

getrusage(RUSAGE_SELF, {ru_utime={19, 483038}, ru_stime={3, 285500}, ...}) = 0

times({tms_utime=1948, tms_stime=328, tms_cutime=0, tms_cstime=0}) = 10865304314

times({tms_utime=1948, tms_stime=328, tms_cutime=0, tms_cstime=0}) = 10865304314

--//呼叫7次getrusage,呼叫2次times.

--//對比前面的呼叫比例也可以看出getrusage呼叫700708,times呼叫times200179.非常接近7:2

--//而10g下僅僅看到:

getrusage(RUSAGE_SELF, {ru_utime={13, 203992}, ru_stime={1, 700741}, ...}) = 0

getrusage(RUSAGE_SELF, {ru_utime={13, 203992}, ru_stime={1, 700741}, ...}) = 0

getrusage(RUSAGE_SELF, {ru_utime={13, 203992}, ru_stime={1, 700741}, ...}) = 0

getrusage(RUSAGE_SELF, {ru_utime={13, 203992}, ru_stime={1, 700741}, ...}) = 0

getrusage(RUSAGE_SELF, {ru_utime={13, 203992}, ru_stime={1, 700741}, ...}) = 0

getrusage(RUSAGE_SELF, {ru_utime={13, 203992}, ru_stime={1, 700741}, ...}) = 0

getrusage(RUSAGE_SELF, {ru_utime={13, 203992}, ru_stime={1, 700741}, ...}) = 0

getrusage(RUSAGE_SELF, {ru_utime={13, 203992}, ru_stime={1, 700741}, ...}) = 0

getrusage(RUSAGE_SELF, {ru_utime={13, 203992}, ru_stime={1, 700741}, ...}) = 0

getrusage(RUSAGE_SELF, {ru_utime={13, 203992}, ru_stime={1, 700741}, ...}) = 0

getrusage(RUSAGE_SELF, {ru_utime={13, 203992}, ru_stime={1, 700741}, ...}) = 0

getrusage(RUSAGE_SELF, {ru_utime={13, 203992}, ru_stime={1, 700741}, ...}) = 0

--//正是這樣的差異導致10g下明顯快於11g.