[20190505]關於latch 一些統計資訊.txt

--//我在兩篇文章,提到一些latch的統計資訊.連結如下:

http://blog.itpub.net/267265/viewspace-2642329/ =>[20190423]簡單測試latch nowilling等待模式.txt

http://blog.itpub.net/267265/viewspace-2641549/ =>[20190416]檢視shared latch gets的變化.txt

--//我提到過以前我對這些統計是非常混亂的,到底什麼情況是immediate_gets,什麼情況下SPIN_GETS,sleep會增加.

--//我還是透過測試說明,一個測試勝過一大堆文字說明...

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

>select addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_parent where lower(name) like '%'||lower('test excl. parent l0')||'%'

ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME

---------------- ---------------------------------------- ---------- ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------

00000000600098D8 test excl. parent l0 0 4 151 0 0 0 0 0 0 0 0

--//我在連結http://blog.itpub.net/267265/viewspace-2642329/提到nowilling等待模式的情況,IMMEDIATE_GETS和IMMEDIATE_GETS的變化.不再論述.

--//如下測試僅僅關注SPIN_GETS,MISSES,SLEEPS的變化.

2.測試:

$ cat aa.sql

select sysdate,addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_parent where name='test excl. parent l0';

host sleep 1

--//注意是test excl. parent l0 後面的不是10是l0.一直以為是10。看來要一副好眼力.

$ cat y1.sh

#! /bin/bash

zdate=$(date '+%Y%m%d%H%M%S')

echo $zdate

source peek.sh 'test excl. parent l0' 20 | timestamp.pl > /tmp/peekx_${zdate}.txt &

seq 20 | xargs -I{} echo -e 'sqlplus -s -l / as sysdba <<< @latch_free\nsleep 1' | bash > /tmp/latch_free_${zdate}.txt &

sqlplus -s -l / as sysdba <<EOF > /tmp/latch_sum_${zdate}.txt &

$(seq 20 | xargs -I {} echo @aa)

EOF

# 引數如下: @ exclusive_latch.txt latch_name willing why where sleep_num

sqlplus / as sysdba <<< "@ exclusive_latch.txt 'test excl. parent l0' 1 1 2 6" > /dev/null &

sleep 2

sqlplus / as sysdba <<< "@ exclusive_latch.txt 'test excl. parent l0' 1 3 4 6" > /dev/null &

sleep 10.2

sqlplus / as sysdba <<< "@ exclusive_latch.txt 'test excl. parent l0' 1 5 6 6" > /dev/null &

wait

$ cat exclusive_latch.txt

/* 引數如下: @ exclusive_latch.txt latch_name willing why where sleep_num */

--//connect / as sysdba

col laddr new_value laddr

SELECT addr laddr FROM v$latch_parent WHERE NAME='&&1';

oradebug setmypid

oradebug call kslgetl 0x&laddr &&2 &&3 &&4

host sleep &&5

oradebug call kslfre 0x&laddr

--//exit

3.執行:

SYS@book> select sysdate,addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_parent where name='test excl. parent l0';

SYSDATE ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME

------------------- ---------------- -------------------- ------ ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------

2019-04-30 12:13:39 00000000600098D8 test excl. parent l0 0 4 17 12 12 0 0 0 0 0 95671068

$ . y1.sh

20190430121417

[4]- Done sqlplus / as sysdba <<< "@ exclusive_latch.txt 'test excl. parent l0' 1 1 2 6" > /dev/null

[5]+ Done sqlplus / as sysdba <<< "@ exclusive_latch.txt 'test excl. parent l0' 1 3 4 6" > /dev/null

[1] Done source peek.sh 'test excl. parent l0' 20 | timestamp.pl > /tmp/peekx_${zdate}.txt

[4]+ Done sqlplus / as sysdba <<< "@ exclusive_latch.txt 'test excl. parent l0' 1 5 6 6" > /dev/null

[2]- Done seq 20 | xargs -I{} echo -e 'sqlplus -s -l / as sysdba <<< @latch_free\nsleep 1' | bash > /tmp/latch_free_${zdate}.txt

