服务启动过程性能波动的分析与解决方案

图片来源：https://images.unsplash.com/photo-1611087889903-b4837b46857c?crop=entropy&cs=tinysrgb&fm=jpg&ixlib=rb-1.2.1&q=80&raw_url=true&ixid=MnwxMjA3fDB8MHxwaG90by1wYWdlfHx8fGVufDB8fHx8&auto=format&fit=crop&w=2070

作者：浩然

1. 前言

• 本文仅分享自己在工作中遇到的问题时的解决方案和思路，以及排查的过程。重点还是分享排查的思路，知识点其实已经挺老了。如有疑问或描述不妥，欢迎赐教。

2. 问题表象

• 在工程启动的时候，系统的请求会有一波超时，从监控来看，JVM 的GC（G1） 波动较大，CPU波动较大，各个业务使用的线程池波动较大，外部IO耗时增加。系统调用产生较多异常（也是由于超时导致）
• 发布过程中的异常次数：

3. 先说结论

• 由于JIT的优化，导致系统启动时触发了热点代码的编译，且为C2编译，引发了CPU占用较高，进而引发一系列问题，最终导致部分请求超时。

4. 排查过程

其实知识点就放在那里，重要的是能够将实际遇到的问题和知识点联系到一起并能更深刻的理解这部分知识。这样才能转化为经验。

4.1 最初的排查

• 我们的工程是一个算法排序工程，里面或多或少也加了一些小的模型和大大小小的缓存，而且从监控上来看，JVM 的GC 突刺和 CPU 突刺时间极为接近（这也是一个监控平台时间不够精准的原因）。所以在前期，我耗费了大量精力和时间去排查JVM，GC 的问题。

• 首先推荐给大家一个网站：https://gceasy.io/ ，真的分析GC日志巨好用。配合以下的JVM参数打印GC日志：

-XX:+PrintGC 输出GC日志
-XX:+PrintGCDetails 输出GC的详细日志
-XX:+PrintGCTimeStamps 输出GC的时间戳（以基准时间的形式，你启动的时候相当于12点，跟真实时间无关）
-XX:+PrintGCDateStamps 输出GC的时间戳（以日期的形式，如 2013-05-04T21:53:59.234+0800）
-Xloggc:../logs/gc.log 日志文件的输出路径

• 因为看到YGC严重，所以先后尝试了如下的方法：
• 调整JVM 的堆大小。即 -Xms, -Xmx 参数。无效。
• 调整回收线程数目。即 -XX:ConcGCThreads 参数。无效。
• 调整期望单次回收时间。即 -XX:MaxGCPauseMillis 参数，无效，甚至更惨。
• 以上调整混合测试，均无效。
• 鸡贼的方法。在加载模型之后sleep 一段时间，让GC平稳，然后再放请求进来，这样操作之后GC确实有些好转，但是刚开始的请求仍然有超时。（当然了，因为问题根本不在GC上）

4.2 换个思路

• 根据监控上来看，线程池，外部IO，启动时都有明显的RT上升然后下降，而且趋势非常一致，这种一般都是系统性问题造成的，比如CPU，GC，网卡，云主机超售，机房延迟等等。所以GC既然无法根治，那么就从CPU方面入手看看。
• 因为系统启动时JVM会产生大量GC，无法区分是由于系统启动还没预热好就来了流量，还是说无论系统启动了多久，流量一来就会出问题。而我之前排查GC的操作，即加上了sleep时间，恰好帮我看到了这个问题，因为能明显的看出，GC波动的时间，和超时的时间，时间点上已经差了很多了，那就是说，波动与GC无关，无论GC已经多么平稳，流量一来，还是要超时。

4.3 分析利器Arthas

不得不说，Arthas 真的是一个很好用的分析工具，节省了很多复杂的操作。

• Arthas 文档：https://arthas.aliyun.com/doc/quick-start.html
• 其实要分析的核心还是流量最开始到来的时候，我们的CPU到底做了什么，于是我们使用Arthas分析流量到来时的CPU情况。其实这部分也可以使用top -Hp pid , jstack 等命令配合完成，不展开叙述。
• CPU情况：

图中可以看出C2 CompilerThread 占据了非常多的CPU资源。

4.4 问题的核心

