云原生知识星球
0%

K8S问题排查-业务高并发导致Pod反复重启

发表于 更新于 分类于 阅读时长 ≈ 5 分钟

问题背景

K8S集群环境中，有个业务在做大量配置的下发（持续几小时甚至更长时间），期间发现calico的Pod反复重启。

1
2
3
4
5
[root@node02 ~]# kubectl get pod -n kube-system -owide|grep node01
calico-kube-controllers-6f59b8cdd8-8v2qw   1/1     Running            0          4h45m   10.10.119.238    node01   <none>           <none>
calico-node-b8w2b                          1/1     CrashLoopBackOff   43         3d19h   10.10.119.238    node01   <none>           <none>
coredns-795cc9c45c-k7qpb                   1/1     Running            0          4h45m   177.177.237.42    node01   <none>           <none>
...

分析过程

看到Pod出现CrashLoopBackOff状态，就想到大概率是Pod内服务自身的原因，先使用kubectl describe命令查看一下：

1
2
3
4
5
6
7
8
9
[root@node02 ~]# kubectl descroiebe pod -n kube-system calico-node-b8w2b
...
Events:
  Type     Reason     Age                      From               Message
  ----     ------     ----                     ----               -------
  Warning  Unhealthy  58m (x111 over 3h12m)    kubelet, node01  (combined from similar events): Liveness probe failed: Get http://localhost:9099/liveness: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
  Normal   Pulled     43m (x36 over 3d19h)     kubelet, node01  Container image "calico/node:v3.15.1" already present on machine
  Warning  Unhealthy  8m16s (x499 over 3h43m)  kubelet, node01  Liveness probe failed: Get http://localhost:9099/liveness: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
  Warning  BackOff    3m31s (x437 over 3h3m)   kubelet, node01  Back-off restarting failed container

从Event日志可以看出，是calico的健康检查没通过导致的重启，出错原因也比较明显：net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)，这个错误的含义是建立连接超时[1]，并且手动在控制台执行健康检查命令，发现确实响应慢（正常环境是毫秒级别）：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
[root@node01 ~]# time curl -i http://localhost:9099/liveness
HTTP/1.1 204 No Content
Date: Tue, 15 Jun 2021 06:24:35 GMT
real0m1.012s
user0m0.003s
sys0m0.005s
[root@node01 ~]# time curl -i http://localhost:9099/liveness
HTTP/1.1 204 No Content
Date: Tue, 15 Jun 2021 06:24:39 GMT
real0m3.014s
user0m0.002s
sys0m0.005s
[root@node01 ~]# time curl -i http://localhost:9099/liveness
real1m52.510s
user0m0.002s
sys0m0.013s
[root@node01 ~]# time curl -i http://localhost:9099/liveness
^C

先从calico相关日志查起，依次查看了calico的bird、confd和felix日志，没有发现明显错误，再看端口是否处于正常监听状态：

1
2
3
4
[root@node02 ~]# netstat -anp|grep 9099
tcp        0      0 127.0.0.1:9099          0.0.0.0:*               LISTEN      1202/calico-node    
tcp        0      0 127.0.0.1:9099          127.0.0.1:56728         TIME_WAIT   -                   
tcp        0      0 127.0.0.1:56546         127.0.0.1:9099          TIME_WAIT   -

考虑到错误原因是建立连接超时，并且业务量比较大，先观察一下TCP连接的状态情况：

1
2
3
4
5
[root@node01 ~]# netstat -na | awk '/^tcp/{s[$6]++}END{for(key in s) print key,s[key]}'
LISTEN 49
ESTABLISHED 284
SYN_SENT 4
TIME_WAIT 176

连接状态没有什么大的异常，再使用top命令看看CPU负载，好家伙，业务的java进程的CPU跑到了700%，持续观察一段时间发现最高飙到了2000%+，跟业务开发人员沟通，说是在做压力测试，并且线上有可能也存在这么大的并发量。好吧，那就继续看看这个状态下，CPU是不是出于高负载；

1
2
3
4
5
6
7
8
9
10
11
[root@node01 ~]# top
top - 14:28:57 up 13 days, 27 min,  2 users,  load average: 9.55, 9.93, 9.91
Tasks: 1149 total,   1 running, 1146 sleeping,   0 stopped,   2 zombie
%Cpu(s): 16.0 us,  2.9 sy,  0.0 ni, 80.9 id,  0.0 wa,  0.0 hi,  0.1 si,  0.0 st
KiB Mem : 15249982+total, 21419184 free, 55542588 used, 75538048 buff/cache
KiB Swap:        0 total,        0 free,        0 used. 94226176 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                                                        
 6754 root      20   0   66.8g  25.1g 290100 S 700.0 17.3   2971:49 java                                                                                           
