[20210115]sqlnet.ora設定sqlnet.expire_time斷開時oracle如何探測.txt

[20210115]sqlnet.ora設定sqlnet.expire_time斷開時oracle如何探測.txt

--//測試sqlnet.ora設定sqlnet.expire_time斷開時oracle如何探測的,這個測試我以前做過,連結找不到了,重新測試加強記憶.

1.環境:
SYS@192.168.31.8:1521/hrp430> @ ver1

PORT_STRING                    VERSION        BANNER
------------------------------ -------------- --------------------------------------------------------------------------------
x86_64/Linux 2.4.xx            11.2.0.3.0     Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production

--//今天上午發現設定sqlnet.expire_time=1也不行.正好測試看看.
$ grep sqlnet.expire_time $ORACLE_HOME/network/admin/sqlnet.ora
sqlnet.expire_time=1

2.測試:
--//服務端執行:
# seq 100000 | xargs -IQ bash -c "netstat -tonp | grep 192.168.100.78:|ts.awk;sleep 0.999999" | tee aa.txt
--//注:我sleep 0.999999可能避免一些命令執行時的誤差.看了以前測試我以前這裡使用tcpdump來跟蹤的.

--//客戶端執行:
$ rlsql sys/XXXX@192.168.31.8:1521/hrp430 as sysdba
SQL*Plus: Release 11.2.0.4.0 Production on Fri Jan 15 10:10:18 2021
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

--//注登入後不要再執行任何命令,另外最好使用NTP保證客戶端端與伺服器時間同步,這樣好診斷問題.
--//剩下就是等待問題出現.如果你想模擬有不想等2*sqlnet.expire_time時間,注我這裡設定很短,許多使用者無法模擬這個問題的.
--//可以拔掉客戶端網線或者使用iptables阻塞連線(小心不要設定錯誤!!),並且服務端最好在tmux或者screen下操作,這樣服務端的連線不會斷開.

3.中間檢視情況:
# seq 100000 | xargs -IQ bash -c "netstat -tonp | grep 192.168.100.78:|ts.awk;sleep 0.999999" | tee aa.txt
[2021-01-15 10:10:19] tcp        0      0 ::ffff:192.168.31.8:1521    ::ffff:192.168.100.78:7763  ESTABLISHED 27737/oraclehrp430  off (0.00/0/0)
[2021-01-15 10:10:20] tcp        0      0 ::ffff:192.168.31.8:1521    ::ffff:192.168.100.78:7763  ESTABLISHED 27737/oraclehrp430  off (0.00/0/0)
...
[2021-01-15 10:12:17] tcp        0      0 ::ffff:192.168.31.8:1521    ::ffff:192.168.100.78:7763  ESTABLISHED 27737/oraclehrp430  off (0.00/0/0)
[2021-01-15 10:12:18] tcp        0     10 ::ffff:192.168.31.8:1521    ::ffff:192.168.100.78:7763  ESTABLISHED 27737/oraclehrp430  on (0.12/0/0)
~~~~~~~~~~~~~~~~~~~~~
[2021-01-15 10:12:19] tcp        0     10 ::ffff:192.168.31.8:1521    ::ffff:192.168.100.78:7763  ESTABLISHED 27737/oraclehrp430  on (0.24/2/0)

--//注意看下劃線內容,登入10:10:18,10:12:18斷開正好2分鐘.
--//後面的狀態從off變成on.

4.分析:
--//出現on後大約等925秒(15分鐘),連線就會斷開.這個時候你可以出去聊天干別的事情.
# seq 100000 | xargs -IQ bash -c "netstat -tonp | grep 192.168.100.78:|ts.awk;sleep 0.999999" | tee aa.txt
[2021-01-15 10:27:45] tcp        0    160 ::ffff:192.168.31.8:1521    ::ffff:192.168.100.78:7763  ESTABLISHED 27737/oraclehrp430  on (5.03/15/0)
[2021-01-15 10:27:46] tcp        0    160 ::ffff:192.168.31.8:1521    ::ffff:192.168.100.78:7763  ESTABLISHED 27737/oraclehrp430  on (3.90/15/0)
[2021-01-15 10:27:47] tcp        0    160 ::ffff:192.168.31.8:1521    ::ffff:192.168.100.78:7763  ESTABLISHED 27737/oraclehrp430  on (2.77/15/0)
[2021-01-15 10:27:48] tcp        0    160 ::ffff:192.168.31.8:1521    ::ffff:192.168.100.78:7763  ESTABLISHED 27737/oraclehrp430  on (1.65/15/0)
[2021-01-15 10:27:49] tcp        0    160 ::ffff:192.168.31.8:1521    ::ffff:192.168.100.78:7763  ESTABLISHED 27737/oraclehrp430  on (0.52/15/0)

