Node使用火焰图优化CPU爆涨

时间 2019-11-05

标签 node 使用火焰优化 cpu 繁體版

原文原文链接

背景

话很少说，先上图，这是获得App静态资源更新服务的CPU使用率监控，能够看到7月2号到7月3号后，cpu使用率发生了爆涨，在八点的早高峰和下午六点的晚高峰，几乎能够把cpu打满。发现问题当机立断，升级配置将2核4g升级至4核8g，先保证服务稳定，咱们再继续查问题。javascript

下图是升级配置后的截图，因此看到的图已经温柔不少了，本人当时看到监控的时候，全部波峰都是打在红线以上的，虽然尚未引发报警，可是默默掏出小本本记下找时间查问题。html

问题分析

由于有很明显的发生变化的时间点，直接能找到这一次的改动，通过一点点的代码级review，并无发现变更的代码上有什么问题。做为一个小前端没遇到过这种问题呀，毫无头绪的我，把救世主锁定在了火焰图身上，想看一看到底什么地方耗时长到底cpu占用在了什么东西上。前端

火焰图

因而怎么生成火焰图成了我最大的难题，开始Google搜索，“如何生成火焰图” ，“node 火焰图”，“node cpu profiler”， “node flamegraph”。看来看去全部文章千篇一概，95%以上的文章都是以下解决方案。java

1.Linux perf

参考文章：nodejs调试指南 perf + FlameGraphnode

Linux自带的系统性能分析工具，一堆功能我就很少说了，有兴趣的本身去看nodejs调试指南打开书的第一页。由于使用的局限性不是Linux的我，第一步apt install linux-tools-common都安不上，若是还要跑在虚拟机什么的上面是否是太麻烦了，方案一卒。linux

2.Node.js 自带的分析工具

参考文章：易于分析的 Node.js 应用程序 | Node.jsgit

Node.js4.4.0开始，node自己就能够记录进程中V8引擎的性能信息(profiler)，只须要在启动的时候加上参数--prof。 Node自带的分析工具：github

启动应用的时候，node须要带上—-prof参数
而后就会将性能相关信息收集到node运行目录下生成isolate-xxxxxxxxxxxxx-v8.log文件
npm有一个包能够方便的直接将isolate文件转换成，html形式的火焰图GitHub - mapbox/flamebearer: Blazing fast flame graph tool for V8 and Node 🔥 完成以上步骤火焰图果不其然的跑了出来

但是仔细一看好像不是那么一回事，由于项目用的是egg框架，火焰图里的所有信息都是egg启动的东西啊，我长达五分钟的接口压测，一点都没有体如今火焰图上，一拍脑壳，想起来我用node --prof的形式收集到的性能数据都是egg主进程上的东西，而咱们全部的接口全都打到了egg worker上去了，一点都没有收集到。顺便提一句egg提供了单进程模式RFC 增长单进程启动模式 · Issue #3180 · eggjs/egg · GitHub但还只是实验阶段。方案二又卒，好在我起码看到了一张图。

3.使用Dtrace收集性能数据

直接查到应用的pid直接对pid进行收集，而后也能够将收集到的数据制成火焰图，具体操做就不作赘述了，最后跑出来的图以下， chrome

所有是一些v8底层的东西，好像也没有我想要看的内容呀，方案三卒。

好了以上就是我Google出来的各类方案在我一一踩坑后所有以失败了结，其实也还有一些更简单的方案，例如直接接入alinode用阿里云的平台就好，一方面该项目没有接入阿里云，恰好用的node镜像又不是ali的，另外一方面，若是能够在开发环境查出问题，不但愿再经过上线去查问题。npm

方案四：v8-profiler

Node.js 是基于 V8 引擎的，V8 暴露了一些 profiler API，咱们能够经过 v8-profiler 收集一些运行时的CPU和内存数据。在安装v8-profiler的时候遇到了一些问题老是安装失败，而且得不到解决。不过好在有大神基于v8-profiler发布了v8-profiler-node8，下面是v8-profiler-node8的一段描述。

Based on v8-profiler-node8@5.7.0, Solved the v8-profiler segment fault error in node-v8.x.
v8-profiler-node8 provides node bindings for the v8 profiler and integration with node-inspector
收集数据：简单的npm install v8-profiler-node8后，开始收集CPU profile，收集时长五分钟。

const profiler = require('v8-profiler-node8');
const fs = require('fs');
const Bluebird = require('bluebird');

class PackageController extends Controller {
  async cpuProf() {
    console.log('开始收集');
    // Start Profiling
    profiler.startProfiling('CPU profile');
    await Bluebird.delay(60000 * 5);
    const profile = profiler.stopProfiling();
    profile.export()
      .pipe(fs.createWriteStream(`cpuprofile-${Date.now()}.cpuprofile`))
      .on('finish', () => profile.delete());
    this.ctx.status = 204;
  }
}
复制代码

而后当即用ab压测，给服务压力，

ab -t 300 -c 10 -p post.txt -T "application/json" http://localhost:7001/xxx/xxxxx/xxxxxx/xxxxx
复制代码

收集完成后，获得一个cpuProfile文件，Chrome 自带了分析 CPU profile 日志的工具。打开 Chrome -> 调出开发者工具（DevTools） -> 单击右上角三个点的按钮 -> More tools -> JavaScript Profiler -> Load，加载刚才生成的 cpuprofile 文件。能够直接用chrome的性能分析直接读这个文件打开分析。这里我要推荐一下 speedscope 一个根据cpuProfile生成火焰图的工具，他生成的火焰图，更清晰，还有leftHeavy模式，直接将CPU占用率最高的排在最左边，一目了然，快速的能够定位到问题。

