👌 IMPROVE: Print warnning log when boot action takes more than 5000ms (…

…#5049)

.eslintrc

@@ -1,6 +1,3 @@
 {
-  "extends": "eslint-config-egg",
-  "parserOptions": {
-    "ecmaVersion": 2017
-  }
+  "extends": "eslint-config-egg"
 }

config/config.default.js

@@ -152,6 +152,10 @@ module.exports = appInfo => {
         // ignore any key contains "secret" keyword
         /secret/i,
       ]),
+      timing: {
+        // if boot action >= slowBootActionMinDuration, egg core will print it to warnning log
+        slowBootActionMinDuration: 5000,
+      },
     },
 
     /**

index.js

@@ -1,5 +1,3 @@
-'use strict';
-
 /**
  * @namespace Egg
  */

lib/egg.js

@@ -1,5 +1,3 @@
-'use strict';
-
 const { performance } = require('perf_hooks');
 const path = require('path');
 const fs = require('fs');
@@ -412,12 +410,19 @@ class EggApplication extends EggCore {
 
   dumpTiming() {
     try {
-      const json = this.timing.toJSON();
+      const items = this.timing.toJSON();
       const rundir = this.config.rundir;
       const dumpFile = path.join(rundir, `${this.type}_timing_${process.pid}.json`);
-      fs.writeFileSync(dumpFile, CircularJSON.stringify(json, null, 2));
+      fs.writeFileSync(dumpFile, CircularJSON.stringify(items, null, 2));
       // only disable, not clear bootstrap timing data.
       this.timing.disable();
+      // show duration >= ${slowBootActionMinDuration}ms action to warnning log
+      for (const item of items) {
+        if (item.duration >= this.config.dump.timing.slowBootActionMinDuration) {
+          this.coreLogger.warn('[egg:core][slow-boot-action] #%d %dms, name: %s',
+            item.index, item.duration, item.name);
+        }
+      }
     } catch (err) {
       this.coreLogger.warn(`dumpTiming error: ${err.message}`);
     }

test/fixtures/apps/dumptiming-slowBootActionMinDuration/app.js

@@ -0,0 +1,15 @@
+module.exports = class {
+  constructor(app) {
+    this.app = app;
+  }
+
+  async didLoad() {
+    this.app.coreLogger.info('start doing sth in didLoad');
+    return new Promise(resolve => {
+      setTimeout(() => {
+        this.app.coreLogger.info('end doing sth in didLoad');
+        resolve();
+      }, 150);
+    });
+  }
+}

test/fixtures/apps/dumptiming-slowBootActionMinDuration/config/config.default.js

@@ -0,0 +1,6 @@
+exports.keys = 'test key';
+exports.dump = {
+  timing: {
+    slowBootActionMinDuration: 100,
+  },
+};

test/fixtures/apps/dumptiming-slowBootActionMinDuration/config/plugin.js

@@ -0,0 +1 @@
+exports.static = false;

test/fixtures/apps/dumptiming-slowBootActionMinDuration/package.json

@@ -0,0 +1,3 @@
+{
+  "name": "dumptiming-slowBootActionMinDuration"
+}

test/lib/egg.test.js

@@ -178,6 +178,16 @@ describe('test/lib/egg.test.js', () => {
       assertFile(path.join(baseDir, `run/application_timing_${process.pid}.json`));
       assertFile(path.join(baseDir, 'logs/dumptiming-timeout/common-error.log'), /unfinished timing item: {"name":"Did Load in app.js:didLoad"/);
     });
+
+    it('should dump slow-boot-action warnning log', async () => {
+      const baseDir = utils.getFilepath('apps/dumptiming-slowBootActionMinDuration');
+      await rimraf(path.join(baseDir, 'run'));
+      await rimraf(path.join(baseDir, 'logs'));
+      const app = utils.app(baseDir);
+      await app.ready();
+      await sleep(100);
+      assertFile(path.join(baseDir, 'logs/dumptiming-slowBootActionMinDuration/egg-web.log'), /\[egg:core]\[slow-boot-action] #\d+ \d+ms, name: Did Load in app\.js:didLoad/);
+    });
   });
 
   describe('dump disabled plugin', () => {