记一次React直出服务CPU阶梯性上升的排查

[HexMox]

记一次React直出服务CPU阶梯性上升的排查

前段日子，忙忙碌碌地搞了个基于React&Redux的同构直出服务，终于上线了。没想到上线的运营问题更让人爆炸，各种监控问题及性能问题，被leader问起来也只能给个不太好看的数据或者模糊的回答。作为一个前端伪全栈工程师，在如何打造高可用，高性能的服务上确实欠缺一些实践经验，还需努力学习。

前言

由于身处于鹅厂，各种监控体系较为健全，且团队在Node上有着较深厚的积累，写代码的时候不需要操心太多。直出服务上线前就接入了各类基础监控，比如：

• 服务器单机属性监控（CPU，内存，IO等）
• monitor自定义量监控
• 直出服务日志
• ...

一开始直出服务灰度上线运行后，CPU偶尔会出现高负载告警，频率大概是两、三天一次。后面迫于进度压力全量时，由于机器数量不是很足，出现的频率更高了一点。当然还有一些其他小问题，这里不予讨论。

从上面两张图可以看出CPU呈现阶梯性上升的趋势（高处直接降为0的情况是我手动重启处理的表现）。

排查过程

只看到表象

在服务灰度过程中，第一次CPU过高告警，因为是现网环境我略微感到紧张马上登录内部运维系统重启服务或者上机器把进程给kill掉了（类似pm2等工具会有进程保护机制，一台机器上运行若干个服务进程，kill掉CPU负载高的子进程会自行重启）。在后续回溯问题的过程中，先查看的是关于流量的监控：

上面是某日CPU平均值24小时图，可以看到10点左右CPU使用率有一次迅猛上升，并维持在一个较高的值。结合当时的进入量上报图：

上面是当日内部安全系统扫描的量，可以看到服务刚上线不久，收到现网流量后，安全系统就开始疯狂扫描服务了。当时刚发生的时候，结合两个图初步认为是因为是请求量过大导致的CPU上升（当时做过简单压测React同构服务性能较差，并且灰度期间部署的机器还少）。

被其他问题所干扰

实际上灰度时服务问题也比较多，当时影响CPU上升的因素主要还有内存泄漏（本篇暂时不深入讨论，后面会有另一篇文章）。由于是同构应用，服务器运行的代码中夹杂着经过构建编译生成的前端代码，有部分依赖的开源模块代码也没看过，有的协同者工作经验不足甚至没有这样的意识，讲道理还是很慌的。有几次CPU告警确实是因为内存爆掉引起服务频繁GC导致的。

上图是某机器内存使用大小24小时图，明显可以得到内存已经爆掉的结论（机器上还运行着其他服务），后面内存的断崖式下降是重启操作，而且能看到重启后也迅猛上升。

注意到阶梯性上升后

解决掉一些灰度出现的内存，性能问题后，服务扩大灰度比例并稳定运行了一段时间，这时候终于发现了上面所说的CPU阶梯性上升的现象。所幸可以隔两三天重启一次服务暂时hold住，并且Nginx层做了一层降级异步的逻辑，要不然我可能就要失业了。

调整下心态慢慢思考这个现象，Node服务引起CPU高的常见原因无非就是：

1. 内存泄漏导致频繁GC
2. 阻塞IO
3. setTimeout之类的定时器
4. 复杂计算逻辑

根据上图结合当日的内存使用大小、磁盘IO图来看，明显不是内存和IO引起的，且就算单单从CPU图来看，也与请求量大小的监控图不匹配。所以比较大的可能是第3、4点原因，继续深究。

第一次尝试：Code Review

像这类CPU上升一个阶梯后基本没有再下降过，看起来真的很想是触发了某个隐藏的setTimeout或者setInterval逻辑导致吃掉一部分CPU资源。所以一开始我就在代码中全局搜setTimeout/setInterval/setImmediate之类的（当然还搜了process.nextTick）：

但是Review完后并没有什么收获，要不就是放在componentDidMount里走SSR的话逻辑不会运行，要不就是拆成异步包加载的逻辑。从监控图感觉第三点是最有可能，难道这部分逻辑会在依赖的开源模块中吗？那这个就很蛋疼了，毕竟看第三方的模块代码比较耗时且不一定有收获（我引入的模块我还是会评估一下的）。既然这条路暂时走不通，就换一个思路吧。

第二次尝试：本地复现

早期压测的时候，就没有复现过CPU阶梯性上升的情况。从监控图看，每个阶梯CPU上升时所经历的时间也是不确定的，非常像是由于请求参数数据不同触发了某个隐藏逻辑导致的。所以看起来只能从现网的流量日志中捞取数据来重现，毕竟我们已经知道CPU上升大概的时间点。虽然线上的流量比较大，但是捞取上升时间点左右2分钟的数据还是可以接受的，于是我们上机器把日志捞下来（日志目前的能力相对弱一点，其实有日志系统但不是很好用）：

