本案例来自西区某客户,数据库版本12.2。客户故障现象为连接local vip正常,但是连接scan vip就异常缓慢甚至超时。严重影响到了业务的连接。
1 2 3 4 5 6 7 8 9 10 11 12 |
oracle@vgapaascsdb02:/home/oracle> tnsping XXX.XXX.XXX.47:XXX/XXX TNS Ping Utility for Linux: Version 12.2.0.1.0 - Production on 25-APR-2022 20:16:34 Copyright (c) 1997, 2016, Oracle. All rights reserved. Used parameter files: /oracle/app/product/12.2/db/network/admin/sqlnet.ora Used HOSTNAME adapter to resolve the alias Attempting to contact (DESCRIPTION=(CONNECT_DATA=(SERVICE_NAME=XXX))(ADDRESS=(PROTOCOL=TCP)(HOST=XXX.XXX.XXX.47)(PORT=XXX))) OK (16460 msec) |
话不多说,遇到这种问题不管三七二十一先strace跟踪一把
1 2 3 4 5 6 |
20:41:20 connect(9, {sa_family=AF_INET, sin_port=htons(1521), sin_addr=inet_addr("135.10.115.47")}, 16) = -1 EINPROGRESS (Operation now in progress) <0.000054> 20:41:20 times(NULL) = 3429336038 <0.000026> 20:41:20 mmap(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fac5e101000 <0.000032> 20:41:20 poll([{fd=9, events=POLLOUT}], 1, 60000) = 0 (Timeout) <60.059497> 20:42:20 close(9) = 0 <0.000048> 20:42:20 getsockopt(9, SOL_SOCKET, SO_SNDBUF, 0x7ffd1afb5ca8, 0x7ffd1afb5d98) = -1 EBADF (Bad file descriptor) <0.000021> |
可以看到此次连接运气很差,达到了sqlnet.inbound_connect_timeout默认的60s,都无法获取到socket,所以连接超时。
再试一次,这次运气比较好,能连接上,但是获取socket仍然花了近15s。
1 2 3 4 5 |
37792 0.000053 connect(9, {sa_family=AF_INET, sin_port=htons(1521), sin_addr=inet_addr("135.10.115.47")}, 16) = -1 EINPROGRESS (Operation now in progress) 37792 0.000095 times(NULL) = 3429712467 37792 0.000052 mmap(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f880234f000 37792 0.000062 poll([{fd=9, events=POLLOUT}], 1, 60000) = 1 ([{fd=9, revents=POLLOUT}]) 37792 15.020915 getsockopt(9, SOL_SOCKET, SO_ERROR, [0], [4]) = 0 |
分析网络相关问题,还是老办法先看看网卡的TX errors 、dropped 、overruns,发现无明显异常后,通过watch结合netstat分析故障时刻的各项统计指标增长。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 |
Every 1.0s: netstat -s|grep -E "err|timeout|over|fail|drop|bad" Mon Apr 25 19:23:13 2022 10703 outgoing packets dropped 60 dropped because of missing route 26839 fragments dropped after timeout 61086 packet reassembles failed 10174 fragments failed 4520 input ICMP message failed. timeout in transit: 239194 0 ICMP messages failed 1880630 failed connection attempts 1140 bad segments received. 62 packet receive errors 744 packets pruned from receive queue because of socket buffer overrun 1951 ICMP packets dropped because they were out-of-window 35931 times the listen queue of a socket overflowed TCPRenoRecovery: 0 TCPSackRecovery: 10121 TCPLossProbeRecovery: 34157 TCPRenoRecoveryFail: 0 TCPSackRecoveryFail: 112 |
可以发现times the listen queue of a socket overflowed一直在增长,说明存在全连接队列溢出。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 |
[root@vgapaascsdb02 ~]#ss -lnt State Recv-Q Send-Q Local Address:Port Peer Address:Port LISTEN 0 128 *:50021 *:* LISTEN 0 128 169.254.253.148:15049 *:* LISTEN 0 128 *:50025 *:* LISTEN 0 128 *:56015 *:* LISTEN 0 128 *:47824 *:* LISTEN 129 128 135.10.115.47:1521 *:* LISTEN 0 128 135.10.115.42:1521 *:* LISTEN 0 128 135.10.115.35:1521 *:* LISTEN 0 128 127.0.0.1:6100 *:* LISTEN 0 128 *:22 *:* LISTEN 0 128 192.168.115.35:1526 *:* LISTEN 0 128 *:56025 *:* LISTEN 0 100 127.0.0.1:25 *:* LISTEN 0 128 *:50011 *:* LISTEN 0 128 169.254.253.148:61020 *:* LISTEN 0 128 169.254.253.148:61021 *:* LISTEN 0 128 *:50015 *:* LISTEN 0 128 127.0.0.1:2016 *:* LISTEN 0 128 169.254.253.148:10241 *:* LISTEN 0 128 *:7777 *:* LISTEN 0 128 127.0.0.1:7778 *:* LISTEN 0 128 :::8100 :::* LISTEN 0 50 :::8101 :::* LISTEN 0 5 ::ffff:135.10.115.35:5000 :::* LISTEN 0 128 :::11795 :::* LISTEN 0 128 ::1:6100 :::* LISTEN 0 128 :::22 :::* LISTEN 0 128 :::6200 :::* LISTEN 0 5 ::ffff:127.0.0.1:13593 :::* LISTEN 0 100 ::1:25 :::* LISTEN 0 128 ::1:2016 :::* LISTEN 0 50 :::3872 :::* |
通过ss命令查看scanip(xxx.xxx.xxx.47)对应的RECV-Q溢出了,在LISTEN状态下RECV-Q就代表全队列,可以看到此时全队列最大长度为128。当前长度为129,说明大量连接已经完成了TCP三次握手正在等待服务端accept() ,但由于连接风暴监听过于繁忙或者系统负载过高来不及处理。
此时看看监听日志是否存在连接风暴,发现几个小时的监听日志,连接并不多,并且tail发现当前的监听日志也并没有大量的连接进来,这就有点奇怪了。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 |
993 # SERVICE_NAME=xxxx # 10.196.184.83 634 # SERVICE_NAME=xxxx # 10.196.184.83 372 # # 10.196.184.83 41 # SERVICE_NAME=xxxx # 10.196.184.83 210 25-APR-2022 20:24--- 151 211 25-APR-2022 20:25--- 115 212 25-APR-2022 20:26--- 118 213 25-APR-2022 20:27--- 137 214 25-APR-2022 20:28--- 120 215 25-APR-2022 20:29--- 114 216 25-APR-2022 20:30--- 141 217 25-APR-2022 20:31--- 131 218 25-APR-2022 20:32--- 158 219 25-APR-2022 20:33--- 134 220 25-APR-2022 20:34--- 123 221 25-APR-2022 20:35--- 125 222 25-APR-2022 20:36--- 120 223 25-APR-2022 20:37--- 134 224 25-APR-2022 20:38--- 131 225 25-APR-2022 20:39--- 112 226 25-APR-2022 20:40--- 115 |
莫非有一些非数据库连接在一直连接scanip吗?比如频繁的telnet scanip。
尝试调整一些TCP参数包括增加全队列长度,仍然没有效果,发现全队列长度仍然为128,后续通过查看资料才发现全队列长度并不止取决于net.core.somaxconn,而是取决于 somaxconn 和 backlog 之间的最小值,也就是 min(somaxconn, backlog),backlog 是 listen(int sockfd, int backlog) 函数中的 backlog 大小。
1 2 3 4 5 6 |
net.ipv4.tcp_synack_retries = 1 net.ipv4.tcp_tw_reuse=1 net.ipv4.tcp_tw_recycle=1 net.ipv4.tcp_max_syn_backlog = 8192 net.core.somaxconn=8192 net.core.netdev_max_backlog = 8192 |
回顾监听的工作原理,也有可能是大量的连接全在全队列上直到被丢弃都无法通过等待到服务器accept(),这种情况的连接风暴监听日志是分析不出来的。
监听工作原理大致如下:
1) 首先客户端向监听进程发起数据库连接请求。这个过程又分为两个步骤:
a) 通过三次握手机制建立 TCP 连接。这一步一般来说比较快,只是在客户端操作系统与监听所在操作系统内核之间的交互过程,不涉及到监听进程。
b) 监听进程接受客户端的连接。在客户端发起数据库连接请求这一过程中,如果监听进程太忙,则在建立 TCP 连接之后,需要等待一段时间,监听进程才能真正地接受连接请求,监听进程接受连接将使用操作系统调用 accept。
2) 监听进程 fork 一个子进程,这里我们称为“监听子进程 1”,然后等待子进程退出。在这一步中,如果子进程退出之前所耗的时间越长,那么监听等待的时间也越长,在这个等待过程 中监听不能做任何其他动作。如果子进程异常,不能退出,监听进程将 Hang 住。在一个连接频繁的系统上,我们使用 ps –ef | grep tnslsnr 命令看到的父进程不为 1 的 tnslsnr 进程, 就是这样的子进程。
3) 监听子进程 1 fork 一个子进程,这里我们称为“子进程 2”。
4) 监听子进程 1 完成工作,立即结束。监听进程然后又会一直等待,这里是等待 Oracle Server Process 发送数据过来。
5) 子进程 2 执行系统调用 exec,调用的是 oracle 这个可执行文件,这样这个子进程 2 就变更 为 Oracle Server Process。也就是说,Server Process 与“子进程 2”具有相同的进程号。 Server Process 进行一些初始化操作。
6) Server Process 向监听进程传递一些特定的数据,包括进程号等,典型的数据是“N T P 0 1 9 1 9 0”,这里 19190 为进程号,每个字符用空格分开。
7) 监听进程向 Server Process 发送客户端的连接串数据,这个数据用于 Server Process 验证客户端。然后监听进程向 listener.log 写入日志。这个时候,监听进程的工作就完成了,继续处理下一个连接请求。监听进程能工作到这一步,表明监听并没有被挂起。
8) Server Process 向客户端发送数据,对客户端的连接进行响应。
9) 客户端与 Server Process 之间进行交互,完成连接过程,然后再提交SQL执行真正的工作等等。
直到第7步才会写入监听日志,此时很可能大量的进程都在TCP三次握手成功后,在全队列队列上或者由于全连接队列已满被废弃(由tcp_abort_on_overflow)控制。
通过netstat可以看到scanip上存在大量ESTABLISHED的连接,说明都已经完成了TCP三次握手在等待accept(),并且1s时间内增长了400多个,ip都为10.196.184.83
1 2 3 4 |
rootevgapaascsdb02 ~]netstat -an1pt|grep 47|wc -1 1797 rootovgapaascsdb02 ~]netstat -an1pt|grep 47|wc -1 2225 |
询问客户和业务厂商,没有人知道这个IP的出处,由于紧急需要恢复所以并没有通过tcpdump去继续深入分析,使用sqlnet黑名单禁用该ip的连接之后,业务连接恢复正常。