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自帶的分析工具：

1. 啓動應用的時候，node須要帶上—-prof參數
2. 而後就會將性能相關信息收集到node運行目錄下生成isolate-xxxxxxxxxxxxx-v8.log文件
3. 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在使用時須要更加當心謹慎，他給咱們帶來了無限的便利的同時，可能也會由於一些額外的操做，讓咱們的服務承受額外的負擔，正常狀況下這一點性能差距不易察覺，然而到了高峯期，或者大型活動的時侯，可能就會由於這一點小坑，對服務形成更大的影響。

謹記。

做者專欄：juejin.im/user/56e8e9…