# cd /path/to/server/logs/
# 不太熟悉linux，应该有更高效的捞取方法，请多多指教
grep "2018-12-19T01:0[1-5]:00" | grep -o -E "GET /course/[0-9]+" | grep "[0-9]+" | uniq > ./temp

拉取下来后，写一个简单的脚本：

const path = require('path');
const fs = require('fs');
const http = require('http');

function request(cid) {
  return new Promise(resolve => {
    http
      .get(
        {
          port: 6001,
          path: `/course/${cid}`,
          headers: {
            Host: 'm.ke.qq.com',
            'User-Agent':
              'Mozilla/5.0 (iPhone; CPU iPhone OS 11_0 like Mac OS X) AppleWebKit/604.1.38 (KHTML, like Gecko) Version/11.0 Mobile/15A372 Safari/604.1'
          }
        },
        res => {
          resolve();
        }
      )
      .on('error', e => {
        console.error(e);
      })
      .end();
  });
}

fs.readFile(path.resolve(__dirname, 'temp'), 'utf-8', (err, content) => {
  if (err) {
    throw err;
  }

  const cids = content.split(/,|\r|\n|\r\n/).filter(x => !!x);
  const execute = () => {
    console.log('left ', cids.length);
    if (!cids.length) {
      return;
    }

    const cid = cids.shift();
    console.log('requesting cid', cid);
    request(cid).then(() => {
      execute();
    });
  };

  execute();
});

奈何尝试了很多次也没重现，包括使用了一些压测工具（比如ab等）。

第三次尝试：调试工具

其实上一步已经非常接近真相，奈何陷入迷局看不清。CPU问题已经持续几周了，每几天重启一次服务也不是办法，既然本地无法重现，那就直接上服务器调试吧！！！

参考一些文章之后，先打算用linux系统分析工具perf看下（其实对perf不是非常了解，仅仅是通过搜索结果简单学习了下），因为对Node进程本身没有任何影响：

# 不知道为何我们的机器perf不支持--call-graph
perf top --call-graph -p [pid]
perf record -g -p [pid]

但是得到的结果没有很大的参考价值，google了一下finish_task_switch像是CPU上下文切换之类的操作：

于是我简单得出perf无法分析到Node进程内部函数维度的调用消耗（别的文章实践貌似可以），还是node官方的profile手段靠谱，看来不得不发布一次了，于是我改了服务的启动命令进行了灰度发布：

# args指内部Server框架的其他参数
node --prof [...args] app.js

稳定运行一天之后，果然在这台机器复现了CPU阶梯性上升的现象。于是将数据从服务器拉下来分析：

# 处理上面的log文件得到
node --prof-process isolate-0xnnnnnnnnnnnn-v8.log > processed.txt

• Builtin: StringPrototypeReplace指的就是调用了String类型的replace方法
• components/course.js标注出了吃CPU的源码位置

分析到这里，就可以明显的看出引起CPU的函数调用是哪个了，回去源码一看，那个函数调用了很多次replace呀，不过第一个参数都是正则，灵机一动立马去google了一下正则、CPU关键词，果然得到了结论——Catastrophic Backtracking。

在参考资料里面的文章提到：

Nested quantifiers are repeated or alternated tokens inside a group that is itself repeated or alternated. These almost always lead to catastrophic backtracking.

翻译过来就是：嵌套的分组中存在多个带有重复限定词的标记且此分组本身也带有重复限定词时，几乎总是会发生灾难性回溯

而带着这个解释查看这个函数使用的正则表达式，立马揪出很可以的一条：

// 注意看([^>a-zA-Z0-9_:\.\-]+[^>]*)*
const REGEXP_ATTR_TAG = /<(\/)*([a-zA-Z0-9_:\.\-]+)([^>a-zA-Z0-9_:\.\-]+[^>]*)*>/gi;

在https://regex101.com/上试了一下，确实会发生这样的事情：

终于找到问题所在，太好了，立马修复了一个版本发布了。剩下的就是找出现网能复现的请求了，再回去机器上捞日志，不可能没有呀，结果偶然对匹配计算了一下数量：

觉得不对呀，为什么有个进程匹配的数量是0呢？随即一想就通了，请求一过来这个进程立马就吃满CPU卡死了，而本机日志的写是异步的，所以一旦发生就不可能写下来。[大哭]这大概就是没去日志系统捞日志的后果吧，比较机器上的日志服务是一个独立进程，不受服务进程的影响。接下来就简单了，既然服务日志不行，那去捞一下Nginx日志不就得了，果然复现了。给一个现网的数据例子：

总结

2018年了Node也不是当年刚出来的被诟病的玩具语言了，其本身及相关的生态中有非常多的调试工具，面对此类问题我也总结了一个简单的方法思路，仅供参考，当然能不写出这样的代码（上面出问题的正则也是历史包袱）才是最好的，好好做Code Review吧。

参考资料：

• Easy profiling for Node.js Applications
• 系统级性能分析工具perf的介绍与使用
• 记一次Vue全页面SSR深坑之旅 - 微弱的内存/CPU泄漏
• How a RegEx can bring your Node.js service down
• https://www.regular-expressions.info/catastrophic.html