From f2bd913cd459854894447f5422a953d23fa4e7ba Mon Sep 17 00:00:00 2001 From: kozyatinskiy Date: Fri, 28 Apr 2017 14:07:01 -0700 Subject: [PATCH] [inspector] better stacks for promises - we should always set creation async stack if it's available regardless existing of current parent async stack, - we should cleanup parent link iff there is no creation and schedule async stack for parent. Let's consider example: Promise.resolve().then(x => x).then(x => x), there is three promises which will call following instrumentation: 1) created #1 (Promise.resolve()) - collected stack #1 2) scheduled #1 - collected stack #2 3) created #2 with #1 as parent (first .then) - collected stack #3 4) created #3 with #2 as parent (first .then) - collected stack #4 5) started #2 - use stack #2 as scheduled 6) scheduled #2 - collected stack #6 7) finished #2 8) started #3 - use stack #6 as scheduled 9) scheduled #3 - collected stack #7 10) finished #3 If we collect stacks between step 4 and 5, it's possible to collect scheduled stack #2 but still have creation stack for #2 - stack #3 - so we always need to add creation event if scheduled is collected. If we collect stacks between created and scheduled we should not remove parent link even if parent was not scheduled yet. BUG=v8:6189 R=dgozman@chromium.org Review-Url: https://codereview.chromium.org/2844753002 Cr-Commit-Position: refs/heads/master@{#44990} --- src/inspector/v8-debugger.cc | 21 +- src/inspector/v8-stack-trace-impl.cc | 14 +- src/inspector/v8-stack-trace-impl.h | 1 + ...collect-old-async-call-chains-expected.txt | 6 +- .../promise-chain-when-limit-hit-expected.txt | 297 ++++++++++++++++++ .../debugger/promise-chain-when-limit-hit.js | 51 +++ 6 files changed, 375 insertions(+), 15 deletions(-) create mode 100644 test/inspector/debugger/promise-chain-when-limit-hit-expected.txt create mode 100644 test/inspector/debugger/promise-chain-when-limit-hit.js diff --git a/src/inspector/v8-debugger.cc b/src/inspector/v8-debugger.cc index 3acb329dae1c..f65b590b04cf 100644 --- a/src/inspector/v8-debugger.cc +++ b/src/inspector/v8-debugger.cc @@ -913,10 +913,6 @@ void V8Debugger::asyncTaskCanceledForStack(void* task) { void V8Debugger::asyncTaskStartedForStack(void* task) { if (!m_maxAsyncCallStackDepth) return; - m_currentTasks.push_back(task); - auto parentIt = m_parentTask.find(task); - AsyncTaskToStackTrace::iterator stackIt = m_asyncTaskStacks.find( - parentIt == m_parentTask.end() ? task : parentIt->second); // Needs to support following order of events: // - asyncTaskScheduled // <-- attached here --> @@ -924,15 +920,21 @@ void V8Debugger::asyncTaskStartedForStack(void* task) { // - asyncTaskCanceled <-- canceled before finished // <-- async stack requested here --> // - asyncTaskFinished - std::weak_ptr asyncParent; - if (stackIt != m_asyncTaskStacks.end()) asyncParent = stackIt->second; + m_currentTasks.push_back(task); + auto parentIt = m_parentTask.find(task); + AsyncTaskToStackTrace::iterator stackIt = m_asyncTaskStacks.find( + parentIt == m_parentTask.end() ? task : parentIt->second); + if (stackIt != m_asyncTaskStacks.end()) { + m_currentAsyncParent.push_back(stackIt->second.lock()); + } else { + m_currentAsyncParent.emplace_back(); + } auto itCreation = m_asyncTaskCreationStacks.find(task); - if (asyncParent.lock() && itCreation != m_asyncTaskCreationStacks.end()) { + if (itCreation != m_asyncTaskCreationStacks.end()) { m_currentAsyncCreation.push_back(itCreation->second.lock()); } else { m_currentAsyncCreation.emplace_back(); } - m_currentAsyncParent.push_back(asyncParent.lock()); } void V8Debugger::asyncTaskFinishedForStack(void* task) { @@ -1041,7 +1043,8 @@ void V8Debugger::collectOldAsyncStacksIfNeeded() { } for (auto it = m_parentTask.begin(); it != m_parentTask.end();) { if (m_asyncTaskCreationStacks.find(it->second) == - m_asyncTaskCreationStacks.end()) { + m_asyncTaskCreationStacks.end() && + m_asyncTaskStacks.find(it->second) == m_asyncTaskStacks.end()) { it = m_parentTask.erase(it); } else { ++it; diff --git a/src/inspector/v8-stack-trace-impl.cc b/src/inspector/v8-stack-trace-impl.cc index 663b0706ead7..cb509bd8e9d6 100644 --- a/src/inspector/v8-stack-trace-impl.cc +++ b/src/inspector/v8-stack-trace-impl.cc @@ -63,8 +63,14 @@ void calculateAsyncChain(V8Debugger* debugger, int contextGroupId, std::unique_ptr buildInspectorObjectCommon( const std::vector>& frames, + const String16& description, const std::shared_ptr& asyncParent, const std::shared_ptr& asyncCreation, int maxAsyncDepth) { + if (asyncParent && frames.empty() && + description == asyncParent->description() && !asyncCreation) { + return asyncParent->buildInspectorObject(nullptr, maxAsyncDepth); + } + std::unique_ptr> inspectorFrames = protocol::Array::create(); for (size_t i = 0; i < frames.size(); i++) { @@ -74,6 +80,7 @@ std::unique_ptr buildInspectorObjectCommon( protocol::Runtime::StackTrace::create() .setCallFrames(std::move(inspectorFrames)) .build(); + if (!description.isEmpty()) stackTrace->setDescription(description); if (asyncParent && maxAsyncDepth > 0) { stackTrace->setParent(asyncParent->buildInspectorObject(asyncCreation.get(), maxAsyncDepth - 1)); @@ -206,7 +213,7 @@ StringView V8StackTraceImpl::topFunctionName() const { std::unique_ptr V8StackTraceImpl::buildInspectorObjectImpl() const { - return buildInspectorObjectCommon(m_frames, m_asyncParent.lock(), + return buildInspectorObjectCommon(m_frames, String16(), m_asyncParent.lock(), m_asyncCreation.lock(), m_maxAsyncDepth); } @@ -292,9 +299,8 @@ std::unique_ptr AsyncStackTrace::buildInspectorObject(AsyncStackTrace* asyncCreation, int maxAsyncDepth) const { std::unique_ptr stackTrace = - buildInspectorObjectCommon(m_frames, m_asyncParent.lock(), + buildInspectorObjectCommon(m_frames, m_description, m_asyncParent.lock(), m_asyncCreation.lock(), maxAsyncDepth); - if (!m_description.isEmpty()) stackTrace->setDescription(m_description); if (asyncCreation && !asyncCreation->isEmpty()) { stackTrace->setPromiseCreationFrame( asyncCreation->m_frames[0]->buildInspectorObject()); @@ -304,6 +310,8 @@ AsyncStackTrace::buildInspectorObject(AsyncStackTrace* asyncCreation, int AsyncStackTrace::contextGroupId() const { return m_contextGroupId; } +const String16& AsyncStackTrace::description() const { return m_description; } + std::weak_ptr AsyncStackTrace::parent() const { return m_asyncParent; } diff --git a/src/inspector/v8-stack-trace-impl.h b/src/inspector/v8-stack-trace-impl.h index ba8fa3feeb71..302f6fbbb92d 100644 --- a/src/inspector/v8-stack-trace-impl.h +++ b/src/inspector/v8-stack-trace-impl.h @@ -97,6 +97,7 @@ class AsyncStackTrace { AsyncStackTrace* asyncCreation, int maxAsyncDepth) const; int contextGroupId() const; + const String16& description() const; std::weak_ptr parent() const; std::weak_ptr creation() const; bool isEmpty() const; diff --git a/test/inspector/debugger/collect-old-async-call-chains-expected.txt b/test/inspector/debugger/collect-old-async-call-chains-expected.txt index e3981b0603a8..e3a8842fde72 100644 --- a/test/inspector/debugger/collect-old-async-call-chains-expected.txt +++ b/test/inspector/debugger/collect-old-async-call-chains-expected.txt @@ -95,7 +95,7 @@ actual async chain len: 1 inspector.setMaxAsyncTaskStacks(3) Run expression 'console.trace(42)' with async chain len: 2 -actual async chain len: 0 +actual async chain len: 1 inspector.setMaxAsyncTaskStacks(3) Run expression 'console.trace(42)' with async chain len: 3 @@ -123,7 +123,7 @@ actual async chain len: 1 inspector.setMaxAsyncTaskStacks(4) Run expression 'console.trace(42)' with async chain len: 3 -actual async chain len: 0 +actual async chain len: 1 inspector.setMaxAsyncTaskStacks(4) Run expression 'console.trace(42)' with async chain len: 1 @@ -171,7 +171,7 @@ actual async chain len: 2 inspector.setMaxAsyncTaskStacks(6) Run expression 'console.trace(42)' with async chain len: 3 -actual async chain len: 2 +actual async chain len: 1 inspector.setMaxAsyncTaskStacks(6) Run expression 'console.trace(42)' with async chain len: 1 diff --git a/test/inspector/debugger/promise-chain-when-limit-hit-expected.txt b/test/inspector/debugger/promise-chain-when-limit-hit-expected.txt new file mode 100644 index 000000000000..1b63dea52557 --- /dev/null +++ b/test/inspector/debugger/promise-chain-when-limit-hit-expected.txt @@ -0,0 +1,297 @@ +Checks correctness of promise chains when limit hit +inspector.setMaxAsyncTaskStacks(3) +Run expression 'console.trace()' with async chain len: 3 +{ + method : Runtime.consoleAPICalled + params : { + args : [ + [0] : { + type : string + value : console.trace + } + ] + executionContextId : + stackTrace : { + callFrames : [ + [0] : { + columnNumber : 67 + functionName : Promise.resolve.then.then.then + lineNumber : 0 + scriptId : + url : + } + ] + } + timestamp : + type : trace + } +} +inspector.setMaxAsyncTaskStacks(4) +Run expression 'console.trace()' with async chain len: 3 +{ + method : Runtime.consoleAPICalled + params : { + args : [ + [0] : { + type : string + value : console.trace + } + ] + executionContextId : + stackTrace : { + callFrames : [ + [0] : { + columnNumber : 67 + functionName : Promise.resolve.then.then.then + lineNumber : 0 + scriptId : + url : + } + ] + parent : { + callFrames : [ + ] + description : Promise.resolve + promiseCreationFrame : { + columnNumber : 46 + functionName : + lineNumber : 0 + scriptId : + url : + } + } + } + timestamp : + type : trace + } +} +inspector.setMaxAsyncTaskStacks(5) +Run expression 'console.trace()' with async chain len: 3 +{ + method : Runtime.consoleAPICalled + params : { + args : [ + [0] : { + type : string + value : console.trace + } + ] + executionContextId : + stackTrace : { + callFrames : [ + [0] : { + columnNumber : 67 + functionName : Promise.resolve.then.then.then + lineNumber : 0 + scriptId : + url : + } + ] + parent : { + callFrames : [ + ] + description : Promise.resolve + parent : { + callFrames : [ + ] + description : Promise.resolve + promiseCreationFrame : { + columnNumber : 32 + functionName : + lineNumber : 0 + scriptId : + url : + } + } + promiseCreationFrame : { + columnNumber : 46 + functionName : + lineNumber : 0 + scriptId : + url : + } + } + } + timestamp : + type : trace + } +} +inspector.setMaxAsyncTaskStacks(6) +Run expression 'console.trace()' with async chain len: 3 +{ + method : Runtime.consoleAPICalled + params : { + args : [ + [0] : { + type : string + value : console.trace + } + ] + executionContextId : + stackTrace : { + callFrames : [ + [0] : { + columnNumber : 67 + functionName : Promise.resolve.then.then.then + lineNumber : 0 + scriptId : + url : + } + ] + parent : { + callFrames : [ + ] + description : Promise.resolve + promiseCreationFrame : { + columnNumber : 46 + functionName : + lineNumber : 0 + scriptId : + url : + } + } + } + timestamp : + type : trace + } +} +inspector.setMaxAsyncTaskStacks(7) +Run expression 'console.trace()' with async chain len: 3 +{ + method : Runtime.consoleAPICalled + params : { + args : [ + [0] : { + type : string + value : console.trace + } + ] + executionContextId : + stackTrace : { + callFrames : [ + [0] : { + columnNumber : 67 + functionName : Promise.resolve.then.then.then + lineNumber : 0 + scriptId : + url : + } + ] + parent : { + callFrames : [ + ] + description : Promise.resolve + parent : { + callFrames : [ + ] + description : Promise.resolve + parent : { + callFrames : [ + [0] : { + columnNumber : 8 + functionName : + lineNumber : 0 + scriptId : + url : + } + ] + description : Promise.resolve + promiseCreationFrame : { + columnNumber : 18 + functionName : + lineNumber : 0 + scriptId : + url : + } + } + promiseCreationFrame : { + columnNumber : 32 + functionName : + lineNumber : 0 + scriptId : + url : + } + } + promiseCreationFrame : { + columnNumber : 46 + functionName : + lineNumber : 0 + scriptId : + url : + } + } + } + timestamp : + type : trace + } +} +inspector.setMaxAsyncTaskStacks(8) +Run expression 'console.trace()' with async chain len: 3 +{ + method : Runtime.consoleAPICalled + params : { + args : [ + [0] : { + type : string + value : console.trace + } + ] + executionContextId : + stackTrace : { + callFrames : [ + [0] : { + columnNumber : 67 + functionName : Promise.resolve.then.then.then + lineNumber : 0 + scriptId : + url : + } + ] + parent : { + callFrames : [ + ] + description : Promise.resolve + parent : { + callFrames : [ + ] + description : Promise.resolve + parent : { + callFrames : [ + [0] : { + columnNumber : 8 + functionName : + lineNumber : 0 + scriptId : + url : + } + ] + description : Promise.resolve + promiseCreationFrame : { + columnNumber : 18 + functionName : + lineNumber : 0 + scriptId : + url : + } + } + promiseCreationFrame : { + columnNumber : 32 + functionName : + lineNumber : 0 + scriptId : + url : + } + } + promiseCreationFrame : { + columnNumber : 46 + functionName : + lineNumber : 0 + scriptId : + url : + } + } + } + timestamp : + type : trace + } +} diff --git a/test/inspector/debugger/promise-chain-when-limit-hit.js b/test/inspector/debugger/promise-chain-when-limit-hit.js new file mode 100644 index 000000000000..53ff71780cb9 --- /dev/null +++ b/test/inspector/debugger/promise-chain-when-limit-hit.js @@ -0,0 +1,51 @@ +// Copyright 2017 the V8 project authors. All rights reserved. +// Use of this source code is governed by a BSD-style license that can be +// found in the LICENSE file. + +(async function test(){ + InspectorTest.log('Checks correctness of promise chains when limit hit'); + await Protocol.Runtime.enable(); + await Protocol.Debugger.enable(); + Protocol.Debugger.setAsyncCallStackDepth({maxDepth: 128}); + + await setMaxAsyncTaskStacks(3); + runWithAsyncChainPromise(3, 'console.trace()'); + InspectorTest.logMessage(await Protocol.Runtime.onceConsoleAPICalled()); + + await setMaxAsyncTaskStacks(4); + runWithAsyncChainPromise(3, 'console.trace()'); + InspectorTest.logMessage(await Protocol.Runtime.onceConsoleAPICalled()); + + await setMaxAsyncTaskStacks(5); + runWithAsyncChainPromise(3, 'console.trace()'); + InspectorTest.logMessage(await Protocol.Runtime.onceConsoleAPICalled()); + + await setMaxAsyncTaskStacks(6); + runWithAsyncChainPromise(3, 'console.trace()'); + InspectorTest.logMessage(await Protocol.Runtime.onceConsoleAPICalled()); + + await setMaxAsyncTaskStacks(7); + runWithAsyncChainPromise(3, 'console.trace()'); + InspectorTest.logMessage(await Protocol.Runtime.onceConsoleAPICalled()); + + await setMaxAsyncTaskStacks(8); + runWithAsyncChainPromise(3, 'console.trace()'); + InspectorTest.logMessage(await Protocol.Runtime.onceConsoleAPICalled()); + + InspectorTest.completeTest(); +})(); + +function runWithAsyncChainPromise(len, source) { + InspectorTest.log(`Run expression '${source}' with async chain len: ${len}`); + let then = '.then(() => 1)'; + let pause = `.then(() => { ${source} })`; + Protocol.Runtime.evaluate({ + expression: `Promise.resolve()${then.repeat(len - 1)}${pause}` + }); +} + +async function setMaxAsyncTaskStacks(max) { + let expression = `inspector.setMaxAsyncTaskStacks(${max})`; + InspectorTest.log(expression); + await Protocol.Runtime.evaluate({expression}); +}