Skip to content

Only collect async ID when it's safe to do so #197

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
szegedi merged 4 commits into from
Mar 19, 2025
Merged

Only collect async ID when it's safe to do so #197

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
b0e8085
Guard against collecting async ID while performing GC
szegedi Feb 17, 2025
bb0bc2d
Additional sanity checks:
szegedi Feb 17, 2025
a694680
Move GetAsyncId and GC callbacks out of the header file.
szegedi Feb 27, 2025
79992a0
Have a config option for collecting async IDs
szegedi Mar 6, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
151 changes: 99 additions & 52 deletions bindings/profilers/wall.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -291,6 +291,9 @@ void SignalHandler::HandleProfilerSignal(int sig,
return;
}
auto isolate = Isolate::GetCurrent();
if (!isolate || isolate->IsDead()) {
Copy link
Copy Markdown

@nsavoire nsavoire Feb 26, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In which cases does GetCurrent returns null ?

Copy link
Copy Markdown
Author

@szegedi szegedi Feb 27, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I honestly don't know – I'm just trying to be pedantically defensive and not unconditionally dereference a pointer. I can envision a race condition between signal delivery and an isolate going away? I know the logic is different, but even the V8 sampler manager checks for isolate on a sampler not being null.

Copy link
Copy Markdown
Author

@szegedi szegedi Feb 27, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I could be more lenient and still invoke old_handler?

Copy link
Copy Markdown

@nsavoire nsavoire Mar 7, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it's ok as this.

return;
}
WallProfiler* prof = g_profilers.GetProfiler(isolate);

if (!prof) {
Expand All @@ -315,9 +318,7 @@ void SignalHandler::HandleProfilerSignal(int sig,
auto time_from = Now();
old_handler(sig, info, context);
auto time_to = Now();
int64_t async_id = -1;
// don't capture for now until we work out the issues with GC and thread start
// static_cast<int64_t>(node::AsyncHooksGetExecutionAsyncId(isolate));
auto async_id = prof->GetAsyncId(isolate);
prof->PushContext(time_from, time_to, cpu_time, async_id);
}
#else
Expand Down Expand Up @@ -473,11 +474,13 @@ std::shared_ptr<ContextsByNode> WallProfiler::GetContextsByNode(
sampleContext.context.get()->Get(isolate))
.Check();
}
timedContext
->Set(v8Context,
asyncIdKey,
NewNumberFromInt64(isolate, sampleContext.async_id))
.Check();
if (collectAsyncId_) {
timedContext
->Set(v8Context,
asyncIdKey,
NewNumberFromInt64(isolate, sampleContext.async_id))
.Check();
}
}
}
array->Set(v8Context, array->Length(), timedContext).Check();
Expand All @@ -492,12 +495,27 @@ std::shared_ptr<ContextsByNode> WallProfiler::GetContextsByNode(
return contextsByNode;
}

void GCPrologueCallback(Isolate* isolate,
GCType type,
GCCallbackFlags flags,
void* data) {
static_cast<WallProfiler*>(data)->OnGCStart(isolate);
}

void GCEpilogueCallback(Isolate* isolate,
GCType type,
GCCallbackFlags flags,
void* data) {
static_cast<WallProfiler*>(data)->OnGCEnd();
}

