dubbo服务出现大量超时问题

最新推荐文章于 2023-03-04 17:48:42 发布

太阳伞下的阿呆

最新推荐文章于 2023-03-04 17:48:42 发布

阅读量2.3k

点赞数 1

分类专栏： java Linux 文章标签： dubbo docker tcp rpc 超时

本文链接：https://blog.csdn.net/u010597819/article/details/108819166

版权

java 同时被 2 个专栏收录

140 篇文章 2 订阅

订阅专栏

Linux

9 篇文章 0 订阅

订阅专栏

背景：最近服务由服务器切换为容器，原服务：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+的并发连接：https://www.linkedin.com/pulse/ec2-tuning-1m-tcp-connections-using-linux-stephen-blum
思考下一个链接是有方向的，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源码中可以找到答案：https://gitlab.com/cip-project/cip-kernel/linux-cip/-/blob/103f6112f253017d7062cd74d17f4a514ed4485c/net/ipv4/tcp_diag.c

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-的一些问题：http://jaseywang.me/2014/07/20/tcp-queue-%E7%9A%84%E4%B8%80%E4%BA%9B%E9%97%AE%E9%A2%98/

当 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这块的课还是需要补一哈-_-!!!

太阳伞下的阿呆

关注

1
点赞
踩
1

收藏

觉得还不错? 一键收藏
0
评论
dubbo服务出现大量超时问题

背景：最近服务由服务器切换为容器，原服务：5台服务器+1个docker容器，近期由于业务原因开始降本，物理机全部下掉换为容器，并且砍掉了两台服务，现服务：4个docker容器。最近线上dubbo服务出现大量超时。找运维大佬帮忙定位问题是backlog参数过小的原因。超时时执行命令查看下socket状态// 查看所有tcp监听端口的队列使用情况ss -ant | grep 15335 | wc -ldocker容器所在服务器资源问题？文件句柄查看进程打开文件限制配置：100多万查看：ulimi
复制链接

扫一扫