Skip to content

Commit

Permalink
LoAF: support approximate source locations for promise resolvers
Browse files Browse the repository at this point in the history
Attribute the source location of a promise resolver that contributed
to LoAF to the script that created it, e.g. the script that called
fetch().

Getting the exact source location of the promise resolver itself
would require capturing a stack trace, which might be too much
overhead, so this is the next best thing. We can revise in the future
whether a shallow stack trace is something we're OK with in some
circumstances.

Note that it's impossible to get the location of the actual then(),
as that's a microtask that's batched together with all the rest of
the microtasks (e.g. other then()s of the same promise).

The animation frame monitor maintains a weak map between the promise
resolver and the source location of the event
listener/script-block/callback that was responsible for creating it.
This source location is then used when a promise is resolved and the
resolution task is a long script that contributes to the LoAF.

Bug: 1392685
Change-Id: I268ebbbf035b0800a5d1bd61cd939e46533fe064
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/4783320
Reviewed-by: Yoav Weiss <yoavweiss@chromium.org>
Commit-Queue: Noam Rosenthal <nrosenthal@chromium.org>
Cr-Commit-Position: refs/heads/main@{#1186486}
  • Loading branch information
noamr authored and Chromium LUCI CQ committed Aug 22, 2023
1 parent eecf6b1 commit 07a41b1
Show file tree
Hide file tree
Showing 9 changed files with 115 additions and 37 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -49,6 +49,8 @@ ScriptPromiseResolver::ScriptPromiseResolver(ScriptState* script_state)
state_ = kDetached;
resolver_.Clear();
}
probe::DidCreateScriptPromiseResolver(ExecutionContext::From(script_state),
this);
}

