【性能调优】记录一次性能tps从几十调优到上千的过程

问题现象和描述

服务增加实例后,tps不增加反而下降,系统资源也没有充分利用起来,需尽快定位问题,找到tps上不去的原因,通过调优达到上线要求

商城压测服务响应时间优化记录

高并发下系统性能优化主要有两方面:

一是提升系统资源情况,主要为了增加并行处理能力。 image.png image.png

二是减少单次任务响应时间

针对软件系统不同层次的架构优化单词任务响应时间,主要需要区分是CPU密集型还是IO密集型(更多的是侧重,实际不是完全某种类型)。如 nginx、网关、serverlet等需要用到大量的连接等情况,一般是有池化技术等进行的多路IO复用,涉及到大量的CPU线程切换,所以偏向CPU密集型(也会有IO阻塞等问题)。而数据库操作、缓存、日志记录等实现,更多的是IO密集型。

针对以上理论思路,对于南网商城压测优化,以下是在之前优化的基础上对于服务单次响应时间优化的记录。

当前调用链路是 nginx->openapi->mall-api->鉴权服务

在压测时发现,当压力上来之后,mall-api出现了响应时间变长的情况(最多达到2s多) image.png

我们的mall-api 是通过spring-mvc基础架构进行的Rest服务提供,其核心运行原理如下:

Spring的web框架围绕DispatcherServlet。DispatcherServlet的作用是将请求分发到不同的处理器。从Spring2.5开始,使用java5或者以上版本的用户可以采用基于注解的controller声明方式

Spring MVC框架像许多其他MVC框架一样,以请求为驱动,围绕一个中心Servlet分派请求及提供其他功能,DispatcherServlet是一个实际的Servlet(它继承自HttpServlet基类) image.png

使用arthas 工具,对DispatcherServlet类进行trace监控,在负载大的情况下,发现该类每次响应请求出现大量的高延迟响应的情况: image.png image.png

针对其中triggerAfterCompletion进行trace,发现有四个Interceptor的afterCompletion方法执行时间比较长 image.png

对afterCompletion方法进行trace,发现一个自定义实现的组件,其中调取log.debug时间较长,初步判断该部分耗时主要是压力大时写日志IO阻塞造成。 image.png

该类实现存在大量的log.debug image.png

通过admin和mall-api代码进行查看,发现默认日志级别是debug

image.png image.png

admin中调整日志级别后,QPS无明显的提升,此时出现Nginx 504错误,且再次trace 发现log.debug仍然耗时较长。 image.png image.png

下图多个红色耗时提醒原因,都是组件内针对不同的部分拦截时存在log.debug image.png image.png image.png

修改mall-api代码日志默认级别后再次进行测试,出现部分 nginx 504报错,此时QPS为

170左右,无法达到之前470左右水平,重启nginx,此问题另外单独分析。 image.png

代码中及admin中修改日志级别为info,压力高时log.debug仍会耗费长时间 image.png

修改组件 去除日志记录逻辑 image.png

doDispatch trace 在进行返回值转换时还有耗时 image.png

此时1000线程压测结果如下 image.png

Skywalking 监控如下 image.png

仍存在时间较久情况 image.png

此时服务器服务对应cpu消耗较高,代码执行时间短,可能出现在线程等待调度上,后续继续排查。

优化Leading-openapi-gateway

在之前的优化过程中,发现了nginx 会出现大量的504报错,导致QPS出现大幅度波动,通过查找确认主要出现在 nginx proxy_read_timeout 超时上,而此超时主要是nginx 等待从 upstream server 读取相应数据的超时,所以可以通过优化 通过 upstream server 转发的 openapi-gateway 性能,看看是否可以提升。 image.png

上图 优化前 qps 最高600多 出现报错后,qps大幅度下降

先说下 spring gateway webflux底层最基础的处理流程及实现 image.png image.png