--//(27-12)*60+49-18 = 931 斷開.分析aa.txt檔案.

# awk '{print $10}' aa.txt  | grep off|wc
    105     105     420
--//105行,看來sleep 要設定0.99才行.正確佔120秒.

# grep off aa.txt  | head -1 ; grep off aa.txt | tail -1
[2021-01-15 10:10:19] tcp        0      0 ::ffff:192.168.31.8:1521    ::ffff:192.168.100.78:7763  ESTABLISHED 27737/oraclehrp430  off (0.00/0/0)
[2021-01-15 10:12:17] tcp        0      0 ::ffff:192.168.31.8:1521    ::ffff:192.168.100.78:7763  ESTABLISHED 27737/oraclehrp430  off (0.00/0/0)

# grep on aa.txt  | head -1 ; grep on aa.txt | tail -1
[2021-01-15 10:12:18] tcp        0     10 ::ffff:192.168.31.8:1521    ::ffff:192.168.100.78:7763  ESTABLISHED 27737/oraclehrp430  on (0.12/0/0)
[2021-01-15 10:27:49] tcp        0    160 ::ffff:192.168.31.8:1521    ::ffff:192.168.100.78:7763  ESTABLISHED 27737/oraclehrp430  on (0.52/15/0)
--//(27-12)*60+49-18 = 931 斷開.分析aa.txt檔案.

# awk '{print $10}' aa.txt  | grep on|wc
    822     822    2466

# awk '{if ($10=="on") print $11}' aa.txt  | cut -d'/' -f2| uniq -c
      1 0
      1 2
      1 3
      3 4
      6 5
     12 6
     23 7
     47 8
     93 9
    106 10
    105 11
    106 12
    106 13
    106 14
    106 15
-//實際上最後幾次探測120秒.

# awk '{if ($10=="on") print $11}' aa.txt  | cut -d'/' -f1,2 --output-delimiter=' ' | sed 's/^(//' >| aaa.txt

# grep on aa.txt | head -4
[2021-01-15 10:12:18] tcp        0     10 ::ffff:192.168.31.8:1521    ::ffff:192.168.100.78:7763  ESTABLISHED 27737/oraclehrp430  on (0.12/0/0)
[2021-01-15 10:12:19] tcp        0     10 ::ffff:192.168.31.8:1521    ::ffff:192.168.100.78:7763  ESTABLISHED 27737/oraclehrp430  on (0.24/2/0)
[2021-01-15 10:12:20] tcp        0     10 ::ffff:192.168.31.8:1521    ::ffff:192.168.100.78:7763  ESTABLISHED 27737/oraclehrp430  on (0.76/3/0)
[2021-01-15 10:12:21] tcp        0     10 ::ffff:192.168.31.8:1521    ::ffff:192.168.100.78:7763  ESTABLISHED 27737/oraclehrp430  on (2.94/4/0)
--//前面3次探測時間很短.不到1秒.前面從0-3的佔2秒時間,注意探測從0開始到15,也就是探測16次.

# seq 4 15 | xargs -IQ bash -c "grep ' Q' aaa.txt|head -1" | awk '{print $2 " " $1}'
4 2.94
5 6.16
6 12.59
7 25.45
8 52.26
9 104.95
10 119.15
11 118.86
12 119.80
13 119.71
14 119.44
15 119.38

# seq 4 15 | xargs -IQ bash -c "grep ' Q' aaa.txt|head -1" | awk '{print $2 " " int($1+1)}'
4 3
5 7
6 13
7 26
8 53
9 105
10 120
11 119  --> 下面計算選擇120
12 120
13 120
14 120
15 120
--//3+7+13+26+53+105+120+120+120+120+120+120+2 = 929秒
--//還是換成tcpdump跟蹤.重複測試:
# seq 100000 | xargs -IQ bash -c "netstat -tonp | grep 192.168.100.78:|ts.awk;sleep 0.99" | tee bb.txt
# tcpdump -i eth0 host 192.168.100.78 -nn -vv -w tcp.out

