大的软件公司里总是会出现这么一些做吃力不讨好工作的团队: 拆迁队. 他们的一段时期内的主要工作就是把原有的业务从旧的平台/框架, 迁移到新的平台/框架. 为什么? 因为软件行业里总是会出现新的框架, 基础软件更新, 比如从 Python 2.x 迁移到 3.x, Spring 从 1.x, 2.x 迁移到 Spring IO, 从物理服务器迁移到虚拟机, 然后迁移到Kubernetes, 又或者从关系型数据库迁移到NoSQL, 图数据库, 列数据库等. 更新软件平台/框架不仅能让公司的代码随着时代前进, 还能让开发者的知识保持跟业界同步.

当然, 迁移也是有成本的. 人力成本是一项重大支出, 另一个大家不容忽视的是: 在迁移的过程中, 总会遇到一些看上去很诡异的问题.

这个系列的文章将向大家展示我们在迁移的过程中遇到的一些有趣的问题.

问题发现

最近新迁移了一个应用, 这个应用迁移到新的平台之后, 所有的系统指标, 业务指标基本没变动. 唯一的一个让人担心的变动是: 在某些时候, 它的应用服务器 Tomcat 的忙碌线程数(active count)会达到顶峰.

Tomcat 的忙碌线程数表示某个时刻, Tomcat 正在处理的请求的数目. 比如一个请求平均的响应时间是100毫秒, 那么一个 Tomcat 线程一秒钟能响应10个这样的请求. 假如每秒收到的请求数都是小于或等于10个, 那么我们只需要一个忙碌的 Tomcat 服务线程. 若一秒钟平均匀速来了15个, 那么只需要2个忙碌的 Tomcat 服务线程就好了. 但是如果他们同时来15个请求, 为了最快响应客户的请求, 我们就需要15个 Tomcat 服务线程同时忙碌, 来让客户满意. 当然, 我们也可以设置最多同时有10个并发响应的客户的请求, 另外5个放到等待队列里面, 等待有空闲的的服务线程空出来.

对于我们迁移的这个应用, 它的处理能力确实很强, 平均的处理时间大概只有几十毫秒, 每秒的请求数量也不小. 它平时的 Tomcat 忙碌线程数只有3到8. 对于这个应用, 我们设置的最大 Tomcat 并发服务线程数是80, 平时绝对达不到这个水平.

可是迁移到新的平台后, 它平时的 Tomcat 忙碌线程数也只有3到8区间, 可是某些时候, 它竟然会在短时间内达到惊人的80, 这直接导致告警发出.

症状

从上面的图中可以看到, 有很多服务器在某些短暂的瞬间突然达到80, 持续很短的时间, 然后又恢复正常. 还有一些没有达到最高80, 但是也是瞬间上升, 然后又很快恢复了平静.

我们选取了其中一台, 观察它3个小时的变化, 如下图:

可以看到它在这3个小时内, 有1次冲顶, 很快恢复.

要想找到其中的原因, 我们先看它的其它指标. 我们从众多的其它指标中筛选出跟这次冲顶行为可能相关的数据有如下几个指标:

1. tps 很有规律, 大概十几分钟的降低, 然后十几分钟的升高, 整个过程中保持这个趋势.
2. latency 大概保持在20ms以内, 偶尔有些到达30多毫秒, 不过当 Tomcat 忙碌线程数达到80的时候, 它稍许有些升高.
3. CPU 的使用率维持跟 tps 一样的趋势.
4. GC overhead 和 JVM 可用内存指标保持一致, 因为二者强相关. 虽然这里可以看到2次内存的强力回收, 不过只有第一处和我们看到的 Tomcat 忙碌线程数相关.

初步推理

从已有的这些数据来看, 这次 Tomcat 忙碌线程数跟第一处的 GC 内存回收很有可能有很强的关系. 于是我们去查找第一处内存回收时候的 GC 日志, 从日志可以看到, 这2次都是 G1 的 Full GC, 也就是较长的 Stop the world 停顿.

第一次:

第二次:

那么如何解释第一处, 产生了 Tomcat 服务线程数冲顶, 而第二次却没有呢? 原因在于我们收集指标的频率, 从上面 2 次 Full GC 的截图可以看到, 2次 Full GC 大概持续的时间是3秒多一点, 而我们 Tomcat 服务线程数的收集频率是每分钟一次, 也就是说有大概 3.77/60 的概率在采集数据的时候碰到这个时间段, 其余时间碰到的概率偏小. 另外, 可以看到请求的平均延迟在20毫秒, 也就是说最多有 (3770 + 20) / (60 * 60 * 1000) = 0.001054 的概率, 这个可能性还是偏小. 当碰到这个区间的时候, 前面3.77秒因为 Stop the world 没法采集到数据, 只能等停顿完成后才能拿到这个数据.

