background

Without further discussion, the above figure shows the CPU usage monitored by the App static resource update service. It can be seen that the CPU usage has skyrocketed from July 2 to July 3, and the CPU can be almost full in the morning peak at 8:00 and evening peak at 6:00 p.m. When problems were found, we made a prompt decision and upgraded the configuration to upgrade 2-core 4G to 4-core 8G. We first ensured the stability of the service, and then we continued to investigate the problems.

The figure below is the screenshot after the upgrade configuration, so see the figure has been a lot of gentle, I saw the monitoring at that time, all the peaks are hit in the red line above, although it has not caused the alarm, but silently took out a small notebook to find time to check the problem.

Problem analysis

Because there was an obvious time point of change, we could directly find the change this time. After a little code-level review, we did not find any problems in the changed code. As a small front-end that didn’t have this kind of problem, I had no idea what to do and locked the savior into the fire chart to see where the time was taking and what the CPU was being used for.

Flame figure

So how to generate a flamegraph became my biggest problem, and I started googling, “how to generate a flamegraph”, “node flamegraph”, “node CPU profiler”, “node flamegraph”. It looks like all the articles are the same, more than 95% of the articles are the following solutions.

1.Linux perf

See article: NodeJS Debugging Guide Perf + FlameGraph

The nodeJS debug guide is the first page of the Linux debug guide. The nodeJS debug guide is the first page of the Linux debug guide. Due to the limitation of using Linux, I cannot install apt linux-tools-common in the first step. If I need to run on virtual machines or other things, it will be too much trouble.

2.Node.js provides built-in analysis tools

Refer to the article: easy to analyze the Node. Js application | Node. Js

As of Node.js4.4.0, Node itself can log the V8 engine profiler in the process by adding the parameter –prof at startup time. Node provides the following analysis tools:

  1. When starting an application, Node needs to take the — prof parameter
  2. The performance information is then collected to the node run directory to generate the isolATE-XXXXXXXXXXX-v8.log file
  3. NPM has a package that makes it easy to convert isolate files directly into HTML flame chartsGitHub – mapbox/flamebearer: Blazing fast flame graph tool for V8 and Node 🔥Complete the above steps and the flame chart comes out as expected

    But a carefully look like not so one thing, because the project is an egg framework, flame all the information in the chart are an egg to start things ah, I interface pressure measurement for five minutes, no reflect on the figure of flame, a racket head, think of me in the form of the node – the initial performance data collected is an egg on the main process, All of our interfaces went to the egg worker, and none of them were collected. Incidentally, egg provides a single-process modeRFC added single-process startup mode · Issue #3180 · eggJS/Egg · GitHubBut it’s still experimental. Plan two is dead, but at least I got a picture.

3. Use Dtrace to collect performance data

Directly check the PID of the application and collect the PID directly. Then, the collected data can also be made into a flame map. The specific operation will not be described.

In fact, there are also some simpler solutions, such as direct access to Alinode and ali Cloud platform. On the one hand, the project is not connected to Ali Cloud, and the node image used is not Ali. On the other hand, If you can find the problem in the development environment, you don’t want to go online to find the problem.

Plan 4: V8-profiler

Node.js is based on the V8 engine, and V8 exposes some profiler apis that can be used to collect runtime CPU and memory data. I encountered some problems when installing v8 profiler that failed to be installed and could not be resolved. V8-profiler-node8 is a v8-profiler version of node8.

On [email protected], 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 data collection: After simple NPM install V8-profiler-node8, the CPU profile collection begins for five minutes.

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

class PackageController extends Controller {
  async cpuProf() {
    console.log('Start collecting');
    // Start Profiling
    profiler.startProfiling('CPU profile');
    await Bluebird.delay(60000 * 5);
    const profile = profiler.stopProfiling();
    profile.export()
      .pipe(fs.createWriteStream(`cpuprofile-The ${Date.now()}.cpuprofile`))
      .on('finish', () => profile.delete());
    this.ctx.status = 204; }}Copy the code

And then immediately with the ab pressure test, to the service pressure,

ab -t 300 -c 10 -p post.txt -T "application/json" http://localhost:7001/xxx/xxxxx/xxxxxx/xxxxx
Copy the code

After collecting CPU profile logs, a cpuProfile file is generated. Chrome provides a tool to analyze CPU profile logs. Open Chrome -> DevTools -> More Tools -> JavaScript Profiler -> Load to Load the cpuProfile file you just generated. You can read this file directly using Chrome profiling to open profiling. I’d like to recommend SpeedScope, a tool that generates a fire map based on the cpuProfile. Its fire map is clearer, and leftHeavy mode, which places the highest CPU usage on the far left. It’s easy to spot problems quickly.

Solve the problem according to the flame diagram

Here is the leftHeavy pattern for the flame chart

When looking at the flame chart, the more pointed the graph is, the more normal it is. The longer the horizontal bar is, the longer the occupying time is. As can be seen from the chart, the CPU occupied time is as long as two minutes in the five minutes of the pressure measurement, most of which are occupied by the red box

/ *! * 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); }}Copy the code

The completeMany method turns every passed docs into a Mongoose Document via helres. createModel, so let’s see where the completeMany method is called again, The find method determines whether options.lean is true. If not, the completeMany method is called to wrap the query result.

/** * 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) {// Look at the key points here!
      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);
};
Copy the code

Go to the documentation and search for Lean Mongoose Query Lean. The documentation says that if you use Lean then the query will return a javascript object, not Mongoose Documents. The words are as follows.

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

Also mentioned in the documentation is the Lean lean mode, which is useful for high-performance read-only situations.

To optimize the

Coming back to the problem, when I saw the problem of Mongoose Document, from July 2 to July 3, I suddenly realized why the CPU suddenly skyrocketed. I reviewed the code before and there was no problem with the code, but I ignored this version because the business adjustment led to a great increase in query pressure. Probably several times more than it used to be. Then change the query to thin mode. Just a few simple changes as follows.

await model.Package.find(query).lean();
Copy the code

As for the performance problems caused by frequent processing of Mongoose Document, there is an optimization point that can be made. In fact, when querying, it is more likely to use the second parameter of Find projection to projection the key that needs to be returned, instead of all key values being returned at once. After processing this series, rewrite carried out the same pressure survey locally for five minutes and produced a flame map. Figure 1 below is the flame map during these five minutes. Figure 2 is the leftHeavy map after speedScope analysis, directly observing the disaster area.

From figure a flame in the figure, and can’t see the obvious differences, but a see figure 2 we know that we of optimization is effective, from the most intuitive, originally a part of the red box on the left side of the completeMany directly, and then the total CPU time also directly by the original nearly two minutes to 36 s, and the optimization effect is very obvious. Go online and observe the effect for a few days

Keep in mind.

Author’s column: juejin.cn/user/301671…