本文已参与「新人创作礼」活动,一起开启掘金创作之路。
背景:最近服务由服务器切换为容器,原服务:5台服务器+1个docker容器,近期由于业务原因开始降本,物理机全部下掉换为容器,并且砍掉了两台服务,现服务:4个docker容器。最近线上dubbo服务出现大量超时。找运维大佬帮忙定位问题是backlog参数过小的原因。超时时执行命令查看下socket状态
// 查看所有tcp监听端口的队列使用情况
ss -ant | grep 15335 | wc -l
docker容器所在服务器资源问题?
文件句柄
查看进程打开文件限制配置:100多万
查看:ulimit -a
修改配置:vim /etc/security/limits.conf
// 输出如下
core file size (blocks, -c) unlimited
data seg size (kbytes, -d) unlimited
scheduling priority (-e) 0
file size (blocks, -f) unlimited
pending signals (-i) 256980
max locked memory (kbytes, -l) 64
max memory size (kbytes, -m) unlimited
open files (-n) 1048576
pipe size (512 bytes, -p) 8
POSIX message queues (bytes, -q) 819200
real-time priority (-r) 0
stack size (kbytes, -s) 8192
cpu time (seconds, -t) unlimited
max user processes (-u) unlimited
virtual memory (kbytes, -v) unlimited
file locks (-x) unlimited
当前系统文件句柄使用情况:很充足。 注:上面是100多万为什么这边最大值是200多万?因为上面的限制时单个进程的限制,下面的限制时系统全局的限制
查看:cat /proc/sys/fs/file-nr
修改配置:vim /etc/sysctl.conf
// 输出如下
列序号 列含义
1 已经分配的文件句柄数
2 已经分配但没有使用的文件句柄数
3 最大文件句柄数
10208 0 2097152
端口号
查看Linux系统端口范围:很充足
sysctl -a | grep ipv4.ip_local_port_range
// 输出如下
net.ipv4.ip_local_port_range = 32768 60999
一个链接:serverIp:serverPort - clientIp:clientPort。不考虑地址重用,ip分类等因素,对于ipv4,一个服务器理论上可以支持的最大tcp连接数为2的32次方(ip数)×2的16次方(port数),即server端单机最大tcp连接数为2的48次方。当然这仅是理论值。 亚马逊云产品可以支持100W+的并发连接:www.linkedin.com/pulse/ec2-t… 思考下一个链接是有方向的,A->B,B->A。我们看下超时服务的所有连接情况
ss -anp | grep 15335
// 输出如下
tcp LISTEN 0 50 *:15335 *:*
tcp ESTAB 0 0 serverIp:15335 client0:52492
tcp ESTAB 0 0 serverIp:15335 client1:14495
tcp ESTAB 0 0 serverIp:15335 client2:47936
tcp ESTAB 0 0 serverIp:15335 client3:59848
tcp ESTAB 0 0 serverIp:15335 client4:40002
tcp ESTAB 0 0 serverIp:15335 client5:46200
tcp ESTAB 0 0 serverIp:15335 client6:47712
tcp ESTAB 0 0 serverIp:15335 client7:56630
tcp ESTAB 0 0 serverIp:15335 client8:48478
tcp ESTAB 0 0 serverIp:15335 client9:55362
tcp ESTAB 0 0 serverIp:15335 clienta:46722
tcp ESTAB 0 0 serverIp:15335 clientb:38726
tcp ESTAB 0 0 serverIp:15335 clientc:45470
tcp ESTAB 0 0 serverIp:15335 clientd:54818
tcp ESTAB 0 0 serverIp:15335 cliente:42906
tcp ESTAB 0 0 serverIp:15335 clientf:51436
tcp ESTAB 0 0 serverIp:15335 clientg:52156
tcp ESTAB 0 0 serverIp:15335 clienth:36480
tcp ESTAB 0 0 serverIp:15335 clienti:29891
tcp ESTAB 0 0 serverIp:15335 clientj:53696
tcp ESTAB 0 0 serverIp:15335 clientk:54160
tcp ESTAB 0 0 serverIp:15335 clientl:34772
tcp ESTAB 0 0 serverIp:15335 clientm:35318
tcp ESTAB 0 0 serverIp:15335 clientn:54448
tcp ESTAB 0 0 serverIp:15335 cliento:48476
tcp ESTAB 0 0 serverIp:15335 clientp:48876
tcp ESTAB 0 0 serverIp:15335 clientq:60420
tcp ESTAB 0 0 serverIp:15335 clientr:46984
tcp ESTAB 0 0 serverIp:15335 clients:48586
tcp ESTAB 0 0 serverIp:15335 clientt:38110
服务端是接收连接方,连入,不受端口限制,仅受物理资源的限制 客户端是连接方,连出,每连接一个服务都要为连接生成一个随机的端口号,受端口限制 总结:连入,受物理资源限制;连出,受端口+物理资源限制。
内存
free命令查看内存资源:很充足,往大了计算,不考虑内核、标准输入、输出、错误、进程数据等等资源占用,当前使用内存月4.4G,ss连接总数194,平均一个连接占用200多M,现在剩余6G,理论上还可以再加连接数
free -m
// 输出如下
total used free shared buff/cache available
Mem: 64263 43716 6071 150 14476 19293
Swap: 0 0 0
IO
很遗憾没有iostat命令授权,并且io文件也没有权限
iostat -d -x -k 1 10
cat /proc/pid/io
但是换个思路,看下我们服务的磁盘日志输出情况发现超时期间确实日质量很大,高峰期是低峰期的13倍,高峰期1.3G,低峰期100M。那么也只能从此继续排查了 日志按照小时分片,拎出来高峰期的日志统计下是谁打印了辣么多的日志,排查qps大约50左右,不高,排在第一位的线程日志大小50M,并且历史日志也在这个量级,并且发现日质量减少的情况下依然有告警,故排除
awk '{print $4}' my-service.log-2020-09-21-09 | sort | uniq -c | sort -k1,1rn> ~/tmp.log
// 输出如下
79180 [DubboServerHandler-serverIp:15335-thread-399]
76192 [DubboServerHandler-serverIp:15335-thread-393]
72519 [DubboServerHandler-serverIp:15335-thread-385]
69359 [DubboServerHandler-serverIp:15335-thread-397]
68852 [DubboServerHandler-serverIp:15335-thread-386]
62936 [DubboServerHandler-serverIp:15335-thread-382]
61426 [DubboServerHandler-serverIp:15335-thread-391]
57587 [DubboServerHandler-serverIp:15335-thread-400]
57091 [DubboServerHandler-serverIp:15335-thread-398]
56088
54424 [DubboServerHandler-serverIp:15335-thread-388]
52591 [DubboServerHandler-serverIp:15335-thread-390]
52023 [DubboServerHandler-serverIp:15335-thread-387]
49322 [DubboServerHandler-serverIp:15335-thread-395]
37332 [DubboServerHandler-serverIp:15335-thread-384]
36065 [scan-order-service_ConsumeMessageThread_13]
36056 [scan-order-service_ConsumeMessageThread_5]
36050 [scan-order-service_ConsumeMessageThread_14]
36050 [scan-order-service_ConsumeMessageThread_20]
36043 [scan-order-service_ConsumeMessageThread_17]
36040 [scan-order-service_ConsumeMessageThread_8]
36035 [scan-order-service_ConsumeMessageThread_15]
36034 [scan-order-service_ConsumeMessageThread_2]
36031 [scan-order-service_ConsumeMessageThread_3]
36021 [scan-order-service_ConsumeMessageThread_18]
36019 [scan-order-service_ConsumeMessageThread_19]
36013 [scan-order-service_ConsumeMessageThread_1]
36013 [scan-order-service_ConsumeMessageThread_6]
36013 [scan-order-service_ConsumeMessageThread_7]
36006 [scan-order-service_ConsumeMessageThread_16]
36005 [scan-order-service_ConsumeMessageThread_11]
35992 [scan-order-service_ConsumeMessageThread_9]
35984 [scan-order-service_ConsumeMessageThread_10]
35959 [scan-order-service_ConsumeMessageThread_12]
35955 [scan-order-service_ConsumeMessageThread_4]
34868 [MQClientFactoryScheduledThread]
26501 [DubboServerHandler-serverIp:15335-thread-389]
24840 [reload-task-]
16763 [DubboServerHandler-serverIp:15335-thread-383]
9293 [DubboServerHandler-serverIp:15335-thread-392]
2091 [dispatcher-build-18]
2084 [dispatcher-build-41]
2081 [dispatcher-build-49]
2078 [dispatcher-build-46]
2075 [dispatcher-build-43]
2074 [dispatcher-build-16]
2072 [dispatcher-build-4]
2071 [dispatcher-build-21]
2070 [dispatcher-build-36]
2070 [dispatcher-build-42]
2069 [dispatcher-build-10]
2068 [dispatcher-build-6]
2067 [dispatcher-build-23]
2064 [dispatcher-build-7]
2063 [dispatcher-build-31]
2062 [dispatcher-build-33]
2061 [dispatcher-build-44]
2059 [dispatcher-build-26]
2059 [dispatcher-build-34]
2059 [dispatcher-build-45]
2058 [dispatcher-build-28]
2057 [dispatcher-build-27]
2057 [dispatcher-build-29]
2056 [dispatcher-build-14]
2056 [dispatcher-build-22]
2056 [dispatcher-build-25]
2056 [dispatcher-build-30]
2054 [dispatcher-build-9]
2053 [dispatcher-build-32]
2052 [dispatcher-build-35]
2051 [dispatcher-build-8]
2050 [dispatcher-build-37]
2050 [dispatcher-build-47]
2049 [dispatcher-build-11]
2049 [dispatcher-build-15]
2048 [dispatcher-build-0]
2044 [dispatcher-build-19]
2044 [dispatcher-build-5]
2043 [dispatcher-build-20]
2042 [dispatcher-build-17]
2042 [dispatcher-build-3]
2041 [dispatcher-build-12]
2041 [dispatcher-build-2]
2040 [dispatcher-build-38]
2038 [dispatcher-build-40]
2037 [dispatcher-build-13]
2037 [dispatcher-build-39]
2034 [dispatcher-build-24]
2031 [dispatcher-build-48]
2021 [dispatcher-build-1]
...
网络IO虽然没有权限,但是每天都有大量超时,并且调用是走的RPC,而且同一个物理机上面多个docker容器只有一个服务存在该问题,暂时也可以排除网络瓶颈
Recv-Q与Send-Q含义
tcp_diag.c源码中可以找到答案:gitlab.com/cip-project…
- TCP连接处于LISTEN状态:Recv-Q代表已经经历一次握手并相应ack队列的值;Send-Q代表已经经历一次握手并响应ack的backlog队列的最大值。
- TCP连接其他状态:Recv-Q代表socket接收队列中的字节数;Send-Q代表socket写出队列的字节数
if (sk_state_load(sk) == TCP_LISTEN) {
r->idiag_rqueue = sk->sk_ack_backlog;
r->idiag_wqueue = sk->sk_max_ack_backlog;
} else if (sk->sk_type == SOCK_STREAM) {
const struct tcp_sock *tp = tcp_sk(sk);
r->idiag_rqueue = max_t(int, tp->rcv_nxt - tp->copied_seq, 0);
r->idiag_wqueue = tp->write_seq - tp->snd_una;
}
截图中ss命令输出的监听状态的连接并不是当前队列值,仅仅是说明当前的配置值。因为我们线上监控在不告警的期间我去服务器执行了一下命令依然如上图所示,对于本次问题的排查并没有太大的帮助
tcp-queue-的一些问题:jaseywang.me/2014/07/20/…
- 当 client 通过 connect 向 server 发出 SYN 包时,client 会维护一个 socket 等待队列,而 server 会维护一个 SYN 队列
- 此时进入半链接的状态,如果 socket 等待队列满了,server 则会丢弃,而 client 也会由此返回 connection time out;只要是 client 没有收到 SYN+ACK,3s 之后,client 会再次发送,如果依然没有收到,9s 之后会继续发送
- 半连接 syn 队列的长度为 max(64, /proc/sys/net/ipv4/tcp_max_syn_backlog) 决定
- 当 server 收到 client 的 SYN 包后,会返回 SYN, ACK 的包加以确认,client 的 TCP 协议栈会唤醒 socket 等待队列,发出 connect 调用
- client 返回 ACK 的包后,server 会进入一个新的叫 accept 的队列,该队列的长度为 min(backlog, somaxconn),默认情况下,somaxconn 的值为 128,表示最多有 129 的 ESTAB 的连接等待 accept(),而 backlog 的值则由 int listen(int sockfd, int backlog) 中的第二个参数指定,listen 里面的 backlog 的含义请看这里。需要注意的是,一些 Linux 的发型版本可能存在对 somaxcon 错误 truncating 方式。
- 当 accept 队列满了之后,即使 client 继续向 server 发送 ACK 的包,也会不被相应,此时,server 通过 /proc/sys/net/ipv4/tcp_abort_on_overflow 来决定如何返回,0 表示直接丢丢弃该 ACK,1 表示发送 RST 通知 client;相应的,client 则会分别返回 read timeout 或者 connection reset by peer。上面说的只是些理论,如果服务器不及时的调用 accept(),当 queue 满了之后,服务器并不会按照理论所述,不再对 SYN 进行应答,返回 ETIMEDOUT。根据这篇文档的描述,实际情况并非如此,服务器会随机的忽略收到的 SYN,建立起来的连接数可以无限的增加,只不过客户端会遇到延时以及超时的情况。
抓包文件分析
运维大佬提供了抓包文件,找阿里云分析反馈无异常:协调网络同学详细分析了下报文文件,没有发现交互异常,建议用长连接 以及http2
// 截取网络接口eth0,端口6666的tcp数据包。数据文件保存为 mydump.pcap
// 同时截取udp端口号7777和8888
tcpdump -w mydump.pcap -i eth0 tcp port 6666 or udp \( 7777 or 8888 \)
GC
分析gc日志,均在20ms左右,没有异常,故排除
// gc,所有线程总花费时间=user+sys
// 并发参数配置:-XX:+UseParNewGC -XX:ParallelGCThreads=5
real:指的是在此次GC事件中所花费的总时间;注:单线程gc花费时间,多线程则*线程数
user:指的是CPU工作在用户态所花费的时间;
sys:指的是CPU工作在内核态所花费的时间。
: 1712928K->25421K(1887488K), 0.0178382 secs] 2436307K->748816K(3984640K), 0.0183137 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
总结
总结呢很无奈,结论还没有出来,木得总结呀,后续有结论再来更新吧。 最后解决方案有点出乎意料,docker容器配置增加cpu资源后超时问题便解决了。。。后续对于docker这块的课还是需要补一哈-_-!!!