另外一个奇怪的状况是: 这次迁移, 应用程序基本都没有改动, 应用程序的这些指标除了 Tomcat 忙碌服务线程数的冲高有变化之外, 其它的所有指标都是和之前一模一样的. 那么大家自然而然的怀疑是环境的变动导致的.

那么到底是环境的那个因素导致了这个变化呢?

找到元凶

事情发展到这里, 不得不回答一个问题: 为什么迁移之前没问题.

迁移之前如果遇到 Full GC, 应用程序是怎么反应的? 它为什么没有在 Full GC 之后大量处理请求? 很有可能就是在 Full GC 之后, 它并没有那么多的请求需要处理.

什么情况下不会堆积大量的请求呢? 就是应用在 Full GC 期间不会收到大量的请求堆积. 也就是说给它转发请求的负载均衡服务器不会在此期间继续给它发送请求.

于是我们想到负载均衡服务器最常见的2种策略: Round Robin 和 Least Connection. 当采用 Round Robin 的时候, 负载均衡服务器不管现有的连接数, 平均的给后面的每台应用服务器发送请求. 当采用 Least Connection 的时候, 它会考虑现有的连接数, 谁的连接数最少, 新来的请求就发送给谁.

所以, 根据我们上面的推断, 新的环境采用的应该是 Round Robin, 而老的环境(迁移之前)使用的是 Least Connection. 于是分别查看新老环境的负载均衡服务器的配置, 果然是猜测的情况.

原因找到, 下一步就是对症下药.

思考

虽然找到了原因, 但是过程并不是那么直接顺利. 有些东西还是需要更多的思考.

请求堆积量的计算

假如tps按照200计算, latency 按照20ms 计算, 假设理想情况下都是顺序匀速来的请求, 那么每个服务线程每秒可以处理1000/20=50个请求, 那么就需要200/50=4个服务线程.

某个瞬间开始 Full GC, 那么将会有4个请求受到影响, 本来应该在20ms完成, 请求处理已经开始, 还没结束, 就要经历长达3.77秒的 Stop the world 停顿.

又假设在这长达3.77秒的停顿期间, 负载均衡服务器还是按照 Round Robin 策略继续给它发送请求. 虽然这时整个Java进程的非GC 线程都进入的停顿, 但是操作系统负责接受连接的内核进程还在继续工作, 它不属于该Java进程, 它会把监听端口设置的 connection backlog 一点点填满. 在这3.77秒的窗口内, 按照之前发送的速率, 负载均衡服务器会发送大概 3.77 * 200 = 7540 个请求. 但是一般监听端口的 connection backlog 不会设置这么大. 我们服务器设置的是100, 所以, 在此期间, 这100个 backlog 都填满了. 之后还有的连接只会多次连接重试, 然后失败.

当3.77秒的 Stop the world 结束之后, 应用服务器的服务线程开始工作. 发现连接 backlog 里面竟然这么多等待的请求, 于是全部服务线程开始工作, 于是设置的最大值80开始发挥作用, 80个服务线程全部运转起来. 虽然堆积了100个请求, 但是基本40ms 之内就全部干完了. 所以能看到80个服务线程同时工作的时间区间也只有 Full GC 刚结束后的短短20ms. 接下来的20ms虽然也比较多, 大概20多个, 相对来说已经不算多.

当然上面的计算都是按照理想情况下计算的, 实际情况没有这么平均, 也有可能某些时候发送的请求多一些, 有时候少一些, 所以, 我们也能看到有些时候服务线程数大概是30~40左右.

假如负载均衡服务器和应用服务器维持长连接呢?

在长连接的情况下, 只有当对应请求的回应(response)发送完之后, 负载均衡服务器才会发送下一个请求. 在平时的情况下, 它会维持4个连接(理想均匀的情况下), 在 Full GC 期间, 如果使用 Round Robin 它会创建更多的连接, 并且由于服务器虽然收到了连接, 只是把连接放到了 connection 的backlog, 没有真正的服务器线程去取请求做处理, 所以, 它会把监听端口设置的 connection backlog 填满, 之后再也连接不上.

逻辑推理的问题

我们在一开始就看到了 Tomcat 忙碌服务线程数的暴涨, 从这个暴涨应该能推理出某个时刻它的请求堆积. 请求的堆积很有可能是2个方面的问题:

1. 服务变慢;
2. 请求突然变多;

然而我们一开始花费了大量的时间在第一种情况上. 其实第一种情况下, 应该很容易看到 latency 变长, 然而这和看到的并不匹配. 于是才花时间到第二种情况, 导致花费将近2个小时才知道真正的原因.