本文共 9631 字，大约阅读时间需要 32 分钟。
[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 Production2.测试:
--你可以先执行一次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 BOSTONSCOTT@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.300WAIT #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 isolatedtc 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 =====================--可以发现现在延迟很小.
转载地址：http://otwzx.baihongyu.com/