# tcpdump -r tcp.out
reading from file tcp.out, link-type EN10MB (Ethernet)
10:44:47.592896 IP 192.168.100.78.8592 > kkkkkzzz.ncube-lm: S 2215388911:2215388911(0) win 14600 <mss 1440,sackOK,timestamp 3524648198 0,nop,wscale 7>
10:44:47.592903 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: S 581299505:581299505(0) ack 2215388912 win 5792 <mss 1460,sackOK,timestamp 2839961348 3524648198,nop,wscale 7>
10:44:47.593258 IP 192.168.100.78.8592 > kkkkkzzz.ncube-lm: . ack 1 win 115 <nop,nop,timestamp 3524648199 2839961348>
10:44:47.593636 IP 192.168.100.78.8592 > kkkkkzzz.ncube-lm: P 1:214(213) ack 1 win 115 <nop,nop,timestamp 3524648199 2839961348>
10:44:47.593646 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: . ack 214 win 54 <nop,nop,timestamp 2839961349 3524648199>
10:44:47.613375 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: P 1:9(8) ack 214 win 54 <nop,nop,timestamp 2839961368 3524648199>
10:44:47.613863 IP 192.168.100.78.8592 > kkkkkzzz.ncube-lm: . ack 9 win 115 <nop,nop,timestamp 3524648220 2839961368>
10:44:47.613908 IP 192.168.100.78.8592 > kkkkkzzz.ncube-lm: P 214:427(213) ack 9 win 115 <nop,nop,timestamp 3524648220 2839961368>
10:44:47.613971 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: P 9:41(32) ack 427 win 62 <nop,nop,timestamp 2839961369 3524648220>
10:44:47.615235 IP 192.168.100.78.8592 > kkkkkzzz.ncube-lm: P 427:588(161) ack 41 win 115 <nop,nop,timestamp 3524648221 2839961369>
10:44:47.615382 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: P 41:168(127) ack 588 win 71 <nop,nop,timestamp 2839961370 3524648221>
10:44:47.616461 IP 192.168.100.78.8592 > kkkkkzzz.ncube-lm: P 588:626(38) ack 168 win 115 <nop,nop,timestamp 3524648222 2839961370>
10:44:47.616576 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: P 168:386(218) ack 626 win 71 <nop,nop,timestamp 2839961372 3524648222>
10:44:47.617609 IP 192.168.100.78.8592 > kkkkkzzz.ncube-lm: P 626:707(81) ack 386 win 123 <nop,nop,timestamp 3524648223 2839961372>
10:44:47.618946 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: P 386:412(26) ack 707 win 71 <nop,nop,timestamp 2839961374 3524648223>
10:44:47.620616 IP 192.168.100.78.8592 > kkkkkzzz.ncube-lm: P 707:951(244) ack 412 win 123 <nop,nop,timestamp 3524648226 2839961374>
10:44:47.623234 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: P 412:802(390) ack 951 win 79 <nop,nop,timestamp 2839961378 3524648226>
10:44:47.624811 IP 192.168.100.78.8592 > kkkkkzzz.ncube-lm: P 951:2337(1386) ack 802 win 131 <nop,nop,timestamp 3524648230 2839961378>
10:44:47.629411 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: P 802:1936(1134) ack 2337 win 101 <nop,nop,timestamp 2839961384 3524648230>
10:44:47.630500 IP 192.168.100.78.8592 > kkkkkzzz.ncube-lm: P 2337:2397(60) ack 1936 win 149 <nop,nop,timestamp 3524648236 2839961384>
10:44:47.630587 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: P 1936:2115(179) ack 2397 win 101 <nop,nop,timestamp 2839961386 3524648236>
10:44:47.631110 IP 192.168.100.78.8592 > kkkkkzzz.ncube-lm: P 2397:2410(13) ack 2115 win 167 <nop,nop,timestamp 3524648237 2839961386>
10:44:47.631195 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: P 2115:2132(17) ack 2410 win 101 <nop,nop,timestamp 2839961386 3524648237>
10:44:47.631588 IP 192.168.100.78.8592 > kkkkkzzz.ncube-lm: P 2410:2423(13) ack 2132 win 167 <nop,nop,timestamp 3524648237 2839961386>
10:44:47.631642 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: P 2132:2149(17) ack 2423 win 101 <nop,nop,timestamp 2839961387 3524648237>
10:44:47.671774 IP 192.168.100.78.8592 > kkkkkzzz.ncube-lm: . ack 2149 win 167 <nop,nop,timestamp 3524648278 2839961387>
10:46:47.626867 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: P 2149:2159(10) ack 2423 win 101 <nop,nop,timestamp 2840081382 3524648278>
--//10:44:47.671774 10:46:47.626867 間隔2分鐘
10:46:47.832843 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: P 2149:2159(10) ack 2423 win 101 <nop,nop,timestamp 2840081588 3524648278>
10:46:48.244848 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: P 2149:2159(10) ack 2423 win 101 <nop,nop,timestamp 2840082000 3524648278>
10:46:49.068849 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: P 2149:2159(10) ack 2423 win 101 <nop,nop,timestamp 2840082824 3524648278>
10:46:50.716874 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: P 2149:2159(10) ack 2423 win 101 <nop,nop,timestamp 2840084472 3524648278>
10:46:54.012923 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: P 2149:2159(10) ack 2423 win 101 <nop,nop,timestamp 2840087768 3524648278>
10:47:00.605007 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: P 2149:2159(10) ack 2423 win 101 <nop,nop,timestamp 2840094360 3524648278>
10:47:13.789169 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: P 2149:2159(10) ack 2423 win 101 <nop,nop,timestamp 2840107544 3524648278>
10:47:40.156509 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: P 2149:2159(10) ack 2423 win 101 <nop,nop,timestamp 2840133912 3524648278>
10:48:32.893179 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: P 2149:2159(10) ack 2423 win 101 <nop,nop,timestamp 2840186648 3524648278>
10:50:18.364513 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: P 2149:2159(10) ack 2423 win 101 <nop,nop,timestamp 2840292120 3524648278>
10:52:18.365036 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: P 2149:2159(10) ack 2423 win 101 <nop,nop,timestamp 2840412120 3524648278>
10:54:18.364560 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: P 2149:2159(10) ack 2423 win 101 <nop,nop,timestamp 2840532120 3524648278>
10:56:18.365089 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: P 2149:2159(10) ack 2423 win 101 <nop,nop,timestamp 2840652120 3524648278>
10:58:18.364609 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: P 2149:2159(10) ack 2423 win 101 <nop,nop,timestamp 2840772120 3524648278>
11:00:18.348079 IP kkkkkzzz.ncube-lm > 192.168.100.78.8592: P 2149:2159(10) ack 2423 win 101 <nop,nop,timestamp 2840892120 3524648278>
--//探測16次.

