[20190505]关于latch 一些统计信息.txt

来源：这里教程网时间：2026-03-03 13:36:37 作者：

[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 --//乱...