25214 root      20   0 6309076 179992  37016 S  36.8  0.1 439:06.29 kubelet                                                                                        
20331 root      20   0 3196660 172364  24908 S  21.1  0.1 349:56.64 dockerd

查看CPU总核数，再结合上面统计出的load average和cpu的使用率，貌似负载也没有高到离谱；

1
2
3
4
[root@node01 ~]# cat /proc/cpuinfo| grep "physical id"| sort| uniq| wc -l
48
[root@node01 ~]# cat /proc/cpuinfo| grep "cpu cores"| uniq
cpu cores: 1

这就奇怪了，凭感觉，问题大概率是高并发导致的，既然这里看不出什么，那就再回到建立连接超时这个现象上面来。说到连接超时，就会想到TCP建立连接的几个阶段（参考下图），那超时发生在哪个阶段呢？

tcp-state-transmission

Google相关资料[2]，引用一下：

在TCP三次握手创建一个连接时，以下两种情况会发生超时：

  1. client发送SYN后，进入SYN_SENT状态，等待server的SYN+ACK。
  2. server收到连接创建的SYN，回应SYN+ACK后，进入SYN_RECD状态，等待client的ACK。

那么，我们的问题发生在哪个阶段？从下面的验证可以看出，问题卡在了SYN_SENT阶段，并且不止calico的健康检查会卡住，其他如kubelet、kube-controller等组件也会卡住：

1
2
3
4
5
6
7
8
9
10
11
12
[root@node01 ~]# curl http://localhost:9099/liveness
^C
[root@node01 ~]# netstat -anp|grep 9099
tcp        0      0 127.0.0.1:44360         127.0.0.1:9099          TIME_WAIT   -                   
tcp        0      1 127.0.0.1:47496         127.0.0.1:9099          SYN_SENT    16242/curl

[root@node01 ~]# netstat -anp|grep SYN_SENT
tcp        0      1 127.0.0.1:47496         127.0.0.1:9099          SYN_SENT    16242/curl
tcp        0      1 127.0.0.1:39142         127.0.0.1:37807         SYN_SENT    25214/kubelet       
tcp        0      1 127.0.0.1:38808         127.0.0.1:10251         SYN_SENT    25214/kubelet       
tcp        0      1 127.0.0.1:53726         127.0.0.1:10252         SYN_SENT    25214/kubelet
...

到目前为止，我们可以得出2个结论：

  1. calico健康检查不通过的原因是TCP请求在SYN_SENT阶段卡住了；
  2. 该问题不是特定Pod的问题，应该是系统层面导致的通用问题；

综合上面2个结论，那就怀疑TCP相关内核参数是不是合适呢？特别是与SYN_SENT状态有关的参数[3]；

1
2
net.ipv4.tcp_max_syn_backlog 默认为1024，表示SYN队列的长度
net.core.somaxconn 默认值是128，用于调节系统同时发起的tcp连接数，在高并发的请求中，默认值可能会导致链接超时或者重传，因此需要结合并发请求数来调节此值

查看系统上的配置，基本都是默认值，那就调整一下上面两个参数的值并设置生效：

1
2
3
4
5
6
7
8
9
[root@node01 ~]# cat /etc/sysctl.conf 
...
net.ipv4.tcp_max_syn_backlog = 32768
net.core.somaxconn = 32768

[root@node01 ~]# sysctl -p
...
net.ipv4.tcp_max_syn_backlog = 32768
net.core.somaxconn = 32768

再次执行calico的健康检查命令，请求已经不再卡住了，问题消失，查看异常的Pod也恢复正常：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
[root@node01 ~]# time curl -i http://localhost:9099/liveness
HTTP/1.1 204 No Content
Date: Tue, 15 Jun 2021 14:48:38 GMT
real    0m0.011s
user    0m0.004s
sys     0m0.004s
[root@node01 ~]# time curl -i http://localhost:9099/liveness
HTTP/1.1 204 No Content
Date: Tue, 15 Jun 2021 14:48:39 GMT
real    0m0.010s
user    0m0.001s
sys     0m0.005s
[root@node01 ~]# time curl -i http://localhost:9099/liveness
HTTP/1.1 204 No Content
Date: Tue, 15 Jun 2021 14:48:40 GMT
real    0m0.011s
user    0m0.002s

其实，最终这个问题的解决也是半猜半验证得到的，如果是正向推演，发现TCP请求在SYN_SENT阶段卡住之后，其实应该要确认相关内核参数是不是确实太小。

解决方案

在高并发场景下，做服务器内核参数的调优。

参考资料

  1. https://romatic.net/post/go_net_errors/
  2. http://blog.qiusuo.im/blog/2014/03/19/tcp-timeout/
  3. http://www.51testing.com/html/13/235813-3710663.html