这次排查发生在2020年11月，还没来得及写博客描述发生的事情。这次一起写吧。具体现象是线上环境下的一个应用出现界面慢的问题！基于这种现象，可以列举出无数的原因。这篇博客主要描述了几次排查的过程，以及最终是如何确定原因的。它不一定适用于其他集群，因此应作为参考。调查过程比较长，时间太长了，我不可能全部回忆起来，还望大家见谅。网络拓扑当网络请求流入集群时，对于我们集群的结构：用户请求=>Nginx=>Ingress=>uwsgi，不要问为什么会有Ingress和Nginx，这是历史原因，有些工作需要暂由Nginx承担。当最初的定位请求变慢的时候，一般会马上考虑是不是程序变慢了，所以发现问题后，先给uwsgi添加一个简单的小接口。该接口快速处理并立即返回数据，然后定时请求该接口。经过几天的运行，确认这个接口的访问速度也很慢，排除了程序中的问题，在链接中查找原因。搬迁——简单的全链路数据统计由于我们的Nginx有2层，所以我们需要分别确认一下，看是哪一层慢。请求量比较大。如果每一个请求都看，效率不高，可能会掩盖真正的原因，所以这个过程采用了统计的方法。统计的方法是分别查看Nginx的两层日志。由于我们已经将日志接入ELK，所以ELK中过滤数据的脚本很简单：{"bool":{"must":[{"match_all":{}},{"match_phrase":{"app_name":{"query":"xxxx"}}},{"match_phrase":{"path":{"query":"/app/v1/user/ping"}}},{"range":{"request_time":{"gte":1,"lt":10}}},{"range":{"@timestamp":{"gt":"2020-11-0900:00:00","lte":"2020-11-1200:00:00","format":"yyyy-MM-ddHH:mm:ss","time_zone":"+08:00"}}}]}}数据处理方案可以根据trace_id获取到Nignx日志和Ingress日志，通过ELKAPI获取。#这个数据结构是用来记录统计结果的，#[[0,0.1],3]表示有3条落在0~0.1范围内的记录#因为小数和区间的比较比较麻烦，所以用整数，这里0~35其实就是0~3.5s的间隔#ingress_cal_map=[#[[0,0.1],0],#[[0.1,0.2],0],#[[0.2,0.3],0],#[[0.3,0.4],0],#[[0.4,0.5],0],#[[0.5,1],0],#]ingress_cal_map=[]forxinrange(0,35,1):ingress_cal_map.append([[x,(x+1)],0])nginx_cal_map=copy.deepcopy(ingress_cal_map)nginx_ingress_gap=copy.deepcopy(ingress_cal_map)ingress_upstream_gap=copy.deepcopy(ingress_cal_map)deftrace_statisics():trace_ids=[]#trace_id这里是提前查的不过trace_idwithopen(trace_id_file)asf:data=f.readlines()fordindata:trace_ids.append(d.strip())cnt=0fortrace_idintrace_ids:try:access_data,ingress_data=get_igor_trace(trace_id)exceptTypeErrorase:#继续重试try:access_data,ingress_data=get_igor_trace.force_refresh(trace_id)exceptTypeErrorase:print("无法处理race{}:{}".format(trace_id,e))continueifaccess_data['path']!="/app/v1/user/ping":#filterdirtydatacontinueif'request_time'notiningress_data:continuedefget_int_num(data):#数据统一处理*10returnint(float(data)*10)#每个区间段的数据统计可能有点啰嗦和重复，我统计够了ingress_req_time=get_int_num(ingress_data['request_time'])ingress_upstream_time=get_int_num(ingress_data['upstream_response_time'])forcalinigress_cal_map:ifingress_req_time>=cal[0][0]andingress_req_time=cal[0][0]andnginx_req_time=cal[0][0]andgap<=cal[0][1]:cal[1]+=1breakgap=ingress_req_time-ingress_upstream_timeforcalinigress_upstream_gap:ifgap>=cal[0][0]andgap<=cal[0][1]:cal[1]+=1breakforrequest_time(Nginx),request_time(Ingress)和request_time(nginx)-request_time(Ingress)做了统计，最终的统计结果大致如下：结果分析我们总共有大概3000条数据！图1：超过半数的请求落在1~1.1s区间内，1s到2s的请求比较均匀，之后请求越来越少。图2：大约1/4的请求在0.1s内实际上已经返回，但是1/4的请求也在1~1.1s内落下，后续结果与图1类似。结合图1和图2来看，Ingress端有些请求的处理时间其实是比较短的。图3：很明显，2/3的请求在响应时间上可以保持一致，1/3的请求会有1s左右的延迟。总结从统计结果来看，Nginx=>Ingress和Ingress=>upstream有不同程度的延迟。对于超过1s的应用，大约2/3的延迟来自Ingress=>upstream，1/3的延迟来自Nginx=>Ingress。深入调查——抓包处理抓包调查主要针对Ingress=>uwsgi。由于包延迟只是偶尔的现象，所以需要将所有的包都抓包然后过滤掉。。。这是一个请求时间比较长的数据，这个接口本身的返回应该是很快的。{"_source":{"INDEX":"51","path":"/app/v1/media/","re??ferer":"","user_agent":"okhttp/4.8.1","upstream_connect_time":"1.288","upstream_response_time":"1.400","TIMESTAMP":"1605776490465","re??quest":"POST/app/v1/media/HTTP/1.0","status":"200","proxy_upstream_name":"default-prod-XXX-80","re??sponse_size":"68","client_ip":"XXXXX","upstream_addr":"172.32.18.194:6000","re??quest_size":"1661","@source":"XXXX","domain":"XXX","upstream_status":"200","@version":"1","re??quest_time":"1.403","protocol":"HTTP/1.0","tags":["_dateparsefailure"],"@timestamp":"2020-11-19T09:01:29.000Z","re??quest_method":"POST","trace_id":"87bad3cf9d184df0:87bad3cf9d184df0:0:1"}}入口端数据包uwsgi端数据包数据包流程回顾TCP三次握手：首先从Ingress端查看，21.585446开始连接，在22.588023进行了重发数据包的操作。从Node端查看，Node收到了synIngress数据包发送后不久，也是立马返回了syn，但是不知道为什么过了1s才出现在Ingress，比较关心的一点是，即使数据包重传，也没有丢包两台机器的数据从包流来看，这个请求中大部分时间是数据包延迟到达造成的，重传只是表面现象，真正的问题是数据包的延迟。不仅仅是ACK数据包的延迟从随机p的情况来看acket捕获，不仅会重传SYNACKs：还会出现一些FINACKs，而且数据包的延迟是一种概率行为！总结只看这个抓包可能只能确认丢包了，但是如果结合Ingress和Nginx的日志请求，如果丢包发生在TCP连接阶段，那么在Ingress中，我们可以查看upstream_connect_time的值来粗略估计超时情况。当时记录是这样组织的：我初步猜测这部分时间主要是在建立TCP连接时消耗的，因为在两次Nginx转发的过程中都存在建立连接的操作，而我们的链接都是使用短连接.接下来我打算增加变量$upstream_connect_time来记录建立连接的开销http://nginx.org/en/docs/http/....html后续工作由于我们可以理解为TCP连接需要一个时间久了，我们可以把它作为一个衡量指标。我也使用wrk修改增加了连接时间的测量。具体的PR可以看这里。我们可以通过这个指标来衡量后端的服务情况。找老大看看有没有遇到类似的问题。上面的工作我前后做了好几次，都没有什么头绪，于是找了公司其他的Kubernetes大佬请教。老大提供了一个思路：宿主机的延迟也高的话，暂时排除宿主机到容器的路径。我们之前调查过延迟问题。是因为Kubernetes的监控工具会定时catproc系统下的cgroup统计。但是由于Docker频繁的销毁和重建以及内核缓存机制，每只猫占用内核的时间都比较长，造成网络延迟。请问楼主有没有类似的情况？不一定是cgroup，其他需要频繁陷入内核的操作可能会造成高延迟。这与我们调查的cgroup非常相似。宿主机上有一些周期性的任务。随着执行次数的增加，占用的内核资源越来越多，一定程度上会影响网络延迟。大佬们还提供了一个内核检查工具（可以跟踪定位中断或者软中断关闭的时间）：https://github.com/bytedance/trace-irqoff有问题的Ingress机器有很多延迟，并且很多都是这样的报错，其他机器没有这个日志：然后，我对机器中的kubelet进行了trace，从火焰图中可以确认，很多时间都花在了读取内核信息上.具体代码如下：总结根据老大给的方向，基本可以确定问题的真正原因：机器上执行的定时任务过多，内核缓存不断增加，导致速度变慢内核速度。一旦变慢，就会导致TCP握手时间变长，最终导致用户体验下降。既然找到了问题，就更容易找到解决方案了。添加任务，检查内核是否慢，慢则清理一次：sync&&echo3>/proc/sys/vm/drop_caches应用层出现问题影响用户体验后，进一步延伸到网络层，经历了一个漫长的抓包过程，并加入了自己的指标测量脚本，然后使用内核工具定位到具体的应用。最后，根据应用的pprof工具生成的火焰图，定位到了比较准确的异常位置。期间自己解决不了问题，就请其他大佬帮忙。大佬们见多识广，能给出一些可能的猜想，还是很有帮助的。当你发现一台机器不管做什么都慢，但CPU和核心不是瓶颈时，可能就是核心慢了。希望这篇文章能对大家以后排查集群问题有所帮助。
