feat: support show app.timing in timline string (#260)

```bash
egg start timeline:
▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇ [289ms] - #0 Process Start
                  ▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇ [510ms] - #1 Application Start
                  ▇ [2ms] - #2 Load Plugin
                  ▇ [1ms] - #3 Load Config
                  ▇ [0ms] - #4 Require(0) ~/eggjs/egg-core/test/fixtures/egg/config/config.default.js
                  ▇ [0ms] - #5 Require(1) ~/eggjs/egg-core/test/fixtures/egg/config/config.unittest.js
                  ▇ [0ms] - #6 Load extend/application.js
                  ▇ [0ms] - #7 Require(2) ~/eggjs/egg-core/test/fixtures/egg/app/extend/application.js
                  ▇ [1ms] - #8 Load extend/context.js
                  ▇ [0ms] - #9 Load extend/request.js
                  ▇ [0ms] - #10 Load extend/response.js
                  ▇ [1ms] - #11 Load app.js
                  ▇ [0ms] - #12 Require(3) ~/eggjs/egg-core/test/fixtures/egg/node_modules/session/app.js
                  ▇ [0ms] - #13 Require(4) app.js
                  ▇▇▇▇▇▇ [101ms] - #14 readyCallback in a
                  ▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇ [501ms] - #15 readyCallback in b
                  ▇ [4ms] - #16 Load Middleware
                  ▇ [4ms] - #17 Load "middlewares" to Application
                  ▇ [2ms] - #18 Load Service
                  ▇ [2ms] - #19 Load "service" to Context
                  ▇ [0ms] - #20 Load Controller
                  ▇ [0ms] - #21 Load "controller" to Application
                  ▇ [0ms] - #22 Load Router
```

lib/utils/timing.js

@@ -1,13 +1,15 @@
 'use strict';
 
+const { EOL } = require('os');
 const assert = require('assert');
+
 const MAP = Symbol('Timing#map');
 const LIST = Symbol('Timing#list');
 
 class Timing {
-
   constructor() {
     this._enable = true;
+    this._start = null;
     this[MAP] = new Map();
     this[LIST] = [];
 
@@ -16,7 +18,7 @@ class Timing {
 
   init() {
     // process start time
-    this.start('Process Start', Date.now() - Math.floor((process.uptime() * 1000)));
+    this.start('Process Start', Date.now() - Math.floor(process.uptime() * 1000));
     this.end('Process Start');
 
     if (typeof process.scriptStartTime === 'number') {
@@ -32,6 +34,9 @@ class Timing {
     if (this[MAP].has(name)) this.end(name);
 
     start = start || Date.now();
+    if (this._start === null) {
+      this._start = start;
+    }
     const item = {
       name,
       start,
@@ -71,6 +76,29 @@ class Timing {
   toJSON() {
     return this[LIST];
   }
+
+  itemToString(timelineEnd, item, times) {
+    const isEnd = typeof item.duration === 'number';
+    const duration = isEnd ? item.duration : timelineEnd - item.start;
+    const offset = item.start - this._start;
+    const status = `${duration}ms${isEnd ? '' : ' NOT_END'}`;
+    const timespan = Math.floor((offset * times).toFixed(6));
+    let timeline = Math.floor((duration * times).toFixed(6));
+    timeline = timeline > 0 ? timeline : 1; // make sure there is at least one unit
+    const message = `#${item.index} ${item.name}`;
+    return ' '.repeat(timespan) + '▇'.repeat(timeline) + ` [${status}] - ${message}`;
+  }
+
+  toString(prefix = 'egg start timeline:', width = 50) {
+    const timelineEnd = Date.now();
+    const timelineDuration = timelineEnd - this._start;
+    let times = 1;
+    if (timelineDuration > width) {
+      times = width / timelineDuration;
+    }
+    // follow https://github.com/node-modules/time-profile/blob/master/lib/profiler.js#L88
+    return prefix + EOL + this[LIST].map(item => this.itemToString(timelineEnd, item, times)).join(EOL);
+  }
 }
 
 module.exports = Timing;

package.json

@@ -13,6 +13,7 @@
     "lint": "eslint .",
     "test": "npm run lint -- --fix && npm run test-local",
     "test-local": "egg-bin test -p",
+    "test-single": "egg-bin test",
     "cov": "egg-bin cov -p",
     "ci": "npm run lint && npm run cov",
     "contributor": "git-contributor"
@@ -58,7 +59,7 @@
     "co": "^4.6.0",
     "debug": "^4.1.1",
     "depd": "^2.0.0",
-    "egg-logger": "^2.4.1",
+    "egg-logger": "^3.1.0",
     "egg-path-matching": "^1.0.1",
     "extend2": "^1.0.0",
     "get-ready": "^2.0.1",

test/egg.test.js

@@ -149,14 +149,15 @@ describe('test/egg.test.js', () => {
         assert(message === '[egg:core:ready_timeout] %s seconds later %s was still unable to finish.');
         assert(b === 10);
         assert(a === 'a');
+        console.log(app.timing.toString());
         done();
       });
       app.ready(() => {
         throw new Error('should not be called');
       });
     });
 
-    it('should log info when plugin is not ready', done => {
+    it('should log info when plugin is ready', done => {
       app = utils.createApp('ready');
       app.loader.loadAll();
       let message = '';
@@ -166,6 +167,7 @@ describe('test/egg.test.js', () => {
       app.ready(() => {
         assert(/\[egg:core:ready_stat] end ready task a, remain \["b"]/.test(message));
         assert(/\[egg:core:ready_stat] end ready task b, remain \[]/.test(message));
+        console.log(app.timing.toString());
         done();
       });
     });
@@ -206,6 +208,9 @@ describe('test/egg.test.js', () => {
       assert(app.beforeStartFunction === false);
       await app.ready();
       assert(app.beforeStartFunction === true);
+      const timeline = app.timing.toString();
+      console.log(timeline);
+      assert.match(timeline, /#14 Before Start in app.js:3:7/);
     });
 
     it('should beforeStart excute timeout without EGG_READY_TIMEOUT_ENV too short', function(done) {
@@ -215,6 +220,10 @@ describe('test/egg.test.js', () => {
       app.once('ready_timeout', id => {
         const file = path.normalize('test/fixtures/beforestart-with-timeout-env/app.js');
         assert(id.includes(file));
+        const timeline = app.timing.toString();
+        console.log(timeline);
+        assert.match(timeline, /▇ \[\d+ms NOT_END] - #1 Application Start/);
+        assert.match(timeline, /▇ \[\d+ms NOT_END] - #14 Before Start in app.js:3:7/);
         done();
       });
     });
@@ -224,6 +233,7 @@ describe('test/egg.test.js', () => {
       app.loader.loadAll();
       app.once('error', err => {
         assert(err.message === 'not ready');
+        console.log(app.timing.toString());
         done();
       });
     });
@@ -236,6 +246,7 @@ describe('test/egg.test.js', () => {
         throw new Error('should not run');
       } catch (err) {
         assert(err.message === 'not ready');
+        console.log(app.timing.toString());
       }
     });
 
@@ -760,6 +771,9 @@ describe('test/egg.test.js', () => {
             'didReady',
             'beforeClose',
           ]);
+        console.log(app.timing.toString());
+        assert.match(app.timing.toString(), /egg start timeline:/);
+        assert.match(app.timing.toString(), /#1 Application Start/);
       });
     });
 

test/utils/timing.test.js

@@ -21,6 +21,9 @@ describe('test/utils/timing.test.js', () => {
     assert(json[2].name === 'b');
     assert(json[2].end - json[2].start === json[2].duration);
     assert(json[2].pid === process.pid);
+
+    timing.start('c');
+    console.log(timing.toString());
   });
 
   it('should set item when start', () => {