Skip to content

Commit 8561028

Browse files
jpinkney-awsjpinkney-aws
authored
fix(tests): improve reliability of performance tests (aws#5492)
## Problem - We currently do a one-shot performance test measurement, which can be be impacted by the underlying cpu ## Solution - Run 5 performance tests by default, this should give us a more accurate reading ### Performance of the last 10 test runs on my computer: ``` {userCpuUsage: 27.763992642839753, systemCpuUsage: 5.8700764000563925, duration: 0.0488549862, heapTotal: 0.15} {userCpuUsage: 32.432557472712574, systemCpuUsage: 7.287778251185924, duration: 0.0350972354, heapTotal: 0.15} {userCpuUsage: 36.17269595509756, systemCpuUsage: 8.190125881726889, duration: 0.0313357906, heapTotal: 0.15} {userCpuUsage: 23.575720185158513, systemCpuUsage: 5.680905138190308, duration: 0.0468292694, heapTotal: 0.05} {userCpuUsage: 29.722270663855547, systemCpuUsage: 6.725376761131834, duration: 0.044072017399999996, heapTotal: 0.05} {userCpuUsage: 30.981420694546227, systemCpuUsage: 6.724871937232588, duration: 0.0404778744, heapTotal: 0.05} {userCpuUsage: 29.15659118178076, systemCpuUsage: 6.544881314879868, duration: 0.0438601896, heapTotal: 0.15} {userCpuUsage: 29.66190894781342, systemCpuUsage: 6.556456308274413, duration: 0.042828962400000004, heapTotal: 0.1} {userCpuUsage: 32.209253755861006, systemCpuUsage: 7.245284221753529, duration: 0.036528329, heapTotal: 0.1} {userCpuUsage: 30.4379237001285, systemCpuUsage: 6.790691656039722, duration: 0.0378142194, heapTotal: 0.1} {userCpuUsage: 28.075430930361144, systemCpuUsage: 6.952612678963097, duration: 0.042763791, heapTotal: 0.1} ``` <!--- REMINDER: - Read CONTRIBUTING.md first. - Add test coverage for your changes. - Update the changelog using `npm run newChange`. - Link to related issues/commits. - Testing: how did you test your changes? - Screenshots (if the pull request is related to UI/UX then please include light and dark theme screenshots) --> ## License By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.
1 parent ab46760 commit 8561028

File tree

6 files changed

+106
-30
lines changed

6 files changed

+106
-30
lines changed

‎packages/core/src/shared/performance/performance.ts‎

Lines changed: 78 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -8,7 +8,17 @@ import { getLogger } from '../logger'
88
import { isWeb } from '../extensionGlobals'
99

1010
interface PerformanceMetrics {
11-
cpuUsage: number
11+
/**
12+
* The percentange of CPU time spent executing the user-space portions
13+
* of the application, (javascript and user-space libraries/dependencies)
14+
*/
15+
userCpuUsage: number
16+
17+
/**
18+
* The percentage CPU time spent executing system-level operations
19+
* related to the application, (file I/O, network, ipc, other kernel-space tasks)
20+
*/
21+
systemCpuUsage: number
1222
heapTotal: number
1323
duration: number
1424
}
@@ -17,6 +27,7 @@ interface TestOptions {
1727
darwin?: Partial<PerformanceMetrics>
1828
win32?: Partial<PerformanceMetrics>
1929
linux?: Partial<PerformanceMetrics>
30+
testRuns?: number
2031
}
2132

2233
export interface PerformanceSpan<T> {
@@ -55,13 +66,16 @@ export class PerformanceTracker {
5566

5667
const elapsedTime = process.hrtime(this.#startPerformance.duration)
5768
const duration = elapsedTime[0] + elapsedTime[1] / 1e9 // convert microseconds to seconds
58-
const usage = ((userCpuUsage + systemCpuUsage) / duration) * 100 // convert to percentage
69+
70+
const totalUserUsage = (userCpuUsage / duration) * 100
71+
const totalSystemUsage = (systemCpuUsage / duration) * 100
5972

6073
const endMemoryUsage = process.memoryUsage().heapTotal - this.#startPerformance?.memory
6174
const endMemoryUsageInMB = endMemoryUsage / (1024 * 1024) // converting bytes to MB
6275

6376
return {
64-
cpuUsage: usage,
77+
userCpuUsage: totalUserUsage,
78+
systemCpuUsage: totalSystemUsage,
6579
heapTotal: endMemoryUsageInMB,
6680
duration,
6781
}
@@ -71,21 +85,60 @@ export class PerformanceTracker {
7185
}
7286
}
7387

74-
export function performanceTest(options: TestOptions, name: string, fn: () => Promise<void>): Mocha.Test
75-
export function performanceTest(options: TestOptions, name: string, fn: () => void): Mocha.Test
88+
/**
89+
* Generate a test suite that runs fn options.testRuns times and gets the average performance metrics of all the test runs
90+
*/
91+
export function performanceTest(options: TestOptions, name: string, fn: () => Promise<void>): Mocha.Suite
92+
export function performanceTest(options: TestOptions, name: string, fn: () => void): Mocha.Suite
7693
export function performanceTest(options: TestOptions, name: string, fn: () => void | Promise<void>) {
7794
const testOption = options[process.platform as 'linux' | 'darwin' | 'win32']
7895

79-
const performanceTracker = new PerformanceTracker(name)
96+
const totalTestRuns = options.testRuns ?? 5
97+
98+
return describe(`${name} performance tests`, async () => {
99+
let performanceTracker: PerformanceTracker | undefined
100+
const testRunMetrics: PerformanceMetrics[] = []
101+
102+
beforeEach(() => {
103+
performanceTracker = new PerformanceTracker(name)
104+
performanceTracker.start()
105+
})
106+
107+
afterEach(() => {
108+
const metrics = performanceTracker?.stop()
109+
if (!metrics) {
110+
assert.fail('Performance metrics not found')
111+
}
112+
testRunMetrics.push(metrics)
113+
})
80114

81-
return it(name, async () => {
82-
performanceTracker.start()
83-
await fn()
84-
const metrics = performanceTracker.stop()
85-
if (!metrics) {
86-
assert.fail('Performance metrics not found')
115+
for (let testRun = 1; testRun <= totalTestRuns; testRun++) {
116+
it(`${name} - test run ${testRun}`, async () => {
117+
await fn()
118+
})
87119
}
88-
assertPerformanceMetrics(metrics, name, testOption)
120+
121+
after(async () => {
122+
const totalUserCPUUsage =
123+
testRunMetrics.reduce((acc, metric) => acc + metric.userCpuUsage, 0) / testRunMetrics.length
124+
const totalSystemCPUUsage =
125+
testRunMetrics.reduce((acc, metric) => acc + metric.systemCpuUsage, 0) / testRunMetrics.length
126+
const totalMemoryUsage =
127+
testRunMetrics.reduce((acc, metric) => acc + metric.heapTotal, 0) / testRunMetrics.length
128+
const totalDuration =
129+
testRunMetrics.reduce((acc, metric) => acc + metric.duration, 0) / testRunMetrics.length
130+
131+
assertPerformanceMetrics(
132+
{
133+
userCpuUsage: totalUserCPUUsage,
134+
systemCpuUsage: totalSystemCPUUsage,
135+
duration: totalDuration,
136+
heapTotal: totalMemoryUsage,
137+
},
138+
name,
139+
testOption
140+
)
141+
})
89142
})
90143
}
91144

@@ -94,12 +147,20 @@ function assertPerformanceMetrics(
94147
name: string,
95148
testOption?: Partial<PerformanceMetrics>
96149
) {
97-
const expectedCPUUsage = testOption?.cpuUsage ?? 50
98-
const foundCPUUsage = performanceMetrics.cpuUsage
150+
const expectedUserCPUUsage = testOption?.userCpuUsage ?? 50
151+
const foundUserCPUUsage = performanceMetrics.userCpuUsage
152+
153+
assert(
154+
foundUserCPUUsage < expectedUserCPUUsage,
155+
`Expected total user CPU usage for ${name} to be less than ${expectedUserCPUUsage}. Actual user CPU usage was ${foundUserCPUUsage}`
156+
)
157+
158+
const expectedSystemCPUUsage = testOption?.systemCpuUsage ?? 20
159+
const foundSystemCPUUsage = performanceMetrics.systemCpuUsage
99160

100161
assert(
101-
foundCPUUsage < expectedCPUUsage,
102-
`Expected total CPU usage for ${name} to be less than ${expectedCPUUsage}. Actual CPU usage was ${foundCPUUsage}`
162+
foundSystemCPUUsage < expectedUserCPUUsage,
163+
`Expected total system CPU usage for ${name} to be less than ${expectedSystemCPUUsage}. Actual system CPU usage was ${foundSystemCPUUsage}`
103164
)
104165

105166
const expectedMemoryUsage = testOption?.heapTotal ?? 400

‎packages/core/src/shared/telemetry/spans.ts‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -224,7 +224,8 @@ export class TelemetrySpan<T extends MetricBase = MetricBase> {
224224
const performanceMetrics = this.#performance?.stop()
225225
if (performanceMetrics) {
226226
this.record({
227-
cpuUsage: performanceMetrics.cpuUsage,
227+
userCpuUsage: performanceMetrics.userCpuUsage,
228+
systemCpuUsage: performanceMetrics.systemCpuUsage,
228229
heapTotal: performanceMetrics.heapTotal,
229230
functionName: this.#options.functionId?.name ?? this.name,
230231
} as any)

‎packages/core/src/shared/telemetry/vscodeTelemetry.json‎

Lines changed: 12 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -277,9 +277,14 @@
277277
"description": "A detailed state of a specific auth connection. Use `authStatus` for a higher level view of an extension's general connection."
278278
},
279279
{
280-
"name": "cpuUsage",
280+
"name": "userCpuUsage",
281281
"type": "int",
282-
"description": "Percentage of cpu usage"
282+
"description": "Percentage of user cpu usage (user space)"
283+
},
284+
{
285+
"name": "systemCpuUsage",
286+
"type": "int",
287+
"description": "Percentage of system cpu usage (kernal space)"
283288
},
284289
{
285290
"name": "heapTotal",
@@ -1095,7 +1100,11 @@
10951100
"description": "Represents a function call. In most cases this should wrap code with a run(), then you can add context.",
10961101
"metadata": [
10971102
{
1098-
"type": "cpuUsage",
1103+
"type": "userCpuUsage",
1104+
"required": true
1105+
},
1106+
{
1107+
"type": "systemCpuUsage",
10991108
"required": true
11001109
},
11011110
{

‎packages/core/src/test/shared/performance/performance.test.ts‎

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -21,12 +21,14 @@ describe('performance tooling', () => {
2121

2222
describe('PerformanceTracker', () => {
2323
it('gets performance metrics', () => {
24-
const { expectedCpuUsage, expectedHeapTotal, expectedTotalSeconds } = stubPerformance(sandbox)
24+
const { expectedUserCpuUsage, expectedSystemCpuUsage, expectedHeapTotal, expectedTotalSeconds } =
25+
stubPerformance(sandbox)
2526
const perf = new PerformanceTracker('foo')
2627
perf.start()
2728
const metrics = perf.stop()
2829

29-
assert.deepStrictEqual(metrics?.cpuUsage, expectedCpuUsage)
30+
assert.deepStrictEqual(metrics?.userCpuUsage, expectedUserCpuUsage)
31+
assert.deepStrictEqual(metrics?.systemCpuUsage, expectedSystemCpuUsage)
3032
assert.deepStrictEqual(metrics?.heapTotal, expectedHeapTotal)
3133
assert.deepStrictEqual(metrics?.duration, expectedTotalSeconds)
3234
})

‎packages/core/src/test/shared/telemetry/spans.test.ts‎

Lines changed: 6 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -78,15 +78,16 @@ describe('TelemetrySpan', function () {
7878
})
7979

8080
it('records performance', function () {
81-
const { expectedCpuUsage, expectedHeapTotal } = stubPerformance(sandbox)
81+
const { expectedUserCpuUsage, expectedSystemCpuUsage, expectedHeapTotal } = stubPerformance(sandbox)
8282
const span = new TelemetrySpan('function_call', {
8383
emit: true,
8484
})
8585
span.start()
8686
clock.tick(90)
8787
span.stop()
8888
assertTelemetry('function_call', {
89-
cpuUsage: expectedCpuUsage,
89+
userCpuUsage: expectedUserCpuUsage,
90+
systemCpuUsage: expectedSystemCpuUsage,
9091
heapTotal: expectedHeapTotal,
9192
duration: 90,
9293
result: 'Succeeded',
@@ -269,7 +270,7 @@ describe('TelemetryTracer', function () {
269270

270271
it('records performance', function () {
271272
clock = installFakeClock()
272-
const { expectedCpuUsage, expectedHeapTotal } = stubPerformance(sandbox)
273+
const { expectedUserCpuUsage, expectedSystemCpuUsage, expectedHeapTotal } = stubPerformance(sandbox)
273274
tracer.run(
274275
'function_call',
275276
() => {
@@ -281,7 +282,8 @@ describe('TelemetryTracer', function () {
281282
)
282283

283284
assertTelemetry('function_call', {
284-
cpuUsage: expectedCpuUsage,
285+
userCpuUsage: expectedUserCpuUsage,
286+
systemCpuUsage: expectedSystemCpuUsage,
285287
heapTotal: expectedHeapTotal,
286288
duration: 90,
287289
result: 'Succeeded',

‎packages/core/src/test/utilities/performance.ts‎

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -6,11 +6,11 @@
66
import Sinon from 'sinon'
77

88
export function stubPerformance(sandbox: Sinon.SinonSandbox) {
9-
const expectedCpuUsage = { user: 10000, system: 2000 }
9+
const cpuUsage = { user: 10000, system: 2000 }
1010
const initialHeapTotal = 1
1111
const totalNanoseconds = 30000000 // 0.03 seconds
1212

13-
sandbox.stub(process, 'cpuUsage').returns(expectedCpuUsage)
13+
sandbox.stub(process, 'cpuUsage').returns(cpuUsage)
1414

1515
const memoryUsageStub = sandbox.stub(process, 'memoryUsage')
1616
memoryUsageStub
@@ -21,7 +21,8 @@ export function stubPerformance(sandbox: Sinon.SinonSandbox) {
2121
sandbox.stub(process, 'hrtime').onCall(0).returns([0, 0]).onCall(1).returns([0, totalNanoseconds])
2222

2323
return {
24-
expectedCpuUsage: 40,
24+
expectedUserCpuUsage: 33.333333333333336,
25+
expectedSystemCpuUsage: 6.666666666666667,
2526
expectedHeapTotal: 10,
2627
expectedTotalSeconds: totalNanoseconds / 1e9,
2728
}

0 commit comments

Comments
 (0)