[inspector] Implement Async Stack Tagging API v2

This CL adds a new method to the `console` that is available
when DevTools is open. In TypeScript notation the API is:

```
namespace console {
  // Creates a new `Task` and associates the current async
  // stack trace with the created `Task`.
  scheduleTask(name: string): Task;
}

interface Task {
  // Executes an arbitrary payload and forwards the return value
  // back to the caller. Any async stack trace captured during
  // 'f' has the site of the corresponding `scheduleTask` as
  // its parent.
  run<T>(f: () => T): T;
}
```

The API is a saner user-facing API for our async stack trace
mechanism:
  * scheduleAsyncTask corresponds to scheduleTask
  * startAsyncTask/stopAsyncTask are called implicitly before `f`
    is executed.
  * cancelAsyncTask is called implicitly when `Task` is GC'ed

The API is behind the flag --experimental-async-stack-tagging-api

Bug: chromium:1334585
Change-Id: Ic6054279a108756caed6b4b5f2d1fe4a1bdbaf78
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/3776678
Reviewed-by: Jaroslav Sevcik <jarin@chromium.org>
Reviewed-by: Kim-Anh Tran <kimanh@chromium.org>
Commit-Queue: Simon Zünd <szuend@chromium.org>
Cr-Commit-Position: refs/heads/main@{#81881}
This commit is contained in:
Simon Zünd 2022-07-21 14:12:59 +02:00 committed by V8 LUCI CQ
parent d99fd1aa48
commit c53c20fe64
6 changed files with 475 additions and 1 deletions

View File

@ -586,6 +586,103 @@ void V8Console::cancelAsyncTask(
m_asyncTaskIds.erase(taskId);
}
void V8Console::scheduleTask(const v8::FunctionCallbackInfo<v8::Value>& info) {
v8::Isolate* isolate = info.GetIsolate();
if (info.Length() < 1 || !info[0]->IsString() ||
!v8::Local<v8::String>::Cast(info[0])->Length()) {
isolate->ThrowError("First argument must be a non-empty string.");
return;
}
v8::Local<v8::External> data = v8::External::New(isolate, this);
v8::Local<v8::ObjectTemplate> taskTemplate = v8::ObjectTemplate::New(isolate);
v8::Local<v8::FunctionTemplate> funcTemplate = v8::FunctionTemplate::New(
isolate, &V8Console::call<&V8Console::runTask>, data);
taskTemplate->Set(isolate, "run", funcTemplate);
v8::Local<v8::Object> task =
taskTemplate->NewInstance(isolate->GetCurrentContext()).ToLocalChecked();
auto taskInfo = std::make_unique<TaskInfo>(isolate, this, task);
void* taskId = taskInfo->Id();
auto [iter, inserted] = m_tasks.emplace(taskId, std::move(taskInfo));
CHECK(inserted);
String16 nameArgument =
toProtocolString(isolate, v8::Local<v8::String>::Cast(info[0]));
StringView taskName =
StringView(nameArgument.characters16(), nameArgument.length());
m_inspector->asyncTaskScheduled(taskName, taskId, /* recurring */ true);
info.GetReturnValue().Set(task);
}
void V8Console::runTask(const v8::FunctionCallbackInfo<v8::Value>& info) {
v8::Isolate* isolate = info.GetIsolate();
if (info.Length() < 1 || !info[0]->IsFunction()) {
isolate->ThrowError("First argument must be a function.");
return;
}
v8::Local<v8::Function> function = info[0].As<v8::Function>();
v8::Local<v8::Object> task = info.This();
v8::Local<v8::Value> maybeTaskExternal;
if (!task->GetPrivate(isolate->GetCurrentContext(), taskInfoKey())
.ToLocal(&maybeTaskExternal)) {
// An exception is already thrown.
return;
}
if (!maybeTaskExternal->IsExternal()) {
isolate->ThrowError("'run' called with illegal receiver.");
return;
}
v8::Local<v8::External> taskExternal =
v8::Local<v8::External>::Cast(maybeTaskExternal);
TaskInfo* taskInfo = reinterpret_cast<TaskInfo*>(taskExternal->Value());
m_inspector->asyncTaskStarted(taskInfo->Id());
v8::Local<v8::Value> result;
if (function
->Call(isolate->GetCurrentContext(), v8::Undefined(isolate), 0, {})
.ToLocal(&result)) {
info.GetReturnValue().Set(result);
}
m_inspector->asyncTaskFinished(taskInfo->Id());
}
v8::Local<v8::Private> V8Console::taskInfoKey() {
v8::Isolate* isolate = m_inspector->isolate();
if (m_taskInfoKey.IsEmpty()) {
m_taskInfoKey.Reset(isolate, v8::Private::New(isolate));
}
return m_taskInfoKey.Get(isolate);
}
void V8Console::cancelConsoleTask(TaskInfo* taskInfo) {
m_inspector->asyncTaskCanceled(taskInfo->Id());
m_tasks.erase(taskInfo->Id());
}
namespace {
void cleanupTaskInfo(const v8::WeakCallbackInfo<TaskInfo>& info) {
TaskInfo* task = info.GetParameter();
CHECK(task);
task->Cancel();
}
} // namespace
TaskInfo::TaskInfo(v8::Isolate* isolate, V8Console* console,
v8::Local<v8::Object> task)
: m_task(isolate, task), m_console(console) {
task->SetPrivate(isolate->GetCurrentContext(), console->taskInfoKey(),
v8::External::New(isolate, this))
.Check();
m_task.SetWeak(this, cleanupTaskInfo, v8::WeakCallbackType::kParameter);
}
void V8Console::keysCallback(const v8::FunctionCallbackInfo<v8::Value>& info,
int sessionId) {
v8::Isolate* isolate = info.GetIsolate();
@ -846,6 +943,14 @@ void V8Console::installAsyncStackTaggingAPI(v8::Local<v8::Context> context,
v8::SideEffectType::kHasSideEffect)
.ToLocalChecked())
.Check();
console
->Set(
context, toV8StringInternalized(isolate, "scheduleTask"),
v8::Function::New(context, &V8Console::call<&V8Console::scheduleTask>,
data, 0, v8::ConstructorBehavior::kThrow,
v8::SideEffectType::kHasSideEffect)
.ToLocalChecked())
.Check();
}
v8::Local<v8::Object> V8Console::createCommandLineAPI(

View File

@ -20,6 +20,7 @@ class Set;
namespace v8_inspector {
class InspectedContext;
class TaskInfo;
class V8InspectorImpl;
// Console API
@ -32,6 +33,11 @@ class V8Console : public v8::debug::ConsoleDelegate {
v8::Local<v8::Object> console);
void installAsyncStackTaggingAPI(v8::Local<v8::Context> context,
v8::Local<v8::Object> console);
void cancelConsoleTask(TaskInfo* taskInfo);
std::map<void*, std::unique_ptr<TaskInfo>>& AllConsoleTasksForTest() {
return m_tasks;
}
class V8_NODISCARD CommandLineAPIScope {
public:
@ -64,6 +70,8 @@ class V8Console : public v8::debug::ConsoleDelegate {
explicit V8Console(V8InspectorImpl* inspector);
private:
friend class TaskInfo;
void Debug(const v8::debug::ConsoleCallArguments&,
const v8::debug::ConsoleContext& consoleContext) override;
void Error(const v8::debug::ConsoleCallArguments&,
@ -143,6 +151,8 @@ class V8Console : public v8::debug::ConsoleDelegate {
void startAsyncTask(const v8::FunctionCallbackInfo<v8::Value>&);
void finishAsyncTask(const v8::FunctionCallbackInfo<v8::Value>&);
void cancelAsyncTask(const v8::FunctionCallbackInfo<v8::Value>&);
void scheduleTask(const v8::FunctionCallbackInfo<v8::Value>&);
void runTask(const v8::FunctionCallbackInfo<v8::Value>&);
// CommandLineAPI
void keysCallback(const v8::FunctionCallbackInfo<v8::Value>&, int sessionId);
@ -186,6 +196,11 @@ class V8Console : public v8::debug::ConsoleDelegate {
void queryObjectsCallback(const v8::FunctionCallbackInfo<v8::Value>& info,
int sessionId);
// Lazily creates m_taskInfoKey and returns a local handle to it. We can't
// initialize m_taskInfoKey in the constructor as it would be part of
// Chromium's context snapshot.
v8::Local<v8::Private> taskInfoKey();
V8InspectorImpl* m_inspector;
// A map of unique pointers used for the scheduling and joining async stacks.
@ -195,6 +210,46 @@ class V8Console : public v8::debug::ConsoleDelegate {
// be improved for userland code that uses custom schedulers.
int64_t m_taskIdCounter = 0;
std::map<int64_t, AsyncTaskInfo> m_asyncTaskIds;
// All currently alive tasks. We mark tasks immediately as weak when created
// but we need the finalizer to cancel the task when GC cleans them up.
std::map<void*, std::unique_ptr<TaskInfo>> m_tasks;
// We use a private symbol to stash the `TaskInfo` as an v8::External on the
// JS task objects created by `console.scheduleTask`.
v8::Global<v8::Private> m_taskInfoKey;
};
/**
* Each JS task object created via `console.scheduleTask` has a corresponding
* `TaskInfo` object on the C++ side (in a 1:1 relationship).
*
* The `TaskInfo` holds on weakly to the JS task object.
* The JS task objects uses a private symbol to store a pointer to the
* `TaskInfo` object (via v8::External).
*
* The `TaskInfo` objects holds all the necessary information we need to
* properly cancel the corresponding async task then the JS task object
* gets GC'ed.
*/
class TaskInfo {
public:
TaskInfo(v8::Isolate* isolate, V8Console* console,
v8::Local<v8::Object> task);
// For these task IDs we duplicate the ID logic from blink and use even
// pointers compared to the odd IDs we use for promises. This guarantees that
// we don't have any conflicts between task IDs.
void* Id() const {
return reinterpret_cast<void*>(reinterpret_cast<intptr_t>(this) << 1);
}
// After calling `Cancel` the `TaskInfo` instance is destroyed.
void Cancel() { m_console->cancelConsoleTask(this); }
private:
v8::Global<v8::Object> m_task;
V8Console* m_console = nullptr;
};
} // namespace v8_inspector

View File

@ -126,7 +126,7 @@ class V8InspectorImpl : public V8Inspector {
V8InspectorSessionImpl* sessionById(int contextGroupId, int sessionId);
InspectedContext* getContext(int groupId, int contextId) const;
InspectedContext* getContext(int contextId) const;
V8Console* console();
V8_EXPORT_PRIVATE V8Console* console();
void forEachContext(int contextGroupId,
const std::function<void(InspectedContext*)>& callback);
void forEachSession(

View File

@ -254,3 +254,38 @@ TEST(NoConsoleAPIForUntrustedClient) {
channel.expected_response_matcher_ = R"("className":"ReferenceError")";
untrusted_session->dispatchProtocolMessage(toStringView(kCommand));
}
TEST(ApiCreatedTasksAreCleanedUp) {
i::FLAG_experimental_async_stack_tagging_api = true;
LocalContext env;
v8::Isolate* isolate = env->GetIsolate();
v8::HandleScope handle_scope(isolate);
v8_inspector::V8InspectorClient default_client;
std::unique_ptr<v8_inspector::V8InspectorImpl> inspector =
std::make_unique<v8_inspector::V8InspectorImpl>(isolate, &default_client);
V8ContextInfo context_info(env.local(), 1, toStringView(""));
inspector->contextCreated(context_info);
// Trigger V8Console creation.
v8_inspector::V8Console* console = inspector->console();
CHECK(console);
{
v8::HandleScope handle_scope(isolate);
v8::MaybeLocal<v8::Value> result = CompileRun(env.local(), R"(
globalThis['task'] = console.scheduleTask('Task');
)");
CHECK(!result.IsEmpty());
// Run GC and check that the task is still here.
CcTest::CollectAllGarbage();
CHECK_EQ(console->AllConsoleTasksForTest().size(), 1);
}
// Get rid of the task on the context, run GC and check we no longer have
// the TaskInfo in the inspector.
env->Global()->Delete(env.local(), v8_str("task")).Check();
CcTest::CollectAllGarbage();
CHECK_EQ(console->AllConsoleTasksForTest().size(), 0);
}

View File

@ -0,0 +1,145 @@
Stack tagging API works
Running test: simpleTaskLogsCorrectAsyncTrace
---------- console.trace: Inside run ----------
runner (simpleTaskLogsCorrectAsyncTrace.js:4:14)
simpleTaskLogsCorrectAsyncTrace (simpleTaskLogsCorrectAsyncTrace.js:3:9)
(anonymous) (simpleTaskLogsCorrectAsyncTrace.js:6:4)
-- Task --
foo (simpleTaskLogsCorrectAsyncTrace.js:1:36)
simpleTaskLogsCorrectAsyncTrace (simpleTaskLogsCorrectAsyncTrace.js:2:17)
(anonymous) (simpleTaskLogsCorrectAsyncTrace.js:6:4)
Running test: nestedTasksLogCorrectAsyncTrace
---------- console.trace: Inside runInner ----------
runInner (nestedTasksLogCorrectAsyncTrace.js:5:16)
runOuter (nestedTasksLogCorrectAsyncTrace.js:4:16)
nestedTasksLogCorrectAsyncTrace (nestedTasksLogCorrectAsyncTrace.js:2:14)
(anonymous) (nestedTasksLogCorrectAsyncTrace.js:8:4)
-- Inner Task --
runOuter (nestedTasksLogCorrectAsyncTrace.js:3:32)
nestedTasksLogCorrectAsyncTrace (nestedTasksLogCorrectAsyncTrace.js:2:14)
(anonymous) (nestedTasksLogCorrectAsyncTrace.js:8:4)
-- Outer Task --
nestedTasksLogCorrectAsyncTrace (nestedTasksLogCorrectAsyncTrace.js:1:30)
(anonymous) (nestedTasksLogCorrectAsyncTrace.js:8:4)
Running test: setTimeoutWorksCorrectly
---------- console.trace: Inside runInner ----------
runInner (setTimeoutWorksCorrectly.js:6:18)
(anonymous) (setTimeoutWorksCorrectly.js:5:18)
-- Inner Task --
(anonymous) (setTimeoutWorksCorrectly.js:4:34)
-- setTimeout --
(anonymous) (setTimeoutWorksCorrectly.js:3:30)
runOuter (setTimeoutWorksCorrectly.js:3:13)
setTimeoutWorksCorrectly (setTimeoutWorksCorrectly.js:2:20)
(anonymous) (setTimeoutWorksCorrectly.js:11:4)
-- Outer Task --
setTimeoutWorksCorrectly (setTimeoutWorksCorrectly.js:1:30)
(anonymous) (setTimeoutWorksCorrectly.js:11:4)
Running test: runForwardsTheReturnValue
---------- console.log: 42 ----------
runForwardsTheReturnValue (runForwardsTheReturnValue.js:3:12)
(anonymous) (runForwardsTheReturnValue.js:4:4)
Running test: runWorksWithAsyncPayloads
---------- console.log: 42 ----------
runWorksWithAsyncPayloads (runWorksWithAsyncPayloads.js:3:12)
Running test: runWorksWithGenerators
---------- console.log: 42 ----------
runWorksWithGenerators (runWorksWithGenerators.js:3:12)
(anonymous) (runWorksWithGenerators.js:4:4)
Running test: runCanBeCalledMultipleTimes
---------- console.log: First run ----------
(anonymous) (runCanBeCalledMultipleTimes.js:2:27)
runCanBeCalledMultipleTimes (runCanBeCalledMultipleTimes.js:2:9)
(anonymous) (runCanBeCalledMultipleTimes.js:4:4)
---------- console.log: Second run ----------
(anonymous) (runCanBeCalledMultipleTimes.js:3:27)
runCanBeCalledMultipleTimes (runCanBeCalledMultipleTimes.js:3:9)
(anonymous) (runCanBeCalledMultipleTimes.js:4:4)
Running test: runForwardsExceptions
Expected exception:
{
className : Error
description : Error: Thrown from task.run at runForwardsExceptions.js:4:13 at runForwardsExceptions (runForwardsExceptions.js:3:10) at runForwardsExceptions.js:6:5
objectId : <objectId>
subtype : error
type : object
}
Running test: recursivelyCalledRunDoesntCrash
---------- console.trace: Inside nestedRunOuter ----------
nestedRunOuter (recursivelyCalledRunDoesntCrash.js:6:18)
runInner (recursivelyCalledRunDoesntCrash.js:5:18)
runOuter (recursivelyCalledRunDoesntCrash.js:4:16)
recursivelyCalledRunDoesntCrash (recursivelyCalledRunDoesntCrash.js:2:14)
(anonymous) (recursivelyCalledRunDoesntCrash.js:10:4)
-- Outer Task --
recursivelyCalledRunDoesntCrash (recursivelyCalledRunDoesntCrash.js:1:30)
(anonymous) (recursivelyCalledRunDoesntCrash.js:10:4)
Running test: scheduleThrowsAnErrorWhenCalledWithoutAnArgument
Expected exception:
{
className : Error
description : Error: First argument must be a non-empty string. at scheduleThrowsAnErrorWhenCalledWithoutAnArgument (scheduleThrowsAnErrorWhenCalledWithoutAnArgument.js:2:13) at scheduleThrowsAnErrorWhenCalledWithoutAnArgument.js:3:5
objectId : <objectId>
subtype : error
type : object
}
Running test: scheduleThrowsAnErrorWhenCalledWithAnEmptyString
Expected exception:
{
className : Error
description : Error: First argument must be a non-empty string. at scheduleThrowsAnErrorWhenCalledWithAnEmptyString (scheduleThrowsAnErrorWhenCalledWithAnEmptyString.js:2:13) at scheduleThrowsAnErrorWhenCalledWithAnEmptyString.js:3:5
objectId : <objectId>
subtype : error
type : object
}
Running test: runThrowsAnErrorWhenCalledWithoutAnArgument
Expected exception:
{
className : Error
description : Error: First argument must be a function. at runThrowsAnErrorWhenCalledWithoutAnArgument (runThrowsAnErrorWhenCalledWithoutAnArgument.js:3:10) at runThrowsAnErrorWhenCalledWithoutAnArgument.js:4:5
objectId : <objectId>
subtype : error
type : object
}
Running test: runThrowsAnErrorWhenCalledWithNonFunction
Expected exception:
{
className : Error
description : Error: First argument must be a function. at runThrowsAnErrorWhenCalledWithNonFunction (runThrowsAnErrorWhenCalledWithNonFunction.js:3:10) at runThrowsAnErrorWhenCalledWithNonFunction.js:4:5
objectId : <objectId>
subtype : error
type : object
}
Running test: runThrowsAnErrorWhenCalledWithNullReceiver
Expected exception:
{
className : Error
description : Error: 'run' called with illegal receiver. at runThrowsAnErrorWhenCalledWithNullReceiver (runThrowsAnErrorWhenCalledWithNullReceiver.js:3:14) at runThrowsAnErrorWhenCalledWithNullReceiver.js:4:5
objectId : <objectId>
subtype : error
type : object
}
Running test: runThrowsAnErrorWhenCalledWithIllegalReceiver
Expected exception:
{
className : Error
description : Error: 'run' called with illegal receiver. at runThrowsAnErrorWhenCalledWithIllegalReceiver (runThrowsAnErrorWhenCalledWithIllegalReceiver.js:3:14) at runThrowsAnErrorWhenCalledWithIllegalReceiver.js:4:5
objectId : <objectId>
subtype : error
type : object
}

View File

@ -0,0 +1,134 @@
// Copyright 2022 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.
// Flags: --experimental-async-stack-tagging-api
const { session, contextGroup, Protocol } = InspectorTest.start('Stack tagging API works');
session.setupScriptMap();
// We write the test cases as functions instead of string literals so the
// fuzzer can fuzz them as well.
const testCases = [
function simpleTaskLogsCorrectAsyncTrace() {
function foo() { return console.scheduleTask('Task'); }
const task = foo();
task.run(function runner() {
console.trace('Inside run');
});
},
function nestedTasksLogCorrectAsyncTrace() {
const outerTask = console.scheduleTask('Outer Task');
outerTask.run(function runOuter() {
const innerTask = console.scheduleTask('Inner Task');
innerTask.run(function runInner() {
console.trace('Inside runInner');
});
});
},
async function setTimeoutWorksCorrectly() {
const outerTask = console.scheduleTask('Outer Task');
await outerTask.run(async function runOuter() {
return new Promise(r => setTimeout(() => {
const innerTask = console.scheduleTask('Inner Task');
innerTask.run(function runInner() {
console.trace('Inside runInner');
r();
});
}, 0));
});
},
function runForwardsTheReturnValue() {
const task = console.scheduleTask('Task');
const result = task.run(() => 42);
console.log(result);
},
async function runWorksWithAsyncPayloads() {
const task = console.scheduleTask('Task');
const result = await task.run(async () => 42);
console.log(result);
},
function runWorksWithGenerators() {
const task = console.scheduleTask('Task');
const iter = task.run(function* () { yield 42; });
console.log(iter.next().value);
},
function runCanBeCalledMultipleTimes() {
const task = console.scheduleTask('Task');
task.run(() => console.log('First run'));
task.run(() => console.log('Second run'));
},
function runForwardsExceptions() {
const task = console.scheduleTask('Task');
task.run(() => {
throw new Error('Thrown from task.run');
});
},
function recursivelyCalledRunDoesntCrash() {
const outerTask = console.scheduleTask('Outer Task');
outerTask.run(function runOuter() {
const innerTask = console.scheduleTask('Inner Task');
innerTask.run(function runInner() {
outerTask.run(function nestedRunOuter() {
console.trace('Inside nestedRunOuter');
});
});
});
},
function scheduleThrowsAnErrorWhenCalledWithoutAnArgument() {
console.scheduleTask();
},
function scheduleThrowsAnErrorWhenCalledWithAnEmptyString() {
console.scheduleTask('');
},
function runThrowsAnErrorWhenCalledWithoutAnArgument() {
const task = console.scheduleTask('Task');
task.run();
},
function runThrowsAnErrorWhenCalledWithNonFunction() {
const task = console.scheduleTask('Task');
task.run(42);
},
function runThrowsAnErrorWhenCalledWithNullReceiver() {
const task = console.scheduleTask('Task');
task.run.call(undefined, () => { });
},
function runThrowsAnErrorWhenCalledWithIllegalReceiver() {
const task = console.scheduleTask('Task');
task.run.call({}, () => { }); // The private symbol is missing.
},
];
(async () => {
Protocol.Runtime.onConsoleAPICalled(({params}) => {
InspectorTest.log(`---------- console.${params.type}: ${params.args[0].value} ----------`);
session.logCallFrames(params.stackTrace.callFrames);
session.logAsyncStackTrace(params.stackTrace.parent);
});
await Protocol.Runtime.enable();
await Protocol.Debugger.enable();
await Protocol.Debugger.setAsyncCallStackDepth({ maxDepth: 128 });
for (const testCase of testCases) {
InspectorTest.log(`\nRunning test: ${testCase.name}`);
// Turn the function into an IIFE and compile + run it as a script.
const {result: {scriptId}} = await Protocol.Runtime.compileScript({
expression: `(${testCase.toString()})();`,
sourceURL: `${testCase.name}.js`,
persistScript: true,
});
const { result: { exceptionDetails } } = await Protocol.Runtime.runScript({
scriptId,
awaitPromise: true,
});
if (exceptionDetails) {
InspectorTest.log(`Expected exception: `);
InspectorTest.logMessage(exceptionDetails.exception);
}
}
InspectorTest.completeTest();
})();