[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