[3]+ Done sqlplus -s -l / as sysdba > /tmp/latch_sum_${zdate}.txt <<EOF

$(seq 20 | xargs -I {} echo @aa)

EOF

$ grep "00000000600098D8" /tmp/latch_sum_20190430121417.txt

--//行頭是我新增上的。

SYSDATE ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME

------------------- ---------------- -------------------- ------ ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------

2019-04-30 12:14:18 00000000600098D8 test excl. parent l0 0 4 18 12 12 0 0 0 0 0 95671068

2019-04-30 12:14:19 00000000600098D8 test excl. parent l0 0 4 18 12 12 0 0 0 0 0 95671068

2019-04-30 12:14:20 00000000600098D8 test excl. parent l0 0 4 18 12 12 0 0 0 0 0 95671068

2019-04-30 12:14:21 00000000600098D8 test excl. parent l0 0 4 18 12 12 0 0 0 0 0 95671068

2019-04-30 12:14:22 00000000600098D8 test excl. parent l0 0 4 18 12 12 0 0 0 0 0 95671068

2019-04-30 12:14:23 00000000600098D8 test excl. parent l0 0 4 18 12 12 0 0 0 0 0 95671068

--//過了6秒。gets數量增加1。MISSES,SLEEPS數量不變。

2019-04-30 12:14:24 00000000600098D8 test excl. parent l0 0 4 19 13 13 0 0 0 0 0 99676819

--//7秒後,第2個session請求獲得latch（實際上等了4秒），統計更新gets增加1(也就是在獲得latch時統計資訊才更新).因為這次沒有馬上獲取成功。

--//MISSES,SLEEPS數量增加1。

2019-04-30 12:14:25 00000000600098D8 test excl. parent l0 0 4 19 13 13 0 0 0 0 0 99676819

2019-04-30 12:14:26 00000000600098D8 test excl. parent l0 0 4 19 13 13 0 0 0 0 0 99676819

2019-04-30 12:14:27 00000000600098D8 test excl. parent l0 0 4 19 13 13 0 0 0 0 0 99676819

2019-04-30 12:14:28 00000000600098D8 test excl. parent l0 0 4 19 13 13 0 0 0 0 0 99676819

2019-04-30 12:14:29 00000000600098D8 test excl. parent l0 0 4 19 13 13 0 0 0 0 0 99676819

2019-04-30 12:14:30 00000000600098D8 test excl. parent l0 0 4 19 13 13 0 0 0 0 0 99676819

--//第3個session 沒有阻塞，僅僅gets增加1。

2019-04-30 12:14:31 00000000600098D8 test excl. parent l0 0 4 20 13 13 0 0 0 0 0 99676819

2019-04-30 12:14:32 00000000600098D8 test excl. parent l0 0 4 20 13 13 0 0 0 0 0 99676819

2019-04-30 12:14:33 00000000600098D8 test excl. parent l0 0 4 20 13 13 0 0 0 0 0 99676819

2019-04-30 12:14:34 00000000600098D8 test excl. parent l0 0 4 20 13 13 0 0 0 0 0 99676819

2019-04-30 12:14:35 00000000600098D8 test excl. parent l0 0 4 20 13 13 0 0 0 0 0 99676819

2019-04-30 12:14:36 00000000600098D8 test excl. parent l0 0 4 20 13 13 0 0 0 0 0 99676819

2019-04-30 12:14:37 00000000600098D8 test excl. parent l0 0 4 20 13 13 0 0 0 0 0 99676819

SYS@book> select sysdate,addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_parent where name='test excl. parent l0';

SYSDATE ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME

------------------- ---------------- --------------------- ------ ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------

2019-04-30 12:16:02 00000000600098D8 test excl. parent l0 0 4 20 13 13 0 0 0 0 0 99676819

--//最終gets增加3次,MISSES增加1次,SLEEPS增加1次.你可能發現一個現象spin_gets並沒有變化。