WallProfiler::WallProfiler(std::chrono::microseconds samplingPeriod,
std::chrono::microseconds duration,
bool includeLines,
bool withContexts,
bool workaroundV8Bug,
bool collectCpuTime,
bool collectAsyncId,
bool isMainThread)
: samplingPeriod_(samplingPeriod),
includeLines_(includeLines),
Expand All @@ -509,14 +527,17 @@ WallProfiler::WallProfiler(std::chrono::microseconds samplingPeriod,
// event just after triggers the issue.
workaroundV8Bug_ = workaroundV8Bug && DD_WALL_USE_SIGPROF && detectV8Bug_;
collectCpuTime_ = collectCpuTime && withContexts;
collectAsyncId_ = collectAsyncId && withContexts;

if (withContexts_) {
contexts_.reserve(duration * 2 / samplingPeriod);
}

curContext_.store(&context1_, std::memory_order_relaxed);
collectionMode_.store(CollectionMode::kNoCollect, std::memory_order_relaxed);
gcCount.store(0, std::memory_order_relaxed);

// TODO: bind to this isolate? Would fix the Dispose(nullptr) issue.
auto isolate = v8::Isolate::GetCurrent();
v8::Local<v8::ArrayBuffer> buffer =
v8::ArrayBuffer::New(isolate, sizeof(uint32_t) * kFieldCount);
Expand All @@ -526,6 +547,11 @@ WallProfiler::WallProfiler(std::chrono::microseconds samplingPeriod,
fields_ = static_cast<uint32_t*>(buffer->GetBackingStore()->Data());
jsArray_ = v8::Global<v8::Uint32Array>(isolate, jsArray);
std::fill(fields_, fields_ + kFieldCount, 0);

if (collectAsyncId_) {
isolate->AddGCPrologueCallback(&GCPrologueCallback, this);
isolate->AddGCEpilogueCallback(&GCEpilogueCallback, this);
}
}

WallProfiler::~WallProfiler() {
Expand All @@ -538,9 +564,22 @@ void WallProfiler::Dispose(Isolate* isolate) {
cpuProfiler_ = nullptr;

g_profilers.RemoveProfiler(isolate, this);

if (isolate != nullptr && collectAsyncId_) {
isolate->RemoveGCPrologueCallback(&GCPrologueCallback, this);
isolate->RemoveGCEpilogueCallback(&GCEpilogueCallback, this);
}
}
}

#define DD_WALL_PROFILER_GET_BOOLEAN_CONFIG(name) \
Copy link
Copy Markdown

@nsavoire nsavoire Mar 7, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No a big fan of macros, but here this nicely simplifies the code.

auto name##Value = \
Nan::Get(arg, Nan::New<v8::String>(#name).ToLocalChecked()); \
if (name##Value.IsEmpty() || !name##Value.ToLocalChecked()->IsBoolean()) { \
return Nan::ThrowTypeError(#name " must be a boolean."); \
} \
bool name = name##Value.ToLocalChecked().As<v8::Boolean>()->Value();

NAN_METHOD(WallProfiler::New) {
if (info.Length() != 1 || !info[0]->IsObject()) {
return Nan::ThrowTypeError("WallProfiler must have one object argument.");
Expand Down Expand Up @@ -579,50 +618,12 @@ NAN_METHOD(WallProfiler::New) {
return Nan::ThrowTypeError("Duration must not be less than sample rate.");
}

auto lineNumbersValue =
Nan::Get(arg, Nan::New<v8::String>("lineNumbers").ToLocalChecked());
if (lineNumbersValue.IsEmpty() ||
!lineNumbersValue.ToLocalChecked()->IsBoolean()) {
return Nan::ThrowTypeError("lineNumbers must be a boolean.");
}
bool lineNumbers =
lineNumbersValue.ToLocalChecked().As<v8::Boolean>()->Value();

auto withContextsValue =
Nan::Get(arg, Nan::New<v8::String>("withContexts").ToLocalChecked());
if (withContextsValue.IsEmpty() ||
!withContextsValue.ToLocalChecked()->IsBoolean()) {
return Nan::ThrowTypeError("withContext must be a boolean.");
}
bool withContexts =
withContextsValue.ToLocalChecked().As<v8::Boolean>()->Value();

auto workaroundV8BugValue =
Nan::Get(arg, Nan::New<v8::String>("workaroundV8Bug").ToLocalChecked());
if (workaroundV8BugValue.IsEmpty() ||
!workaroundV8BugValue.ToLocalChecked()->IsBoolean()) {
return Nan::ThrowTypeError("workaroundV8Bug must be a boolean.");
}
bool workaroundV8Bug =
workaroundV8BugValue.ToLocalChecked().As<v8::Boolean>()->Value();

auto collectCpuTimeValue =
Nan::Get(arg, Nan::New<v8::String>("collectCpuTime").ToLocalChecked());
if (collectCpuTimeValue.IsEmpty() ||
!collectCpuTimeValue.ToLocalChecked()->IsBoolean()) {
return Nan::ThrowTypeError("collectCpuTime must be a boolean.");
}
bool collectCpuTime =
collectCpuTimeValue.ToLocalChecked().As<v8::Boolean>()->Value();

auto isMainThreadValue =
Nan::Get(arg, Nan::New<v8::String>("isMainThread").ToLocalChecked());
if (isMainThreadValue.IsEmpty() ||
!isMainThreadValue.ToLocalChecked()->IsBoolean()) {
return Nan::ThrowTypeError("isMainThread must be a boolean.");
}
bool isMainThread =
isMainThreadValue.ToLocalChecked().As<v8::Boolean>()->Value();
DD_WALL_PROFILER_GET_BOOLEAN_CONFIG(lineNumbers);
DD_WALL_PROFILER_GET_BOOLEAN_CONFIG(withContexts);
DD_WALL_PROFILER_GET_BOOLEAN_CONFIG(workaroundV8Bug);
DD_WALL_PROFILER_GET_BOOLEAN_CONFIG(collectCpuTime);
DD_WALL_PROFILER_GET_BOOLEAN_CONFIG(collectAsyncId);
DD_WALL_PROFILER_GET_BOOLEAN_CONFIG(isMainThread);

if (withContexts && !DD_WALL_USE_SIGPROF) {
return Nan::ThrowTypeError("Contexts are not supported.");
Expand All @@ -632,6 +633,10 @@ NAN_METHOD(WallProfiler::New) {
return Nan::ThrowTypeError("Cpu time collection requires contexts.");
}

if (collectAsyncId && !withContexts) {
return Nan::ThrowTypeError("Async ID collection requires contexts.");
}

if (lineNumbers && withContexts) {
// Currently custom contexts are not compatible with caller line
// information, because it's not possible to associate context with line
Expand All @@ -657,6 +662,7 @@ NAN_METHOD(WallProfiler::New) {
withContexts,
workaroundV8Bug,
collectCpuTime,
collectAsyncId,
isMainThread);
obj->Wrap(info.This());
info.GetReturnValue().Set(info.This());
Expand All @@ -668,6 +674,8 @@ NAN_METHOD(WallProfiler::New) {
}
}

#undef DD_WALL_PROFILER_GET_BOOLEAN_CONFIG

NAN_METHOD(WallProfiler::Start) {
WallProfiler* wallProfiler =
Nan::ObjectWrap::Unwrap<WallProfiler>(info.Holder());
Expand Down Expand Up @@ -1019,6 +1027,45 @@ NAN_METHOD(WallProfiler::Dispose) {
delete profiler;
}

int64_t GetAsyncIdNoGC(v8::Isolate* isolate) {
return isolate->InContext()
? static_cast<int64_t>(
node::AsyncHooksGetExecutionAsyncId(isolate))
: -1;
}

int64_t WallProfiler::GetAsyncId(v8::Isolate* isolate) {
if (!collectAsyncId_) {
return -1;
}
auto curGcCount = gcCount.load(std::memory_order_relaxed);
std::atomic_signal_fence(std::memory_order_acquire);
if (curGcCount > 0) {
return gcAsyncId;
}
return GetAsyncIdNoGC(isolate);
}

void WallProfiler::OnGCStart(v8::Isolate* isolate) {
auto curCount = gcCount.load(std::memory_order_relaxed);
std::atomic_signal_fence(std::memory_order_acquire);
if (curCount == 0) {
gcAsyncId = GetAsyncIdNoGC(isolate);
}
gcCount.store(curCount + 1, std::memory_order_relaxed);
std::atomic_signal_fence(std::memory_order_release);
}

void WallProfiler::OnGCEnd() {
auto newCount = gcCount.load(std::memory_order_relaxed) - 1;
std::atomic_signal_fence(std::memory_order_acquire);
gcCount.store(newCount, std::memory_order_relaxed);
std::atomic_signal_fence(std::memory_order_release);
if (newCount == 0) {
gcAsyncId = -1;
}
}

void WallProfiler::PushContext(int64_t time_from,
int64_t time_to,
int64_t cpu_time,
Expand Down
9 changes: 9 additions & 0 deletions bindings/profilers/wall.hh
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -58,6 +58,9 @@ class WallProfiler : public Nan::ObjectWrap {
ContextPtr context2_;
std::atomic<ContextPtr*> curContext_;

std::atomic<int> gcCount = 0;
int64_t gcAsyncId;

std::atomic<CollectionMode> collectionMode_;
std::atomic<uint64_t> noCollectCallCount_;
std::string profileId_;
Expand All @@ -68,6 +71,7 @@ class WallProfiler : public Nan::ObjectWrap {
bool workaroundV8Bug_;
static inline constexpr bool detectV8Bug_ = true;
bool collectCpuTime_;
bool collectAsyncId_;
bool isMainThread_;
int v8ProfilerStuckEventLoopDetected_ = 0;
ProcessCpuClock::time_point startProcessCpuTime_{};
Expand Down Expand Up @@ -117,6 +121,7 @@ class WallProfiler : public Nan::ObjectWrap {
bool withContexts,
bool workaroundV8bug,
bool collectCpuTime,
bool collectAsyncId,
bool isMainThread);

v8::Local<v8::Value> GetContext(v8::Isolate*);
Expand Down Expand Up @@ -149,6 +154,10 @@ class WallProfiler : public Nan::ObjectWrap {
return threadCpuStopWatch_.GetAndReset();
}

int64_t GetAsyncId(v8::Isolate* isolate);
void OnGCStart(v8::Isolate* isolate);
void OnGCEnd();

static NAN_METHOD(New) GENERAL_REGS_ONLY;
static NAN_METHOD(Start);
static NAN_METHOD(Stop);
Expand Down
2 changes: 2 additions & 0 deletions ts/src/time-profiler.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -66,6 +66,7 @@ export interface TimeProfilerOptions {
withContexts?: boolean;
workaroundV8Bug?: boolean;
collectCpuTime?: boolean;
collectAsyncId?: boolean;
Copy link
Copy Markdown

@datadog-datadog-prod-us1 datadog-datadog-prod-us1 Bot Mar 6, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

⚪ Code Quality Violation

Prop name (collectAsyncId) doesn't match rule (is|has) (...read more)

Enforces a consistent naming pattern for boolean props.

The pattern is: "^(is|has)[A-Z]([A-Za-z0-9]?)+" to enforce is and has prefixes.

View in Datadog  Leave us feedback  Documentation

Copy link
Copy Markdown
Author

@szegedi szegedi Mar 6, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Well, that's new. I'm inclined to ignore it, seeing how existing boolean properties also don't follow this format.

}

const DEFAULT_OPTIONS: TimeProfilerOptions = {
Expand All @@ -75,6 +76,7 @@ const DEFAULT_OPTIONS: TimeProfilerOptions = {
withContexts: false,
workaroundV8Bug: true,
collectCpuTime: false,
collectAsyncId: false,
};

export async function profile(options: TimeProfilerOptions = {}) {
Expand Down
55 changes: 49 additions & 6 deletions ts/test/test-time-profiler.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -39,7 +39,7 @@ describe('Time Profiler', () => {
assert.equal(profile.stringTable.strings!.indexOf('(program)'), -1);
});

it('should update state', function () {
it('should update state', function shouldUpdateState() {
if (process.platform !== 'darwin' && process.platform !== 'linux') {
this.skip();
}
Expand Down Expand Up @@ -90,7 +90,7 @@ describe('Time Profiler', () => {
assert(checked, 'No context found');
});

it('should assign labels', function () {
it('should have labels', function shouldHaveLabels() {
if (process.platform !== 'darwin' && process.platform !== 'linux') {
this.skip();
}
Expand Down Expand Up @@ -129,10 +129,8 @@ describe('Time Profiler', () => {
if (!context) {
return {};
}
assert(
typeof context.asyncId === 'number',
'context.asyncId should be a number'
);
// Does not collect async IDs by default
assert(typeof context.asyncId === 'undefined');
const labels: LabelSet = {};
for (const [key, value] of Object.entries(context.context ?? {})) {
if (typeof value === 'string') {
Expand Down Expand Up @@ -356,6 +354,51 @@ describe('Time Profiler', () => {
});
});

it('should have async IDs when enabled', async function shouldCollectAsyncIDs() {
if (process.platform !== 'darwin' && process.platform !== 'linux') {
this.skip();
}
this.timeout(3000);

time.start({
intervalMicros: PROFILE_OPTIONS.intervalMicros,
durationMillis: PROFILE_OPTIONS.durationMillis,
withContexts: true,
lineNumbers: false,
collectAsyncId: true,
});
let setDone: () => void;
const done = new Promise<void>(resolve => {
setDone = resolve;
});

const testStart = hrtime.bigint();
const testDurationNanos = PROFILE_OPTIONS.durationMillis * 1_000_000;
setTimeout(loop, 0);

function loop() {
const loopDurationNanos = PROFILE_OPTIONS.intervalMicros * 1_000;
const loopStart = hrtime.bigint();
while (hrtime.bigint() - loopStart < loopDurationNanos);
if (hrtime.bigint() - testStart < testDurationNanos) {
setTimeout(loop, 0);
} else {
setDone();
}
}

await done;

let asyncIdObserved = false;
time.stop(false, ({context}: GenerateTimeLabelsArgs) => {
if (!asyncIdObserved && typeof context?.asyncId === 'number') {
asyncIdObserved = context?.asyncId !== -1;
}
return {};
});
assert(asyncIdObserved, 'Async ID was not observed');
});

describe('profile (w/ stubs)', () => {
// eslint-disable-next-line @typescript-eslint/no-explicit-any
const sinonStubs: Array<sinon.SinonStub<any, any>> = [];
Expand Down