[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
–//乱…