• 那么这个C2 CompilerThread 究竟是什么呢。
• 《深入理解JAVA虚拟机》其实有对这部分的叙述，这里我就大白话给大家解释一下。
• 其实Java在最开始运行的时候，你可以理解为，就是傻乎乎的按照你写的代码执行下去，称之为"解释器"，这样有一个好处，就是很快，Java搞成.class ，很快就能启动，跑起来了，但是问题也很明显啊，就是运行的慢，那么聪明的JVM开发者们做了一件事情，他们如果发现你有一些代码频繁的执行，那么他们就会在运行期间帮你把这段代码编译成机器码，这样运行就会飞快，这就是即时编译（just-in-time compilation 也就是JIT）。但是这样也有一个问题，就是编译的那段时间，耗费CPU。而C2 CompilerThread，正是JIT中的一层优化（共计五层，C2 是第五层）。所以，罪魁祸首找到了。

5. 尝试解决

• 解释器和编译器的关系可以如下所示：

• 就像上面说的，解释器启动快，但是执行慢。而编译器又分为以下五个层次。

第 0 层：程序解释执行，默认开启性能监控功能（Profiling），如果不开启，可触发第二层编译；
第 1 层：可称为 C1 编译，将字节码编译为本地代码，进行简单、可靠的优化，不开启 Profiling；
第 2 层：也称为 C1 编译，开启 Profiling，仅执行带方法调用次数和循环回边执行次数 profiling 的 C1 编译；
第 3 层：也称为 C1 编译，执行所有带 Profiling 的 C1 编译；
第 4 层：可称为 C2 编译，也是将字节码编译为本地代码，但是会启用一些编译耗时较长的优化，甚至会根据性能监控信息进行一些不可靠的激进优化。

• 所以我们可以尝试从C1，C2编译器的角度去解决问题。

5.1 关闭分层编译

增加参数 ： -XX:-TieredCompilation -client （关闭分层编译，开启C1编译）

• 效果稀烂。
• CPU使用率持续高水位（相比于调整前）。确实没了C2 thread 的问题，但是猜测由于代码编译的不够C2那么优秀，所以代码持续性能低下。
• CPU截图：

5.2 增加C2 线程数

增加参数 ：-XX:CICompilerCount=8 恢复参数：-XX:+TieredCompilation

• 效果一般，仍然有请求超时。但是会少一些。
• CPU截图：

5.3 推论

• 其实从上面的分析可以看出，如果绕不过C2，那么必然会有一些抖动，如果绕过了C2，那么整体性能就会低很多，这是我们不愿看见的，所以关闭C1，C2，直接以解释器模式运行我并没有尝试。

6. 解决方案

6.1最终方案

• 既然这部分抖动绕不过去，那么我们可以使用一些mock 流量来承受这部分抖动，也可以称之为预热，在工程启动的时候，使用提前录制好的流量来使系统热点代码完成即时编译，然后再接收真正的流量，这样就可以做到真实流量不抖动的效果。
• 在系统正常运行的过程中采集部分流量，并序列化为文件存储下来，当系统启动的时候，将文件反序列化为请求对象，进行流量重放。进而触发JIT的C2 compile，使CPU的波动在预热期间内完成，不影响正常的线上的流量。

6.2先放结果

• 预计每次发布减少10000次异常请求（仅计算异常不包括超时）。
• 减少因搜索导流带来的其他业务的营收损失。
• 其他相关搜索的引流操作均减少每次发布10000次请求的损失。
• 异常的减少情况：

• RT 的变化情况：

• 整体变化，可以监控系统上来看，对比两次发布过程中的RT变化，发现经过治理之后的系统，发布更加平稳，RT基本没有较大的波动，而未经过治理的接口RT较高：

6.3 预热设计

6.3.1 整体的流程表示

• 下图表达了正常线上服务时候顺便采集流量的流量采集过程，以及当发成重启，发布等操作时候的重播过程。

6.3.2 对其中的细节解释

• ①：排序系统接收不同的code的请求（可以理解为不同的业务的请求），在图中，不同的请求以不同的颜色标记出来。

• ②：表达排序系统请求的入口，虽然内部都是链式执行，但是对外的RPC是不同的接口。

• ③：此处使用的AOP是Around方式来完成的，设计了特定注解来减少warmup操作对既有代码的入侵。此注解放置在入口的RPC实现处，即可自动采集请求信息。

