Wedge本章前两节分别重点介绍单CPU高和单内存问题的生产案例。我们也详细给大家展示了问题的排查过程，那么其实还有一个相对复杂的场景——本质上是V8引擎的GC导致的问题。简单给大家介绍一下什么是GC。GC实际上是语言引擎实现的一种自动垃圾回收机制。它会在设置的条件触发时（比如堆内存达到一定值时）检查当前堆上有哪些对象被删除了。不再使用，释放这些不用的对象占用的空间。许多现代高级语言都实现了这种机制，以减轻程序员的精神负担。本书首发于Github，仓库地址：https://github.com/aliyun-node/Node.js-Troubleshooting-Guide，云栖社区同步更新。GC带来的问题虽然上面介绍的现代语言的GC机制解放了程序员，间接提高了开发效率，但是凡事有利有弊。将GC引入底层引擎后，程序员不再需要关注对象何时释放。那么相对来说，程序员没有办法实现对自己编写的程序的精确控制，这就带来了两大问题：代码编写问题导致的内存泄漏，程序执行的性能下降，内存泄漏。我们已经在上一节中讨论了生产案例。我经历过，那么后者是怎么回事？其实理解起来也很简单：本来一个程序的所有工作就是执行业务逻辑，但是GC机制存在后，程序会一直花时间扫描堆空间，寻找不再使用的对象在某些条件下。它变相减少了程序执行业务逻辑的时间，从而导致性能下降，而性能下降与GC所花费的时间成正比，换句话说就是GC次数*所花费的时间每个GC。问题现象及原分析现在大家应该对GC有了一个比较全面的认识。在这里我们可以看到由GC引起的问题在生产中的表现。这种情况下，表面上是Node.js性能平台上监控的进程CPU达到100%，但此时服务器负载其实并不大，QPS只有100左右。我们按照上面提到的步骤以上处理CPU问题。拿CPUProfile来分析一下，可以看出这次的问题很明显是GarbageCollector太耗CPU了，也就是GC的问题。其实大部分GC机制导致的问题往往都体现在Node.js进程的CPU上。本质上，此类问题可以认为是引擎的GC导致的问题，也可以理解为内存问题。看看这种问题的产生过程如下：堆内存不断达到预设条件触发GC动作，进程不断触发GC运行过程，CPU飙升，GC问题不像问题之前由于ejs模板渲染导致的，即使我们在CPUProfile中可以看到这部分开销，但是基本不可能优化解决这个问题。幸运的是，Node.js提供了（实际上是V8引擎提供的）一系列的启动Flags，可以在进程触发GC动作时输出相关的日志，供开发者分析：--trace_gc:一行日志简单描述了时间，类型，heapsizechangeandcauseofeachGC--trace_gc_verbose:结合--trace_gc，会在每次GC后显示每个V8heap空间的详细状态--trace_gc_nvp:每次GC的一些详细的键值对信息，包括GC类型，暂停时间，内存变化等。加粗的Flag表示我们需要在启动应用程序之前添加它才能在运行时生效，这部分日志实际上是文本格式。遗憾的是，Chromedevtools本身并不支持GC日志解析和结果展示，需要自己获取并进行相应的逐行解析。当然，我们也可以使用社区提供的v8-gc-log-parser模块直接进行解析处理。对这块感兴趣的同学可以看看@joyeeCheung在JSInteractive的分享：AreYourV8GarbageCollectionLogsSpeakingToYou?，这里不再详细展开。更好的GC日志展示虽然Chromedevtools不能直接帮助我们分析和展示GC日志结果，但是Node.js性能平台实际上为你提供了更方便和动态的获取在线运行进程的GC状态信息以及相应的结果展示，换句话说，开发者在运行你的Node.js应用程序之前不需要启用上面提到的标志，但是当他们想要获取GC信息时，仍然可以通过控制台在3分钟内获取GC数据。对应这种情况，我们可以进入平台的应用实例详情页，找到GC消耗比较大的进程，然后点击GCTrace抓取GC数据：这里默认是对应进程的GC日志信息会抓取3分钟，等到最后生成的文件会显示在文件页面：此时点击转储上传到云端在线分析展示，如下图：最后点击点击这里的Analyze按钮可以看到AliNode自定义的GC信息分析结果的展示：在结果的展示中，可以很方便的看到问题过程中具体的GC次数，GC的类型，以及每次花费的时间GC，方便我们进一步分析定位。比如在这个问题的GCTrace结果分析图中，我们可以看到红圈圈出的几个重要信息：GC总停顿时间高达47.8s，其中最重要的部分是Scavenge3min。在GC跟踪日志中，一共进行了988次Scavenge收集，每次Scavenge平均耗时在50到60ms之间。从这些解决方案中我们可以看出，本次GC案例的问题集中在Scavenge回收阶段，即新生代的内存回收。那么通过阅读V8的Scavenge回收逻辑，我们可以知道这个阶段触发回收的条件是：Semispaceallocationfailed。这样可以推测，我们的应用在压测的时候应该会频繁的在新生代中产生大量的小对象，导致默认的Semi空间一直处于被快速填充的状态，从而触发Flip，这样就会GC中出现了这么多的scavengecollections以及跟踪期间相应的CPU消耗，问题就变成了如何优化新一代GC以提高应用程序性能。优化新生代的GC通过平台提供的GC数据抓取和结果分析，我们知道可以尝试优化新生代的GC，达到提升应用性能的目的，以及空间的条件新生代触发GC是因为它的空间满了，那么新生代的空间大小是通过Flag--max-semi-space-size来控制的，默认是16MB，所以我们很自然的可以想到优化调整默认半空间的值。这里需要注意的是，控制新生代空间的Flag在不同的Node.js版本下是不一样的。您可以检查当前版本以进行确认。在这种情况下，很明显默认的16M相对于当前应用来说是比较小的，导致Scavenge过于频繁。我们首先尝试在启动时增加flag--max-semi-space-size=64来设置默认新生代使用的空间大小从16M增加到64M，并在流量增加时抓取CPUProfile比较大，进程的CPU高。观察结果：调整后可以看到Garbagecollector阶段的CPU消耗比例下降到7%左右，然后抓取GCTrace，观察显示结果，确认Scavenge阶段的消耗是否下降：很明显，Semi空间增加到64M后，Scavenge次数从近1000次减少到294次，但是这种情况下每次Scavenge恢复时间并没有明显增加，仍然在50~60ms之间波动。因此，3分钟GC跟踪的总暂停时间从48秒减少到12秒。相应地，业务的QPS提升了10%左右。那么如果我们继续通过标志--max-semi-space-size来增加新生代使用的空间，是否可以进一步优化这个应用程序的性能呢？这时候试试--max-semi-space-size=128，从64M增加到128M，继续抓取CPUProfile查看进程CPU很高时的效果：此时Garbage的消耗collector相比上面设置的64M减少的不是很明显，GC消耗减少了不到1%。我们抓取GCTrace的结果观察一下，看看具体原因：很明显，与64M的设置相比，GC比率并没有增加多少。原因是：虽然这时Semi空间进一步增加到128M，而且scavenge回收次数确实从294次下降到145次，但是每次算法回收的时间增加了近一倍，所以总收益并不明显。按照这个思路，我们使用--max-semi-space-size=256进一步增加新生代使用的空间到256M，然后做最后的观察：这里和调整到128M时类似：3分钟内部清除次数从294次下降到72次，但每次算法恢复的相对耗时波动在150ms左右，因此整体性能没有明显提升。借助性能平台的GC数据抓取和结果展示，经过多次尝试提高Semi空间的值，我们可以看到Node应用的整体GC性能从默认的16M设置提升到64M，反映出压测QPS提升了10%左右；但是当Semi空间进一步增加到128M和256M时，好处并不明显，而且Semi空间本身也用于新生代对象的快速内存分配，不适合设置太大，所以这次优化最终为本项目选择了最优的runtimeSemispace值64M。End在这个生产案例中，我们首先可以看到，项目使用的三方库并不是在所有场景下都没有bug（其实这是不可能的），所以在遇到三方库解决问题的时候，一定要敢于从源码层面深入分析问题。最后，其实在生产环境中，通过GC运行时调优来提升我们项目的性能是一种不太常见的方式。这也很大程度上是因为GC状态本身并没有在应用程序运行时直接暴露给开发人员。.通过以上客户案??例我们可以看到，借助Node.js性能平台，实时感知Node应用的GC状态并进行相应的优化，无需改动一行代码即可轻松提升项目性能.本文作者：易君阅读原文，为云栖社区原创内容，未经允许不得转载。
