Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
merged 4 commits into from
Jan 13, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
32 changes: 30 additions & 2 deletions lib/utils/timing.js
Original file line number Diff line number Diff line change
@@ -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] = [];

Expand All @@ -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') {
Expand All @@ -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,
Expand Down Expand Up @@ -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;
3 changes: 2 additions & 1 deletion package.json
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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",
Expand Down
16 changes: 15 additions & 1 deletion test/egg.test.js
Original file line number Diff line number Diff line change
Expand Up @@ -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 = '';
Expand All @@ -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();
});
});
Expand Down Expand Up @@ -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) {
Expand All @@ -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();
});
});
Expand All @@ -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();
});
});
Expand All @@ -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());
}
});

Expand Down Expand Up @@ -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/);
});
});

Expand Down
3 changes: 3 additions & 0 deletions test/utils/timing.test.js
Original file line number Diff line number Diff line change
Expand Up @@ -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', () => {
Expand Down