Skip to content

Commit d73f6b4

Browse files
matz3RandomByte
matz3
and
RandomByte
authored
perf(cli): Add CPU profiling support (#1260)
Profiling can be enabled via the `UI5_CLI_PROFILE` environment variable. This is a development feature to help identify performance bottlenecks. The produced profile name and format might change in future releases. --------- Co-authored-by: Merlin Beutlberger <[email protected]>
1 parent cb29ec1 commit d73f6b4

File tree

5 files changed

+275
-17
lines changed

5 files changed

+275
-17
lines changed

‎packages/cli/bin/ui5.cjs‎

Lines changed: 12 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -94,8 +94,19 @@ const ui5 = {
9494
},
9595

9696
async invokeCLI(pkg) {
97+
let profile;
98+
if (process.env.UI5_CLI_PROFILE) {
99+
profile = await import("../lib/utils/profile.js");
100+
await profile.start();
101+
}
97102
const {default: cli} = await import("../lib/cli/cli.js");
98-
await cli(pkg);
103+
const argv = await cli(pkg);
104+
105+
// Stop profiling after CLI finished execution
106+
// Except for "serve" command, which continues running and only stops on sigint (see profile.js)
107+
if (profile && argv._[0] !== "serve") {
108+
await profile.stop();
109+
}
99110
},
100111

101112
async main() {

‎packages/cli/lib/cli/cli.js‎

Lines changed: 1 addition & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -68,7 +68,5 @@ export default async (pkg) => {
6868
// Format terminal output to full available width
6969
cli.wrap(cli.terminalWidth());
7070

71-
// yargs registers a get method on the argv property.
72-
// The property needs to be accessed to initialize everything.
73-
cli.argv;
71+
return cli.parse();
7472
};

‎packages/cli/lib/utils/profile.js‎

Lines changed: 83 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,83 @@
1+
/* eslint-disable no-console */
2+
import {writeFileSync} from "node:fs";
3+
import {Session} from "node:inspector/promises";
4+
5+
let session;
6+
let processSignals;
7+
8+
export async function start() {
9+
if (session) {
10+
return;
11+
}
12+
session = new Session();
13+
session.connect();
14+
await session.post("Profiler.enable");
15+
await session.post("Profiler.start");
16+
console.log(`Recording CPU profile...`);
17+
processSignals = registerSigHooks();
18+
}
19+
20+
async function writeProfile(profile) {
21+
const formatter = new Intl.DateTimeFormat("en-GB", {
22+
year: "numeric",
23+
month: "2-digit",
24+
day: "2-digit",
25+
hour: "2-digit",
26+
minute: "2-digit",
27+
second: "2-digit",
28+
});
29+
const dateParts = Object.create(null);
30+
const parts = formatter.formatToParts(new Date());
31+
parts.forEach((p) => {
32+
dateParts[p.type] = p.value;
33+
});
34+
35+
const fileName = `./ui5_${dateParts.year}-${dateParts.month}-${dateParts.day}_` +
36+
`${dateParts.hour}-${dateParts.minute}-${dateParts.second}.cpuprofile`;
37+
console.log(`\nSaving CPU profile to ${fileName}...`);
38+
writeFileSync(fileName, JSON.stringify(profile));
39+
}
40+
41+
export async function stop() {
42+
if (!session) {
43+
return;
44+
}
45+
const {profile} = await session.post("Profiler.stop");
46+
session = null;
47+
if (profile) {
48+
await writeProfile(profile);
49+
}
50+
if (processSignals) {
51+
deregisterSigHooks(processSignals);
52+
processSignals = null;
53+
}
54+
}
55+
56+
function registerSigHooks() {
57+
function createListener(exitCode) {
58+
return function() {
59+
// Gracefully end profiling, then exit
60+
stop().then(() => {
61+
process.exit(exitCode);
62+
});
63+
};
64+
}
65+
66+
const processSignals = {
67+
"SIGHUP": createListener(128 + 1),
68+
"SIGINT": createListener(128 + 2),
69+
"SIGTERM": createListener(128 + 15),
70+
"SIGBREAK": createListener(128 + 21)
71+
};
72+
73+
for (const signal of Object.keys(processSignals)) {
74+
process.on(signal, processSignals[signal]);
75+
}
76+
return processSignals;
77+
}
78+
79+
function deregisterSigHooks(signals) {
80+
for (const signal of Object.keys(signals)) {
81+
process.removeListener(signal, signals[signal]);
82+
}
83+
}

‎packages/cli/test/lib/cli/cli.js‎

Lines changed: 10 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -11,18 +11,16 @@ test.beforeEach(async (t) => {
1111
notify: t.context.updateNotifierNotify
1212
}).named("updateNotifier");
1313

14-
t.context.argvGetter = sinon.stub();
14+
t.context.yargsHideBin = sinon.stub().named("hideBin").returns([]);
15+
1516
t.context.yargsInstance = {
1617
parserConfiguration: sinon.stub(),
1718
version: sinon.stub(),
1819
scriptName: sinon.stub(),
1920
command: sinon.stub(),
2021
terminalWidth: sinon.stub().returns(123),
2122
wrap: sinon.stub(),
22-
get argv() {
23-
t.context.argvGetter();
24-
return undefined;
25-
}
23+
parse: sinon.stub().resolves({_: []})
2624
};
2725

2826
t.context.yargs = sinon.stub().returns(t.context.yargsInstance).named("yargs");
@@ -54,10 +52,9 @@ test.beforeEach(async (t) => {
5452
t.context.cli = await esmock.p("../../../lib/cli/cli.js", {
5553
"update-notifier": t.context.updateNotifier,
5654
"yargs": t.context.yargs,
57-
// TODO: Somehow esmock is unable to mock this import
58-
// "yargs/helpers": {
59-
// hideBin: t.context.yargsHideBin
60-
// },
55+
"yargs/helpers": {
56+
hideBin: t.context.yargsHideBin
57+
},
6158
"../../../lib/cli/version.js": {
6259
setVersion: t.context.setVersion
6360
},
@@ -76,7 +73,7 @@ test.afterEach.always((t) => {
7673

7774
test.serial("CLI", async (t) => {
7875
const {
79-
cli, updateNotifier, updateNotifierNotify, argvGetter, yargsInstance, yargs,
76+
cli, updateNotifier, updateNotifierNotify, yargsInstance, yargs,
8077
setVersion, cliBase
8178
} = t.context;
8279

@@ -131,8 +128,8 @@ test.serial("CLI", async (t) => {
131128
t.is(yargsInstance.wrap.callCount, 1);
132129
t.deepEqual(yargsInstance.wrap.getCall(0).args, [123]);
133130

134-
t.is(argvGetter.callCount, 1);
135-
t.deepEqual(argvGetter.getCall(0).args, []);
131+
t.is(yargsInstance.parse.callCount, 1);
132+
t.deepEqual(yargsInstance.parse.getCall(0).args, []);
136133

137134
sinon.assert.callOrder(
138135
updateNotifier,
@@ -146,7 +143,7 @@ test.serial("CLI", async (t) => {
146143
yargsInstance.command,
147144
yargsInstance.terminalWidth,
148145
yargsInstance.wrap,
149-
argvGetter
146+
yargsInstance.parse
150147
);
151148
});
152149

‎packages/cli/test/lib/utils/profile.js‎

Lines changed: 169 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,169 @@
1+
import test from "ava";
2+
import sinon from "sinon";
3+
import esmock from "esmock";
4+
5+
function createSessionStubs() {
6+
const connectStub = sinon.stub();
7+
const postStub = sinon.stub().callsFake(async (method) => {
8+
if (method === "Profiler.stop") {
9+
return {profile: {foo: "bar"}};
10+
}
11+
return {};
12+
});
13+
class Session {
14+
connect() {
15+
return connectStub();
16+
}
17+
post(method) {
18+
return postStub(method);
19+
}
20+
}
21+
return {Session, connectStub, postStub};
22+
}
23+
24+
test.afterEach.always(() => {
25+
sinon.restore();
26+
});
27+
28+
test.serial("start() enables and starts profiler and registers signals", async (t) => {
29+
const {Session, connectStub, postStub} = createSessionStubs();
30+
const writeFileSyncStub = sinon.stub();
31+
32+
const installed = new Map();
33+
const onStub = sinon.stub(process, "on").callsFake((signal, handler) => {
34+
installed.set(signal, handler);
35+
return process;
36+
});
37+
const removeListenerStub = sinon.stub(process, "removeListener");
38+
39+
const {start, stop} = await esmock("../../../lib/utils/profile.js", {
40+
"node:inspector/promises": {Session},
41+
"node:fs": {writeFileSync: writeFileSyncStub}
42+
});
43+
44+
await start();
45+
46+
t.true(connectStub.calledOnce, "session.connect called once");
47+
t.true(postStub.calledWith("Profiler.enable"), "Profiler.enable posted");
48+
t.true(postStub.calledWith("Profiler.start"), "Profiler.start posted");
49+
50+
// Four signals should be registered
51+
t.true(onStub.calledWith("SIGHUP"));
52+
t.true(onStub.calledWith("SIGINT"));
53+
t.true(onStub.calledWith("SIGTERM"));
54+
t.true(onStub.calledWith("SIGBREAK"));
55+
56+
// Cleanup to reset internal state
57+
await stop();
58+
59+
// stop should deregister the same handlers
60+
t.true(removeListenerStub.calledWith("SIGHUP", installed.get("SIGHUP")));
61+
t.true(removeListenerStub.calledWith("SIGINT", installed.get("SIGINT")));
62+
t.true(removeListenerStub.calledWith("SIGTERM", installed.get("SIGTERM")));
63+
t.true(removeListenerStub.calledWith("SIGBREAK", installed.get("SIGBREAK")));
64+
});
65+
66+
test.serial("start() is idempotent", async (t) => {
67+
const {Session, connectStub} = createSessionStubs();
68+
const writeFileSyncStub = sinon.stub();
69+
70+
sinon.stub(process, "on").returns(process);
71+
sinon.stub(process, "removeListener");
72+
73+
const {start, stop} = await esmock("../../../lib/utils/profile.js", {
74+
"node:inspector/promises": {Session},
75+
"node:fs": {writeFileSync: writeFileSyncStub}
76+
});
77+
78+
await start();
79+
await start();
80+
t.true(connectStub.calledOnce, "connect should be called only once");
81+
82+
await stop();
83+
});
84+
85+
test.serial("stop() writes profile and deregisters signals", async (t) => {
86+
const {Session, postStub} = createSessionStubs();
87+
const writeFileSyncStub = sinon.stub();
88+
89+
const installed = new Map();
90+
sinon.stub(process, "on").callsFake((signal, handler) => {
91+
installed.set(signal, handler);
92+
return process;
93+
});
94+
const removeListenerStub = sinon.stub(process, "removeListener");
95+
96+
const {start, stop} = await esmock("../../../lib/utils/profile.js", {
97+
"node:inspector/promises": {Session},
98+
"node:fs": {writeFileSync: writeFileSyncStub}
99+
});
100+
101+
await start();
102+
t.true(postStub.calledWith("Profiler.start"));
103+
104+
await stop();
105+
106+
t.true(writeFileSyncStub.calledOnce, "profile written once");
107+
const [fileName, content] = writeFileSyncStub.firstCall.args;
108+
t.regex(fileName, /^\.\/ui5_\d{4}-\d{2}-\d{2}_\d{2}-\d{2}-\d{2}\.cpuprofile$/, "filename matches pattern");
109+
t.deepEqual(JSON.parse(content), {foo: "bar"}, "written profile content matches");
110+
111+
t.true(removeListenerStub.calledWith("SIGHUP", installed.get("SIGHUP")));
112+
t.true(removeListenerStub.calledWith("SIGINT", installed.get("SIGINT")));
113+
t.true(removeListenerStub.calledWith("SIGTERM", installed.get("SIGTERM")));
114+
t.true(removeListenerStub.calledWith("SIGBREAK", installed.get("SIGBREAK")));
115+
});
116+
117+
test.serial("stop() without start is a no-op", async (t) => {
118+
const writeFileSyncStub = sinon.stub();
119+
120+
const removeListenerStub = sinon.stub(process, "removeListener");
121+
122+
const {stop} = await esmock("../../../lib/utils/profile.js", {
123+
"node:inspector/promises": {Session: class {}},
124+
"node:fs": {writeFileSync: writeFileSyncStub}
125+
});
126+
127+
await stop();
128+
129+
t.true(removeListenerStub.notCalled, "no signal deregistration happened");
130+
t.true(writeFileSyncStub.notCalled, "no write happened");
131+
});
132+
133+
test.serial("signal handler stops profiling and exits", async (t) => {
134+
const {Session, postStub} = createSessionStubs();
135+
const writeFileSyncStub = sinon.stub();
136+
137+
const installed = new Map();
138+
sinon.stub(process, "on").callsFake((signal, handler) => {
139+
installed.set(signal, handler);
140+
return process;
141+
});
142+
const removeListenerStub = sinon.stub(process, "removeListener");
143+
const exitStub = sinon.stub(process, "exit");
144+
145+
const {start} = await esmock("../../../lib/utils/profile.js", {
146+
"node:inspector/promises": {Session},
147+
"node:fs": {writeFileSync: writeFileSyncStub}
148+
});
149+
150+
await start();
151+
152+
t.true(typeof installed.get("SIGINT") === "function", "SIGINT handler registered");
153+
154+
// Trigger the signal handler
155+
installed.get("SIGINT")();
156+
157+
// Allow the Promise chain in the handler (stop().then(...)) to run
158+
await new Promise((resolve) => setImmediate(resolve));
159+
160+
t.true(postStub.calledWith("Profiler.stop"), "Profiler.stop posted via handler");
161+
t.true(writeFileSyncStub.calledOnce, "profile written by handler");
162+
t.true(exitStub.calledWith(128 + 2), "process.exit called with SIGINT code");
163+
164+
// Signals should be deregistered during stop
165+
t.true(removeListenerStub.calledWith("SIGHUP", installed.get("SIGHUP")));
166+
t.true(removeListenerStub.calledWith("SIGINT", installed.get("SIGINT")));
167+
t.true(removeListenerStub.calledWith("SIGTERM", installed.get("SIGTERM")));
168+
t.true(removeListenerStub.calledWith("SIGBREAK", installed.get("SIGBREAK")));
169+
});

0 commit comments

Comments
 (0)