[20190423]那個更快的疑問3.txt--//前一陣子,做了11g在單表單條記錄唯一索引掃描的測試,摘要如下:--//參考鏈接:http://blog.itpub.net/267265/viewspace-2636321/http://blog.itpub.net/267265/viewspa ...
[20190423]那個更快的疑問3.txt
--//前一陣子,做了11g在單表單條記錄唯一索引掃描的測試,摘要如下:
--//參考鏈接:
http://blog.itpub.net/267265/viewspace-2636321/
http://blog.itpub.net/267265/viewspace-2636342/
--//在鏈接中我解析唯一索引查詢的情況，為什麼10g快於11g，鏈接：http://blog.itpub.net/267265/viewspace-2639920/
--//差異在於10g很少做times的系統調用上.10g下僅僅116次.而11g高達200179.(getrusage與times調用次數比大約是7:2)
--//我當時的感覺10g漏寫times系統函數調用，導致這樣的情況，11g把它補上了。
--//實際上有網友提出疑問.我的測試下的結論有問題.當時測試的情況如下:
--//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
--//1e5次執行times調用消耗0.011947秒,放大10倍(我每個session執行次數是1e6)也就是0.119470秒,什麼可能產生這麼大的差異.
--//仔細查看,我覺得strace跟蹤記錄的syscallsyscall.linux標準C函數.看不出oracle內部函數調用次數.
--//我當時的解析是這增加的times調用一定是11g版本唯一索引掃描中增加幾個oracle內部函數調用,導致11g的唯一索引
--//掃描更慢,如何驗證我當時確實不知道? 最近shared latch測試,建立一些gdb腳本,有了這些腳本可以latch獲得釋放的情況.
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 t as select rownum id from dual ;
create unique index pk_t on t(id);
alter table t modify id not null ;
create table job_times (sid number, time_ela number,method varchar2(20));
--//分析表略.
$ cat z1.txt
set verify off
host sleep $(echo &&3/50 | bc -l )
variable vmethod varchar2(20);
exec :vmethod := '&&2';
insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,:vmethod) ;
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 ;
end loop;
end ;
/
update job_times set time_ela = dbms_utility.get_time - time_ela where sid=sys_context ('userenv', 'sid') and method=:vmethod;
commit;
quit
3.分別測試:
$ sqlplus -s -l scott/book @z1.txt 1e6 id=unindex 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=unindex 1 2723 2723
--//在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
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=unindex 1 1591 1591
--//即使單用戶執行10g下比11g快許多.
3.通過gdb腳本分析:
--//11g:
SCOTT@book> @ spid
SID SERIAL# PROCESS SERVER SPID PID P_SERIAL# C50
---------- ---------- ------------------------ --------- ------ ------- ---------- --------------------------------------------------
88 89 65066 DEDICATED 65067 30 65 alter system kill session '88,89' immediate;
--//執行多次3次以上避免遞歸.
select count(*) from t where id=1;
--//打開window 2:
$ gdb -p 65067 -x latch11g.gdb
(gdb) c
Continuing.
ksl_get_shared_latch laddr:85f7fe28, willing:1, where:-2050764096, why:95, mode:8
ksl_get_shared_latch laddr:85f7fe28, willing:1, where:-2050764096, why:96, mode:16
ksl_get_shared_latch laddr:85f7fe28, willing:1, where:-2050764096, why:95, mode:8
kslgetl 844ed538, 0, 49, 2062
kslgetl 8353a258, 1, 16777771, 2053
ksl_get_shared_latch laddr:85f7fe28, willing:1, where:-2050764096, why:96, mode:16
ksl_get_shared_latch laddr:85f7fe28, willing:1, where:-2050764096, why:95, mode:8
ksl_get_shared_latch laddr:85f7fe28, willing:1, where:-2050764096, why:96, mode:16
--//看到ksl_get_shared_latch 6次,kslgetl 2次,看看是什麼latch.
> select addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_children where addr=lpad(upper('85f7fe28'),'16','0')
ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME
---------------- ---------------- ------ ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------
0000000085F7FE28 session idle bit 1 14 1095 0 0 0 0 0 0 0 0
--//session idle bit 第一次看見,我看了我的測試機器,一共24次children latch.估計跟CPU數量有關.我在另外的會話重覆測試
--//ksl_get_shared_latch的地址不一樣,而kslgetl 也是2次都是一樣.
> select addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_children where addr=lpad(upper('844ed538'),'16','0')
ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME
---------------- ------------------- ------ ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------
00000000844ED538 simulator lru latch 6 185 560 1 0 72795239 3207148 0 0 1 0
> select addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_children where addr=lpad(upper('8353a258'),'16','0')
ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME
---------------- -------------------- ------ ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------
000000008353A258 simulator hash latch 7 186 72792634 0 0 0 0 0 0 0 0
--//奇怪這兩個latch我從來沒有過,而且奇怪的是根本看不到cbc latch.
--//在10g下重覆測試看看(註10g shared latch 的函數是kslgetsl )
Breakpoint 1 at 0x7a0644
Breakpoint 2 at 0x7a0a44
Breakpoint 3 at 0x3bccd52
Breakpoint 4 at 0x3be9a04
Breakpoint 5 at 0x3181cd6400
Breakpoint 6 at 0x78ef44
Function "ksl_get_shared_latch" not defined.
Make breakpoint pending on future shared library load? (y or [n]) [answered N; input not from terminal]
Breakpoint 7 at 0x78f4bc
Breakpoint 8 at 0x79054c
--//奇怪10g沒有ksl_get_shared_latchoracle內部函數.註解這部分內容.
(gdb) c
Continuing.
kslgetsl laddr:7cfb24f8, willing:1, where:2096584384, why:80, mode:8
kslgetsl laddr:7cfb24f8, willing:1, where:2096584384, why:81, mode:16
kslgetsl laddr:7cfb24f8, willing:1, where:2096584384, why:80, mode:8
kslgetl 7a10aaa0, 1, 0, 2741
kslgetsl laddr:7cfb24f8, willing:1, where:2096584384, why:81, mode:16
kslgetsl laddr:7cfb24f8, willing:1, where:2096584384, why:80, mode:8
kslgetsl laddr:7cfb24f8, willing:1, where:2096584384, why:81, mode:16
--//看到kslgetsl 6次,kslgetl 1次,看看是什麼latch.
SYS@test> select addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_children where addr=lpad(upper('7cfb24f8'),'16','0');
ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME
---------------- -------------------- ------ ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------
000000007CFB24F8 session idle bit 1 7 7112 0 0 0 0 0 0 0 0
SYS@test> select addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_children where addr=lpad(upper('7a10aaa0'),'16','0');
ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME
---------------- ---------------------- ------ ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------
000000007A10AAA0 shared pool simulator 8 241 146325 1 0 0 0 0 0 1 0
--//你可以再次執行sql語句看看gets的變化:
SYS@test> select addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_children where addr=lpad(upper('7cfb24f8'),'16','0');
ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME
---------------- ---------------- ------ ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------
000000007CFB24F8 session idle bit 1 7 7118 0 0 0 0 0 0 0 0
SYS@test> select addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_children where addr=lpad(upper('7a10aaa0'),'16','0');
ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME
---------------- --------------------- ------ ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------
000000007A10AAA0 shared pool simulator 8 241 146326 1 0 0 0 0 0 1 0
--//說明跟蹤到的get變化沒有問題.我在11g看了latch的變化,只不過simulator lru latch 變成了IMMEDIATE_GETS數量增加:
> select addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_children where addr=lpad(upper('8353a258'),'16','0')
ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME
---------------- ---------------------------------------- ---------- ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------
000000008353A258 simulator hash latch 7 186 72792639 0 0 0 0 0 0 0 0
> select addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_children where addr=lpad(upper('844ed538'),'16','0')
ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME
---------------- ---------------------------------------- ---------- ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------
00000000844ED538 simulator lru latch 6 185 563 1 0 72795248 3207148 0 0 1 0
--//執行sql語句再查看.
> select addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_children where addr=lpad(upper('8353a258'),'16','0')
ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME
---------------- ---------------------------------------- ---------- ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------
000000008353A258 simulator hash latch 7 186 72792640 0 0 0 0 0 0 0 0
> select addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_children where addr=lpad(upper('844ed538'),'16','0')
ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME
---------------- ---------------------------------------- ---------- ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------
00000000844ED538 simulator lru latch 6 185 563 1 0 72795249 3207148 0 0 1 0
--//我估計跟一些參數有關:
kslgetl 844ed538, 0, 49, 2062
kslgetl 8353a258, 1, 16777771, 2053
--//我猜測0表示no willing等待. 1表示willing等待.
--//我最後猜測也許正是11g下代碼改動使用ksl_get_shared_latch,多了1次kslgetl調用,使用導致11g下每次執行多了2次times syscall,
--//可以講11g下唯一索引掃描是一個退步.
--//至於為什麼沒有阻塞看不到cbc latch獲取和釋放,我給再探究看看...
4.我加入1個欄位看看:
drop table t purge ;
create table t as select rownum id,'test' name from dual ;
create unique index pk_t on t(id);
alter table t modify id not null ;
$ cat z1.txt
set verify off
host sleep $(echo &&3/50 | bc -l )
variable vmethod varchar2(20);
exec :vmethod := '&&2';
insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,:vmethod) ;
commit ;
declare
v_id number;
v_d date;
v_name varchar2(4) ;
begin
for i in 1 .. &&1 loop
select /*+ &&3 */ name into v_name from t where id=1 ;
end loop;
end ;
/
update job_times set time_ela = dbms_utility.get_time - time_ela where sid=sys_context ('userenv', 'sid') and method=:vmethod;
commit;
quit
--//重覆測試:
--//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)
-------------------- ---------- ---------------------- -------------
id=unindex_name 1 2135 2135
id=unindex 1 2723 2723
--//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=unindex_name 1 1359 1359
id=unindex 1 1591 1591
--//真心搞不懂,回表反而更快一些.oracle許多東西真心搞不懂....
--//感覺如果訪問數據塊緩存數據塊,沒有阻塞無需要獲取cbc latch嗎?
5.附上gdb腳本:
--//11g版本:
$ cat latch11g.gdb
break kslgetl
commands
silent
printf "kslgetl %x, %d, %d, %d\n", $rdi, $rsi, $rdx, $rcx
c
end
break kslges
commands
silent
printf "kslges %x, %d, %d, %d\n", $rdi, $rsi, $rdx, $rcx
c
end
break skgpwwait
commands
silent
printf "skgpwwait %d, %d, %d, %d\n", $rdi, $rsi, $rdx, $rcx
c
end
break sskgpwwait
commands
silent
printf "sskgpwwait %d, %d, %d, %d\n", $rdi, $rsi, $rdx, $rcx
c
end
break semop
commands
silent
printf "semop %d, %d, %d, %d\n", $rdi, $rsi, $rdx, $rcx
c
end
#break *0x93f9ddc
# commands
# silent
# printf " spin count loop: %d %d %x\n", $rax,$rcx,$rip
# c
# end
##
break kslgetsl_w
commands
silent
printf "kslgetsl_w laddr:%x, willing:%d, where:%d, why:%d, mode:%d\n", $rdi, $rsi, $rdx, $rcx, $r8
c
end
break ksl_get_shared_latch
commands
silent
printf "ksl_get_shared_latch laddr:%x, willing:%d, where:%d, why:%d, mode:%d\n", $rdi, $rsi, $rdx, $rcx, $r8
c
end
break kslgess
commands
silent
printf "kslgess %x, %d, %d, %d\n", $rdi, $rsi, $rdx, $rcx
c
end
break kslskgs
commands
silent
printf "kslskgs %x, %d, %d, %d\n", $rdi, $rsi, $rdx, $rcx
c
end
break kslfre
commands
silent
printf "kslfre %x, %d, %d, %d\n", $rdi, $rsi, $rdx, $rcx
c
end
#break *0xa875be
# commands
# silent
# printf " spin count loop: %d %x\n", $r13,$rip
# c
# end
--//10g版本:
$ cat latch10g.gdb
break kslgetl
commands
silent
printf "kslgetl %x, %d, %d, %d\n", $rdi, $rsi, $rdx, $rcx
c
end
break kslges
commands
silent
printf "kslges %x, %d, %d, %d\n", $rdi, $rsi, $rdx, $rcx
c
end
break skgpwwait
commands
silent
printf "skgpwwait %d, %d, %d, %d\n", $rdi, $rsi, $rdx, $rcx
c
end
break sskgpwwait
commands
silent
printf "sskgpwwait %d, %d, %d, %d\n", $rdi, $rsi, $rdx, $rcx
c
end
break semop
commands
silent
printf "semop %d, %d, %d, %d\n", $rdi, $rsi, $rdx, $rcx
c
end
#break *0x93f9ddc
# commands
# silent
# printf " spin count loop: %d %d %x\n", $rax,$rcx,$rip
# c
# end
##
break kslgetsl
commands
silent
printf "kslgetsl laddr:%x, willing:%d, where:%d, why:%d, mode:%d\n", $rdi, $rsi, $rdx, $rcx, $r8
c
end
#break ksl_get_shared_latch
# commands
# silent
# printf "ksl_get_shared_latch laddr:%x, willing:%d, where:%d, why:%d, mode:%d\n", $rdi, $rsi, $rdx, $rcx, $r8
# c
# end
break kslgess
commands
silent
printf "kslgess %x, %d, %d, %d\n", $rdi, $rsi, $rdx, $rcx
c
end
break kslskgs
commands
silent
printf "kslskgs %x, %d, %d, %d\n", $rdi, $rsi, $rdx, $rcx
c
end
#break *0xa875be
# commands
# silent
# printf " spin count loop: %d %x\n", $r13,$rip
# c
# end
