[20161208]SQL*Net message from client

[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
=====================

--可以發現現在延遲很小.