--//我前面測試已經說明，latch spin方式發生了變化，僅僅spin 10*_spin_count(對於exclusive latch)，_spin_count(對於shared latch).

--//然後在申請不成功的情況下系統呼叫semop休眠，等待喚醒。這樣方式消耗CPU資源很少。

--//那麼什麼情況下spin_gets下會增加呢?是在spin過程中獲得latch嗎？如何測試呢？

3.測試spin_gets變化的情況:

--//我以前測試_mutex_spin_count引數時255,65535時，2個semtimedop間隔大約0.001秒。

--//0.0120157-0.0110002 = .0010155

$ cat y2.sh

#! /bin/bash

zdate=$(date '+%Y%m%d%H%M%S')

echo $zdate

source peek.sh 'test excl. parent l0' 6 | timestamp.pl > /tmp/peekx_${zdate}.txt &

seq 20 | xargs -I{} echo -e 'sqlplus -s -l / as sysdba <<< @latch_free\nsleep 1' | bash > /tmp/latch_free_${zdate}.txt &

sqlplus -s -l / as sysdba <<EOF > /tmp/latch_sum_${zdate}.txt &

$(seq 20 | xargs -I {} echo @aa)

EOF

# 引數如下: @ exclusive_latch.txt latch_name willing why where sleep_num

sqlplus / as sysdba <<< "@ exclusive_latch.txt 'test excl. parent l0' 1 1 2 2" > /dev/null &

sleep $1

sqlplus / as sysdba <<< "@ exclusive_latch.txt 'test excl. parent l0' 1 3 4 2" > /dev/null &

wait

--//$1=1.999,不行!!指令碼控制太困難使用手工測試看看.

4.手工測試更容易一下。

--//session 1:

SYS@book> @ spid

SID SERIAL# PROCESS SERVER SPID PID P_SERIAL# C50

---------- ---------- ------------------------ --------- ------ ------- ---------- --------------------------------------------------

295 3 43362 DEDICATED 19499 21 2 alter system kill session '295,3' immediate;

SYS@book> @ exclusive_latch.txt 'test excl. parent l0' 1 1 2 100000

LADDR

----------------

00000000600098D8

Statement processed.

Function returned 1

--//session 2:

SYS@book> @ spid

SID SERIAL# PROCESS SERVER SPID PID P_SERIAL# C50

---------- ---------- ------------------------ --------- ------ ------- ---------- --------------------------------------------------

58 21 20098 DEDICATED 20099 28 6 alter system kill session '58,21' immediate;

--//記下spid=20099

SYS@book> select sysdate,addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_parent where name='test excl. parent l0';

SYSDATE ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME

------------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------

2019-05-05 09:37:53 00000000600098D8 test excl. parent l0 0 4 9 3 3 0 0 0 0 0 46203

--//window 3:

$ gdb -p 20099

(gdb) break kslges

Breakpoint 1 at 0x93f9b74

--//參考：http://blog.itpub.net/267265/viewspace-2641872/ =>[20190418]exclusive latch spin count.txt

(gdb) bt 6

#0 0x00000037990d6407 in semop () from /lib64/libc.so.6

#1 0x0000000009809c0f in sskgpwwait ()

#2 0x00000000098089ce in skgpwwait ()

#3 0x00000000093f9fe1 in kslges ()

#4 0x00000000093f997a in kslgetl ()

#5 0x0000000007d7402e in skdxcall ()

(More stack frames follow...)

--//如果停在kslges這裡，進入spin階段。

(gdb) disassemble kslges

--//反彙編看看.

...

0x00000000093f9ddc <kslges+620>: xor %esi,%esi

0x00000000093f9dde <kslges+622>: mov %esi,-0xd8(%rbp)

0x00000000093f9de4 <kslges+628>: mov %sil,-0xa6(%rbp)

0x00000000093f9deb <kslges+635>: mov 0x0(%r13),%rdi

0x00000000093f9def <kslges+639>: test %rdi,%rdi

0x00000000093f9df2 <kslges+642>: je 0x93fa6c0 <kslges+2896>

