[20190423]那个更快的疑问3.txt

[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