[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