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