mirror of https://github.com/lukechilds/node.git
Browse Source
Implement a special async_hooks listener that forwards information about async tasks to V8Inspector asyncTask* API, thus enabling DevTools feature "async stack traces". The feature is enabled only on 64bit platforms due to a technical limitation of V8 Inspector: inspector uses a pointer as a task id, while async_hooks use 64bit numbers as ids. To avoid performance penalty of async_hooks when not debugging, the new listener is enabled only when the process enters a debug mode: - When the process is started with `--inspect` or `--inspect-brk`, the listener is enabled immediately and async stack traces lead all the way to the first tick of the event loop. - When the debug mode is enabled via SIGUSR1 or `_debugProcess()`, the listener is enabled together with the debugger. As a result, only async operations started after the signal was received will be correctly observed and reported to V8 Inspector. For example, a `setInterval()` called in the first tick of the event will not be shown in the async stack trace when the callback is invoked. This behaviour is consistent with Chrome DevTools. Last but not least, this commit fixes handling of InspectorAgent's internal property `enabled_` to ensure it's set back to `false` after the debugger is deactivated (typically via `process._debugEnd()`). Fixes: https://github.com/nodejs/node/issues/11370 PR-URL: https://github.com/nodejs/node/pull/13870 Reviewed-by: Timothy Gu <timothygu99@gmail.com> Reviewed-by: Anna Henningsen <anna@addaleax.net>canary-base
Miroslav Bajtoš
8 years ago
committed by
Timothy Gu
Timothy Gu
17 changed files with 656 additions and 17 deletions
@ -0,0 +1,64 @@ |
|||
'use strict'; |
|||
|
|||
const { createHook } = require('async_hooks'); |
|||
const inspector = process.binding('inspector'); |
|||
const config = process.binding('config'); |
|||
|
|||
if (!inspector || !inspector.asyncTaskScheduled) { |
|||
exports.setup = function() {}; |
|||
return; |
|||
} |
|||
|
|||
const hook = createHook({ |
|||
init(asyncId, type, triggerAsyncId, resource) { |
|||
// It's difficult to tell which tasks will be recurring and which won't,
|
|||
// therefore we mark all tasks as recurring. Based on the discussion
|
|||
// in https://github.com/nodejs/node/pull/13870#discussion_r124515293,
|
|||
// this should be fine as long as we call asyncTaskCanceled() too.
|
|||
const recurring = true; |
|||
inspector.asyncTaskScheduled(type, asyncId, recurring); |
|||
}, |
|||
|
|||
before(asyncId) { |
|||
inspector.asyncTaskStarted(asyncId); |
|||
}, |
|||
|
|||
after(asyncId) { |
|||
inspector.asyncTaskFinished(asyncId); |
|||
}, |
|||
|
|||
destroy(asyncId) { |
|||
inspector.asyncTaskCanceled(asyncId); |
|||
}, |
|||
}); |
|||
|
|||
function enable() { |
|||
if (config.bits < 64) { |
|||
// V8 Inspector stores task ids as (void*) pointers.
|
|||
// async_hooks store ids as 64bit numbers.
|
|||
// As a result, we cannot reliably translate async_hook ids to V8 async_task
|
|||
// ids on 32bit platforms.
|
|||
process.emitWarning( |
|||
'Warning: Async stack traces in debugger are not available ' + |
|||
`on ${config.bits}bit platforms. The feature is disabled.`, |
|||
{ |
|||
code: 'INSPECTOR_ASYNC_STACK_TRACES_NOT_AVAILABLE', |
|||
}); |
|||
} else { |
|||
hook.enable(); |
|||
} |
|||
} |
|||
|
|||
function disable() { |
|||
hook.disable(); |
|||
} |
|||
|
|||
exports.setup = function() { |
|||
inspector.registerAsyncHook(enable, disable); |
|||
|
|||
if (inspector.isEnabled()) { |
|||
// If the inspector was already enabled via --inspect or --inspect-brk,
|
|||
// the we need to enable the async hook immediately at startup.
|
|||
enable(); |
|||
} |
|||
}; |
|||
@ -0,0 +1,45 @@ |
|||
'use strict'; |
|||
const common = require('../common'); |
|||
common.skipIfInspectorDisabled(); |
|||
common.skipIf32Bits(); |
|||
common.crashOnUnhandledRejection(); |
|||
const { NodeInstance } = require('./inspector-helper.js'); |
|||
const assert = require('assert'); |
|||
|
|||
const script = ` |
|||
setTimeout(() => { |
|||
debugger; |
|||
process.exitCode = 55; |
|||
}, 50); |
|||
`;
|
|||
|
|||
async function checkAsyncStackTrace(session) { |
|||
console.error('[test]', 'Verify basic properties of asyncStackTrace'); |
|||
const paused = await session.waitForBreakOnLine(2, '[eval]'); |
|||
assert(paused.params.asyncStackTrace, |
|||
`${Object.keys(paused.params)} contains "asyncStackTrace" property`); |
|||
assert(paused.params.asyncStackTrace.description, 'Timeout'); |
|||
assert(paused.params.asyncStackTrace.callFrames |
|||
.some((frame) => frame.functionName === 'Module._compile')); |
|||
} |
|||
|
|||
async function runTests() { |
|||
const instance = new NodeInstance(undefined, script); |
|||
const session = await instance.connectInspectorSession(); |
|||
await session.send([ |
|||
{ 'method': 'Runtime.enable' }, |
|||
{ 'method': 'Debugger.enable' }, |
|||
{ 'method': 'Debugger.setAsyncCallStackDepth', |
|||
'params': { 'maxDepth': 10 } }, |
|||
{ 'method': 'Debugger.setBlackboxPatterns', |
|||
'params': { 'patterns': [] } }, |
|||
{ 'method': 'Runtime.runIfWaitingForDebugger' } |
|||
]); |
|||
|
|||
await checkAsyncStackTrace(session); |
|||
|
|||
await session.runToCompletion(); |
|||
assert.strictEqual(55, (await instance.expectShutdown()).exitCode); |
|||
} |
|||
|
|||
runTests(); |
|||
@ -0,0 +1,70 @@ |
|||
'use strict'; |
|||
const common = require('../common'); |
|||
common.skipIfInspectorDisabled(); |
|||
common.skipIf32Bits(); |
|||
common.crashOnUnhandledRejection(); |
|||
const { NodeInstance } = require('../inspector/inspector-helper.js'); |
|||
const assert = require('assert'); |
|||
|
|||
// Even with --inspect, the default async call stack depth is 0. We need a
|
|||
// chance to call Debugger.setAsyncCallStackDepth *before* activating the timer
|
|||
// for async stack traces to work.
|
|||
const script = ` |
|||
process._rawDebug('Waiting until the inspector is activated...'); |
|||
const waiting = setInterval(() => { debugger; }, 50); |
|||
|
|||
// This function is called by the inspector client (session)
|
|||
function setupTimeoutWithBreak() { |
|||
clearInterval(waiting); |
|||
process._rawDebug('Debugger ready, setting up timeout with a break'); |
|||
setTimeout(() => { debugger; }, 50); |
|||
} |
|||
`;
|
|||
|
|||
async function waitForInitialSetup(session) { |
|||
console.error('[test]', 'Waiting for initial setup'); |
|||
await session.waitForBreakOnLine(2, '[eval]'); |
|||
} |
|||
|
|||
async function setupTimeoutForStackTrace(session) { |
|||
console.error('[test]', 'Setting up timeout for async stack trace'); |
|||
await session.send([ |
|||
{ 'method': 'Runtime.evaluate', |
|||
'params': { expression: 'setupTimeoutWithBreak()' } }, |
|||
{ 'method': 'Debugger.resume' } |
|||
]); |
|||
} |
|||
|
|||
async function checkAsyncStackTrace(session) { |
|||
console.error('[test]', 'Verify basic properties of asyncStackTrace'); |
|||
const paused = await session.waitForBreakOnLine(8, '[eval]'); |
|||
assert(paused.params.asyncStackTrace, |
|||
`${Object.keys(paused.params)} contains "asyncStackTrace" property`); |
|||
assert(paused.params.asyncStackTrace.description, 'Timeout'); |
|||
assert(paused.params.asyncStackTrace.callFrames |
|||
.some((frame) => frame.functionName === 'setupTimeoutWithBreak')); |
|||
} |
|||
|
|||
async function runTests() { |
|||
const instance = new NodeInstance(['--inspect=0'], script); |
|||
const session = await instance.connectInspectorSession(); |
|||
await session.send([ |
|||
{ 'method': 'Runtime.enable' }, |
|||
{ 'method': 'Debugger.enable' }, |
|||
{ 'method': 'Debugger.setAsyncCallStackDepth', |
|||
'params': { 'maxDepth': 10 } }, |
|||
{ 'method': 'Debugger.setBlackboxPatterns', |
|||
'params': { 'patterns': [] } }, |
|||
{ 'method': 'Runtime.runIfWaitingForDebugger' } |
|||
]); |
|||
|
|||
await waitForInitialSetup(session); |
|||
await setupTimeoutForStackTrace(session); |
|||
await checkAsyncStackTrace(session); |
|||
|
|||
console.error('[test]', 'Stopping child instance'); |
|||
session.disconnect(); |
|||
instance.kill(); |
|||
} |
|||
|
|||
runTests(); |
|||
@ -0,0 +1,81 @@ |
|||
'use strict'; |
|||
const common = require('../common'); |
|||
common.skipIfInspectorDisabled(); |
|||
common.skipIf32Bits(); |
|||
common.crashOnUnhandledRejection(); |
|||
const { NodeInstance } = require('../inspector/inspector-helper.js'); |
|||
const assert = require('assert'); |
|||
|
|||
const script = ` |
|||
process._rawDebug('Waiting until a signal enables the inspector...'); |
|||
let waiting = setInterval(waitUntilDebugged, 50); |
|||
|
|||
function waitUntilDebugged() { |
|||
if (!process.binding('inspector').isEnabled()) return; |
|||
clearInterval(waiting); |
|||
// At this point, even though the Inspector is enabled, the default async
|
|||
// call stack depth is 0. We need a chance to call
|
|||
// Debugger.setAsyncCallStackDepth *before* activating the actual timer for
|
|||
// async stack traces to work. Directly using a debugger statement would be
|
|||
// too brittle, and using a longer timeout would unnecesarily slow down the
|
|||
// test on most machines. Triggering a debugger break through an interval is
|
|||
// a faster and more reliable way.
|
|||
process._rawDebug('Signal received, waiting for debugger setup'); |
|||
waiting = setInterval(() => { debugger; }, 50); |
|||
} |
|||
|
|||
// This function is called by the inspector client (session)
|
|||
function setupTimeoutWithBreak() { |
|||
clearInterval(waiting); |
|||
process._rawDebug('Debugger ready, setting up timeout with a break'); |
|||
setTimeout(() => { debugger; }, 50); |
|||
} |
|||
`;
|
|||
|
|||
async function waitForInitialSetup(session) { |
|||
console.error('[test]', 'Waiting for initial setup'); |
|||
await session.waitForBreakOnLine(15, '[eval]'); |
|||
} |
|||
|
|||
async function setupTimeoutForStackTrace(session) { |
|||
console.error('[test]', 'Setting up timeout for async stack trace'); |
|||
await session.send([ |
|||
{ 'method': 'Runtime.evaluate', |
|||
'params': { expression: 'setupTimeoutWithBreak()' } }, |
|||
{ 'method': 'Debugger.resume' } |
|||
]); |
|||
} |
|||
|
|||
async function checkAsyncStackTrace(session) { |
|||
console.error('[test]', 'Verify basic properties of asyncStackTrace'); |
|||
const paused = await session.waitForBreakOnLine(22, '[eval]'); |
|||
assert(paused.params.asyncStackTrace, |
|||
`${Object.keys(paused.params)} contains "asyncStackTrace" property`); |
|||
assert(paused.params.asyncStackTrace.description, 'Timeout'); |
|||
assert(paused.params.asyncStackTrace.callFrames |
|||
.some((frame) => frame.functionName === 'setupTimeoutWithBreak')); |
|||
} |
|||
|
|||
async function runTests() { |
|||
const instance = await NodeInstance.startViaSignal(script); |
|||
const session = await instance.connectInspectorSession(); |
|||
await session.send([ |
|||
{ 'method': 'Runtime.enable' }, |
|||
{ 'method': 'Debugger.enable' }, |
|||
{ 'method': 'Debugger.setAsyncCallStackDepth', |
|||
'params': { 'maxDepth': 10 } }, |
|||
{ 'method': 'Debugger.setBlackboxPatterns', |
|||
'params': { 'patterns': [] } }, |
|||
{ 'method': 'Runtime.runIfWaitingForDebugger' } |
|||
]); |
|||
|
|||
await waitForInitialSetup(session); |
|||
await setupTimeoutForStackTrace(session); |
|||
await checkAsyncStackTrace(session); |
|||
|
|||
console.error('[test]', 'Stopping child instance'); |
|||
session.disconnect(); |
|||
instance.kill(); |
|||
} |
|||
|
|||
runTests(); |
|||
@ -0,0 +1,33 @@ |
|||
'use strict'; |
|||
const common = require('../common'); |
|||
common.skipIfInspectorDisabled(); |
|||
common.skipIf32Bits(); |
|||
|
|||
const spawn = require('child_process').spawn; |
|||
|
|||
const script = ` |
|||
const assert = require('assert'); |
|||
|
|||
// Verify that inspector-async-hook is registered
|
|||
// by checking that emitInit with invalid arguments
|
|||
// throw an error.
|
|||
// See test/async-hooks/test-emit-init.js
|
|||
assert.throws( |
|||
() => async_hooks.emitInit(), |
|||
'inspector async hook should have been enabled initially'); |
|||
|
|||
process._debugEnd(); |
|||
|
|||
// Verify that inspector-async-hook is no longer registered,
|
|||
// thus emitInit() ignores invalid arguments
|
|||
// See test/async-hooks/test-emit-init.js
|
|||
assert.doesNotThrow( |
|||
() => async_hooks.emitInit(), |
|||
'inspector async hook should have beend disabled by _debugEnd()'); |
|||
`;
|
|||
|
|||
const args = ['--inspect', '-e', script]; |
|||
const child = spawn(process.execPath, args, { stdio: 'inherit' }); |
|||
child.on('exit', (code, signal) => { |
|||
process.exit(code || signal); |
|||
}); |
|||
@ -0,0 +1,69 @@ |
|||
'use strict'; |
|||
const common = require('../common'); |
|||
common.skipIfInspectorDisabled(); |
|||
common.skipIf32Bits(); |
|||
common.crashOnUnhandledRejection(); |
|||
const { NodeInstance } = require('./inspector-helper'); |
|||
const assert = require('assert'); |
|||
|
|||
const script = `runTest();
|
|||
function runTest() { |
|||
const p = Promise.resolve(); |
|||
p.then(function break1() { // lineNumber 3
|
|||
debugger; |
|||
}); |
|||
p.then(function break2() { // lineNumber 6
|
|||
debugger; |
|||
}); |
|||
} |
|||
`;
|
|||
|
|||
async function runTests() { |
|||
const instance = new NodeInstance(undefined, script); |
|||
const session = await instance.connectInspectorSession(); |
|||
await session.send([ |
|||
{ 'method': 'Runtime.enable' }, |
|||
{ 'method': 'Debugger.enable' }, |
|||
{ 'method': 'Debugger.setAsyncCallStackDepth', |
|||
'params': { 'maxDepth': 10 } }, |
|||
{ 'method': 'Debugger.setBlackboxPatterns', |
|||
'params': { 'patterns': [] } }, |
|||
{ 'method': 'Runtime.runIfWaitingForDebugger' } |
|||
]); |
|||
|
|||
console.error('[test] Waiting for break1'); |
|||
debuggerPausedAt(await session.waitForBreakOnLine(4, '[eval]'), |
|||
'break1', 'runTest:3'); |
|||
|
|||
await session.send({ 'method': 'Debugger.resume' }); |
|||
|
|||
console.error('[test] Waiting for break2'); |
|||
debuggerPausedAt(await session.waitForBreakOnLine(7, '[eval]'), |
|||
'break2', 'runTest:6'); |
|||
|
|||
await session.runToCompletion(); |
|||
assert.strictEqual(0, (await instance.expectShutdown()).exitCode); |
|||
} |
|||
|
|||
function debuggerPausedAt(msg, functionName, previousTickLocation) { |
|||
assert( |
|||
!!msg.params.asyncStackTrace, |
|||
`${Object.keys(msg.params)} contains "asyncStackTrace" property`); |
|||
|
|||
assert.strictEqual(msg.params.callFrames[0].functionName, functionName); |
|||
assert.strictEqual(msg.params.asyncStackTrace.description, 'PROMISE'); |
|||
|
|||
const frameLocations = msg.params.asyncStackTrace.callFrames.map( |
|||
(frame) => `${frame.functionName}:${frame.lineNumber}`); |
|||
assertArrayIncludes(frameLocations, previousTickLocation); |
|||
} |
|||
|
|||
function assertArrayIncludes(actual, expected) { |
|||
const expectedString = JSON.stringify(expected); |
|||
const actualString = JSON.stringify(actual); |
|||
assert( |
|||
actual.includes(expected), |
|||
`Expected ${actualString} to contain ${expectedString}.`); |
|||
} |
|||
|
|||
runTests(); |
|||
@ -0,0 +1,41 @@ |
|||
'use strict'; |
|||
const common = require('../common'); |
|||
common.skipIfInspectorDisabled(); |
|||
common.skipIf32Bits(); |
|||
common.crashOnUnhandledRejection(); |
|||
const { NodeInstance } = require('./inspector-helper'); |
|||
const assert = require('assert'); |
|||
|
|||
const script = 'setInterval(() => { debugger; }, 50);'; |
|||
|
|||
async function checkAsyncStackTrace(session) { |
|||
console.error('[test]', 'Verify basic properties of asyncStackTrace'); |
|||
const paused = await session.waitForBreakOnLine(0, '[eval]'); |
|||
assert(paused.params.asyncStackTrace, |
|||
`${Object.keys(paused.params)} contains "asyncStackTrace" property`); |
|||
assert(paused.params.asyncStackTrace.description, 'Timeout'); |
|||
assert(paused.params.asyncStackTrace.callFrames |
|||
.some((frame) => frame.functionName === 'Module._compile')); |
|||
} |
|||
|
|||
async function runTests() { |
|||
const instance = new NodeInstance(undefined, script); |
|||
const session = await instance.connectInspectorSession(); |
|||
await session.send([ |
|||
{ 'method': 'Runtime.enable' }, |
|||
{ 'method': 'Debugger.enable' }, |
|||
{ 'method': 'Debugger.setAsyncCallStackDepth', |
|||
'params': { 'maxDepth': 10 } }, |
|||
{ 'method': 'Debugger.setBlackboxPatterns', |
|||
'params': { 'patterns': [] } }, |
|||
{ 'method': 'Runtime.runIfWaitingForDebugger' } |
|||
]); |
|||
|
|||
await checkAsyncStackTrace(session); |
|||
|
|||
console.error('[test]', 'Stopping child instance'); |
|||
session.disconnect(); |
|||
instance.kill(); |
|||
} |
|||
|
|||
runTests(); |
|||
@ -0,0 +1,26 @@ |
|||
'use strict'; |
|||
const common = require('../common'); |
|||
common.skipIfInspectorDisabled(); |
|||
|
|||
const spawn = require('child_process').spawn; |
|||
|
|||
const script = ` |
|||
const assert = require('assert'); |
|||
const inspector = process.binding('inspector'); |
|||
|
|||
assert( |
|||
!!inspector.isEnabled(), |
|||
'inspector.isEnabled() should be true when run with --inspect'); |
|||
|
|||
process._debugEnd(); |
|||
|
|||
assert( |
|||
!inspector.isEnabled(), |
|||
'inspector.isEnabled() should be false after _debugEnd()'); |
|||
`;
|
|||
|
|||
const args = ['--inspect', '-e', script]; |
|||
const child = spawn(process.execPath, args, { stdio: 'inherit' }); |
|||
child.on('exit', (code, signal) => { |
|||
process.exit(code || signal); |
|||
}); |
|||
Loading…
Reference in new issue