From 747a4467b99bd8ef3f52f048f36566691ceda621 Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Wed, 2 Jul 2025 13:47:46 +0200 Subject: [PATCH 1/5] Exercise async ID collection in more tests --- ts/test/test-time-profiler.ts | 47 +++++++++++++++++++++++++---------- ts/test/worker.ts | 3 +++ ts/test/worker2.ts | 3 ++- 3 files changed, 39 insertions(+), 14 deletions(-) diff --git a/ts/test/test-time-profiler.ts b/ts/test/test-time-profiler.ts index 5a14e8cf..b07c92db 100644 --- a/ts/test/test-time-profiler.ts +++ b/ts/test/test-time-profiler.ts @@ -26,12 +26,14 @@ import {GenerateTimeLabelsArgs, LabelSet} from '../src/v8-types'; import {AsyncLocalStorage} from 'async_hooks'; import {satisfies} from 'semver'; -const assert = require('assert'); +import assert from 'assert'; const useCPED = satisfies(process.versions.node, '>=24.0.0') && !process.execArgv.includes('--no-async-context-frame'); +const collectAsyncId = satisfies(process.versions.node, '>=24.0.0'); + const PROFILE_OPTIONS = { durationMillis: 500, intervalMicros: 1000, @@ -116,6 +118,7 @@ describe('Time Profiler', () => { intervalMicros: PROFILE_OPTIONS.intervalMicros, durationMillis: PROFILE_OPTIONS.durationMillis, withContexts: true, + collectAsyncId: collectAsyncId, lineNumbers: false, useCPED, }); @@ -125,6 +128,7 @@ describe('Time Profiler', () => { const rootSpanId = '1234'; const endPointLabel = 'trace endpoint'; const rootSpanIdLabel = 'local root span id'; + const asyncIdLabel = 'async id'; const endPoint = 'foo'; let enableEndPoint = false; const label0 = {label: 'value0'}; @@ -136,7 +140,7 @@ describe('Time Profiler', () => { validateProfile( time.stop( i < repeats - 1, - enableEndPoint ? generateLabels : undefined + enableEndPoint || collectAsyncId ? generateLabels : undefined ) ); } @@ -145,9 +149,11 @@ describe('Time Profiler', () => { if (!context) { return {}; } - // Does not collect async IDs by default - assert(typeof context.asyncId === 'undefined'); const labels: LabelSet = {}; + if (typeof context.asyncId !== 'undefined') { + assert(collectAsyncId); + labels[asyncIdLabel] = context.asyncId; + } for (const [key, value] of Object.entries(context.context ?? {})) { if (typeof value === 'string') { labels[key] = value; @@ -215,13 +221,16 @@ describe('Time Profiler', () => { function validateProfile(profile: Profile) { // Get string table indices for strings we're interested in const stringTable = profile.stringTable; - const [loopIdx, fn0Idx, fn1Idx, fn2Idx, hrtimeBigIntIdx] = [ - 'loop', - 'fn0', - 'fn1', - 'fn2', - 'hrtimeBigInt', - ].map(x => stringTable.dedup(x)); + const [ + loopIdx, + fn0Idx, + fn1Idx, + fn2Idx, + hrtimeBigIntIdx, + asyncIdLabelIdx, + ] = ['loop', 'fn0', 'fn1', 'fn2', 'hrtimeBigInt', asyncIdLabel].map(x => + stringTable.dedup(x) + ); function getString(n: number | bigint): string { if (typeof n === 'number') { @@ -259,6 +268,7 @@ describe('Time Profiler', () => { let fn0ObservedWithLabel0 = false; let fn1ObservedWithLabel1 = false; let fn2ObservedWithoutLabels = false; + let observedAsyncId = false; profile.sample.forEach(sample => { let fnName; for (const locationId of sample.locationId) { @@ -272,7 +282,17 @@ describe('Time Profiler', () => { } } const labels = sample.label; - + if (collectAsyncId) { + const idx = labels.findIndex( + label => label.key === asyncIdLabelIdx + ); + if (idx !== -1) { + // Remove async ID label so it doesn't confuse the assertions on + // labels further below. + labels.splice(idx, 1); + observedAsyncId = true; + } + } switch (fnName) { case loopIdx: if (enableEndPoint) { @@ -366,12 +386,13 @@ describe('Time Profiler', () => { fn2ObservedWithoutLabels, 'fn2 was not observed without a label' ); + assert(!collectAsyncId || observedAsyncId, 'Async ID was not observed'); } }); }); it('should have async IDs when enabled', async function shouldCollectAsyncIDs() { - if (process.platform !== 'darwin' && process.platform !== 'linux') { + if (!(collectAsyncId && ['darwin', 'linux'].includes(process.platform))) { this.skip(); } this.timeout(3000); diff --git a/ts/test/worker.ts b/ts/test/worker.ts index 155c89f5..9c5b9b92 100644 --- a/ts/test/worker.ts +++ b/ts/test/worker.ts @@ -15,6 +15,7 @@ const withContexts = const useCPED = satisfies(process.versions.node, '>=24.0.0') && !process.execArgv.includes('--no-async-context-frame'); +const collectAsyncId = satisfies(process.versions.node, '>=24.0.0'); function createWorker(durationMs: number): Promise { return new Promise((resolve, reject) => { @@ -64,6 +65,7 @@ async function main(durationMs: number) { withContexts, collectCpuTime: withContexts, useCPED: useCPED, + collectAsyncId: collectAsyncId, }); if (withContexts) { time.setContext({}); @@ -108,6 +110,7 @@ async function worker(durationMs: number) { withContexts, collectCpuTime: withContexts, useCPED: useCPED, + collectAsyncId: collectAsyncId, }); if (withContexts) { time.setContext({}); diff --git a/ts/test/worker2.ts b/ts/test/worker2.ts index 3c2c55da..7427017e 100644 --- a/ts/test/worker2.ts +++ b/ts/test/worker2.ts @@ -1,5 +1,6 @@ import {parentPort} from 'node:worker_threads'; import {time} from '../src/index'; +import {satisfies} from 'semver'; const delay = (ms: number) => new Promise(res => setTimeout(res, ms)); @@ -13,7 +14,7 @@ time.start({ intervalMicros: INTERVAL_MICROS, withContexts: withContexts, collectCpuTime: withContexts, - collectAsyncId: false, + collectAsyncId: satisfies(process.versions.node, '>=24.0.0'), }); parentPort?.on('message', () => { From 4f2d7e1be16cd3464690913957e5f1fcad118631 Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Wed, 2 Jul 2025 15:29:55 +0200 Subject: [PATCH 2/5] Make sure async ID collection is off on Windows --- ts/test/worker.ts | 3 ++- ts/test/worker2.ts | 5 ++++- 2 files changed, 6 insertions(+), 2 deletions(-) diff --git a/ts/test/worker.ts b/ts/test/worker.ts index 9c5b9b92..eeffd3c3 100644 --- a/ts/test/worker.ts +++ b/ts/test/worker.ts @@ -15,7 +15,8 @@ const withContexts = const useCPED = satisfies(process.versions.node, '>=24.0.0') && !process.execArgv.includes('--no-async-context-frame'); -const collectAsyncId = satisfies(process.versions.node, '>=24.0.0'); +const collectAsyncId = + withContexts && satisfies(process.versions.node, '>=24.0.0'); function createWorker(durationMs: number): Promise { return new Promise((resolve, reject) => { diff --git a/ts/test/worker2.ts b/ts/test/worker2.ts index 7427017e..12943e63 100644 --- a/ts/test/worker2.ts +++ b/ts/test/worker2.ts @@ -9,12 +9,15 @@ const INTERVAL_MICROS = 10000; const withContexts = process.platform === 'darwin' || process.platform === 'linux'; +const collectAsyncId = + withContexts && satisfies(process.versions.node, '>=24.0.0'); + time.start({ durationMillis: DURATION_MILLIS, intervalMicros: INTERVAL_MICROS, withContexts: withContexts, collectCpuTime: withContexts, - collectAsyncId: satisfies(process.versions.node, '>=24.0.0'), + collectAsyncId: collectAsyncId, }); parentPort?.on('message', () => { From f9a66d50aea69d861ab7eda4be6151cb9755c146 Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Fri, 4 Jul 2025 11:27:08 +0200 Subject: [PATCH 3/5] Also turn on useCPED when possible on worker tests --- ts/test/worker2.ts | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/ts/test/worker2.ts b/ts/test/worker2.ts index 12943e63..e06f5578 100644 --- a/ts/test/worker2.ts +++ b/ts/test/worker2.ts @@ -9,6 +9,10 @@ const INTERVAL_MICROS = 10000; const withContexts = process.platform === 'darwin' || process.platform === 'linux'; +const useCPED = + satisfies(process.versions.node, '>=24.0.0') && + !process.execArgv.includes('--no-async-context-frame'); + const collectAsyncId = withContexts && satisfies(process.versions.node, '>=24.0.0'); @@ -18,6 +22,7 @@ time.start({ withContexts: withContexts, collectCpuTime: withContexts, collectAsyncId: collectAsyncId, + useCPED: useCPED, }); parentPort?.on('message', () => { From 49d022a19af62c7cf76b485ba499eb7c3a117411 Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Wed, 16 Jul 2025 18:04:15 +0200 Subject: [PATCH 4/5] Observe the number of free handles --- bindings/profilers/wall.cc | 35 +++++++++++++++++++++++++++++++---- 1 file changed, 31 insertions(+), 4 deletions(-) diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index 7ab05a9c..69c4987e 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -16,6 +16,7 @@ #include #include +#include #include #include #include @@ -41,6 +42,13 @@ struct TimeTicks { static int64_t Now(); }; } // namespace base +namespace internal { +struct HandleScopeData { + v8::internal::Address* next; + v8::internal::Address* limit; +}; +constexpr int kHandleBlockSize = v8::internal::KB - 2; +} // namespace internal } // namespace v8 static int64_t Now() { @@ -1206,14 +1214,31 @@ ContextPtr WallProfiler::GetContextPtrSignalSafe(Isolate* isolate) { return GetContextPtr(isolate); } +// Returns the number of free Address slots for Locals that can be returned by +// the isolate without triggering memory allocation. +int GetFreeLocalSlotCount(Isolate* isolate) { + v8::internal::HandleScopeData* data = + reinterpret_cast( + reinterpret_cast(isolate) + + v8::internal::Internals::kIsolateHandleScopeDataOffset); + auto diff = data->limit - data->next; + // sanity check: diff can be at most kHandleBlockSize. If it is larger, + // something is suspicious. See + // https://github.com/v8/v8/blob/6fcfeccda2d8bcb7397f89bf5bbacd0c2eb2fb7f/src/handles/handles.cc#L195 + return diff > v8::internal::kHandleBlockSize ? 0 : diff; +} + ContextPtr WallProfiler::GetContextPtr(Isolate* isolate) { #if NODE_MAJOR_VERSION >= 23 if (!useCPED_) { return curContext_; } - if (!isolate->IsInUse()) { - // Must not try to create a handle scope if isolate is not in use. + if (!isolate->IsInUse() || GetFreeLocalSlotCount(isolate) < 4) { + // Must not try to create a handle scope if isolate is not in use or if we + // don't have at least 4 free slots to create local handles. The 4 handles + // are return values of GetCPED, GetEnteredOrMicrotaskContext, + // cpedSymbol_.Get, and GetPrivate. return ContextPtr(); } HandleScope scope(isolate); @@ -1271,8 +1296,10 @@ NAN_METHOD(WallProfiler::Dispose) { } double GetAsyncIdNoGC(v8::Isolate* isolate) { - if (!isolate->IsInUse()) { - // Must not try to create a handle scope if isolate is not in use. + if (!isolate->IsInUse() || GetFreeLocalSlotCount(isolate) < 1) { + // Must not try to create a handle scope if isolate is not in use or if + // we can't create one local handle (return value of + // GetEnteredOrMicrotaskContext) without allocation. return -1; } #if NODE_MAJOR_VERSION >= 24 From 2b232c7b0960e28c6cc245ba1715117d828c477b Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Fri, 18 Jul 2025 13:36:19 +0200 Subject: [PATCH 5/5] Guard against compiler reordering of v8::internal::HandleScope::CreateHandle --- bindings/profilers/wall.cc | 80 ++++++++++++++++++++++++-------------- bindings/profilers/wall.hh | 2 +- 2 files changed, 51 insertions(+), 31 deletions(-) diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index 69c4987e..5e4bca82 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -1120,7 +1120,7 @@ v8::CpuProfiler* WallProfiler::CreateV8CpuProfiler() { } Local WallProfiler::GetContext(Isolate* isolate) { - auto context = GetContextPtr(isolate); + auto context = GetContextPtr(isolate, false); if (context) { return context->Get(isolate); } @@ -1211,16 +1211,19 @@ ContextPtr WallProfiler::GetContextPtrSignalSafe(Isolate* isolate) { } } - return GetContextPtr(isolate); + return GetContextPtr(isolate, true); +} + +v8::internal::HandleScopeData* getHandleScopeData(Isolate* isolate) { + return reinterpret_cast( + reinterpret_cast(isolate) + + v8::internal::Internals::kIsolateHandleScopeDataOffset); } // Returns the number of free Address slots for Locals that can be returned by // the isolate without triggering memory allocation. int GetFreeLocalSlotCount(Isolate* isolate) { - v8::internal::HandleScopeData* data = - reinterpret_cast( - reinterpret_cast(isolate) + - v8::internal::Internals::kIsolateHandleScopeDataOffset); + auto data = getHandleScopeData(isolate); auto diff = data->limit - data->next; // sanity check: diff can be at most kHandleBlockSize. If it is larger, // something is suspicious. See @@ -1228,39 +1231,56 @@ int GetFreeLocalSlotCount(Isolate* isolate) { return diff > v8::internal::kHandleBlockSize ? 0 : diff; } -ContextPtr WallProfiler::GetContextPtr(Isolate* isolate) { +ContextPtr WallProfiler::GetContextPtr(Isolate* isolate, bool inSignalHandler) { #if NODE_MAJOR_VERSION >= 23 if (!useCPED_) { return curContext_; } - if (!isolate->IsInUse() || GetFreeLocalSlotCount(isolate) < 4) { - // Must not try to create a handle scope if isolate is not in use or if we - // don't have at least 4 free slots to create local handles. The 4 handles - // are return values of GetCPED, GetEnteredOrMicrotaskContext, - // cpedSymbol_.Get, and GetPrivate. - return ContextPtr(); - } - HandleScope scope(isolate); - - auto cped = isolate->GetContinuationPreservedEmbedderData(); - if (cped->IsObject()) { - auto v8Ctx = isolate->GetEnteredOrMicrotaskContext(); - if (!v8Ctx.IsEmpty()) { - auto cpedObj = cped.As(); - auto localSymbol = cpedSymbol_.Get(isolate); - auto maybeProfData = cpedObj->GetPrivate(v8Ctx, localSymbol); - if (!maybeProfData.IsEmpty()) { - auto profData = maybeProfData.ToLocalChecked(); - if (!profData->IsUndefined()) { - return static_cast( - profData.As()->Value()) - ->Get(); + // HandleScope::CreateHandle() first increments HandleScopeData::next and only + // then writes to the Address slot in the source code, which is safe for us. + // The compiler is free to reorder these two operations, however, so we'll + // defensively save/restore the current value of the next Address slot in case + // the signal interrupted the thread between these two reordered operations. + v8::internal::Address* nextAddrPtr = nullptr; + v8::internal::Address savedAddr = 0; + if (inSignalHandler) { + if (!isolate->IsInUse() || GetFreeLocalSlotCount(isolate) < 4) { + // Must not try to create a handle scope if isolate is not in use or if we + // don't have at least 4 free slots to create local handles. The 4 handles + // are return values of GetCPED, GetEnteredOrMicrotaskContext, + // cpedSymbol_.Get, and GetPrivate. + return ContextPtr(); + } + nextAddrPtr = getHandleScopeData(isolate)->next; + savedAddr = *nextAddrPtr; + } + ContextPtr retval = ContextPtr(); + { + HandleScope scope(isolate); + + auto cped = isolate->GetContinuationPreservedEmbedderData(); + if (cped->IsObject()) { + auto v8Ctx = isolate->GetEnteredOrMicrotaskContext(); + if (!v8Ctx.IsEmpty()) { + auto cpedObj = cped.As(); + auto localSymbol = cpedSymbol_.Get(isolate); + auto maybeProfData = cpedObj->GetPrivate(v8Ctx, localSymbol); + if (!maybeProfData.IsEmpty()) { + auto profData = maybeProfData.ToLocalChecked(); + if (!profData->IsUndefined()) { + retval = static_cast( + profData.As()->Value()) + ->Get(); + } } } } } - return ContextPtr(); + if (nextAddrPtr) { + *nextAddrPtr = savedAddr; + } + return retval; #else return curContext_; #endif diff --git a/bindings/profilers/wall.hh b/bindings/profilers/wall.hh index 15d5c17e..be3e616f 100644 --- a/bindings/profilers/wall.hh +++ b/bindings/profilers/wall.hh @@ -114,7 +114,7 @@ class WallProfiler : public Nan::ObjectWrap { static void CleanupHook(void* data); void Cleanup(v8::Isolate* isolate); - ContextPtr GetContextPtr(v8::Isolate* isolate); + ContextPtr GetContextPtr(v8::Isolate* isolate, bool inSignalHandler); ContextPtr GetContextPtrSignalSafe(v8::Isolate* isolate); void SetCurrentContextPtr(v8::Isolate* isolate, v8::Local context);