Skip to content

Commit 391b56d

Browse files
nsavoirensavoire
authored
Make sure to not report wall time as part of non-JS threads (#159)
* Only compute non-JS thread CPU time when CPU profiling is enabled * Do not serialize `nonJSThreadsCpuTime` if profile has no CPU time * Fix non-zero wall time in non-JS threads CPU time sample During serialization, every context with labels was counted as if it was a wall time sample. But that is not the case for non-JS threads sample. With this commit, a context with labels has wall time only if its profile node has a non zero hitcount. * Add some tests non-JS threads CPU sample * Check that sample is not serialized when CPU profiling is not enabled * Check that sample has zero wall time
1 parent 7d7500a commit 391b56d

File tree

5 files changed

+165
-40
lines changed

5 files changed

+165
-40
lines changed

‎bindings/profilers/wall.cc

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -856,7 +856,7 @@ Result WallProfiler::StopImpl(bool restart, v8::Local<v8::Value>& profile) {
856856
if (withContexts_) {
857857
int64_t nonJSThreadsCpuTime{};
858858

859-
if (isMainThread_) {
859+
if (isMainThread_ && collectCpuTime_) {
860860
// account for non-JS threads CPU only in main thread
861861
// CPU time of non-JS threads is the difference between process CPU time
862862
// and sum of all worker JS thread during the profiling period of main

‎ts/src/profile-serializer.ts

Lines changed: 9 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -306,7 +306,10 @@ export function serializeTimeProfile(
306306
? generateLabels({node: entry.node, context})
307307
: context.context;
308308
if (Object.keys(labels).length > 0) {
309-
const values = [1, intervalNanos];
309+
// Only assign wall time if there are hits, some special nodes such as `(Non-JS threads)`
310+
// have zero hit count (since they do not count as wall time) and should not be assigned any
311+
// wall time.
312+
const values = unlabelledHits > 0 ? [1, intervalNanos] : [0, 0];
310313
if (prof.hasCpuTime) {
311314
values.push(context.cpuTime);
312315
}
@@ -323,7 +326,10 @@ export function serializeTimeProfile(
323326
}
324327
if (unlabelledHits > 0 || unlabelledCpuTime > 0) {
325328
const labels = generateLabels ? generateLabels({node: entry.node}) : {};
326-
const values = [unlabelledHits, unlabelledHits * intervalNanos];
329+
const values =
330+
unlabelledHits > 0
331+
? [unlabelledHits, unlabelledHits * intervalNanos]
332+
: [0, 0];
327333
if (prof.hasCpuTime) {
328334
values.push(unlabelledCpuTime);
329335
}
@@ -354,7 +360,7 @@ export function serializeTimeProfile(
354360
period: intervalNanos,
355361
};
356362

357-
if (prof.nonJSThreadsCpuTime) {
363+
if (prof.hasCpuTime && prof.nonJSThreadsCpuTime) {
358364
const node: TimeProfileNode = {
359365
name: NON_JS_THREADS_FUNCTION_NAME,
360366
scriptName: '',

‎ts/test/profiles-for-tests.ts

Lines changed: 32 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,8 @@ import {Function, Location, Profile, Sample, ValueType} from 'pprof-format';
2424
import {TimeProfile} from '../src/v8-types';
2525
import {StringTable} from 'pprof-format';
2626

27+
import assert from 'assert';
28+
2729
function buildStringTable(values: string[]): StringTable {
2830
const table = new StringTable();
2931
for (const value of values) {
@@ -1224,3 +1226,33 @@ export const labelEncodingProfile = {
12241226
],
12251227
},
12261228
};
1229+
1230+
const {hasOwnProperty} = Object.prototype;
1231+
1232+
// eslint-disable-next-line @typescript-eslint/no-explicit-any
1233+
export function getAndVerifyPresence(
1234+
list: any[],
1235+
id: number,
1236+
zeroIndex = false
1237+
) {
1238+
assert.strictEqual(typeof id, 'number', 'has id');
1239+
const index = id - (zeroIndex ? 0 : 1);
1240+
assert.ok(list.length > index, 'exists in list');
1241+
return list[index];
1242+
}
1243+
1244+
export function getAndVerifyString(
1245+
stringTable: StringTable,
1246+
// eslint-disable-next-line @typescript-eslint/no-explicit-any
1247+
source: any,
1248+
field: string
1249+
) {
1250+
assert.ok(hasOwnProperty.call(source, field), 'has id field');
1251+
const str = getAndVerifyPresence(
1252+
stringTable.strings,
1253+
source[field] as number,
1254+
true
1255+
);
1256+
assert.strictEqual(typeof str, 'string', 'is a string');
1257+
return str;
1258+
}

‎ts/test/test-profile-serializer.ts

Lines changed: 118 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -17,22 +17,23 @@ import * as sinon from 'sinon';
1717
import * as tmp from 'tmp';
1818

1919
import {
20+
NON_JS_THREADS_FUNCTION_NAME,
2021
serializeHeapProfile,
2122
serializeTimeProfile,
2223
} from '../src/profile-serializer';
2324
import {SourceMapper} from '../src/sourcemapper/sourcemapper';
24-
import {Label} from 'pprof-format';
25+
import {Label, Profile} from 'pprof-format';
26+
import {TimeProfile} from '../src/v8-types';
2527
import {
2628
anonymousFunctionHeapProfile,
27-
anonymousFunctionTimeProfile,
29+
getAndVerifyPresence,
2830
heapProfile,
2931
heapSourceProfile,
3032
labelEncodingProfile,
3133
mapDirPath,
3234
timeProfile,
3335
timeSourceProfile,
3436
v8AnonymousFunctionHeapProfile,
35-
v8AnonymousFunctionTimeProfile,
3637
v8HeapGeneratedProfile,
3738
v8HeapProfile,
3839
v8TimeGeneratedProfile,
@@ -41,6 +42,24 @@ import {
4142

4243
const assert = require('assert');
4344

45+
function getNonJSThreadsSample(profile: Profile): Number[] | null {
46+
for (const sample of profile.sample!) {
47+
const locationId = sample.locationId[0];
48+
const location = getAndVerifyPresence(
49+
profile.location!,
50+
locationId as number
51+
);
52+
const functionId = location.line![0].functionId;
53+
const fn = getAndVerifyPresence(profile.function!, functionId as number);
54+
const fn_name = profile.stringTable.strings[fn.name as number];
55+
if (fn_name === NON_JS_THREADS_FUNCTION_NAME) {
56+
return sample.value as Number[];
57+
}
58+
}
59+
60+
return null;
61+
}
62+
4463
describe('profile-serializer', () => {
4564
let dateStub: sinon.SinonStub<[], number>;
4665

@@ -56,12 +75,103 @@ describe('profile-serializer', () => {
5675
const timeProfileOut = serializeTimeProfile(v8TimeProfile, 1000);
5776
assert.deepEqual(timeProfileOut, timeProfile);
5877
});
59-
it('should produce expected profile when there is anyonmous function', () => {
60-
const timeProfileOut = serializeTimeProfile(
61-
v8AnonymousFunctionTimeProfile,
62-
1000
78+
79+
it('should omit non-jS threads CPU time when profile has no CPU time', () => {
80+
const timeProfile: TimeProfile = {
81+
startTime: 0,
82+
endTime: 10 * 1000 * 1000,
83+
hasCpuTime: false,
84+
nonJSThreadsCpuTime: 1000,
85+
topDownRoot: {
86+
name: '(root)',
87+
scriptName: 'root',
88+
scriptId: 0,
89+
lineNumber: 0,
90+
columnNumber: 0,
91+
hitCount: 0,
92+
children: [],
93+
},
94+
};
95+
const timeProfileOut = serializeTimeProfile(timeProfile, 1000);
96+
assert.equal(getNonJSThreadsSample(timeProfileOut), null);
97+
const timeProfileOutWithLabels = serializeTimeProfile(
98+
timeProfile,
99+
1000,
100+
undefined,
101+
false,
102+
() => {
103+
return {foo: 'bar'};
104+
}
105+
);
106+
assert.equal(getNonJSThreadsSample(timeProfileOutWithLabels), null);
107+
});
108+
109+
it('should omit non-jS threads CPU time when it is zero', () => {
110+
const timeProfile: TimeProfile = {
111+
startTime: 0,
112+
endTime: 10 * 1000 * 1000,
113+
hasCpuTime: true,
114+
nonJSThreadsCpuTime: 0,
115+
topDownRoot: {
116+
name: '(root)',
117+
scriptName: 'root',
118+
scriptId: 0,
119+
lineNumber: 0,
120+
columnNumber: 0,
121+
hitCount: 0,
122+
children: [],
123+
},
124+
};
125+
const timeProfileOut = serializeTimeProfile(timeProfile, 1000);
126+
assert.equal(getNonJSThreadsSample(timeProfileOut), null);
127+
const timeProfileOutWithLabels = serializeTimeProfile(
128+
timeProfile,
129+
1000,
130+
undefined,
131+
false,
132+
() => {
133+
return {foo: 'bar'};
134+
}
135+
);
136+
assert.equal(getNonJSThreadsSample(timeProfileOutWithLabels), null);
137+
});
138+
139+
it('should produce Non-JS thread sample with zero wall time', () => {
140+
const timeProfile: TimeProfile = {
141+
startTime: 0,
142+
endTime: 10 * 1000 * 1000,
143+
hasCpuTime: true,
144+
nonJSThreadsCpuTime: 1000,
145+
topDownRoot: {
146+
name: '(root)',
147+
scriptName: 'root',
148+
scriptId: 0,
149+
lineNumber: 0,
150+
columnNumber: 0,
151+
hitCount: 0,
152+
children: [],
153+
},
154+
};
155+
const timeProfileOut = serializeTimeProfile(timeProfile, 1000);
156+
const values = getNonJSThreadsSample(timeProfileOut);
157+
assert.notEqual(values, null);
158+
assert.equal(values![0], 0);
159+
assert.equal(values![1], 0);
160+
assert.equal(values![2], 1000);
161+
const timeProfileOutWithLabels = serializeTimeProfile(
162+
timeProfile,
163+
1000,
164+
undefined,
165+
false,
166+
() => {
167+
return {foo: 'bar'};
168+
}
63169
);
64-
assert.deepEqual(timeProfileOut, anonymousFunctionTimeProfile);
170+
const valuesWithLabels = getNonJSThreadsSample(timeProfileOutWithLabels);
171+
assert.notEqual(valuesWithLabels, null);
172+
assert.equal(valuesWithLabels![0], 0);
173+
assert.equal(valuesWithLabels![1], 0);
174+
assert.equal(valuesWithLabels![2], 1000);
65175
});
66176
});
67177

‎ts/test/worker.ts

Lines changed: 5 additions & 28 deletions
Original file line numberDiff line numberDiff line change
@@ -1,11 +1,10 @@
11
import {Worker, isMainThread, workerData, parentPort} from 'worker_threads';
22
import {pbkdf2} from 'crypto';
33
import {time} from '../src/index';
4-
import {Profile, StringTable, ValueType} from 'pprof-format';
4+
import {Profile, ValueType} from 'pprof-format';
5+
import {getAndVerifyPresence, getAndVerifyString} from './profiles-for-tests';
56

6-
const assert = require('assert');
7-
8-
const {hasOwnProperty} = Object.prototype;
7+
import assert from 'assert';
98

109
const DURATION_MILLIS = 1000;
1110
const intervalMicros = 10000;
@@ -122,30 +121,6 @@ function sampleName(profile: Profile, sampleType: ValueType[]) {
122121
return sampleType.map(valueName.bind(null, profile));
123122
}
124123

125-
// eslint-disable-next-line @typescript-eslint/no-explicit-any
126-
function getAndVerifyPresence(list: any[], id: number, zeroIndex = false) {
127-
assert.strictEqual(typeof id, 'number', 'has id');
128-
const index = id - (zeroIndex ? 0 : 1);
129-
assert.ok(list.length > index, 'exists in list');
130-
return list[index];
131-
}
132-
133-
function getAndVerifyString(
134-
stringTable: StringTable,
135-
// eslint-disable-next-line @typescript-eslint/no-explicit-any
136-
source: any,
137-
field: string
138-
) {
139-
assert.ok(hasOwnProperty.call(source, field), 'has id field');
140-
const str = getAndVerifyPresence(
141-
stringTable.strings,
142-
source[field] as number,
143-
true
144-
);
145-
assert.strictEqual(typeof str, 'string', 'is a string');
146-
return str;
147-
}
148-
149124
function getCpuTime(profile: Profile) {
150125
let jsCpuTime = 0;
151126
let nonJsCpuTime = 0;
@@ -161,6 +136,8 @@ function getCpuTime(profile: Profile) {
161136
const fn_name = profile.stringTable.strings[fn.name as number];
162137
if (fn_name === time.constants.NON_JS_THREADS_FUNCTION_NAME) {
163138
nonJsCpuTime += sample.value![2] as number;
139+
assert.strictEqual(sample.value![0], 0);
140+
assert.strictEqual(sample.value![1], 0);
164141
} else {
165142
jsCpuTime += sample.value![2] as number;
166143
}

0 commit comments

Comments
 (0)