可以看到NettyServer的Boss Group线程池内的线程循环接收这个请求,然后把完成了TCP三次握手的连接channel交给Worker Group中的某一个事件循环线程来进行处理(该事件处理线程会调用对应的controller进行处理)。所以WebFlux的handler执行是使用Netty的IO线程进行执行的,所以需要注意如果handler的执行比较耗时,会把IO线程耗尽导致不能再处理其他请求,可以通过Reactor的publishOn操作符切换到其他线程池中执行。

框架层级的代码都是通过反应器设计模式(Reactor)进行设计实现的NIO,底层通信是使用的netty框架,默认是用的是epoll 模式,更细节的实现可以参考https://blog.csdn.net/htmlxxxx/article/details/115221707

https://blog.csdn.net/weixin_44802598/article/details/104874266

https://segmentfault.com/a/1190000014269642 image.png

所以基本思路就是两个,一是优化reactor-epoll 线程,让更多的epoll线程可以工作,另一个是针对单个请求,我们自己的处理流程尽量快,使其处理效率标高

Handler 层

image.png

通过对框架入口 请求handler 进性trace 发现,其在高并发请求情况下,并没有太大的性能损失,基本在1ms以下 image.png

Route层

整个框架,route 层有一个RouteLocator 接口,并有三个实现类。 image.png

RouteDefinitionRouteLocator 类,进行Route 和 Filter 处理流程的基本组织,

在其中 有一个核心公共方法getRoutes 通过 请求的 Hanlder 类 lookupRoute 进行调用 image.png image.png

在其中通过 convertToRoute方法调用,进行 Route和对应Filter的组装。 image.png image.png image.png

进行并发请求后,首次会调取RouteDefinitionRouteLocator类 getRoutes方法

后续对应网络io线程处理请求,会调取 CachingRouteLocator 类 getRoutes方法提升性能。并通过内部时间进行动态路由刷新等(我们不涉及)

进行Route层getRoutes方法trace,该层在并发情况下响应无明显增加情况。 image.png

Filter层

filter层最核心有一个工厂接口GatwayFilterFactory 。 image.png image.png

在对filter层代码进行查看的时候,发现对于mall-api请求我们是走了三个filter: image.png

LeadingClientTokenRelayFilter: 对请求做转发前获取erptoken image.png image.png image.png

后续优化建议

发现该接口存在如下问题

1.在Mono过滤接口实现中,直接使用了SpringRedisTemplate调取redis,该方式是底层是调取了 spring-data-redis + Lettuce 进行的,虽然是线程池,但是是同步代码,在filter方法中,并没有将该代码使用reactor的publishOn转发线程进行异步API封装,所以会出现同步代码阻塞住 epoll的接收请求处理的异步线程,发生雪崩现象。

通过在压力保持的时候,通过spring-boot-admin进行查看,每个网关实例中的redis-lettuce线程都存在阻塞现象,且 reactor的epoll线程也存在大量的阻塞。 image.png

2.过滤器中存在大量的打印日志的代码,经过之前的验证,即时日志级别不是Debug,log.debug也会带来性能损耗,而且打印日志的代码基本都是会发生同步IO阻塞异步IO的。

3.当前网关未进行限流、超时、请求等待阻塞队列等设置需要进行更详细使用设计。

通过 设置 reactor.netty.ioWorkerCount 为200,发现qps可以在高压力下保持一定时间,但是随着压力的持续,还是会因为 reactor-http-epoll线程大量阻塞而出发nginx 超时,qps下降。

商城服务架构图如下:

image.png

开发优化代码:

1、 去除了少量的log级别的日志,减少IO

2、 openapi网关使用的是reactor异步编程的方式,所有请求接收后,由主线程reactor-http-epoll进行处理,进行调用erp token和去mall-release校验token时也是使用了reactor-http-epoll主线程,导致主线程阻塞。此次修改,针对调用接口处理逻辑的地方增加了子线程的处理方式(publishOn(Schedulers.parallel())),避免主线程阻塞,接口处理逻辑由子线程完成,待子线程处理完成后,再由主线程介入进行后续的转发。这样大大增加了主线程的使用效率,避免主线程阻塞。

