[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