• ④：表达的是排序系统的流式编排系统，对外有不同的RPC的接口，但是其实内部最终都使用flowexecutor.run 来实现不同业务的不同链路的串联和实现。

• ⑤：AOP中使用异步存储的方式，这样可以避免因为warmup在采集流量的时候影响正常请求的RT，但是这里需要注意的是，这里的异步存储一定要注意对象的深度拷贝，否则将会出现很奇怪的异常，因为后续的链路中。排序系统都是拿着Request对象来操作的，而warmup的异步操作由于文件等操作会略慢，所以如果Request对象已经被变动之后再序列化下来下次使用，就会因为已经破坏了原始的请求导致下次启动时warmup会有异常。所以在AOP中也进行了深度拷贝的操作，使得正常的业务请求和warmup序列化存储操作的不是同一个对象。

• ⑥：最初的AOP设计其实是使用的before设计的，也就是不关心执行的结果，在Request到来的时候就将流量持久化下来。但是后来发现，由于排序系统中本身就存在之前遗留的bug，可能有些请求就是会产生异常，如果我们不关注结果，仍然将可能触发异常的请求记录下来，那么预热的时候可能会产生大量的异常，从而引发报警。所以，AOP的切面由before调整为了Around，关注结果，如果结果不为空，才将流量序列化并持久化存储下来。

• ⑦：序列化之后的文件其实是需要分文件夹存储的，因为不同的code，也就是请求不同的业务RPC的时候，Request的泛型是不同的，所以需要加以区分，并在反序列化的时候指定泛型。

• ⑧：最初的设计是单线程完成整个预热操作，后来发现速度太慢，需要预热12分钟左右，且排序系统机器较多，如果每组都增加12分钟是不可接受的。所以采用多线程方式预热，最后缩短为3分钟左右。

• ⑨：发布系统的发布方式其实是不断的调用check接口，如果有返回了，则表示程序启动成功，接下来会尝试调用online接口完成rpc，消息队列等组件的上线，所以修改了原有的check接口，由无意义的返回“ok”，调整为测试warmup流程是否完成。如果没完成则抛出异常，否则返回ok，这样既可完成在online之前，也就是接收流量之前，完成warmup，不会发生warmup还没结束，流量就来了的情况。

7. 最后

• 本文描述了为一个系统设计预热的原因，结果以及期间遇到的各种细节的问题。最终上线取得的效果还是较为可观的，解决了每次发布时候的疯狂报警和真真实实存在的流量的损失，重点在于分享排查及解决问题的思维，遇到类似问题的同学们或许可以结合自己公司的发布体系来实现这套操作。
• 在整个的开发和自测过程中，着重关注以下的事项：
• 是不是真的解决了线上的问题。
• 是否引入了新的问题。
• 预热的流量是否做了独特的标识以避免预热部分流量的数据回流。
• 如何和公司既有的发布体系进行较好的契合。
• 怎样能够减少入侵性，对本工程其他的开发者以及系统的使用者做到完全无感知。
• 是否能做到完全不需要开发人员关注warmup，能够全自动的完成整套操作，让他们根本不知道我上线了一个新功能，但是真的解决了问题。
• 如果预热系统出现问题是否能够直接关闭预热来保障线上的稳定性。

8. 参考文章

• 【关于java：-XX：-TieredCompilation到底做什么】https://www.codenong.com/38721235/
• 【好像是上面那篇文章的原版】https://stackoverflow.com/questions/38721235/what-exactly-does-xx-tieredcompilation-do
• 【C2 Compiler Thread】https://blog.csdn.net/chenxiusheng/article/details/74007750
• 【C2 CompilerThread9 长时间占用CPU解决方案】https://blog.csdn.net/m0_37886429/article/details/105139611
• 《深入理解Java虚拟机第二版》第四部分的“晚期(运行期)优化”
• 【深入分析JVM中线程的创建和运行原理 ｜｜ JIT（future）】https://www.cnblogs.com/silyvin/p/10228184.html
• 【HotSpot虚拟机的分层编译（Tiered Compilation）】https://blog.csdn.net/u013490280/article/details/108522427

本文发布自网易云音乐技术团队，文章未经授权禁止任何形式的转载。我们常年招收各类技术岗位，如果你准备换工作，又恰好喜欢云音乐，那就加入我们 grp.music-fe(at)corp.netease.com！