测试场景设计和结果记录:

排除旧代码影响TPS

商城代码优化后test5进行压测,出现规律性断崖。在加大压力1000线程依然出现大幅度断崖情况! image.png

代码优化前压测未出现这种大波动的断崖情况,于是想回退旧代码压测验证,回退代码问题依然存在,所以排除了代码问题 image.png

以下图中左图为之前老代码空接口压测结果,右图为优化后近期压测结果,明显现在TPS会出现断崖。 image.png

压测过程中监控了一下TCP的链接情况,timewait的数据很少 image.png

排除DNS域名解析对TPS影响

依据之前nginx断崖的经验,把nginx转发网关的proxy配置由域名修改为ip压测无效果 image.png image.png

拆分nginx服务直接对网关压测

由于查看skywalking时间消耗都在nginx这层 于是转变思路拆分服务 绕过nginx直接压测网关

压测网关依然出现断崖不会恢复 image.png

所有服务都是4个实例情况下压测 出现断崖,尝试修改实例数为1 不走负载尽量接近开发本地环境验证是否还会出现断崖

从图中看TPS依然出现断崖所以跟实例数也无关 image.png

压测过程中开发观看日志发现skywalking插件报错 image.png

在优化了插件后再次压测,TPS趋于平稳保持 不在出现断崖现象,由于该插件临时添加定位问题所以线上不存在该问题 image.png

为最终确定是该插件导致TPS断崖问题所以又添加插件后继续压测,出现断崖且TPS平均只有100左右远远低于1.6k优化后的TPS image.png

直接压测网关的TPS趋于稳定后,尝试增加nginx链路继续压测

在更换为nginx后(此时只有一个nginx)压测结果只有90TPS左右

增加nginx压测

在更改为之前的一拖四的模式后压测结果如下,证明一拖四的nginx是可以提升TPS的 但是依然出现断崖情况,所以暂时判断该断崖与nginx有关 image.png

由上图的低谷时间可以看出大概一分钟的时间查看nginx配置连接网关的readtime超时时间为60s怀疑是端口占用未释放,到达60s超时断开连接后释放端口 TPS继续上升

之前配置是通过proxy直接走域名访问网关,每过来一个请求需要消耗一个端口所以尝试修改upsterm方式并开启多路复用 keepalive来保证端口 image.png

上图修改了http//openapi-gateway 并增加了upstream把网关的ip地址固定写死 压测 image.png

经过压测一段时间后TPS保持不出现断崖 与压测网关的图形保持一致。 image.png image.png

把网关的IP更换成域名方式进行压测 image.png

更换域名后压测依然出现断崖 image.png

把域名更换VIP后进行压测 image.png

断崖依然出现,所以定位到是docker 网络负载有问题,后续需要进行进一步排查 image.png

##修改swarm lb网络空间系统内核参数:(断崖的详细定位过程请参考本人另一偏文章)

conn_resue_mode=1 的bug
开启这个内核参数实际就表示 ipvs 转发时不做连接复用,每次新建的连接都会重新调度 rs 并新建 ip_vs_conn,实际在服务器完成与服务的连接后,它最终处于 TIME_WAIT 状态。该状态保持 2 分钟,然后从 conntrack 表中删除连接。如果在这 2 分钟内客户端尝试重用相同的端口,则在接收到 SYN 时,连接将从 conntrack 表中删除,SYN 不会转发到后端服务器,也不会将 ACK 发送回客户端,就会丢失第一个SYN包,在一秒钟后强制执行来自客户端的重传。这是从客户端感知的,因为服务器需要 1 秒才能响应,从而导建连性能急剧下降。conn_resue_mode=0 即启用ipvs 连接复用的能力
如果该 mode 是 0,只要有client ip:client port 匹配ip_vs_conn 就直接转发到所复用连接对应的rs上,会导致一些新建立连接被“固化”到部分rs上。使得连接不均衡,但可以提高qps性能。