0x00000000093f9df8 <kslges+648>: add $0xffffffffffffffff,%ecx

0x00000000093f9dfb <kslges+651>: add $0xffffffffffffffff,%eax

0x00000000093f9dfe <kslges+654>: jne 0x93f9ddc <kslges+620>

...

--//再次說明我不懂彙編,不過可以猜測:

--//%r13對應地址600098D8的內容賦值給%rdi,實際賦值等於session 1的pid(session 1持有該latch)。

--//也就是oradebug peek 0x600098D8 4 看到的內容。

--//如果不等(說明該latch已經釋放),執行0x00000000093f9df2 <kslges+642>: je 0x93fa6c0 <kslges+2896>，

--//跳轉0x93fa6c0地址執行，跳出spin的迴圈體。

--//繼續：

--//session 2:

SYS@book> @ exclusive_latch.txt 'test excl. parent l0' 1 3 4 2

--//掛起!!

--//window 3:

(gdb) c

Continuing.

Breakpoint 1, 0x00000000093f9b74 in kslges ()

(gdb) ni 1000

0x00000000093f9dfb in kslges ()

(gdb) info register rax rcx rip r13 rdi

rax 0x4dc0 19904

rcx 0x4dbe 19902

rip 0x93f9dfb 0x93f9dfb <kslges+651>

r13 0x600098d8 1610651864

rdi 0x15 21

--//rdi記錄的持有latch的pid號.看session 1的@spid輸出.

--//session 3:

SYS@book> select sysdate,addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_parent where name='test excl. parent l0';

SYSDATE ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME

------------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------

2019-05-05 09:41:23 00000000600098D8 test excl. parent l0 0 4 9 3 3 0 0 0 0 0 46203

--//session 1:

--//按ctrl+c中斷sleep執行,釋放latch.

SYS@book> @ exclusive_latch.txt 'test excl. parent l0' 1 1 2 100000

LADDR

----------------

00000000600098D8

Statement processed.

Function returned 1

Function returned 0

SYS@book> oradebug peek 0x00000000600098D8 8

[0600098D8, 0600098E0) = 00000000 00000000

--//已經為00000000 00000000

--//window 3:

--//單步執行的情況:

(gdb) ni

0x00000000093f9dfe in kslges ()

(gdb) info register rax rcx rip r13 rdi

rax 0x4dbf 19903

rcx 0x4dbe 19902

rip 0x93f9dfe 0x93f9dfe <kslges+654>

r13 0x600098d8 1610651864

rdi 0x15 21

(gdb) ni

0x00000000093f9ddc in kslges ()

(gdb) info register rax rcx rip r13 rdi

rax 0x4dbf 19903

rcx 0x4dbe 19902

rip 0x93f9ddc 0x93f9ddc <kslges+620>

r13 0x600098d8 1610651864

rdi 0x15 21

(gdb) ni

0x00000000093f9dde in kslges ()

(gdb) info register rax rcx rip r13 rdi

rax 0x4dbf 19903

rcx 0x4dbe 19902

rip 0x93f9dde 0x93f9dde <kslges+622>

r13 0x600098d8 1610651864

rdi 0x15 21

(gdb) ni

0x00000000093f9de4 in kslges ()

(gdb) info register rax rcx rip r13 rdi

rax 0x4dbf 19903

rcx 0x4dbe 19902

rip 0x93f9de4 0x93f9de4 <kslges+628>

r13 0x600098d8 1610651864

rdi 0x15 21

(gdb) ni

0x00000000093f9deb in kslges ()

(gdb) info register rax rcx rip r13 rdi

rax 0x4dbf 19903

rcx 0x4dbe 19902

rip 0x93f9deb 0x93f9deb <kslges+635>

r13 0x600098d8 1610651864

rdi 0x15 21

(gdb) ni

0x00000000093f9def in kslges ()

(gdb) info register rax rcx rip r13 rdi

rax 0x4dbf 19903

rcx 0x4dbe 19902

rip 0x93f9def 0x93f9def <kslges+639>

