一次内核问题引起的 Kubernetes 节点故障解决纪实

时间:2021-12-05 14:05:07

一次内核问题引起的 Kubernetes 节点故障解决纪实

1 具体现象

在线上环境中的某个应用出现了接口缓慢的问题!!

就凭这个现象, 能列出来的原因数不胜数. 本篇博客主要叙述一下几次排查以及最后如何确定原因的过程, 可能不一定适用于其他集群, 就当是提供一个参考吧. 排查过程比较冗长, 过去太久了, 我也不太可能回忆出所有细节, 希望大家见谅.

2 网络拓扑结构

网络请求流入集群时, 对于我们集群的结构:

  1. 用户请求=>Nginx=>Ingress =>uwsgi 

不要问为什么有了 Ingress 还有 Nginx. 这是历史原因, 有些工作暂时需要由 Nginx 承担.

3 初次定位

请求变慢一般马上就会考虑, 程序是不是变慢了, 所以在发现问题后, 首先在 uwsgi 中增加 简单的小接口, 这个接口是处理快并且马上返回数据, 然后定时请求该接口. 在运行几天之后, 确认到该接口的访问速度也很慢, 排除程序中的问题, 准备在链路中查找原因.

4 再次定位 – 简单的全链路数据统计

由于我们的 Nginx 有 2 层, 需要针对它们分别确认, 看看究竟是哪一层慢了. 请求量是比较大的, 如果针对每个请求去查看, 效率不高, 而且有可能掩盖真正原因, 所以这个过程采用统计的方式. 统计的方式是分别查看两层 Nginx 的日志情况. 由于我们已经在 elk 上接入了日志. elk 中筛选数据的脚本简单如下:

  1.   "bool": { 
  2.     "must": [ 
  3.       { 
  4.         "match_all": {} 
  5.       }, 
  6.       { 
  7.         "match_phrase": { 
  8.           "app_name": { 
  9.             "query""xxxx" 
  10.           } 
  11.         } 
  12.       }, 
  13.       { 
  14.         "match_phrase": { 
  15.           "path": { 
  16.             "query""/app/v1/user/ping" 
  17.           } 
  18.         } 
  19.       }, 
  20.       { 
  21.         "range": { 
  22.           "request_time": { 
  23.             "gte": 1, 
  24.             "lt": 10 
  25.           } 
  26.         } 
  27.       }, 
  28.       { 
  29.         "range": { 
  30.           "@timestamp": { 
  31.             "gt""2020-11-09 00:00:00"
  32.             "lte""2020-11-12 00:00:00"
  33.             "format""yyyy-MM-dd HH:mm:ss"
  34.             "time_zone""+08:00" 
  35.           } 
  36.         } 
  37.       } 
  38.     ] 
  39.   } 

数据处理方案

根据 trace_id 可以获取到 Nignx 日志以及 Ingress 日志, 通过 elk 的 api 获得.

  1. # 这个数据结构用来记录统计结果, 
  2. # [[0, 0.1], 3]表示 落在 0~0.1区间的有3条记录 
  3. # 因为小数的比较和区间比较麻烦, 所以采用整数, 这里的0~35其实是0~3.5s区间 
  4. # ingress_cal_map = [ 
  5. #     [[0, 0.1], 0], 
  6. #     [[0.1, 0.2], 0], 
  7. #     [[0.2, 0.3], 0], 
  8. #     [[0.3, 0.4], 0], 
  9. #     [[0.4, 0.5], 0], 
  10. #     [[0.5, 1], 0], 
  11. # ] 
  12. ingress_cal_map = [] 
  13. for x in range(0, 35, 1): 
  14.     ingress_cal_map.append( 
  15.         [[x, (x+1)], 0] 
  16.     ) 
  17. nginx_cal_map = copy.deepcopy(ingress_cal_map) 
  18. nginx_ingress_gap = copy.deepcopy(ingress_cal_map) 
  19. ingress_upstream_gap = copy.deepcopy(ingress_cal_map) 
  20.  
  21.  
  22. def trace_statisics(): 
  23.     trace_ids = [] 
  24.     # 这里的trace_id是提前查找过, 那些响应时间比较久的请求所对应的trace_id 
  25.     with open(trace_id_file) as f: 
  26.         data = f.readlines() 
  27.         for d in data: 
  28.             trace_ids.append(d.strip()) 
  29.  
  30.     cnt = 0 
  31.     for trace_id in trace_ids: 
  32.         try: 
  33.             access_data, ingress_data = get_igor_trace(trace_id) 
  34.         except TypeError as e: 
  35.             # 继续尝试一次 
  36.             try: 
  37.                 access_data, ingress_data = get_igor_trace.force_refresh(trace_id) 
  38.             except TypeError as e: 
  39.                 print("Can't process trace {}: {}".format(trace_id, e)) 
  40.                 continue 
  41.         if access_data['path'] != "/app/v1/user/ping":  # 过滤脏数据 
  42.             continue 
  43.         if 'request_time' not in ingress_data: 
  44.             continue 
  45.  
  46.         def get_int_num(data):  # 数据统一做*10处理 
  47.             return int(float(data) * 10) 
  48.  
  49.         # 针对每个区间段进行数据统计, 可能有点罗嗦和重复, 我当时做统计够用了 
  50.         ingress_req_time = get_int_num(ingress_data['request_time']) 
  51.         ingress_upstream_time = get_int_num(ingress_data['upstream_response_time']) 
  52.         for cal in ingress_cal_map: 
  53.             if ingress_req_time >= cal[0][0] and ingress_req_time < cal[0][1]: 
  54.                 cal[1] += 1 
  55.                 break 
  56.  
  57.         nginx_req_time = get_int_num(access_data['request_time']) 
  58.         for cal in nginx_cal_map: 
  59.             if nginx_req_time >= cal[0][0] and nginx_req_time < cal[0][1]: 
  60.                 cal[1] += 1 
  61.                 break 
  62.  
  63.         gap = nginx_req_time - ingress_req_time 
  64.         for cal in nginx_ingress_gap: 
  65.             if gap >= cal[0][0] and gap <= cal[0][1]: 
  66.                 cal[1] += 1 
  67.                 break 
  68.  
  69.         gap = ingress_req_time - ingress_upstream_time 
  70.         for cal in ingress_upstream_gap: 
  71.             if gap >= cal[0][0] and gap <= cal[0][1]: 
  72.                 cal[1] += 1 
  73.                 break 

