[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

--//乱...