根据火焰图解决问题

下面是该火焰图的leftHeavy模式

看火焰图的时候越图形越尖说明越正常，横条越长说明占用时间越长，从图中能够看到压测的五分钟里，CPU占用时间长达两分钟，其中绝大多数被红框中占据，来张大图

这个火焰图中是由上至下的调用顺序，一眼看过去没有我业务代码中出现的内容，再仔细一看，fetchDocs、Cursor.next、completeMany、Document.init这好像是mongo的东西呀，开心的像个傻子，赶快去搜源码。从completeMany这里破案了，这是mongoose中的一个方法，做用是将查询到的结果进行包装，使结果中的每个文档成为mongoose文档，使之能够继续使用mongoose提供的方法。以下相关源码。

/*! * hydrates many documents * * @param {Model} model * @param {Array} docs * @param {Object} fields * @param {Query} self * @param {Array} [pop] array of paths used in population * @param {Function} callback */
function completeMany(model, docs, fields, userProvidedFields, pop, callback) {
  var arr = [];
  var count = docs.length;
  var len = count;
  var opts = pop ? { populated: pop } : undefined;
  var error = null;
  function init(_error) {
    if (error != null) {
      return;
    }
    if (_error != null) {
      error = _error;
      return callback(error);
    }
    --count || callback(null, arr);
  }
  for (var i = 0; i < len; ++i) {
    arr[i] = helpers.createModel(model, docs[i], fields, userProvidedFields);
    arr[i].init(docs[i], opts, init);
  }
}
复制代码

completeMany方法会将传入的每个docs经过 helpers.createModel变成一个mongoose Document，咱们再来看一下是哪里调用的completeMany方法，发如今find方法中会判断options.lean是否等于true若是不等于true才会去调用completeMany方法去包装查询结果。

/** * Thunk around find() * * @param {Function} [callback] * @return {Query} this * @api private */
Query.prototype._find = function(callback) {
  this._castConditions();
  if (this.error() != null) {
    callback(this.error());
    return this;
  }
  this._applyPaths();
  this._fields = this._castFields(this._fields);
  var fields = this._fieldsForExec();
  var options = this._mongooseOptions;
  var _this = this;
  var userProvidedFields = _this._userProvidedFields || {};
  var cb = function(err, docs) {
    if (err) {
      return callback(err);
    }
    if (docs.length === 0) {
      return callback(null, docs);
    }
    if (!options.populate) {
		// 看这里 重点重点！
      return !!options.lean === true
          ? callback(null, docs)
          : completeMany(_this.model, docs, fields, userProvidedFields, null, callback);
    }
    var pop = helpers.preparePopulationOptionsMQ(_this, options);
    pop.__noPromise = true;
    _this.model.populate(docs, pop, function(err, docs) {
      if (err) return callback(err);
      return !!options.lean === true
          ? callback(null, docs)
          : completeMany(_this.model, docs, fields, userProvidedFields, pop, callback);
    });
  };
  return Query.base.find.call(this, {}, cb);
};
复制代码

去文档上搜一下lean mongoose query lean 文档上说了若是使用了lean那么查询返回的将是一个javascript objects, not Mongoose Documents 。原话以下。

Documents returned from queries with theleanoption enabled are plain javascript objects, not Mongoose Documents . They have nosavemethod, getters/setters, virtuals, or other Mongoose features.

在文档中还提到了，lean精简模式，对于高性能只读的状况是很是有用的。

优化

回到问题上来，看到mongoose Document的问题，7月2号到7月3号后，为何会忽然致使CPU暴涨恍然大悟，本身以前review 代码，看着代码没问题，可是忽略了这一个版本由于业务调整致使查询压力大大增长，多是过去的好几倍这个问题。随即将查询改为精简模式。只须要以下很简单的几处修改便可。

await model.Package.find(query).lean();
复制代码

那说到频繁的处理mongoose Document致使的性能问题，那其实还有一个优化点能够作，其实在查询的时候多多使用find的第二个参数projection去投影所须要返回的键，须要用什么就投影什么，不要一股脑把全部的键值一块儿返回了。处理完这一系列，重写在本地进行了一次一样的压测五分钟，出了一份火焰图，下面图1就是这五分钟期间的火焰图，图二就是通过speedscope解析事后的leftHeavy图，直接观察重灾区。

从图一的火焰图中，并不能看出明显的区别，可是一看到图二就知道咱们的优化是有效果的，从最直观的，本来左侧红框中completeMany的部分直接没有了，而后cpu占用的总时长也由本来的接近两分钟直接降到了36s，优化效果仍是十分明显的。上线观察几天看看效果

如图能够看到，cpu使用率在优化后获得了大大提高，而且稳定在了百分之十五之内。问题解决了，一切皆大欢喜，服务器降配一切回到正常。但此次故障也让我对诸如mongoos这样的ODM在使用时须要更加当心谨慎，他给咱们带来了无限的便利的同时，可能也会由于一些额外的操做，让咱们的服务承受额外的负担，正常状况下这一点性能差距不易察觉，然而到了高峰期，或者大型活动的时侯，可能就会由于这一点小坑，对服务形成更大的影响。

谨记。

做者专栏：juejin.im/user/56e8e9…