专栏首页code秘密花园Node使用火焰图优化CPU爆涨

Node使用火焰图优化CPU爆涨

背景

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

下图是升级配置后的截图,所以看到的图已经温柔很多了,本人当时看到监控的时候,所有波峰都是打在红线以上的,虽然还没有引起报警,但是默默掏出小本本记下找时间查问题。

问题分析

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

火焰图

于是怎么生成火焰图成了我最大的难题,开始Google搜索,“如何生成火焰图” ,“node 火焰图”,“node cpu profiler”, “node flamegraph”。看来看去所有文章千篇一律,95%以上的文章都是如下解决方案。

1.Linux perf

参考文章:nodejs调试指南 perf + FlameGraph

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

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

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

Node.js4.4.0开始,node本身就可以记录进程中V8引擎的性能信息(profiler),只需要在启动的时候加上参数--prof。

Node自带的分析工具:

  • 启动应用的时候,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进行收集,然后也可以将收集到的数据制成火焰图,具体操作就不做赘述了,最后跑出来的图如下

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

好了以上就是我Google出来的各种方案在我一一踩坑后全部以失败告终,其实也还有一些更简单的方案,例如直接接入alinode用阿里云的平台就好,一方面该项目没有接入阿里云,刚好用的node镜像又不是ali的,另一方面,如果可以在开发环境查出问题,不希望再通过上线去查问题。

方案四: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在使用时需要更加小心谨慎,他给我们带来了无限的便利的同时,可能也会因为一些额外的操作,让我们的服务承受额外的负担,正常情况下这一点性能差距不易察觉,然而到了高峰期,或者大型活动的时侯,可能就会因为这一点小坑,对服务造成更大的影响。

谨记。

关于本文作者:@Harlan原文:https://zhuanlan.zhihu.com/p/76250769

本文分享自微信公众号 - code秘密花园(code_mmhy),作者:浩男

原文出处及转载信息见文内详细说明,如有侵权,请联系 yunjia_community@tencent.com 删除。

原始发表时间:2020-06-09

本文参与腾讯云自媒体分享计划,欢迎正在阅读的你也加入,一起分享。

我来说两句

0 条评论
登录 后参与评论

相关文章

  • 精读《React Hooks》

    React Hooks 是 React 16.7.0-alpha 版本推出的新特性,想尝试的同学安装此版本即可。

    ConardLi
  • 手动实现call apply bind

    bind:当绑定函数被调用时,bind传入的参数会被插入到目标函数的参数列表的开始位置,传递给绑定函数的参数会跟在它们后面。

    ConardLi
  • 微信支持H5跳转App、跳转小程序

    根据刀哥多年写代码要看文档的经验来看,证实了这次更新不仅支持了打开小程序,连app也顺带支持了,这个信息量着实有点大

    ConardLi
  • 理解nodejs中js和c++的通信原理

    本文分享一下nodejs中js调用c++模块的一些内容。js调用c++模块是v8提供的能力,nodejs是使用了这个能力。这样我们只需要面对js,剩下的事情交给...

    theanarkh
  • 2018-10-22 IDEA的SVN做show history操作时出现问题 Problems while loading file history: svn: E175009: The XM...

    原文地址 https://blog.csdn.net/xing930408/article/details/79179631 https://blog.cs...

    Albert陈凯
  • 快速学习HDFS2.X新特性

    (2)归档文件 把/user/atguigu/input目录里面的所有文件归档成一个叫input.har的归档文件,并把归档后文件存储到/user/atgui...

    cwl_java
  • RocketMQ事务消息代码样例 顶

    第三步,写一个你要执行的方法,比如你的本项目的一次数据库执行,或者其他业务代码。我这里要执行的是保存个人信息。

    算法之名
  • OAuth2简易实战(四)-Github社交联合登录

    老梁
  • 鱼眼相机相关概念

    omnidirectional camera 可以在同一时间看到相机四周所有方向的物体 360度 视野

    用户1148525
  • RSA公钥加密私钥解密实例

    版权声明:本文为博主原创文章,未经博主允许不得转载。 https://blog.csdn.net/huyuyang6688/article/...

    DannyHoo

扫码关注云+社区

领取腾讯云代金券