r13 0x600098d8 1610651864

rdi 0x0 0

--//rdi現在是0了.

(gdb) ni

0x00000000093f9df2 in kslges ()

(gdb) info register rax rcx rip r13 rdi

rax 0x4dbf 19903

rcx 0x4dbe 19902

rip 0x93f9df2 0x93f9df2 <kslges+642>

r13 0x600098d8 1610651864

rdi 0x0 0

(gdb) ni

0x00000000093fa6c0 in kslges ()

(gdb) info register rax rcx rip r13 rdi

rax 0x4dbf 19903

rcx 0x4dbe 19902

rip 0x93fa6c0 0x93fa6c0 <kslges+2896>

r13 0x600098d8 1610651864

rdi 0x0 0

(gdb) ni

0x00000000093fa6c2 in kslges ()

(gdb) info register rax rcx rip r13 rdi

rax 0x4dbf 19903

rcx 0x4dbe 19902

rip 0x93fa6c2 0x93fa6c2 <kslges+2898>

r13 0x600098d8 1610651864

rdi 0x0 0

--//現在已經調出迴圈體.

--//session 3:

SYS@book> select sysdate,addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_parent where name='test excl. parent l0';

SYSDATE ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME

------------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------

2019-05-05 09:52:20 00000000600098D8 test excl. parent l0 0 4 9 3 3 0 0 0 0 0 46203

--//window 3:

--//不再單步跟蹤了.

(gdb) c

Continuing.

--//session 3:

SYS@book> select sysdate,addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_parent where name='test excl. parent l0';

SYSDATE ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME

------------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------

2019-05-05 09:53:29 00000000600098D8 test excl. parent l0 0 4 10 4 3 0 0 0 0 1 46203

--//注意看現在spin_gets增加了1,在獲取latch後,統計資訊增加.MISSES增加1,sleeps不變,SPIN_GETS從0->1.

--//另外注意一個細節wait_time時間不變.也就是spin階段獲取latch,等待的時間不計入該檢視,僅僅在sleep階段wait_time才會增加.

--//重複執行前面的y1.sh測試指令碼對比就可以發現這個變化:

SYS@book> select sysdate,addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_parent where name='test excl. parent l0';

SYSDATE ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME

------------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------

2019-05-05 09:58:38 00000000600098D8 test excl. parent l0 0 4 10 4 3 0 0 0 0 1 46203

$ . y1.sh

20190505095849

[4]- Done sqlplus / as sysdba <<< "@ exclusive_latch.txt 'test excl. parent l0' 1 1 2 6" > /dev/null

[5]+ Done sqlplus / as sysdba <<< "@ exclusive_latch.txt 'test excl. parent l0' 1 3 4 6" > /dev/null

[1] Done source peek.sh 'test excl. parent l0' 20 | timestamp.pl > /tmp/peekx_${zdate}.txt

[4]+ Done sqlplus / as sysdba <<< "@ exclusive_latch.txt 'test excl. parent l0' 1 5 6 6" > /dev/null

[2]- Done seq 20 | xargs -I{} echo -e 'sqlplus -s -l / as sysdba <<< @latch_free\nsleep 1' | bash > /tmp/latch_free_${zdate}.txt

[3]+ Done sqlplus -s -l / as sysdba > /tmp/latch_sum_${zdate}.txt <<EOF

$(seq 20 | xargs -I {} echo @aa)

EOF

SYS@book> select sysdate,addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_parent where name='test excl. parent l0';

SYSDATE ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME

------------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------

2019-05-05 09:59:20 00000000600098D8 test excl. parent l0 0 4 13 5 4 0 0 0 0 1 4050042

--//gets增加3次,misses增加1次.sleeps增加1,spin_gets不變.wait_time,4050042-46203 = 4003839 ,這個單位是微秒.基本吻合.

5.總結:

--//可以透過測試瞭解latch統計資訊的一些細節.

1.獲取latch後gets增加.統計資訊也在這個時刻更新.

