[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 <
$(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 <
$(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 <
$(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
0x00000000093f9dde
0x00000000093f9de4
0x00000000093f9deb
0x00000000093f9def
0x00000000093f9df2
0x00000000093f9df8
0x00000000093f9dfb
0x00000000093f9dfe
...
--//再次说明我不懂汇编,不过可以猜测:
--//%r13对应地址600098D8的内容赋值给%rdi,实际赋值等于session 1的pid(session 1持有该latch)。
--//也就是oradebug peek 0x600098D8 4 看到的内容。
--//如果不等(说明该latch已经释放),执行0x00000000093f9df2
--//跳转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
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
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
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
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
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
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
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
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
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
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 <
$(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
--//乱...