--//擷取前面時間,手工計算如下:
10:46:47.626867
10:46:47.832843   0.832843-0.626867   = .205976
10:46:48.244848   8.244848-7.832843   = .412005
10:46:49.068849   9.068849-8.244848   = .824001
10:46:50.716874   50.716874-49.068849 = 1.648025
10:46:54.012923   54.012923-50.716874 = 3.296049
10:47:00.605007   60.605007-54.012923 = 6.592084
10:47:13.789169   13.789169-00.605007 = 13.184162
10:47:40.156509   40.156509-13.789169 = 26.36734
10:48:32.893179   92.893179-40.156509 = 52.73667
10:50:18.364513   120+18.364513-32.893179 = 105.471334
10:52:18.365036   18.365036-18.364513+120 = 120.000523
10:54:18.364560   18.364560-18.365036+120 = 119.999524
10:56:18.365089   18.365089-18.364560+120 = 120.000529
10:58:18.364609   18.364609-18.365089+120 = 119.99952
11:00:18.348079   18.348079-18.364609+120 = 119.98347

--//在2021-01-15 11:02:17結束.
# tail -1 bb.txt
[2021-01-15 11:02:17] tcp        0    160 ::ffff:192.168.31.8:1521    ::ffff:192.168.100.78:8592  ESTABLISHED 3520/oraclehrp430   on (0.59/15/0)

--//我單獨擷取時間使用bash shell計算看看.

# cat aa1.txt
10:46:47.626867
10:46:47.832843
10:46:48.244848
10:46:49.068849
10:46:50.716874
10:46:54.012923
10:47:00.605007
10:47:13.789169
10:47:40.156509
10:48:32.893179
10:50:18.364513
10:52:18.365036
10:54:18.364560
10:56:18.365089
10:58:18.364609
11:00:18.348079

# cat aa1.txt | xargs -I{} date -d "2021/01/15 {}" "+%s.%N" | awk 'NR==1{a=$1} NR>1{print $1-a;a=$1}'
0.205976
0.412005
0.824001
1.64802
3.29605
6.59208
13.1842
26.3673
52.7367
105.471
120.001
120
120.001
120
119.983
-//開始間隔0.21秒,以後間隔2倍遞增.到105秒後,按照120秒間隔(探測6次).

# cat aa1.txt | xargs -I{} date -d "2021/01/15 {}" "+%s.%N" | awk 'NR==1{a=$1} NR>1{print $1-a;a=$1}' | paste -sd"+" | bc -l
810.722332
--//補上最後120秒,810.722332+120 = 930.722332.

5.總結:
--//我個人並主張採用sqlnet.ora設定sqlnet.expire_time方式,12c以上除外.因為12c設定sqlnet.expire_time,採用的是
--//TCP KEEPALIVE套接字選項來檢查連線是否仍然可用。

--//我以前就遇到dblink連線斷開,SQL*Net message from dblink 出現awr報表的情況.
--//連結 http://blog.itpub.net/267265/viewspace-2150510/ =>0124奇怪的SQL*Net message from dblink
--//我當時的理解確實存在許多錯誤.

--//找到以前測試的連結:
http://blog.itpub.net/267265/viewspace-2150431/ -> [20180123]測試SQLNET.EXPIRE_TIME引數.txt