From 1a55c001f52ec086036ef250daba4b4691f938cc Mon Sep 17 00:00:00 2001 From: fengmk2 Date: Fri, 13 Jan 2023 22:46:52 +0800 Subject: [PATCH] feat: support show app.timing in timline string MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ```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 | 32 ++++++++++++++++++++++++++++++-- package.json | 1 + test/egg.test.js | 16 +++++++++++++++- test/utils/timing.test.js | 3 +++ 4 files changed, 49 insertions(+), 3 deletions(-) diff --git a/lib/utils/timing.js b/lib/utils/timing.js index 64ac1d0b..6de900ff 100644 --- a/lib/utils/timing.js +++ b/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 - this._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; diff --git a/package.json b/package.json index 42dbfad6..72aa1598 100644 --- a/package.json +++ b/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" diff --git a/test/egg.test.js b/test/egg.test.js index a77a8bdb..7a3017d9 100644 --- a/test/egg.test.js +++ b/test/egg.test.js @@ -149,6 +149,7 @@ 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(() => { @@ -156,7 +157,7 @@ describe('test/egg.test.js', () => { }); }); - 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/); }); }); diff --git a/test/utils/timing.test.js b/test/utils/timing.test.js index fd5d775c..fa13c33b 100644 --- a/test/utils/timing.test.js +++ b/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', () => {