Skip to content

Commit 89afc6d

Browse files
committed
- Preserve idle samples with zero wall time and no cpu time rollup to next
- Fix optionality of various elements of the time profile context
1 parent 3be8293 commit 89afc6d

File tree

4 files changed

+49
-49
lines changed

4 files changed

+49
-49
lines changed

bindings/profilers/wall.cc

Lines changed: 28 additions & 29 deletions
Original file line numberDiff line numberDiff line change
@@ -61,12 +61,6 @@ namespace dd {
6161
// Maximum number of rounds in the GetV8ToEpochOffset
6262
static constexpr int MAX_EPOCH_OFFSET_ATTEMPTS = 20;
6363

64-
bool isIdleOrProgram(const v8::CpuProfileNode* node) {
65-
auto* function_name = node->GetFunctionNameStr();
66-
return strcmp(function_name, "(idle)") == 0 ||
67-
strcmp(function_name, "(program)") == 0;
68-
}
69-
7064
int getTotalHitCount(const v8::CpuProfileNode* node, bool* noHitLeaf) {
7165
int count = node->GetHitCount();
7266
auto child_count = node->GetChildrenCount();
@@ -450,23 +444,17 @@ std::shared_ptr<ContextsByNode> WallProfiler::GetContextsByNode(
450444
array = it->second.contexts;
451445
++it->second.hitcount;
452446
}
453-
if (sampleContext.context) {
454-
// Conforms to TimeProfileNodeContext defined in v8-types.ts
455-
Local<Object> timedContext = Object::New(isolate);
456-
timedContext
457-
->Set(v8Context,
458-
contextKey,
459-
sampleContext.context.get()->Get(isolate))
460-
.Check();
461-
timedContext
462-
->Set(v8Context,
463-
timestampKey,
464-
BigInt::New(isolate, sampleTimestamp + V8toEpochOffset))
465-
.Check();
466-
467-
// if current sample is idle/program, reports its cpu time to the next
468-
// sample
469-
if (collectCpuTime_ && !isIdleOrProgram(sample)) {
447+
// Conforms to TimeProfileNodeContext defined in v8-types.ts
448+
Local<Object> timedContext = Object::New(isolate);
449+
timedContext
450+
->Set(v8Context,
451+
timestampKey,
452+
BigInt::New(isolate, sampleTimestamp + V8toEpochOffset))
453+
.Check();
454+
auto* function_name = sample->GetFunctionNameStr();
455+
// If current sample is program, reports its cpu time to the next sample
456+
if (strcmp(function_name, "(program)") != 0) {
457+
if (collectCpuTime_) {
470458
timedContext
471459
->Set(v8Context,
472460
cpuTimeKey,
@@ -475,13 +463,24 @@ std::shared_ptr<ContextsByNode> WallProfiler::GetContextsByNode(
475463
.Check();
476464
lastCpuTime = sampleContext.cpu_time;
477465
}
478-
timedContext
479-
->Set(v8Context,
480-
asyncIdKey,
481-
NewNumberFromInt64(isolate, sampleContext.async_id))
482-
.Check();
483-
array->Set(v8Context, array->Length(), timedContext).Check();
466+
// If current sample is neither program nor idle, associate a sampling
467+
// context and async ID
468+
if (strcmp(function_name, "(idle)") != 0) {
469+
if (sampleContext.context) {
470+
timedContext
471+
->Set(v8Context,
472+
contextKey,
473+
sampleContext.context.get()->Get(isolate))
474+
.Check();
475+
}
476+
timedContext
477+
->Set(v8Context,
478+
asyncIdKey,
479+
NewNumberFromInt64(isolate, sampleContext.async_id))
480+
.Check();
481+
}
484482
}
483+
array->Set(v8Context, array->Length(), timedContext).Check();
485484

486485
// Sample context was consumed, fetch the next one
487486
++contextIt;

ts/src/profile-serializer.ts

Lines changed: 16 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -270,7 +270,9 @@ function computeTotalHitCount(root: TimeProfileNode): number {
270270

271271
/** Perform some modifications on time profile:
272272
* - Add non-JS thread activity node if available
273-
* - Remove `(idle)` and `(program)` nodes
273+
* - remove `(program)` nodes
274+
* - remove `(idle)` nodes with no context
275+
* - set `(idle)` nodes' wall time to zero when they have a context
274276
* - Convert `(garbage collector)` node to `Garbage Collection`
275277
* - Put `non-JS thread activity` node and `Garbage Collection` under a top level `Node.js` node
276278
* This function does not change the input profile.
@@ -297,7 +299,10 @@ function updateTimeProfile(prof: TimeProfile): TimeProfile {
297299
}
298300

299301
for (const child of prof.topDownRoot.children as TimeProfileNode[]) {
300-
if (child.name === '(idle)' || child.name === '(program)') {
302+
if (child.name === '(program)') {
303+
continue;
304+
}
305+
if (child.name === '(idle)' && child.contexts?.length === 0) {
301306
continue;
302307
}
303308
if (child.name === '(garbage collector)') {
@@ -377,17 +382,19 @@ export function serializeTimeProfile(
377382
) => {
378383
let unlabelledHits = entry.node.hitCount;
379384
let unlabelledCpuTime = 0;
385+
const isIdle = entry.node.name === '(idle)';
380386
for (const context of entry.node.contexts || []) {
381387
const labels = generateLabels
382388
? generateLabels({node: entry.node, context})
383-
: context.context;
389+
: context.context ?? {};
384390
if (Object.keys(labels).length > 0) {
385391
// Only assign wall time if there are hits, some special nodes such as `(Non-JS threads)`
386392
// have zero hit count (since they do not count as wall time) and should not be assigned any
387-
// wall time.
388-
const values = unlabelledHits > 0 ? [1, intervalNanos] : [0, 0];
393+
// wall time. Also, `(idle)` nodes should be assigned zero wall time.
394+
const values =
395+
unlabelledHits > 0 ? [1, isIdle ? 0 : intervalNanos] : [0, 0];
389396
if (prof.hasCpuTime) {
390-
values.push(context.cpuTime);
397+
values.push(context.cpuTime ?? 0);
391398
}
392399
const sample = new Sample({
393400
locationId: entry.stack,
@@ -397,14 +404,14 @@ export function serializeTimeProfile(
397404
samples.push(sample);
398405
unlabelledHits--;
399406
} else if (prof.hasCpuTime) {
400-
unlabelledCpuTime += context.cpuTime;
407+
unlabelledCpuTime += context.cpuTime ?? 0;
401408
}
402409
}
403-
if (unlabelledHits > 0 || unlabelledCpuTime > 0) {
410+
if ((!isIdle && unlabelledHits > 0) || unlabelledCpuTime > 0) {
404411
const labels = generateLabels ? generateLabels({node: entry.node}) : {};
405412
const values =
406413
unlabelledHits > 0
407-
? [unlabelledHits, unlabelledHits * intervalNanos]
414+
? [unlabelledHits, isIdle ? 0 : unlabelledHits * intervalNanos]
408415
: [0, 0];
409416
if (prof.hasCpuTime) {
410417
values.push(unlabelledCpuTime);

ts/src/v8-types.ts

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -38,10 +38,10 @@ export interface ProfileNode {
3838
}
3939

4040
export interface TimeProfileNodeContext {
41-
context: object;
41+
context?: object;
4242
timestamp: bigint; // end of sample taking; in microseconds since epoch
43-
cpuTime: number; // cpu time in nanoseconds
44-
asyncId: number; // async_hooks.executionAsyncId() at the time of sample taking
43+
cpuTime?: number; // cpu time in nanoseconds
44+
asyncId?: number; // async_hooks.executionAsyncId() at the time of sample taking
4545
}
4646

4747
export interface TimeProfileNode extends ProfileNode {

ts/test/test-time-profiler.ts

Lines changed: 2 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -36,13 +36,7 @@ describe('Time Profiler', () => {
3636
it('should exclude program and idle time', async () => {
3737
const profile = await time.profile(PROFILE_OPTIONS);
3838
assert.ok(profile.stringTable);
39-
assert.deepEqual(
40-
[
41-
profile.stringTable.strings!.indexOf('(program)'),
42-
profile.stringTable.strings!.indexOf('(idle)'),
43-
],
44-
[-1, -1]
45-
);
39+
assert.equal(profile.stringTable.strings!.indexOf('(program)'), -1);
4640
});
4741

4842
it('should update state', function () {
@@ -140,7 +134,7 @@ describe('Time Profiler', () => {
140134
'context.asyncId should be a number'
141135
);
142136
const labels: LabelSet = {};
143-
for (const [key, value] of Object.entries(context.context)) {
137+
for (const [key, value] of Object.entries(context.context ?? {})) {
144138
if (typeof value === 'string') {
145139
labels[key] = value;
146140
if (

0 commit comments

Comments
 (0)