该参数在docker网络命名空间中进行修改,由于上周国家电网检查,机房断电导致服务重启命名空间变更,之前的配置丢失! image.png

服务均为2个实例

然后尝试压测获取token正常业务接口正常业务接口TPS 平均为553左右,优化前只有200 image.png

服务均为4个实例

增加服务实例都为4个,压测正常业务接口正常业务接口TPS 平均为821左右(服务都为4实例) image.png

减少网关实例为2个,tps小量下降: image.png

增加网关实例为6个,增加线程数为150,tps无明显变化 image.png

查看资源使用情况: image.png

服务均为6个实例

增加服务实例都为6个,压测正常业务接口正常业务接口TPS 平均为1000左右 image.png image.png image.png image.png

服务均为8个实例

增加服务实例都为8个,压测正常业务接口正常业务接口TPS 平均为1100左右

image.png image.png

稳定性测试结果:

跑了一宿,可以看到tps平均1000左右,高点1240,系统资源情况多个宿主机出现内存资源红色预警,存在资源瓶颈 image.png image.png

环境不稳定记录:

长时间压测过程中发现tps波动非常大,不稳定,经安民排查,发现系统资源不足,导致nacos挂掉引起多服务不停的重启(由于现在增加了欣意服务,nacos服务,公共组件等,现有的8台虚拟机在长时间压测经常会出现内存不足的导致)

全链路接口: image.png

空接口 image.png

排查思路:

以下是商城压测断崖问题测试方案:
1、代码优化部署到测试5压测出现规律断崖,代码回退后依然出现规律断崖排除代码自身问题
2、nginx断崖 原一拖四 改成一拖一依然出现TPS断崖,排除一拖四架构问题
3、依据之前的nginx断崖经验,把nginx转发网关由域名修改成ip地址无效果,排除DNS解析
4、重启物理服务器尝试释放一下资源无效果
在查看skywalking与nginx日志发现时间耗时存在nginx上面
测试5于开发本地区别在nginx及docker环境,所以绕过nginx直接压测网关排除nginx问题
还是docker网络转发问题
5、运维更改配置后 绕过nginx通过ip+端口形式访问 直接压测网关TPS依然出现断崖,但断崖不会反复提升后断崖,只是开始一次断崖后趋于平稳,所以排除nginx自身问题
6、经过开发分析后是由于skywalking插件导致spring-webflux,该插件为排查问题临时添加所以线上无影响,在优化该插件后,TPS由80上升到1500
7、增加nginx继续压测后TPS又回退到了90左右此时只有一个后端nginx,nginx更改为1拖四模式后TPS提升到1500左右,但是会出现反复断崖,于是定位到nginx与docker网络负载均衡有关系
8、在经过开发与运维排查后ipvs,docker负载均衡没有问题,所以定位到nginx问题
9、在压测过程中TPS的图形低谷持续时间为1分钟,与nginx connect-time时间配置1分钟对应,怀疑端口占用无法得到释放
10、更改nginx proxypass 为upsterm,添加upstream主机为网关IP后TPS可以正常保持住不出现断崖,但服务重启ip会变动需要每次更改nginx配置

11、修改swarm lb网络系统内存参数后,断崖问题解决

12、增减网关实例,tps变化不明显

13、修改nginx 短连接为长链接,tps变化不明显

14、增减网关,鉴权,mall-api,mall-release服务,tps有明显变化,但由于资源的瓶颈,长时间压测,Tps目前平均1100左右,最大可达1300左右

测试小结:

1、目前经过优化网关线程代码后,压测获取token正常业务接口 优化前后平均TPS分别为:75、1100左右 ,时间由原来的2s多(中间会有报错超时情况)到现在200ms(无超时) ,大幅提升

2、 修改swarm 网络空间内核参数,能有效解决断崖问题