2.正常情況下MISSES=SLEEPS+SPIN_GETS.

3.我在一臺生產系統發現misses,sleeps+spin_gets 差別很小,當然如果執行好幾年還是有一定差別的(一些中斷異常退出會導致這樣的差別)

SYS@xxx> select STARTUP_TIME from v$instance ;

STARTUP_TIME

-------------------

2016-08-28 19:15:56

--//已經執行好幾年的一箇中型資料庫的情況.

SELECT SYSDATE

,addr

,name

,level#

,latch#

,gets

,misses

,sleeps

,immediate_gets

,immediate_misses

,waiters_woken

,waits_holding_latch

,spin_gets

,wait_time

,misses-sleeps-spin_gets

FROM v$latch_children

WHERE name LIKE 'cache buffers chains';

..

select count(*) from (

SELECT SYSDATE

,addr

,name

,level#

,latch#

,gets

,misses

,sleeps

,immediate_gets

,immediate_misses

,waiters_woken

,waits_holding_latch

,spin_gets

,wait_time

,misses-sleeps-spin_gets

FROM v$latch_children

WHERE name LIKE 'cache buffers chains'

and misses-sleeps-spin_gets<>0);

COUNT(*)

----------

39

select count(*) from (

SELECT SYSDATE

,addr

,name

,level#

,latch#

,gets

,misses

,sleeps

,immediate_gets

,immediate_misses

,waiters_woken

,waits_holding_latch

,spin_gets

,wait_time

,misses-sleeps-spin_gets

FROM v$latch_children

WHERE name LIKE 'cache buffers chains'

and misses-sleeps-spin_gets=0);

COUNT(*)

----------

8153

--//39 + 8153 = 8192.另外我發現cbc latch 的統計中immediate_gets有數值,說明一些情況可以以nowilling模式獲取該拴鎖.一些細節還給探究看看.

6.補充測試:

--//測試process allocation latch的情況,我前面說了這個latch很特殊,預設屬於不同類

SYS@book> select CLASS_KSLLT,decode(CLASS_KSLLT,2,KSLLTNAM) name,count(*) from x$kslltr group by CLASS_KSLLT,decode(CLASS_KSLLT,2,KSLLTNAM);

CLASS_KSLLT NAME COUNT(*)

----------- ---------------------------------------- ----------

0 581

2 process allocation 1

SYS@book> select * from x$ksllclass ;

ADDR INDX INST_ID SPIN YIELD WAITTIME SLEEP0 SLEEP1 SLEEP2 SLEEP3 SLEEP4 SLEEP5 SLEEP6 SLEEP7

---------------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ----------

00000000861986C0 0 1 20000 0 1 8000 8000 8000 8000 8000 8000 8000 8000

00000000861986EC 1 1 20000 0 1 1000 1000 1000 1000 1000 1000 1000 1000

0000000086198718 2 1 20000 0 1 8000 8000 8000 8000 8000 8000 8000 8000

0000000086198744 3 1 20000 0 1 1000 1000 1000 1000 1000 1000 1000 1000

0000000086198770 4 1 20000 0 1 8000 8000 8000 8000 8000 8000 8000 8000

000000008619879C 5 1 20000 0 1 8000 8000 8000 8000 8000 8000 8000 8000

00000000861987C8 6 1 20000 0 1 8000 8000 8000 8000 8000 8000 8000 8000

00000000861987F4 7 1 20000 0 1 8000 8000 8000 8000 8000 8000 8000 8000

8 rows selected.

SYS@book> select sysdate,addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_parent where name='process allocation';

SYSDATE ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME

------------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------

2019-05-05 11:05:55 0000000060009F88 process allocation 7 8 82 0 0 37 0 0 0 0 0

$ cat y3.sh

#! /bin/bash

vdate=$(date '+%Y%m%d%H%M%S')

echo $vdate

#source peek.sh "$1" 8 | timestamp.pl >| /tmp/peekx_${vdate}.txt &

