【摸鱼吃瓜工作录】系统突然比乌龟还慢，咋整？

AI袋鼠帝
1,428 阅读9分钟

我是「 kangarooking(袋鼠帝) 」 真心给大家分享经验和技术干货，面试次数100+。面试经验绝对丰富，也当过面试官，内容绝对用心可靠。点赞在看，养成习惯。关注me，每天进步亿点点 ❗ ❗ ❗

2022-10-10

前言

本篇主要涉及：

  1. 生产事件的发现，处理，分析过程
  2. netty的原理浅析

脱毛膏刷牙，蓝瘦

国庆收假回到深圳，开工第一天就被封控了。。。并且拿女朋友的脱毛膏当作牙膏刷牙了0_0，大无语，这脱毛膏简直和牙膏长得一模一样，又被放到了和牙膏一样的位置，挤出来也是白色，和牙膏没什么区别，刚好之前的牙膏用完了。我就挤出来开始刷牙，我刷了几下，感觉到舌头有点疼，刚开始以为是刷疼了，又刷了几下，怎么没有泡沫呢？感觉不太对劲，拿起牙膏一看--脱毛膏 ❗ ❗ ❗ 吓得我赶紧疯狂漱口，重复几十遍之后，又搞了点盐水漱口，然后用真的牙膏刷了一次牙。现在主要舌尖疼，然后舌尖没有味觉，嘴皮也有点疼。。。刚收假回来就出师不利啊。在次也告诫广大网友，一定要注意把家里面的一些东西分类放好，以免误用。特别是长得很像的物品。

1.jpg

2.jpg

生产事件现象

页面：早上10.30打开XXXX页面，请求服务端的websocket，响应很慢（响应大概30秒~3分钟不等）

功能介绍：该业务是前端先请求后端建立websocket连接，保持住长连接，后端会每隔一分钟向前端推送数据。在前端实现一个折线图的准实时展示。该websocket算是一个高并发接口，峰值会达到每秒500qps左右

3.png

逻辑梳理

要分析原因，得先搞清楚服务端的处理逻辑（netty的处理逻辑在我们实现的handler里面）：

4.png

  • 首次建立连接，会执行handler逻辑获取一次数据返回给前端，并将该channel添加到一个列表中；
  • 服务启动的时候新建了一个线程每隔一分钟循环一次列表，获取每个channel并执行handler最后返回给前端。

接下来看看handler里面干了啥：主逻辑就是http请求第三方接口，获取数据。我们为了保证可用性，以及减少对第三方接口的并发压力，做了以下优化：

  • 使用aop对调研第三方接口的方法做缓存处理，缓存过期时间30秒，key=固定前缀+code：

5.png

  • 另外有一个同步服务，定时同步全量第三方数据到我们的redis缓存，如果handler中请求第三方接口的方法返回空，那么就从redis缓存获取数据返回。防止第三发接口异常导致服务不可用。

注：采用这种方案是基于第三方提供数据方式的局限性而设计的。

排查过程

服务端：

  • 在日志平台按照过去6小时查询error日志，只有几十个（都是timed out，调用第三方接口超时），总请求量上万，所以这个超时也是在合理范围内；

  • 查看第三方接口响应速度，基本都在200ms左右（也是比较快的）；

  • 查看第三方接口的访问评率日志：并发大概到了每秒200qps左右，峰值500qps左右；

  • 查看容器资源消耗情况（cpu，内存，网络等）都在正常范围；

  • 友商的服务器也运行正常。

这样看起来整个业务逻辑逻辑处理是比较快的，也没有什么明显的报错信息。

问题定位

由于事发前一天刚升级完一个版本，所以考虑是版本里面的改动导致了这个问题。

查看本次版本修改的代码，查询到开发同事做缓存aop优化，不小心将方法上的缓存注解去除了。该注解作用：调用第三方接口方法，先去缓存里面找数据，没有的话，请求第三方接口获取数据后放入缓存，后面的请求都从缓存里面获取数据，缓存过期时间30s。

没有缓存注解的话，每次请求都是直接走第三方http接口远程访问，获取数据。

查看日志，调用第三方接口的方法处理速度有无缓存的对比（速度上相差了近100倍）：

  • 有缓存：2ms左右返回数据；

  • 无缓存：200ms左右返回数据；

紧急处理：回滚镜像版本，响应慢的问题就消失了（回滚镜像之前我们在配置中心将该功能临时影藏关闭了，所以，对于一些锦上添花的功能，我们在设计之初就可以预留一个开关，当它有问题的时候舍弃它，从而不会对主功能造成影响，或者不会对用户造成困扰，并且能够在出问题的时候快速降级解决）。

处理完毕之后，当天下午也召开了会议：问题汇报以及后续的改进措施汇报等

