feat: timing support Process Start/Script Start (#222)

* feat: timing support Process Start/Script Start
* doc: add timing doc

Co-authored-by: TZ | 天猪 <atian25@qq.com>

Author: killagu

.gitignore

@@ -10,3 +10,4 @@ test/fixtures/egg/node_modules/egg-core
 .nyc_output
 package-lock.json
 run
+test/fixtures/*/timing.json

README.md

@@ -235,6 +235,39 @@ call           | `Boolean`      | determine whether invoke when exports is funct
 inject         | `Object`       | an object that be the argument when invoke the function
 filter         | `Function`     | a function that filter the exports which can be loaded
 
+## Timing
+
+EggCore record boot progress with `Timing`, include:
+- Process start time
+- Script start time(node don't implement an interface like `process.uptime` to record the script start running time, framework can implement a prestart file used with node `--require` options to set `process.scriptTime`)
+- Application start time
+- Load duration
+- `require` duration
+
+### start
+
+Start record a item. If the item exits, end the old one and start a new one.
+
+- {String} name - record item name
+- {Number} [start] - record item start time, default is Date.now()
+
+### end
+
+End a item.
+
+- {String} name - end item name
+
+### toJSON
+
+Generate all record items to json
+
+- {String} name - record item name
+- {Number} start - item start time
+- {Number} end - item end time
+- {Number} duration - item duration
+- {Number} pid - pid
+- {Number} index - item index
+
 ## Questions & Suggestions
 
 Please open an issue [here](https://github.com/eggjs/egg/issues).

lib/utils/timing.js

@@ -11,14 +11,26 @@ class Timing {
     this._enable = true;
     this[MAP] = new Map();
     this[LIST] = [];
+
+    this.init();
+  }
+
+  init() {
+    // process start time
+    this.start('Process Start', Date.now() - Math.floor((process.uptime() * 1000)));
+
+    if (typeof process.scriptStartTime === 'number') {
+      // js script start execute time
+      this.start('Script Start', process.scriptStartTime);
+    }
   }
 
-  start(name) {
+  start(name, start) {
     if (!name || !this._enable) return;
 
     if (this[MAP].has(name)) this.end(name);
 
-    const start = Date.now();
+    start = start || Date.now();
     const item = {
       name,
       start,

test/egg.test.js

@@ -12,6 +12,7 @@ const coffee = require('coffee');
 const utils = require('./utils');
 const EggCore = require('..').EggCore;
 const awaitEvent = require('await-event');
+const fs = require('mz/fs');
 
 describe('test/egg.test.js', () => {
   afterEach(mm.restore);
@@ -479,47 +480,47 @@ describe('test/egg.test.js', () => {
         yield app.ready();
 
         const json = app.timing.toJSON();
-        assert(json.length === 24);
+        assert(json.length === 25);
 
-        assert(json[0].name === 'Application Start');
-        assert(json[0].end - json[0].start === json[0].duration);
-        assert(json[0].pid === process.pid);
+        assert(json[1].name === 'Application Start');
+        assert(json[1].end - json[1].start === json[1].duration);
+        assert(json[1].pid === process.pid);
 
         // loadPlugin
-        assert(json[1].name === 'Load Plugin');
+        assert(json[2].name === 'Load Plugin');
 
         // loadConfig
-        assert(json[2].name === 'Load Config');
-        assert(json[3].name === 'Require(0) config/config.default.js');
-        assert(json[5].name === 'Require(2) config/config.default.js');
+        assert(json[3].name === 'Load Config');
+        assert(json[4].name === 'Require(0) config/config.default.js');
+        assert(json[6].name === 'Require(2) config/config.default.js');
 
         // loadExtend
-        assert(json[7].name === 'Load extend/application.js');
-        assert(json[9].name === 'Require(5) app/extend/application.js');
+        assert(json[8].name === 'Load extend/application.js');
+        assert(json[10].name === 'Require(5) app/extend/application.js');
 
         // loadCustomApp
-        assert(json[10].name === 'Load app.js');
-        assert(json[11].name === 'Require(6) app.js');
-        assert(json[12].name === 'Before Start in app.js:6:9');
-        assert(json[13].name === 'Load "proxy" to Context');
-        assert(json[14].name === 'Load Controller');
-        assert(json[15].name === 'Load "controller" to Application');
+        assert(json[11].name === 'Load app.js');
+        assert(json[12].name === 'Require(6) app.js');
+        assert(json[13].name === 'Before Start in app.js:6:9');
+        assert(json[14].name === 'Load "proxy" to Context');
+        assert(json[15].name === 'Load Controller');
+        assert(json[16].name === 'Load "controller" to Application');
 
         // loadService
-        assert(json[16].name === 'Load Service');
-        assert(json[17].name === 'Load "service" to Context');
+        assert(json[17].name === 'Load Service');
+        assert(json[18].name === 'Load "service" to Context');
 
         // loadMiddleware
-        assert(json[18].name === 'Load Middleware');
-        assert(json[19].name === 'Load "middlewares" to Application');
+        assert(json[19].name === 'Load Middleware');
+        assert(json[20].name === 'Load "middlewares" to Application');
 
         // loadController
-        assert(json[20].name === 'Load Controller');
-        assert(json[21].name === 'Load "controller" to Application');
+        assert(json[21].name === 'Load Controller');
+        assert(json[22].name === 'Load "controller" to Application');
 
         // loadRouter
-        assert(json[22].name === 'Load Router');
-        assert(json[23].name === 'Require(7) app/router.js');
+        assert(json[23].name === 'Load Router');
+        assert(json[24].name === 'Require(7) app/router.js');
       });
     });
 
@@ -533,31 +534,46 @@ describe('test/egg.test.js', () => {
         yield app.ready();
 
         const json = app.timing.toJSON();
-        assert(json.length === 13);
+        assert(json.length === 14);
 
-        assert(json[0].name === 'Application Start');
-        assert(json[0].end - json[0].start === json[0].duration);
-        assert(json[0].pid === process.pid);
+        assert(json[1].name === 'Application Start');
+        assert(json[1].end - json[1].start === json[1].duration);
+        assert(json[1].pid === process.pid);
 
         // loadPlugin
-        assert(json[1].name === 'Load Plugin');
+        assert(json[2].name === 'Load Plugin');
 
         // loadConfig
-        assert(json[2].name === 'Load Config');
-        assert(json[3].name === 'Require(0) config/config.default.js');
-        assert(json[5].name === 'Require(2) config/config.default.js');
+        assert(json[3].name === 'Load Config');
+        assert(json[4].name === 'Require(0) config/config.default.js');
+        assert(json[6].name === 'Require(2) config/config.default.js');
 
         // loadExtend
-        assert(json[7].name === 'Load extend/application.js');
-        assert(json[9].name === 'Require(5) app/extend/application.js');
+        assert(json[8].name === 'Load extend/application.js');
+        assert(json[10].name === 'Require(5) app/extend/application.js');
 
         // loadCustomAgent
-        assert(json[10].name === 'Load agent.js');
-        assert(json[11].name === 'Require(6) agent.js');
-        assert(json[12].name === 'Before Start in agent.js:5:11');
+        assert(json[11].name === 'Load agent.js');
+        assert(json[12].name === 'Require(6) agent.js');
+        assert(json[13].name === 'Before Start in agent.js:5:11');
       });
     });
 
+    describe('script timing', () => {
+      it('should work', async () => {
+        const fixtureApp = utils.getFilepath('timing');
+        await coffee.fork(path.join(fixtureApp, 'index.js'))
+          .beforeScript(path.join(fixtureApp, 'preload'))
+          .debug()
+          .expect('code', 0)
+          .end();
+        const timingJSON = await fs.readFile(path.join(fixtureApp, 'timing.json'), 'utf8');
+        const timing = JSON.parse(timingJSON);
+        const scriptStart = timing.find(item => item.name === 'Script Start');
+        assert(scriptStart);
+        assert(scriptStart.start);
+      });
+    });
   });
 
   describe('boot', () => {

test/fixtures/timing/index.js

@@ -0,0 +1,27 @@
+'use strict';
+
+const fs = require('fs');
+const path = require('path');
+
+const EggApplication = require('../egg').Application;
+const utils = require('../../utils');
+
+class Application extends EggApplication {
+  get [Symbol.for('egg#eggPath')]() {
+    return __dirname;
+  }
+  toJSON() {
+    return {
+      name: this.name,
+      plugins: this.plugins,
+      config: this.config,
+    };
+  }
+}
+
+const app = utils.createApp('application', { Application });
+app.loader.loadAll();
+app.ready(err => {
+  fs.writeFileSync(path.join(__dirname, 'timing.json'), JSON.stringify(app.timing.toJSON()));
+  process.exit(err ? 1 : 0);
+});

test/fixtures/timing/preload.js

@@ -0,0 +1,3 @@
+'use strict';
+
+process.scriptStartTime = Date.now();

test/utils/timing.test.js

@@ -13,48 +13,48 @@ describe('test/utils/timing.test.js', () => {
     timing.end('b');
 
     const json = timing.toJSON();
-    assert(json.length === 2);
+    assert(json.length === 3);
 
-    assert(json[0].name === 'a');
-    assert(json[0].end - json[0].start === json[0].duration);
-    assert(json[0].pid === process.pid);
-    assert(json[1].name === 'b');
+    assert(json[1].name === 'a');
     assert(json[1].end - json[1].start === json[1].duration);
     assert(json[1].pid === process.pid);
+    assert(json[2].name === 'b');
+    assert(json[2].end - json[2].start === json[2].duration);
+    assert(json[2].pid === process.pid);
   });
 
   it('should set item when start', () => {
     const timing = new Timing();
     timing.start('a');
 
     const json = timing.toJSON();
-    assert(json[0].name === 'a');
-    assert(json[0].start);
-    assert(json[0].end === undefined);
-    assert(json[0].duration === undefined);
+    assert(json[1].name === 'a');
+    assert(json[1].start);
+    assert(json[1].end === undefined);
+    assert(json[1].duration === undefined);
   });
 
   it('should ignore start when name is empty', () => {
     const timing = new Timing();
     timing.start();
 
     const json = timing.toJSON();
-    assert(json.length === 0);
+    assert(json.length === 1);
   });
 
   it('should throw when name exists', () => {
     const timing = new Timing();
     timing.start('a');
-    assert(timing.toJSON().length === 1);
+    assert(timing.toJSON().length === 2);
 
     timing.start('a');
-    assert(timing.toJSON().length === 2);
+    assert(timing.toJSON().length === 3);
   });
 
   it('should ignore end when name dont exist', () => {
     const timing = new Timing();
     timing.end();
-    assert(timing.toJSON().length === 0);
+    assert(timing.toJSON().length === 1);
   });
 
   it('should enable/disable', () => {
@@ -74,9 +74,9 @@ describe('test/utils/timing.test.js', () => {
 
     const json = timing.toJSON();
 
-    assert(json[0].name === 'a');
-    assert(json[1].name === 'c');
-    assert(json.length === 2);
+    assert(json[1].name === 'a');
+    assert(json[2].name === 'c');
+    assert(json.length === 3);
   });
 
   it('should clear', () => {
@@ -85,7 +85,7 @@ describe('test/utils/timing.test.js', () => {
     timing.end('a');
 
     const json = timing.toJSON();
-    assert(json[0].name === 'a');
+    assert(json[1].name === 'a');
 
     timing.clear();
 
@@ -105,4 +105,12 @@ describe('test/utils/timing.test.js', () => {
       timing.end('a');
     }, /should run timing.start\('a'\) first/);
   });
+
+  it('should init process start time', () => {
+    const timing = new Timing();
+
+    const processStart = timing.toJSON().find(item => item.name === 'Process Start');
+    assert(processStart);
+    assert(processStart.start);
+  });
 });