[20190401]那個更快的疑問.txt--//前一陣子,做了11g於10g下,單表單條記錄唯一索引掃描的測試,摘要如下:--//參考鏈接:http://blog.itpub.net/267265/viewspace-2636321/http://blog.itpub.net/267265/vie ...
[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.
--//順便看看times輸出表示什麼?
$ man 2 times
NAME
times - get process times
SYNOPSIS
#include <sys/times.h>
clock_t times(struct tms *buf);
DESCRIPTION
times() stores the current process times in the struct tms that buf points to. The struct tms is as defined in <sys/times.h>:
struct tms {
clock_t tms_utime; /* user time */
clock_t tms_stime; /* system time */
clock_t tms_cutime; /* user time of children */
clock_t tms_cstime; /* system time of children */
};
The tms_utime field contains the CPU time spent executing instructions of the calling process. The tms_stime
field contains the CPU time spent in the system while executing tasks on behalf of the calling process. The
tms_cutime field contains the sum of the tms_utime and tms_cutime values for all waited-for terminated children.
The tms_cstime field contains the sum of the tms_stime and tms_cstime values for all waited-for terminated
children.
Times for terminated children (and their descendants) is added in at the moment wait(2) or waitpid(2) returns
their process ID. In particular, times of grandchildren that the children did not wait for are never seen.
All times reported are in clock ticks.
RETURN VALUE
times() returns the number of clock ticks that have elapsed since an arbitrary point in the past. For Linux 2.4
and earlier this point is the moment the system was booted. Since Linux 2.6, this point is (2^32/HZ) - 300
(i.e., about 429 million) seconds before system boot time. The return value may overflow the possible range of
type clock_t. On error, (clock_t) -1 is returned, and errno is set appropriately.
$ cat /proc/uptime ;uptime
104375436.65 104342102.07
10:12:33 up 1208 days, 1:10, 2 users, load average: 0.01, 0.01, 0.07
--//我的計算:
2^32 = 4294967296
4294967296-300 = 4294966996 ,文檔提到 429 million seconds,不對明顯相差10被.難道Hz的單位1/10秒嗎?不懂.
4294967296/60-300 = 429496429.6
10437543665+429496429.6 = 10867040094.6
--//這樣與上面的結果比較接近了,再次驗證看看.
$ strace -f -p 57447 ; cat /proc/uptime
...
getrusage(RUSAGE_SELF, {ru_utime={22, 765539}, ru_stime={3, 829417}, ...}) = 0
times({tms_utime=2276, tms_stime=382, tms_cutime=0, tms_cstime=0}) = 10865578855
times({tms_utime=2276, tms_stime=382, tms_cutime=0, tms_cstime=0}) = 10865578855
getrusage(RUSAGE_SELF, {ru_utime={22, 765539}, ru_stime={3, 829417}, ...}) = 0
getrusage(RUSAGE_SELF, {ru_utime={22, 765539}, ru_stime={3, 829417}, ...}) = 0
getrusage(RUSAGE_SELF, {ru_utime={22, 765539}, ru_stime={3, 829417}, ...}) = 0
getrusage(RUSAGE_SELF, {ru_utime={22, 765539}, ru_stime={3, 829417}, ...}) = 0
getrusage(RUSAGE_SELF, {ru_utime={22, 765539}, ru_stime={3, 829417}, ...}) = 0
getrusage(RUSAGE_SELF, {ru_utime={22, 765539}, ru_stime={3, 829417}, ...}) = 0
getrusage(RUSAGE_SELF, {ru_utime={22, 765539}, ru_stime={3, 829417}, ...}) = 0
^CProcess 57447 detached
104377639.45 2484149083.69
4294967296/2593.795/1^6 -300 = 1655562.27747374021462760164
104377639.45+1655562.27747374021462760164
10437763945+(4294967296/10-300) = 10867260374.6
--//存在很大的誤差放棄!!