我分别针对 request_time(nginx) , request_time(ingress) , 以及 requet_time(nginx) - request_time(ingress) ,做了统计.

最后的统计结果大概如下:

一次内核问题引起的 Kubernetes 节点故障解决纪实

Nginx响应时间

一次内核问题引起的 Kubernetes 节点故障解决纪实

Ingress响应时间

一次内核问题引起的 Kubernetes 节点故障解决纪实

Nginx-Ingress响应时间 

结果分析

我们总共有约 3000 条数据!

  • 图一: 超过半数的请求落在 1 1.1s 区间, 1s 2s 的请求比较均匀, 之后越来越少了.
  • 图二: 大约 1/4 的请求其实已经在 0.1s 内返回了, 但是 1~1.1s 也有 1/4 的请求落上去了, 随后的结果与图一类似.

从图 1 图 2 结合来看, 部分请求在 Ingress 侧处理的时间其实比较短的,

  • 图三: 比较明显了, 2/3 的请求在响应时间方面能够保持一致, 1/3 的请求会有 1s 左右的延迟.

总结

从统计结果来看, Nginx => Ingress 以及 Ingress => upstream, 都存在不同程度的延迟, 超过 1s 的应用, 大约有 2/3 的延迟来自 Ingress=>upstream, 1/3 的延迟来自 Nginx=>Ingress.

5 再深入调查 - 抓包处理

抓包调查主要针对 Ingress=>uwsgi , 由于数据包延迟的情况只是偶发性现象, 所以需要抓取所有的数据包再进行过滤… 这是一条请求时间较长的数据, 本身这个接口返回应该很快.

  1.   "_source": { 
  2.     "INDEX""51"
  3.     "path""/app/v1/media/"
  4.     "referer"""
  5.     "user_agent""okhttp/4.8.1"
  6.     "upstream_connect_time""1.288"
  7.     "upstream_response_time""1.400"
  8.     "TIMESTAMP""1605776490465"
  9.     "request""POST /app/v1/media/ HTTP/1.0"
  10.     "status""200"
  11.     "proxy_upstream_name""default-prod-XXX-80"
  12.     "response_size""68"
  13.     "client_ip""XXXXX"
  14.     "upstream_addr""172.32.18.194:6000"
  15.     "request_size""1661"
  16.     "@source""XXXX"
  17.     "domain""XXX"
  18.     "upstream_status""200"
  19.     "@version""1"
  20.     "request_time""1.403"
  21.     "protocol""HTTP/1.0"
  22.     "tags": ["_dateparsefailure"], 
  23.     "@timestamp""2020-11-19T09:01:29.000Z"
  24.     "request_method""POST"
  25.     "trace_id""87bad3cf9d184df0:87bad3cf9d184df0:0:1" 
  26.   } 

Ingress侧数据包

一次内核问题引起的 Kubernetes 节点故障解决纪实

uwsgi侧数据包

一次内核问题引起的 Kubernetes 节点故障解决纪实

数据包流转情况

回顾一下TCP三次握手:

一次内核问题引起的 Kubernetes 节点故障解决纪实

