Skip to content

Commit faee6c2

Browse files
authored
Capture Node execution async ID with samples (#189)
1 parent 14b2d4f commit faee6c2

File tree

5 files changed

+20
-4
lines changed

5 files changed

+20
-4
lines changed

bindings/profilers/wall.cc

Lines changed: 9 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -321,7 +321,8 @@ void SignalHandler::HandleProfilerSignal(int sig,
321321
auto time_from = Now();
322322
old_handler(sig, info, context);
323323
auto time_to = Now();
324-
prof->PushContext(time_from, time_to, cpu_time);
324+
double async_id = node::AsyncHooksGetExecutionAsyncId(isolate);
325+
prof->PushContext(time_from, time_to, cpu_time, async_id);
325326
}
326327
#else
327328
class SignalHandler {
@@ -388,6 +389,7 @@ ContextsByNode WallProfiler::GetContextsByNode(CpuProfile* profile,
388389
auto contextKey = Nan::New<v8::String>("context").ToLocalChecked();
389390
auto timestampKey = Nan::New<v8::String>("timestamp").ToLocalChecked();
390391
auto cpuTimeKey = Nan::New<v8::String>("cpuTime").ToLocalChecked();
392+
auto asyncIdKey = Nan::New<v8::String>("asyncId").ToLocalChecked();
391393
auto V8toEpochOffset = GetV8ToEpochOffset();
392394
auto lastCpuTime = startCpuTime;
393395

@@ -457,6 +459,9 @@ ContextsByNode WallProfiler::GetContextsByNode(CpuProfile* profile,
457459
Nan::New<v8::Number>(sampleContext.cpu_time - lastCpuTime));
458460
lastCpuTime = sampleContext.cpu_time;
459461
}
462+
Nan::Set(timedContext,
463+
asyncIdKey,
464+
Nan::New<v8::Number>(sampleContext.async_id));
460465
Nan::Set(array, array->Length(), timedContext);
461466
}
462467

@@ -1003,14 +1008,15 @@ NAN_METHOD(WallProfiler::Dispose) {
10031008

10041009
void WallProfiler::PushContext(int64_t time_from,
10051010
int64_t time_to,
1006-
int64_t cpu_time) {
1011+
int64_t cpu_time,
1012+
double async_id) {
10071013
// Be careful this is called in a signal handler context therefore all
10081014
// operations must be async signal safe (in particular no allocations).
10091015
// Our ring buffer avoids allocations.
10101016
auto context = curContext_.load(std::memory_order_relaxed);
10111017
std::atomic_signal_fence(std::memory_order_acquire);
10121018
if (contexts_.size() < contexts_.capacity()) {
1013-
contexts_.push_back({*context, time_from, time_to, cpu_time});
1019+
contexts_.push_back({*context, time_from, time_to, cpu_time, async_id});
10141020
std::atomic_fetch_add_explicit(
10151021
reinterpret_cast<std::atomic<uint32_t>*>(&fields_[kSampleCount]),
10161022
1U,

bindings/profilers/wall.hh

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -82,6 +82,7 @@ class WallProfiler : public Nan::ObjectWrap {
8282
int64_t time_from;
8383
int64_t time_to;
8484
int64_t cpu_time;
85+
double async_id;
8586
};
8687

8788
using ContextBuffer = std::vector<SampleContext>;
@@ -118,7 +119,10 @@ class WallProfiler : public Nan::ObjectWrap {
118119

119120
v8::Local<v8::Value> GetContext(v8::Isolate*);
120121
void SetContext(v8::Isolate*, v8::Local<v8::Value>);
121-
void PushContext(int64_t time_from, int64_t time_to, int64_t cpu_time);
122+
void PushContext(int64_t time_from,
123+
int64_t time_to,
124+
int64_t cpu_time,
125+
double async_id);
122126
Result StartImpl();
123127
std::string StartInternal();
124128
Result StopImpl(bool restart, v8::Local<v8::Value>& profile);

ts/src/profile-serializer.ts

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -326,6 +326,7 @@ function updateTimeProfile(prof: TimeProfile): TimeProfile {
326326
context: {},
327327
timestamp: BigInt(0),
328328
cpuTime: prof.nonJSThreadsCpuTime,
329+
asyncId: -1,
329330
},
330331
],
331332
};

ts/src/v8-types.ts

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -41,6 +41,7 @@ export interface TimeProfileNodeContext {
4141
context: object;
4242
timestamp: bigint; // end of sample taking; in microseconds since epoch
4343
cpuTime: number; // cpu time in nanoseconds
44+
asyncId: number; // async_hooks.executionAsyncId() at the time of sample taking
4445
}
4546

4647
export interface TimeProfileNode extends ProfileNode {

ts/test/test-time-profiler.ts

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -135,6 +135,10 @@ describe('Time Profiler', () => {
135135
if (!context) {
136136
return {};
137137
}
138+
assert(
139+
typeof context.asyncId === 'number',
140+
'context.asyncId should be a number'
141+
);
138142
const labels: LabelSet = {};
139143
for (const [key, value] of Object.entries(context.context)) {
140144
if (typeof value === 'string') {

0 commit comments

Comments
 (0)