diff --git a/Cargo.lock b/Cargo.lock index e122c65a19..a4f734d2d9 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1217,9 +1217,9 @@ dependencies = [ [[package]] name = "deno_core" -version = "0.213.0" +version = "0.214.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "d1799de49977a9b73cd8f931ff429b452f3adfb2d5e9648098905923381a374f" +checksum = "be0af76effe9a766f7c9a253171ab10b9adfaf4b10c6eb0b9f005f9dd0ba2948" dependencies = [ "anyhow", "bytes", diff --git a/Cargo.toml b/Cargo.toml index 966f9a899f..edd5977efe 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -40,7 +40,7 @@ repository = "https://github.com/denoland/deno" [workspace.dependencies] deno_ast = { version = "0.29.3", features = ["transpiling"] } -deno_core = { version = "0.213.0" } +deno_core = { version = "0.214.0" } deno_runtime = { version = "0.126.0", path = "./runtime" } napi_sym = { version = "0.48.0", path = "./cli/napi/sym" } diff --git a/cli/js/40_testing.js b/cli/js/40_testing.js index 30905fb547..2702dccf13 100644 --- a/cli/js/40_testing.js +++ b/cli/js/40_testing.js @@ -22,7 +22,6 @@ const { MapPrototypeSet, MathCeil, ObjectKeys, - ObjectHasOwn, ObjectPrototypeIsPrototypeOf, Promise, SafeArrayIterator, @@ -151,26 +150,14 @@ const OP_DETAILS = { "op_ws_send_pong": ["send a message on a WebSocket", "closing a `WebSocket` or `WebSocketStream`"], }; -function collectReliableOpMetrics() { - let metrics = core.metrics(); - if (metrics.opsDispatched > metrics.opsCompleted) { - // If there are still async ops pending, we drain the event loop to the - // point where all ops that can return `Poll::Ready` have done so, to ensure - // that any ops are ready because of user cleanup code are completed. - const hasPendingWorkerOps = metrics.ops.op_host_recv_message && ( - metrics.ops.op_host_recv_message.opsDispatched > - metrics.ops.op_host_recv_message.opsCompleted || - metrics.ops.op_host_recv_ctrl.opsDispatched > - metrics.ops.op_host_recv_ctrl.opsCompleted - ); - return opSanitizerDelay(hasPendingWorkerOps).then(() => { - metrics = core.metrics(); - const traces = new Map(core.opCallTraces); - return { metrics, traces }; - }); - } - const traces = new Map(core.opCallTraces); - return { metrics, traces }; +let opIdHostRecvMessage = -1; +let opIdHostRecvCtrl = -1; +let opNames = null; + +function populateOpNames() { + opNames = core.ops.op_op_names(); + opIdHostRecvMessage = opNames.indexOf("op_host_recv_message"); + opIdHostRecvCtrl = opNames.indexOf("op_host_recv_ctrl"); } // Wrap test function in additional assertion that makes sure @@ -181,50 +168,61 @@ function collectReliableOpMetrics() { function assertOps(fn) { /** @param desc {TestDescription | TestStepDescription} */ return async function asyncOpSanitizer(desc) { - let metrics = collectReliableOpMetrics(); - if (metrics.then) { - // We're delaying so await to get the result asynchronously. - metrics = await metrics; + if (opNames === null) populateOpNames(); + const res = core.ops.op_test_op_sanitizer_collect( + desc.id, + false, + opIdHostRecvMessage, + opIdHostRecvCtrl, + ); + if (res !== 0) { + await opSanitizerDelay(res === 2); + core.ops.op_test_op_sanitizer_collect( + desc.id, + true, + opIdHostRecvMessage, + opIdHostRecvCtrl, + ); } - const { metrics: pre, traces: preTraces } = metrics; - let post; + const preTraces = new Map(core.opCallTraces); let postTraces; + let report = null; try { const innerResult = await fn(desc); if (innerResult) return innerResult; } finally { - let metrics = collectReliableOpMetrics(); - if (metrics.then) { - // We're delaying so await to get the result asynchronously. - metrics = await metrics; + let res = core.ops.op_test_op_sanitizer_finish( + desc.id, + false, + opIdHostRecvMessage, + opIdHostRecvCtrl, + ); + if (res === 1 || res === 2) { + await opSanitizerDelay(res === 2); + res = core.ops.op_test_op_sanitizer_finish( + desc.id, + true, + opIdHostRecvMessage, + opIdHostRecvCtrl, + ); + } + postTraces = new Map(core.opCallTraces); + if (res === 3) { + report = core.ops.op_test_op_sanitizer_report(desc.id); } - ({ metrics: post, traces: postTraces } = metrics); } - // We're checking diff because one might spawn HTTP server in the background - // that will be a pending async op before test starts. - const dispatchedDiff = post.opsDispatchedAsync - pre.opsDispatchedAsync; - const completedDiff = post.opsCompletedAsync - pre.opsCompletedAsync; - - if (dispatchedDiff === completedDiff) return null; + if (report === null) return null; const details = []; - for (const key in post.ops) { - if (!ObjectHasOwn(post.ops, key)) { - continue; - } - const preOp = pre.ops[key] ?? - { opsDispatchedAsync: 0, opsCompletedAsync: 0 }; - const postOp = post.ops[key]; - const dispatchedDiff = postOp.opsDispatchedAsync - - preOp.opsDispatchedAsync; - const completedDiff = postOp.opsCompletedAsync - - preOp.opsCompletedAsync; + for (const opReport of report) { + const opName = opNames[opReport.id]; + const diff = opReport.diff; - if (dispatchedDiff > completedDiff) { - const [name, hint] = OP_DETAILS[key] || [key, null]; - const count = dispatchedDiff - completedDiff; + if (diff > 0) { + const [name, hint] = OP_DETAILS[opName] || [opName, null]; + const count = diff; let message = `${count} async operation${ count === 1 ? "" : "s" } to ${name} ${ @@ -234,8 +232,8 @@ function assertOps(fn) { message += ` This is often caused by not ${hint}.`; } const traces = []; - for (const [id, { opName, stack }] of postTraces) { - if (opName !== key) continue; + for (const [id, { opName: traceOpName, stack }] of postTraces) { + if (traceOpName !== opName) continue; if (MapPrototypeHas(preTraces, id)) continue; ArrayPrototypePush(traces, stack); } @@ -247,9 +245,9 @@ function assertOps(fn) { message += ArrayPrototypeJoin(traces, "\n\n"); } ArrayPrototypePush(details, message); - } else if (dispatchedDiff < completedDiff) { - const [name, hint] = OP_DETAILS[key] || [key, null]; - const count = completedDiff - dispatchedDiff; + } else if (diff < 0) { + const [name, hint] = OP_DETAILS[opName] || [opName, null]; + const count = -diff; let message = `${count} async operation${ count === 1 ? "" : "s" } to ${name} ${ @@ -261,8 +259,8 @@ function assertOps(fn) { message += ` This is often caused by not ${hint}.`; } const traces = []; - for (const [id, { opName, stack }] of preTraces) { - if (opName !== key) continue; + for (const [id, { opName: traceOpName, stack }] of preTraces) { + if (opName !== traceOpName) continue; if (MapPrototypeHas(postTraces, id)) continue; ArrayPrototypePush(traces, stack); } @@ -274,6 +272,8 @@ function assertOps(fn) { message += ArrayPrototypeJoin(traces, "\n\n"); } ArrayPrototypePush(details, message); + } else { + throw new Error("unreachable"); } } diff --git a/cli/ops/testing.rs b/cli/ops/testing.rs index 2f5f04e8a3..66925ac51c 100644 --- a/cli/ops/testing.rs +++ b/cli/ops/testing.rs @@ -12,6 +12,7 @@ use deno_core::op2; use deno_core::serde_v8; use deno_core::v8; use deno_core::ModuleSpecifier; +use deno_core::OpMetrics; use deno_core::OpState; use deno_runtime::permissions::create_child_permissions; use deno_runtime::permissions::ChildPermissionsArg; @@ -19,6 +20,9 @@ use deno_runtime::permissions::PermissionsContainer; use serde::Deserialize; use serde::Deserializer; use serde::Serialize; +use std::cell::Ref; +use std::collections::hash_map::Entry; +use std::collections::HashMap; use std::sync::atomic::AtomicUsize; use std::sync::atomic::Ordering; use uuid::Uuid; @@ -35,6 +39,9 @@ deno_core::extension!(deno_test, op_register_test, op_register_test_step, op_dispatch_test_event, + op_test_op_sanitizer_collect, + op_test_op_sanitizer_finish, + op_test_op_sanitizer_report, ], options = { sender: TestEventSender, @@ -42,6 +49,7 @@ deno_core::extension!(deno_test, state = |state, options| { state.put(options.sender); state.put(TestContainer::default()); + state.put(TestOpSanitizers::default()); }, ); @@ -202,3 +210,189 @@ fn op_dispatch_test_event( sender.send(event).ok(); Ok(()) } + +#[derive(Default)] +struct TestOpSanitizers(HashMap); + +enum TestOpSanitizerState { + Collecting { metrics: Vec }, + Finished { report: Vec }, +} + +fn try_collect_metrics( + state: &OpState, + force: bool, + op_id_host_recv_msg: usize, + op_id_host_recv_ctrl: usize, +) -> Result>, bool> { + let metrics = state.tracker.per_op(); + for op_metric in &*metrics { + let has_pending_ops = op_metric.ops_dispatched_async + + op_metric.ops_dispatched_async_unref + > op_metric.ops_completed_async + op_metric.ops_completed_async_unref; + if has_pending_ops && !force { + let host_recv_msg = metrics + .get(op_id_host_recv_msg) + .map(|op_metric| { + op_metric.ops_dispatched_async + op_metric.ops_dispatched_async_unref + > op_metric.ops_completed_async + + op_metric.ops_completed_async_unref + }) + .unwrap_or(false); + let host_recv_ctrl = metrics + .get(op_id_host_recv_ctrl) + .map(|op_metric| { + op_metric.ops_dispatched_async + op_metric.ops_dispatched_async_unref + > op_metric.ops_completed_async + + op_metric.ops_completed_async_unref + }) + .unwrap_or(false); + return Err(host_recv_msg || host_recv_ctrl); + } + } + Ok(metrics) +} + +#[op2(fast)] +#[smi] +// Returns: +// 0 - success +// 1 - for more accurate results, spin event loop and call again with force=true +// 2 - for more accurate results, delay(1ms) and call again with force=true +fn op_test_op_sanitizer_collect( + state: &mut OpState, + #[smi] id: u32, + force: bool, + #[smi] op_id_host_recv_msg: usize, + #[smi] op_id_host_recv_ctrl: usize, +) -> Result { + let metrics = { + let metrics = match try_collect_metrics( + state, + force, + op_id_host_recv_msg, + op_id_host_recv_ctrl, + ) { + Ok(metrics) => metrics, + Err(false) => { + return Ok(1); + } + Err(true) => { + return Ok(2); + } + }; + metrics.clone() + }; + let op_sanitizers = state.borrow_mut::(); + match op_sanitizers.0.entry(id) { + Entry::Vacant(entry) => { + entry.insert(TestOpSanitizerState::Collecting { metrics }); + } + Entry::Occupied(_) => { + return Err(generic_error(format!( + "Test metrics already being collected for test id {id}", + ))); + } + } + Ok(0) +} + +#[derive(Serialize)] +#[serde(rename_all = "camelCase")] +struct TestOpSanitizerReport { + id: usize, + diff: i64, +} + +#[op2(fast)] +#[smi] +// Returns: +// 0 - sanitizer finished with no pending ops +// 1 - for more accurate results, spin event loop and call again with force=true +// 2 - for more accurate results, delay(1ms) and call again with force=true +// 3 - sanitizer finished with pending ops, collect the report with op_test_op_sanitizer_report +fn op_test_op_sanitizer_finish( + state: &mut OpState, + #[smi] id: u32, + force: bool, + #[smi] op_id_host_recv_msg: usize, + #[smi] op_id_host_recv_ctrl: usize, +) -> Result { + let report = { + let after_metrics = match try_collect_metrics( + state, + force, + op_id_host_recv_msg, + op_id_host_recv_ctrl, + ) { + Ok(metrics) => metrics, + Err(false) => { + return Ok(1); + } + Err(true) => { + return Ok(2); + } + }; + + let op_sanitizers = state.borrow::(); + let before_metrics = match op_sanitizers.0.get(&id) { + Some(TestOpSanitizerState::Collecting { metrics }) => metrics, + _ => { + return Err(generic_error(format!( + "Metrics not collected before for test id {id}", + ))); + } + }; + let mut report = vec![]; + + for (id, (before, after)) in + before_metrics.iter().zip(after_metrics.iter()).enumerate() + { + let async_pending_before = before.ops_dispatched_async + + before.ops_dispatched_async_unref + - before.ops_completed_async + - before.ops_completed_async_unref; + let async_pending_after = after.ops_dispatched_async + + after.ops_dispatched_async_unref + - after.ops_completed_async + - after.ops_completed_async_unref; + let diff = async_pending_after as i64 - async_pending_before as i64; + if diff != 0 { + report.push(TestOpSanitizerReport { id, diff }); + } + } + + report + }; + + let op_sanitizers = state.borrow_mut::(); + + if report.is_empty() { + op_sanitizers + .0 + .remove(&id) + .expect("TestOpSanitizerState::Collecting"); + Ok(0) + } else { + op_sanitizers + .0 + .insert(id, TestOpSanitizerState::Finished { report }) + .expect("TestOpSanitizerState::Collecting"); + Ok(3) + } +} + +#[op2] +#[serde] +fn op_test_op_sanitizer_report( + state: &mut OpState, + #[smi] id: u32, +) -> Result, AnyError> { + let op_sanitizers = state.borrow_mut::(); + match op_sanitizers.0.remove(&id) { + Some(TestOpSanitizerState::Finished { report }) => Ok(report), + _ => Err(generic_error(format!( + "Metrics not finished collecting for test id {id}", + ))), + } +}