perf(js): resolve_promises_until exits as soon as the awaited IIFE finishes (#213)
Every Puppeteer click ran isIntersectingViewport (an actionability check that wraps IntersectionObserver in a promise). Our IO.observe schedules re-fires at 120/500/1500/3500/7000ms to cover infinite-scroll sentinels. Puppeteer's callback disconnects the observer on the first fire, so the re-fires are no-ops, but they keep the deno_core event loop 'not idle' until they all fire. resolve_promises was waiting for the loop to go idle (5s hard cap), so every awaitPromise call paid the full 5s even though the result was ready in <1ms. Effect: page.click() took ~7s instead of ~150ms because clickableBox + isIntersectingViewport each hit the cap. Fix: each evaluate / callFunctionOn now writes a unique sentinel (globalThis.__obscura_done_<counter> = true) in a finally block. The new resolve_promises_until polls that sentinel with a 1ms / 2ms / ... backoff up to 50ms and exits as soon as the IIFE is done, instead of waiting for unrelated timers to drain. Worst-case miss is one tick (50ms). Measured impact (Puppeteer CDP scenarios, lower is better): scenario before after data: click button 7420ms ~530ms (14x) data: addEvt click 14536ms ~680ms (21x) data: form submit 7676ms ~810ms (9x) CDP bench total 35190ms ~7400ms (~5x) 28/28 integration tests still pass.
This commit is contained in:
SGavrl authored and GitHub committed
1 parent
50462d41a9
commit
282b4646d3
1 file changed
+98
-3
@@ -158,6 +158,7 @@ impl ObscuraJsRuntime {
|
||||
// swallows the closing paren and our wrapper breaks. A newline
|
||||
// before the `)` terminates any trailing line comment so the
|
||||
// parens close on their own line.
|
||||
let done_counter = self.object_counter;
|
||||
let meta_code = if await_promise {
|
||||
format!(
|
||||
"(async function() {{\n\
|
||||
@@ -171,11 +172,13 @@ impl ObscuraJsRuntime {
|
||||
globalThis.__obscura_await_meta = {err_meta_fn};\n\
|
||||
globalThis.__obscura_await_rejected = true;\n\
|
||||
}}\n\
|
||||
globalThis.__obscura_done_{done_counter} = true;\n\
|
||||
}})()",
|
||||
expr = cleaned_expr,
|
||||
oid = oid,
|
||||
meta_fn = Self::meta_extract_js("__result"),
|
||||
err_meta_fn = Self::meta_extract_js("e"),
|
||||
done_counter = done_counter,
|
||||
)
|
||||
} else {
|
||||
format!(
|
||||
@@ -197,7 +200,28 @@ impl ObscuraJsRuntime {
|
||||
.map_err(|e| format!("JS error: {}", e))?;
|
||||
|
||||
let meta_str = if await_promise {
|
||||
self.resolve_promises().await;
|
||||
let __t0 = std::time::Instant::now();
|
||||
let sentinel = format!("globalThis.__obscura_done_{done_counter} === true");
|
||||
self.resolve_promises_until(
|
||||
|rt| rt.runtime.execute_script("<done?>", sentinel.clone())
|
||||
.ok()
|
||||
.and_then(|v| rt.v8_to_json(v).ok())
|
||||
.and_then(|j| j.as_bool())
|
||||
.unwrap_or(false),
|
||||
5000,
|
||||
).await;
|
||||
let __dt = __t0.elapsed();
|
||||
if __dt > std::time::Duration::from_secs(1) {
|
||||
let preview: String = expression
|
||||
.chars()
|
||||
.take(200)
|
||||
.map(|c| if c == '\n' || c == '\t' { ' ' } else { c })
|
||||
.collect();
|
||||
tracing::debug!(
|
||||
"Runtime.evaluate awaitPromise took {}ms; expr={}",
|
||||
__dt.as_millis(), preview,
|
||||
);
|
||||
}
|
||||
let rejected = self.runtime.execute_script("<readRejected>", "globalThis.__obscura_await_rejected".to_string())
|
||||
.map_err(|e| format!("JS error: {}", e))?;
|
||||
if self.v8_to_json(rejected)?.as_bool().unwrap_or(false) {
|
||||
@@ -246,14 +270,25 @@ impl ObscuraJsRuntime {
|
||||
let oid = self.make_oid(self.object_counter);
|
||||
|
||||
if await_promise {
|
||||
let done_counter = self.object_counter;
|
||||
let err_meta_fn = Self::meta_extract_js("__result");
|
||||
let code = format!(
|
||||
"(async function() {{\n\
|
||||
{setup}\n\
|
||||
var __fn = ({fn_decl});\n\
|
||||
var __this = ({this_expr});\n\
|
||||
var __result = await __fn.call(__this, {args});\n\
|
||||
var __result;\n\
|
||||
try {{\n\
|
||||
__result = await __fn.call(__this, {args});\n\
|
||||
globalThis.__obscura_objects['{oid}'] = __result;\n\
|
||||
globalThis.__obscura_await_meta = {meta_fn};\n\
|
||||
}} catch(e) {{\n\
|
||||
__result = e;\n\
|
||||
globalThis.__obscura_objects['{oid}'] = e;\n\
|
||||
globalThis.__obscura_await_meta = {err_meta_fn};\n\
|
||||
}} finally {{\n\
|
||||
globalThis.__obscura_done_{done_counter} = true;\n\
|
||||
}}\n\
|
||||
}})()",
|
||||
setup = setup,
|
||||
fn_decl = function_declaration,
|
||||
@@ -261,13 +296,36 @@ impl ObscuraJsRuntime {
|
||||
args = args_list,
|
||||
oid = oid,
|
||||
meta_fn = Self::meta_extract_js("__result"),
|
||||
err_meta_fn = err_meta_fn,
|
||||
done_counter = done_counter,
|
||||
);
|
||||
|
||||
self.runtime
|
||||
.execute_script("<callFnAsync>", code)
|
||||
.map_err(|e| format!("JS error: {}", e))?;
|
||||
|
||||
self.resolve_promises().await;
|
||||
let __t0 = std::time::Instant::now();
|
||||
let sentinel = format!("globalThis.__obscura_done_{done_counter} === true");
|
||||
self.resolve_promises_until(
|
||||
|rt| rt.runtime.execute_script("<done?>", sentinel.clone())
|
||||
.ok()
|
||||
.and_then(|v| rt.v8_to_json(v).ok())
|
||||
.and_then(|j| j.as_bool())
|
||||
.unwrap_or(false),
|
||||
5000,
|
||||
).await;
|
||||
let __dt = __t0.elapsed();
|
||||
if __dt > std::time::Duration::from_secs(1) {
|
||||
let preview: String = function_declaration
|
||||
.chars()
|
||||
.take(300)
|
||||
.map(|c| if c == '\n' || c == '\t' { ' ' } else { c })
|
||||
.collect();
|
||||
tracing::debug!(
|
||||
"Runtime.callFunctionOn awaitPromise took {}ms; fn={}",
|
||||
__dt.as_millis(), preview,
|
||||
);
|
||||
}
|
||||
|
||||
if return_by_value {
|
||||
let read = self.runtime.execute_script(
|
||||
@@ -607,11 +665,48 @@ impl ObscuraJsRuntime {
|
||||
}
|
||||
|
||||
pub async fn resolve_promises(&mut self) {
|
||||
// Default settle: just pump until idle or 5s.
|
||||
let _ = tokio::time::timeout(
|
||||
tokio::time::Duration::from_secs(5),
|
||||
self.runtime.run_event_loop(deno_core::PollEventLoopOptions::default()),
|
||||
).await;
|
||||
}
|
||||
|
||||
/// Pump the event loop until `done_check` returns true (e.g. an IIFE
|
||||
/// has written its result sentinel), or `max_total_ms` elapses.
|
||||
///
|
||||
/// Why this exists: `run_event_loop(default)` only returns when there is
|
||||
/// no pending work. Page JS routinely schedules long setTimeouts
|
||||
/// (IntersectionObserver re-fires at 7s, requestIdleCallback, etc.) that
|
||||
/// the caller does not care about. With the plain timeout we waited 5s
|
||||
/// even when the IIFE we cared about resolved in <1ms — the click flow
|
||||
/// added ~7s per click because Puppeteer's `isIntersectingViewport`
|
||||
/// disconnects its observer in the callback, but our scheduled
|
||||
/// re-fires keep the event loop "busy" until they all fire.
|
||||
pub async fn resolve_promises_until<F>(&mut self, mut done_check: F, max_total_ms: u64)
|
||||
where
|
||||
F: FnMut(&mut Self) -> bool,
|
||||
{
|
||||
let deadline = tokio::time::Instant::now() + tokio::time::Duration::from_millis(max_total_ms);
|
||||
let mut tick_ms: u64 = 1;
|
||||
loop {
|
||||
if done_check(self) {
|
||||
return;
|
||||
}
|
||||
if tokio::time::Instant::now() >= deadline {
|
||||
return;
|
||||
}
|
||||
// Pump for a short slice. If the loop returns idle in <tick_ms,
|
||||
// run_event_loop returns Ok and we check the predicate again.
|
||||
let _ = tokio::time::timeout(
|
||||
tokio::time::Duration::from_millis(tick_ms),
|
||||
self.runtime.run_event_loop(deno_core::PollEventLoopOptions::default()),
|
||||
).await;
|
||||
// Backoff so a hung promise doesn't burn CPU. Caps at 50ms;
|
||||
// worst case we miss the result by <50ms.
|
||||
if tick_ms < 50 { tick_ms = (tick_ms * 2).min(50); }
|
||||
}
|
||||
}
|
||||
pub fn take_dom(&self) -> Option<DomTree> {
|
||||
self.state.borrow_mut().dom.take()
|
||||
}
|
||||
|
||||
Reference in new issue
Block a user