1具体现象是线上环境下的一个应用出现接口慢的问题！！仅凭这种现象，就可以列举出无数的原因。这篇博客主要描述了几次排查的过程以及最终是如何确定原因的，不一定适用于其他集群，仅供参考。调查过程比较漫长，时间太长了，我不可能全部回忆起来。希望大家见谅.2网络拓扑当网络请求流入集群时，对于我们集群的结构：用户请求=>Nginx=>Ingress=>uwsgi，不要问为什么会有Ingress和Nginx。这是历史原因，有些工作暂时需要Nginx来承担。3当初始定位请求变慢时，一般会立即考虑是不是程序变慢了，所以发现问题后，先添加一个简单的小接口在uwsgi中，这个接口速度很快，立即返回数据，然后周期性地请求接口。运行了几天，确认这个接口的访问速度也很慢，排除了程序中的问题，准备在链接中查找原因。4再次定位——简单的全链路数据统计由于我们的Nginx有2个Layer，所以需要分别确认一下，看看是哪一层慢。请求量比较大。如果对每个请求都进行检查，效率不高，而且可能掩盖真正的原因，所以这个过程采用了统计的方法。统计的方法是分别查看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，可以通过elk的api获取Nignx日志和Ingress日志。#这个数据structure用来记录统计结果，#[[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)exceptTypeError:print("Can'tprocesstrace{}:{}".format(trace_id,e))continueifaccess_data['path']!="/app/v1/user/ping":#过滤脏数据continueif'request_time'notiningress_data:continuedefget_int_num(data):#数据统一做*10处理returnint(float(data)*10)#对每个区间段进行数据统计，可能有点罗嗦和重复，我是用来统计的0][1]:cal[1]+=1breaknginx_req_time=get_int_num(access_data['request_time'])forcalinnginx_cal_map:ifnginx_req_time>=cal[0][0]andnginx_req_time=cal[0][0]andgap<=cal[0][1]:cal[1]+=1breakgap=ingress_req_time-ingress_upstream_timeforcalinaningress_upstream_gap:ifgap>=cal[0][0]andgap<=cal[0][1]:cal[1]+=1break我统计了request_time(nginx),request_time(ingress),andrequet_time(nginx)-request_time(ingress)。最终的统计结果大致如下：NginxResponseTimeIngressResponseTimeNginx-IngressResponseTime结果分析我们总共有3000条左右的数据！图1：超过半数的请求都在11.1s范围内，1s2s的请求比较统一，然后越来越少图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。5深入调查-抓包处理抓包调查主要针对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""response_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","协议":"HTTP/1.0","tags":["_dateparsefailure"],"@timestamp":"2020-11-19T09:01:29.000Z","re??quest_method":"POST","trace_id":"87bad3cf9d184df0:87bad3cf9d184df0:0:1"}}Ingress侧数据包uwsgi侧数据包数据包我们回顾一下三次TCP握手：首先从Ingress端查看，连接从21.585446开始，在22.588023重发数据包。从Node端看，在ingress包发送后不久，node收到了syn，并立即返回了syn，但不知为何1s后并没有出现在ingress。比较关心的一点是，即使重传数据包，也没有丢包问题。从两台机器之间的数据包流向来看，这个请求中大部分时间是由于延迟到达造成的，重传只是表面现象。真正的问题是数据包的延迟。不仅仅是ack数据包的延迟。从随机抓包的情况来看，不仅仅是SYNACK的重传：一些FINACK也会，数据包的延迟是一种概率行为！！！综上所述，光看这个抓包可能只能确认丢包了，但是如果结合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），我们可以通过这个指标来衡量后端的服务情况。6找老大，看看有没有遇到类似的问题下一次，没有任何线索，就找了公司其他的K8S老大请教。老大提供了一个思路：如果宿主机的延迟也很高，那就暂时排除宿主机到容器的路径。我们之前调查过延迟问题。是因为k8s监控工具定时catproc系统下的cgroup统计。但是由于docker的频繁销毁和重建以及内核缓存机制，每只猫占用内核的时间都比较长，造成网络延迟。请问楼主有没有类似的情况？它不一定是cgroup。其他需要频繁落入内核的操作可能会导致高延迟。这和我们检查的cgroup太相似了。主机上有一些周期性的任务。随着执行次数的增加，占用的内核资源越来越多，一定程度上会影响网络延迟。大佬们还提供了一个内核检查工具（可以跟踪定位中断或者软中断关闭的时间）：https://github.com/bytedance/trace-irqoff有问题的ingress机器有很多延迟，很多其中报错是这样的，其他机器是没有这个日志的：然后，我对机器中的kubelet进行了trace，从火焰图中可以确认，很多时间都花在了读取内核信息上。具体代码如下：综上所述，根据老大给的方向，基本可以确定问题的真正原因：机器上的定时任务太多，内核缓存不断增加，内核速度变慢.一旦变慢，就会导致tcp握手时间变长，最终导致用户体验下降。既然找到了问题，解决方案就比较好找了，添加任务，查看内核是否慢，如果慢就清理一次：sync&&echo3>/proc/sys/vm/drop_caches7总结一下排查过程这个时间是由于应用层出现问题影响用户体验后，进一步延伸到网络层，网络层经历了漫长的抓包过程，并且还加入了自己的指标测量脚本，以及然后通过内核工具定位到具体的应用，最后根据应用的pprof工具生成的火焰图定位到比较准确的异常位置。期间自己解决不了问题，就请了其他大佬帮忙。看到大家多给一些可能的猜想很有帮助。当你发现某台机器无论做什么都慢，但cpu和core不是瓶颈时，可能是core慢了。希望这篇文章能够对大家以后排查集群问题有所帮助。本文转载自：《k8s技术圈》，原文：https://tinyurl.com/y5wx3m5x，版权归原作者所有。