#seq 8 | xargs -I{} echo -e 'sqlplus -s -l / as sysdba <<< @latch_free\nsleep 1' | bash >| /tmp/latch_free_${vdate}.txt &

#sleep 1

# 引數如下: @ exclusive_latch.txt latch_name willing why where sleep_num

sqlplus / as sysdba @ exclusive_latch.txt "$1" 1 1 2 3 > /dev/null &

sleep 1

strace -ftT -o /tmp/pp_${vdate}.txt sqlplus -s -l scott/book <<< 'select sysdate from dual ;' &

wait

$ . y3.sh 'process allocation'

20190505110558

[21]+ Stopped sqlplus / as sysdba @ exclusive_latch.txt "$1" 1 1 2 3 > /dev/null

SYSDATE

-------------------

2019-05-05 11:06:01

[22] Done strace -ftT -o /tmp/pp_${vdate}.txt sqlplus -s -l scott/book <<< 'select sysdate from dual ;'

SYS@book> select sysdate,addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_parent where name='process allocation';

SYSDATE ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME

------------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------

2019-05-05 11:06:04 0000000060009F88 process allocation 7 8 88 1 237 39 0 0 0 0 1962925

--//sleeps=237次.gets什麼增加6次.

$ grep "select(0" /tmp/pp_20190505110558.txt |wc

237 2844 17301

--//精確吻合.

$ grep "select(0" /tmp/pp_20190505110558.txt | awk '{print $NF}' | tr -d '<>'| xargs | sed 's/ /+/g' | bc -l

1.930709

--//與後面的等待時間也很接近.

--//我有重複1次.

SYS@book> select sysdate,addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_parent where name='process allocation';

SYSDATE ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME

------------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------

2019-05-05 11:12:33 0000000060009F88 process allocation 7 8 94 1 237 42 0 0 0 0 1962925

$ . y3.sh 'process allocation'

20190505111240

[22]+ Stopped sqlplus / as sysdba @ exclusive_latch.txt "$1" 1 1 2 3 > /dev/null

SYSDATE

-------------------

2019-05-05 11:12:43

[23] Done strace -ftT -o /tmp/pp_${vdate}.txt sqlplus -s -l scott/book <<< 'select sysdate from dual ;'

SYS@book> select sysdate,addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_parent where name='process allocation';

SYSDATE ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME

------------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------

2019-05-05 11:12:49 0000000060009F88 process allocation 7 8 98 2 469 44 0 0 0 0 3882339

$ grep "select(0" /tmp/pp_20190505111240.txt |wc

232 2784 16936

--//這次能對上.也許測試有一些干擾.

--//另外我開啟一個新會話,視乎gets,IMMEDIATE_GETS都增加,視乎開始以nowilling等待申請.

--//登入前:

SYS@book> select sysdate,addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_parent where name='process allocation';

SYSDATE ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME

------------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------

2019-05-05 11:17:06 0000000060009F88 process allocation 7 8 115 2 469 50 0 0 0 0 3882339

--//登入後:

SYS@book> select sysdate,addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_parent where name='process allocation';

SYSDATE ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME

------------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------

2019-05-05 11:17:18 0000000060009F88 process allocation 7 8 116 2 469 51 0 0 0 0 3882339

--//gets,IMMEDIATE_GETS增加1.

--//退出後:

SYS@book> select sysdate,addr,name,level#,latch#,gets,misses,sleeps,immediate_gets,immediate_misses,waiters_woken,waits_holding_latch,spin_gets,wait_time from v$latch_parent where name='process allocation';

SYSDATE ADDR NAME LEVEL# LATCH# GETS MISSES SLEEPS IMMEDIATE_GETS IMMEDIATE_MISSES WAITERS_WOKEN WAITS_HOLDING_LATCH SPIN_GETS WAIT_TIME

------------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------- ---------- -------------- ---------------- ------------- ------------------- ---------- ----------

2019-05-05 11:17:26 0000000060009F88 process allocation 7 8 117 2 469 51 0 0 0 0 3882339

--//亂...

[20190505]關於latch 一些統計資訊.txt

相關文章