[20161208]SQLNet message from client.txt
--SQL/Net message from client是空闲等待事件,一般很少关注,除非网络出现问题.
--通过1个简单的例子来说明问题.
1.环境:
SCOTT@book> @ &r/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
2.测试:
--你可以先执行一次select * from dept ;,避免不必要的递归语句.
SCOTT@book> @ &r/10046on 12
old 1: alter session set events '10046 trace name context forever, level &1'
new 1: alter session set events '10046 trace name context forever, level 12'
Session altered.
SCOTT@book> select * from dept ;
DEPTNO DNAME LOC
---------- -------------- -------------
10 ACCOUNTING NEW YORK
20 RESEARCH DALLAS
30 SALES CHICAGO
40 OPERATIONS BOSTON
SCOTT@book> @ &r/10046off
Session altered.
3.检查跟踪文件:
*** 2016-12-08 10:53:40.300
*** SESSION ID:(232.11) 2016-12-08 10:53:40.300
*** CLIENT ID:() 2016-12-08 10:53:40.300
*** SERVICE NAME:(SYS$USERS) 2016-12-08 10:53:40.300
*** MODULE NAME:(SQL*Plus) 2016-12-08 10:53:40.300
*** ACTION NAME:() 2016-12-08 10:53:40.300
WAIT #140489205831576: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1481165620299535
*** 2016-12-08 10:53:45.737
WAIT #140489205831576: nam='SQL*Net message from client' ela= 5437395 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1481165625737500
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
CLOSE #140489205831576:c=0,e=12,dep=0,type=1,tim=1481165625737878
=====================
PARSING IN CURSOR #140489205813824 len=19 dep=0 uid=83 oct=3 lid=83 tim=1481165625738035 hv=4071881952 ad='7cfceef0' sqlid='4g0qfgmtb7z70'
select * from dept
END OF STMT
PARSE #140489205813824:c=0,e=90,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3383998547,tim=1481165625738026
EXEC #140489205813824:c=0,e=113,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3383998547,tim=1481165625738248
WAIT #140489205813824: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1481165625738321
FETCH #140489205813824:c=0,e=94,p=0,cr=6,cu=0,mis=0,r=1,dep=0,og=1,plh=3383998547,tim=1481165625738453
WAIT #140489205813824: nam='SQL*Net message from client' ela= 341 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1481165625738864
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
WAIT #140489205813824: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1481165625738927
FETCH #140489205813824:c=0,e=44,p=0,cr=1,cu=0,mis=0,r=3,dep=0,og=1,plh=3383998547,tim=1481165625738957
STAT #140489205813824 id=1 cnt=4 pid=0 pos=1 obj=87106 op='TABLE ACCESS FULL DEPT (cr=7 pr=0 pw=0 time=82 us cost=3 size=72 card=4)'
*** 2016-12-08 10:53:53.138
WAIT #140489205813824: nam='SQL*Net message from client' ela= 7399359 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1481165633138495
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
CLOSE #140489205813824:c=0,e=12,dep=0,type=0,tim=1481165633138608
=====================
PARSING IN CURSOR #140489205813824 len=55 dep=0 uid=83 oct=42 lid=83 tim=1481165633138697 hv=2217940283 ad='0' sqlid='06nvwn223659v'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #140489205813824:c=0,e=28,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1481165633138696
EXEC #140489205813824:c=1000,e=421,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1481165633139204
-- 注意看~线的那些行,注意观察ela表示elapsed time ,
ela= 5437395
ela= 341
ela= 7399359
--注:这个时间单位是1/1000000秒.你可以发现前后2个都很大(一个5秒,7秒),实际上第1个,第3个出现等待事件'SQL*Net message from client'.
--而仅仅第2个才是我们在优化时关注的情况,而第1次,第3次实际上我打入命令后,等待打入下一个命令命令的等待时间,完全是idle等待事件.
3.做一个流量限制看看:
#! /bin/bash
DEV=eth0
tc qdisc del dev $DEV root
tc qdisc add dev $DEV root handle 1: cbq avpkt 1000 bandwidth 10000mbit
tc class add dev $DEV parent 1: classid 1:1 cbq rate 10000mbit allot 1500 prio 1 bounded isolated
tc class add dev $DEV parent 1: classid 1:12 cbq rate 8kbit allot 1500 prio 8 bounded isolated
tc filter add dev $DEV parent 1: protocol ip prio 16 u32 match ip dst 192.168.100.40/32 flowid 1:12
tc filter add dev $DEV parent 1: protocol ip prio 16 u32 match ip dst 192.168.0.0/16 flowid 1:1
--主要我限制了client ip=192.168.100.40 很小的流量 仅仅8Kbit.其他都是正常流量.
--在192.168.100.40上执行:
# ping 192.168.100.78 -s 2048
PING 192.168.100.78 (192.168.100.78) 2048(2076) bytes of data.
2056 bytes from 192.168.100.78: icmp_seq=5 ttl=64 time=0.243 ms
2056 bytes from 192.168.100.78: icmp_seq=6 ttl=64 time=0.238 ms
...
...
2056 bytes from 192.168.100.78: icmp_seq=122 ttl=64 time=1217 ms
2056 bytes from 192.168.100.78: icmp_seq=123 ttl=64 time=1276 ms
2056 bytes from 192.168.100.78: icmp_seq=124 ttl=64 time=1335 ms
2056 bytes from 192.168.100.78: icmp_seq=125 ttl=64 time=1393 ms
2056 bytes from 192.168.100.78: icmp_seq=127 ttl=64 time=1512 ms
--你可以发现后面几个很大延迟.接近1秒多.不要关闭ping(好像很慢,可以改-s 1024),在192.168.100.40打开会话,执行如下:
alter session set events '10046 trace name context forever, level 12';
select * from dept;
alter session set events '10046 trace name context off';
WAIT #140024398631792: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1481168388187721
*** 2016-12-08 11:39:49.807
WAIT #140024398631792: nam='SQL*Net message from client' ela= 1619601 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1481168389807882
CLOSE #140024398631792:c=1000,e=8,dep=0,type=1,tim=1481168389807977
=====================
PARSING IN CURSOR #140024398614040 len=18 dep=0 uid=83 oct=3 lid=83 tim=1481168389808123 hv=3599690174 ad='7e5268a0' sqlid='3154rqzb8xudy'
select * from dept
END OF STMT
PARSE #140024398614040:c=0,e=94,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3383998547,tim=1481168389808118
EXEC #140024398614040:c=0,e=54,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3383998547,tim=1481168389808324
WAIT #140024398614040: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1481168389808398
FETCH #140024398614040:c=0,e=96,p=0,cr=6,cu=0,mis=0,r=1,dep=0,og=1,plh=3383998547,tim=1481168389808535
*** 2016-12-08 11:39:51.935
WAIT #140024398614040: nam='SQL*Net message from client' ela= 2127131 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1481168391935719
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
WAIT #140024398614040: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1481168391935829
FETCH #140024398614040:c=0,e=60,p=0,cr=1,cu=0,mis=0,r=3,dep=0,og=1,plh=3383998547,tim=1481168391935866
STAT #140024398614040 id=1 cnt=4 pid=0 pos=1 obj=87106 op='TABLE ACCESS FULL DEPT (cr=7 pr=0 pw=0 time=85 us cost=3 size=72 card=4)'
*** 2016-12-08 11:39:54.648
WAIT #140024398614040: nam='SQL*Net message from client' ela= 2712190 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1481168394648240
CLOSE #140024398614040:c=0,e=14,dep=0,type=1,tim=1481168394648351
=====================
PARSING IN CURSOR #140024398613096 len=55 dep=0 uid=83 oct=42 lid=83 tim=1481168394648436 hv=2217940283 ad='0' sqlid='06nvwn223659v'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #140024398613096:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1481168394648435
EXEC #140024398613096:c=0,e=430,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1481168394648949
--你可以第2次延迟很大,达到2秒,这个延迟就属于网络问题,总之记住idle 事件也可能是考虑优化的重点.
收尾工作:
--在192.168.100.78上执行:
# tc qdisc del dev eth0 root
--检查ping情况:
1032 bytes from 192.168.100.78: icmp_seq=525 ttl=64 time=34904 ms
1032 bytes from 192.168.100.78: icmp_seq=526 ttl=64 time=34967 ms
1032 bytes from 192.168.100.78: icmp_seq=562 ttl=64 time=0.219 ms
1032 bytes from 192.168.100.78: icmp_seq=563 ttl=64 time=0.258 ms
1032 bytes from 192.168.100.78: icmp_seq=564 ttl=64 time=0.278 ms
1032 bytes from 192.168.100.78: icmp_seq=565 ttl=64 time=0.198 ms
1032 bytes from 192.168.100.78: icmp_seq=566 ttl=64 time=0.237 ms
--可以发现现在网络恢复正常.有重复做一次:
=====================
PARSING IN CURSOR #140040940293656 len=18 dep=0 uid=83 oct=3 lid=83 tim=1481168993725223 hv=3599690174 ad='7e5268a0' sqlid='3154rqzb8xudy'
select * from dept
END OF STMT
PARSE #140040940293656:c=1000,e=96,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3383998547,tim=1481168993725218
EXEC #140040940293656:c=0,e=49,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3383998547,tim=1481168993725371
WAIT #140040940293656: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1481168993725433
FETCH #140040940293656:c=0,e=85,p=0,cr=6,cu=0,mis=0,r=1,dep=0,og=1,plh=3383998547,tim=1481168993725554
WAIT #140040940293656: nam='SQL*Net message from client' ela= 444 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1481168993726050
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
WAIT #140040940293656: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1481168993726109
FETCH #140040940293656:c=0,e=44,p=0,cr=1,cu=0,mis=0,r=3,dep=0,og=1,plh=3383998547,tim=1481168993726140
STAT #140040940293656 id=1 cnt=4 pid=0 pos=1 obj=87106 op='TABLE ACCESS FULL DEPT (cr=7 pr=0 pw=0 time=75 us cost=3 size=72 card=4)'
WAIT #140040940293656: nam='SQL*Net message from client' ela= 3299 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1481168993729621
CLOSE #140040940293656:c=0,e=15,dep=0,type=1,tim=1481168993729706
=====================
--可以发现现在延迟很小.