ScriptPromiseResolver::ScriptPromiseResolver(
Expand Down Expand Up @@ -145,9 +147,7 @@ void ScriptPromiseResolver::ResolveOrRejectImmediately() {
DCHECK(!GetExecutionContext()->IsContextDestroyed());
DCHECK(!GetExecutionContext()->IsContextPaused());

probe::WillHandlePromise(GetExecutionContext(), script_state_,
state_ == kResolving, class_like_name_,
property_like_name_);
probe::WillHandlePromise(GetExecutionContext(), this);
{
if (state_ == kResolving) {
resolver_.Resolve(value_.Get(script_state_->GetIsolate()));
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -117,6 +117,9 @@ class CORE_EXPORT ScriptPromiseResolver
void RejectWithWasmCompileError(const String& message);

ScriptState* GetScriptState() const { return script_state_; }
const char* GetClassLikeName() const { return class_like_name_; }
const char* GetPropertyLikeName() const { return property_like_name_; }
bool isResolving() const { return state_ == ResolutionState::kResolving; }

const ExceptionContext& GetExceptionContext() const {
return exception_context_;
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -323,6 +323,7 @@ void AnimationFrameTimingMonitor::RecordLongAnimationFrameUKM(
void AnimationFrameTimingMonitor::Trace(Visitor* visitor) const {
visitor->Trace(current_frame_timing_info_);
visitor->Trace(current_scripts_);
visitor->Trace(promise_resolver_source_location_map_);
}

ScriptTimingInfo* AnimationFrameTimingMonitor::MaybeAddScript(
Expand Down Expand Up @@ -404,16 +405,24 @@ void AnimationFrameTimingMonitor::OnMicrotasksCompleted(
MaybeAddScript(context, base::TimeTicks::Now());
}

void AnimationFrameTimingMonitor::DidCreateScriptPromiseResolver(
ExecutionContext* context,
ScriptPromiseResolver* resolver) {
CHECK(!promise_resolver_source_location_map_.Contains(resolver));
if (pending_script_info_) {
promise_resolver_source_location_map_.Set(
resolver, pending_script_info_->source_location);
}
}

void AnimationFrameTimingMonitor::WillHandlePromise(
ExecutionContext* context,
ScriptState* script_state,
bool resolving,
const char* class_like_name,
const char* property_like_name) {
ScriptPromiseResolver* resolver) {
// Make sure we only monitor top-level promise resolvers that are outside the
// update-the-rendering phase (promise resolvers directly handled from a
// posted task).
if (!context->IsWindow() || !script_state->World().IsMainWorld() ||
if (!context->IsWindow() ||
!resolver->GetScriptState()->World().IsMainWorld() ||
pending_script_info_ || state_ != State::kProcessingTask) {
return;
}
Expand All @@ -435,12 +444,16 @@ void AnimationFrameTimingMonitor::WillHandlePromise(

base::TimeTicks now = base::TimeTicks::Now();
pending_script_info_ = PendingScriptInfo{
.type = resolving ? ScriptTimingInfo::Type::kPromiseResolve
: ScriptTimingInfo::Type::kPromiseReject,
.type = resolver->isResolving() ? ScriptTimingInfo::Type::kPromiseResolve
: ScriptTimingInfo::Type::kPromiseReject,
.start_time = now,
.execution_start_time = now,
.class_like_name = class_like_name,
.property_like_name = property_like_name};
.class_like_name = resolver->GetClassLikeName(),
.property_like_name = resolver->GetPropertyLikeName()};
auto it = promise_resolver_source_location_map_.find(resolver);
if (it != promise_resolver_source_location_map_.end()) {
pending_script_info_->source_location = it->value;
}

user_callback_depth_++;
}
Expand Down Expand Up @@ -660,19 +673,27 @@ void AnimationFrameTimingMonitor::Will(
return;
}

v8::HandleScope handle_scope(probe_data.context->GetIsolate());
if (!probe_data.context->IsWindow() ||
!client_.ShouldReportLongAnimationFrameTiming() || !probe_data.listener ||
!probe_data.listener->IsJSBasedEventListener() ||
!IsCallbackFromMainWorld(
To<JSBasedEventListener>(probe_data.listener)
->GetListenerObject(*probe_data.event_target))) {
!client_.ShouldReportLongAnimationFrameTiming() || !probe_data.listener) {
return;
}
pending_script_info_ =
PendingScriptInfo{.type = ScriptTimingInfo::Type::kEventHandler,
.start_time = probe_data.CaptureStartTime(),
.execution_start_time = probe_data.CaptureStartTime()};

v8::HandleScope handle_scope(probe_data.context->GetIsolate());
v8::MaybeLocal<v8::Value> listener_object;
if (probe_data.listener && probe_data.listener->IsJSBasedEventListener()) {
listener_object = To<JSBasedEventListener>(probe_data.listener)
->GetListenerObject(*probe_data.event_target);
if (listener_object.IsEmpty() ||
!IsCallbackFromMainWorld(listener_object)) {
return;
}
}

pending_script_info_ = PendingScriptInfo{
.type = ScriptTimingInfo::Type::kEventHandler,
.start_time = probe_data.CaptureStartTime(),
.execution_start_time = probe_data.CaptureStartTime(),
.source_location = CaptureScriptSourceLocation(listener_object)};
}

void AnimationFrameTimingMonitor::Did(
Expand Down Expand Up @@ -711,15 +732,6 @@ void AnimationFrameTimingMonitor::Did(
} else {
info->SetClassLikeName(probe_data.event_target->InterfaceName());
}

if (!probe_data.listener->IsJSBasedEventListener()) {
return;
}

v8::HandleScope handle_scope(probe_data.context->GetIsolate());
info->SetSourceLocation(CaptureScriptSourceLocation(
To<JSBasedEventListener>(probe_data.listener)
->GetListenerObject(*probe_data.event_target)));
}

} // namespace blink
Original file line number Diff line number Diff line change
Expand Up @@ -11,9 +11,11 @@
#include "third_party/blink/renderer/core/core_export.h"
#include "third_party/blink/renderer/core/core_probe_sink.h"
#include "third_party/blink/renderer/core/core_probes_inl.h"
#include "third_party/blink/renderer/core/execution_context/execution_context.h"
#include "third_party/blink/renderer/core/frame/frame.h"
#include "third_party/blink/renderer/core/probe/core_probes.h"
#include "third_party/blink/renderer/core/timing/animation_frame_timing_info.h"
#include "third_party/blink/renderer/platform/heap/collection_support/heap_hash_map.h"
#include "third_party/blink/renderer/platform/heap/collection_support/heap_vector.h"
#include "third_party/blink/renderer/platform/heap/garbage_collected.h"
#include "third_party/blink/renderer/platform/wtf/text/atomic_string.h"
Expand Down Expand Up @@ -74,11 +76,9 @@ class CORE_EXPORT AnimationFrameTimingMonitor final
}

// probes
void WillHandlePromise(ExecutionContext*,
ScriptState*,
bool resolving,
const char* class_like,
const char* property_like);
void WillHandlePromise(ExecutionContext*, ScriptPromiseResolver*);
void DidCreateScriptPromiseResolver(ExecutionContext*,
ScriptPromiseResolver*);
void Will(const probe::CompileAndRunScript&);
void Did(const probe::CompileAndRunScript&);
void Will(const probe::ExecuteScript&);
Expand Down Expand Up @@ -131,6 +131,9 @@ class CORE_EXPORT AnimationFrameTimingMonitor final
void ApplyTaskDuration(base::TimeDelta task_duration);

absl::optional<PendingScriptInfo> pending_script_info_;
HeapHashMap<WeakMember<ScriptPromiseResolver>,
ScriptTimingInfo::ScriptSourceLocation>
promise_resolver_source_location_map_;
Client& client_;

enum class State {
Expand Down
1 change: 1 addition & 0 deletions third_party/blink/renderer/core/probe/core_probes.json5
Original file line number Diff line number Diff line change
Expand Up @@ -35,6 +35,7 @@
AnimationFrameTimingMonitor: {
include_path: "third_party/blink/renderer/core/frame",
probes: [
"DidCreateScriptPromiseResolver",
"DidFinishSyncXHR",
"DidRunJavaScriptDialog",
"ExecuteScript",
Expand Down
3 changes: 2 additions & 1 deletion third_party/blink/renderer/core/probe/core_probes.pidl
Original file line number Diff line number Diff line change
Expand Up @@ -162,7 +162,8 @@ interface CoreProbes {
void DocumentWriteFetchScript([Keep] Document*);
void DidChangeViewport(LocalFrame* document);
void BreakableLocation(ExecutionContext* context, const char* name);
void WillHandlePromise([Keep] ExecutionContext* context, ScriptState* script_state, bool resolving, const char* class_like, const char* promise_like);
void WillHandlePromise([Keep] ExecutionContext* context, ScriptPromiseResolver* resolver);
void DidCreateScriptPromiseResolver([Keep] ExecutionContext* context, ScriptPromiseResolver* resolver);
RecalculateStyle(Document* document);
UpdateLayout(Document* document);
ExecuteScript([Keep] ExecutionContext* context, const v8::Local<v8::Context>& v8_context, const String& script_url, int script_id);
Expand Down
3 changes: 3 additions & 0 deletions third_party/blink/web_tests/external/wpt/lint.ignore
Original file line number Diff line number Diff line change
Expand Up @@ -705,3 +705,6 @@ SET TIMEOUT: editing/crashtests/outdent-across-svg-boundary.html
SET TIMEOUT: editing/crashtests/textarea-will-be-blurred-by-focus-event-listener.html
SET TIMEOUT: mathml/crashtests/mozilla/*
PARSE-FAILED: mathml/crashtests/mozilla/289180-1.xml

# Test-harness step_timeout changes what this is supposed to test
SET TIMEOUT: long-animation-frame/tentative/loaf-source-location-promise-resolver.html
Original file line number Diff line number Diff line change
@@ -0,0 +1,49 @@
<!DOCTYPE HTML>
<meta charset=utf-8>
<title>Long Animation Frame Timing: source location extraction for promise resolvers</title>
<meta name="timeout" content="long">
<script src="/resources/testharness.js"></script>
<script src="/resources/testharnessreport.js"></script>
<script src="resources/utils.js"></script>

<body>
<h1>Long Animation Frame: source location extraction for promise resolvers</h1>
<div id="log"></div>
<script>

function create_promise_resolver_with_loaf() {
fetch("/common/dummy.xml").then(() => {
busy_wait(very_long_frame_duration);
})
}

promise_test(async t => {
const [entry, script] = await expect_long_frame_with_script(() => {
setTimeout(create_promise_resolver_with_loaf);
}, script => script.name === "Window.fetch.then", t);
assert_true(script.sourceLocation?.startsWith("create_promise_resolver_with_loaf"));
}, "promise-resolver source location is attributed to callback who created the resolver");

promise_test(async t => {
const [entry, script] = await expect_long_frame_with_script(() => {
const xhr = new XMLHttpRequest();
xhr.open("GET", "/common/dummy.xml");
xhr.addEventListener("load", create_promise_resolver_with_loaf);
xhr.send();
}, script => script.name === "Window.fetch.then", t);
assert_true(script.sourceLocation?.startsWith("create_promise_resolver_with_loaf"));
}, "promise-resolver source location is attributed to event listener who created the resolver");

promise_test(async t => {
const [entry, script] = await expect_long_frame_with_script(() => {
const script_tag = document.createElement("script");
t.add_cleanup(() => script_tag.remove());
script_tag.src = "resources/busy_in_promise.js";
document.body.append(script_tag);
}, script => script.name === "Window.fetch.then", t);
assert_true(script.sourceLocation?.includes("busy_in_promise.js"));
}, "promise-resolver source location is attributed to script block who created the resolver");


</script>
</body>
Original file line number Diff line number Diff line change
@@ -0,0 +1,6 @@
fetch("/common/dummy.xml").then(() => {
const deadline = performance.now() + 360;
while (performance.now() < deadline) {

}
});

0 comments on commit 07a41b1

Please sign in to comment.