首先从Ingress侧查看, 连接在21.585446开始, 22.588023时, 进行了数据包重新发送的操作。

从Node侧查看, node在ingress数据包发出后不久马上就收到了syn, 也立刻进行了syn的返回, 但是不知为何1s后才出现在ingress处。

一次内核问题引起的 Kubernetes 节点故障解决纪实

有一点比较令人在意, 即便是数据包发生了重传, 但是也没有出现丢包的问题, 从两台机器数据包的流转来看, 此次请求中, 大部分的时间是因为数据包的延迟到达造成的, 重传只是表面现象, 真正的问题是发生了数据包的延迟.

不止是ack数据包发生了延迟

从随机抓包的情况来看, 不止是 SYN ACK 发生了重传:

一次内核问题引起的 Kubernetes 节点故障解决纪实

有些 FIN ACK 也会, 数据包的延迟是有概率的行为!!!

总结

单单看这个抓包可能只能确认是发生了丢包, 但是如果结合Ingress与Nginx的日志请求来看, 如果丢包发生在tcp连接阶段, 那么在Ingress中, 我们就可以查看 upstream_connect_time 这个值来大致估计下超时情况. 当时是这么整理的记录:

我初步猜测这部分时间主要消耗在了 TCP 连接建立时, 因为建立连接的操作在两次 Nginx 转发时都存在, 而我们的链路全部使用了短连接, 下一步我准备增加 $upstream_connect_time 变量, 记录建立连接花费的时间. http://nginx.org/en/docs/http/ngx_http_upstream_module.html

后续工作

既然可以了解到tcp连接的建立时间比较久, 我们可以用它来作为一个衡量指标, 我把wrk也修改了下, 增加了对于连接时间的测量, 具体的PR见这里(https://github.com/wg/wrk/pull/447), 我们可以利用这一项指标衡量后端的服务情况.

一次内核问题引起的 Kubernetes 节点故障解决纪实

6 寻找大佬, 看看是否遇到类似问题

上面的工作前前后后我进行了几次, 也没有什么头绪, 遂找到公司的其他K8S大佬咨询问题, 大佬提供了一个思路:

宿主机延迟也高的话,那就暂时排除宿主机到容器这条路径。我们这边此前排查过一个延迟问题, 是由于 k8s 的监控工具定期 cat proc 系统下的 cgroup 统计信息, 但由于 docker 频繁销毁重建以及内核 cache 机制,使得每次 cat 时间很长占用内核导致网络延迟, 可否排查一下你们的宿主机是否有类似情形?不一定是 cgroup,其他需要频繁陷入到内核的操作都可能导致延迟很高

这个跟我们排查的 cgroup 太像了,宿主机上有一些周期性任务,随着执行次数增多,占用的内核资源越来越多,达到一定程度就影响了网络延迟

大佬们也提供了一个内核检查工具(可以追踪和定位中断或者软中断关闭的时间):

https://github.com/bytedance/trace-irqoff

有问题的ingress机器 的latency特别多,好多都是这样的报错, 其他机器没有这个日志:

一次内核问题引起的 Kubernetes 节点故障解决纪实

一次内核问题引起的 Kubernetes 节点故障解决纪实

而后, 我针对机器中的kubelet进行了一次追踪, 从火焰图中可以确认, 大量的时间耗费在了读取内核信息中。

一次内核问题引起的 Kubernetes 节点故障解决纪实

其中具体的代码如下:

一次内核问题引起的 Kubernetes 节点故障解决纪实

总结

根据大佬所给的方向, 基本能够确定问题发生的真正原因: 机器上定时任务的执行过多, 内核缓存一直增加, 导致内核速度变慢了. 它一变慢, 引发了tcp握手时间变长, 最后造成用户体验下降. 既然发现了问题, 解决方案也比较容易搜索到了, 增加任务, 检查内核是否变慢, 慢了的话就清理一次:

  1. sync && echo 3 > /proc/sys/vm/drop_caches 

7 总结

这次的排查过程是由于应用层出现了影响用户体验的问题后, 进一步延伸到了网络层, 其中经历了漫长的抓包过程, 也增加了自己的脚本用于指标衡量, 随后又通过内核工具定位到了具体应用, 最后再根据应用的 pprof 工具制作出的火焰图定位到了更加精确的异常位置, 期间自己一个人没法处理问题, 遂请其他大佬来帮忙, 大佬们见多识广, 可以给出一些可能性的猜想, 还是很有帮助的.

当你发现某台机器无论做什么都慢, 而cpu和内核却不是瓶颈的时候, 那有可能是内核慢了.

希望本文能对大家未来排查集群问题时有所帮助.

本文转载自:「k8s技术圈」,原文:https://tinyurl.com/y5wx3m5x,版权归原作者所有。