分析原因

现在看起来问题就出在无缓存上面。

先分析主观原因：

  • 业务处理速度相比之前慢了（因为不使用缓存的话处理速度比原来慢了100倍）；
  • 上午并发量较大（有缓存的情况，并发量大也不会出现响应很慢的问题）。

到这里，有两个猜测：

  1. 没有缓存，导致产生大量的http请求，连接池占满。
  2. 猜测是处理速度变慢，并发又大导致某个地方排队等待。并且沿着这个猜测方向，在网上找到了相应的文章：blog.csdn.net/rubulai/art…

分析过程：

1.排除因为大量http请求碟蜂接口，连接池占满或者消耗服务器资源的情况。

通过将http请求逻辑修改为线程睡眠200ms，发到测试环境进行压测，也能复现问题。并且当时生产环境排查的时候查看cpu，内存，网络等资源消耗都处于一个正常范围。

通过第一个测试复现就定位到主要是http请求相比之前的读缓存慢了100倍左右造成的

2.把worker线程设置为1个，在本地也可以很容易的复现（因为master的代码是没有设置worker线程数的，所以默认是cpu核数的两倍，本地电脑不设置的话就会有24个worker线程，所以导致需要更高的并发量才可能复现，为了复现方面，就把worker线程数设置为1）。

在业务代码里面线程睡眠20s，并打印开始睡眠和睡眠结束的日志。客户端A请求连接，等A请求在睡眠时，我们发出B请求。通过之前预设好的netty源码断点，分析出：这时B请求可以与netty建立连接，但是不能得到响应。由于只有1个worker线程，它还在业务代码里面睡眠，所以B请求只能等A请求处理完之后才能被处理。可以看到现象就是A请求睡眠完毕之后，立马就打印了B请求开始睡眠的日志。

结论

深层次原因：

netty的handler里面处理耗时任务，导致io线程处理任务的速度比任务生产的速度慢。从而导致请求堆积，处理不过来。最后产生的现象就是页面请求后，过了很久才能收到响应数据。

//初始化连接监听线程组(这里值是1，表示一个线程来监听连接事件) 
bossGroup = Epoll.isAvailable() ? new EpollEventLoopGroup(1) : new NioEventLoopGroup(1);
//初始化读写时间监听线程组(这里没有设置初始大小，默认是当前cpu核数*2)
workerGroup = Epoll.isAvailable() ? new EpollEventLoopGroup() : new NioEventLoopGroup();

生产容器环境分配的是2核，所以一个pod中worker线程组里面有4个线程，boss线程组有1个线程。

boss group负责监听连接，并将建立连接得到的channel绑定到worker group中的线程。

worker group负责监听read/write事件，并进行后续处理。

6.png

结论： 我们业务处理逻辑在netty的handler里面，所以worker线程监听到read事件之后，往下执行会处理业务代码逻辑。处理完之后才能循环回到监听事件处，这个过程是同步阻塞的。

如果请求太多，并发大，并且业务代码耗时，就会导致4个worker线程在handler里面的处理速度跟不上读写事件产生的速度，最后导致请求积压，当前请求要等待前面的请求处理完才轮到它，所以就导致了前端响应慢的问题。

优化思路

恢复缓存注解的同时，另启一个业务线程池来执行handler里面的业务代码（线程池大小需根据业务实际并发压测后得出一个性能最优的配置），防止handler业务代码出问题的时候阻塞netty io线程的工作。

注：另起一个业务线程池来执行业务逻辑，最后writeAndFlush()

在netty里面也是会交给netty自身的io线程来执行，也就是业务代码是非netty线程池执行，但是最后向客户端回写数据还是会由netty 线程来完成。

可参考：blog.csdn.net/rubulai/art…

netty学习

最后说下，这篇没有详细介绍netty的原理，因为我看了网上很多有关netty的博客，我感觉我花大量精力也不一定能比他们写的好，但是我后面还是会出一篇netty的文章，从不同的角度来解析一下，希望能给大家带来一定的帮助。排查问题我也是重新复习了一下netty的源码，打断点不断调试，从源码寻找答案。还是那句话，看源码要带着问题去看，带着想了解的点去看，比如你想了解netty的boss线程是怎么将新建立的channel绑定到worker线程的等，带着问题去看重点，否则就是看的一头雾水，蒙圈。

最后大家也可以针对这种，粗心大意改错代码的问题，出出主意，后续如何避免。

7.png

微信公众号「 袋鼠先生的客栈 」，有问题评论区见。如果你觉得我的分享对你有帮助，或者觉得我有两把刷子，就支持一下我这个干货writer吧，三连，三连，三连就是我最大的动力~，持续分享干货。点赞👍 关注❤️ 分享👥

avatar
文章
阅读
粉丝