perf(cli): strace mode for ops (undocumented) (#21131)

Example usage:

```
# Trace every op except op_*tick*
cargo run -- run --unstable -A --strace-ops=-tick '/Users/matt/Documents/github/deno/deno/ext/websocket/autobahn/autobahn_server.js

# Trace any op matching op_*http*
cargo run -- run --unstable -A --strace-ops=http ...
```

Example output:

```
[    11.478] op_ws_get_buffer                        : Dispatched Slow
[    11.478] op_ws_get_buffer                        : Completed Slow
[    11.478] op_ws_send_binary                       : Dispatched Fast
[    11.478] op_ws_send_binary                       : Completed Fast
[    11.478] op_ws_next_event                        : Dispatched Async
[    11.478] op_try_close                            : Dispatched Fast
[    11.478] op_try_close                            : Completed Fast
[    11.478] op_timer_handle                         : Dispatched Fast
[    11.478] op_timer_handle                         : Completed Fast
[    11.478] op_sleep                                : Dispatched Asyn
```

cli/args/flags.rs

@@ -417,6 +417,7 @@ pub struct Flags {
   pub no_prompt: bool,
   pub reload: bool,
   pub seed: Option<u64>,
+  pub strace_ops: Option<Vec<String>>,
   pub unstable: bool,
   pub unstable_bare_node_builtins: bool,
   pub unstable_byonm: bool,
@@ -2688,6 +2689,7 @@ fn runtime_args(
     .arg(v8_flags_arg())
     .arg(seed_arg())
     .arg(enable_testing_features_arg())
+    .arg(strace_ops_arg())
 }
 
 fn inspect_args(app: Command) -> Command {
@@ -2837,6 +2839,17 @@ fn enable_testing_features_arg() -> Arg {
     .hide(true)
 }
 
+fn strace_ops_arg() -> Arg {
+  Arg::new("strace-ops")
+    .long("strace-ops")
+    .num_args(0..)
+    .use_value_delimiter(true)
+    .require_equals(true)
+    .value_name("OPS")
+    .help("Trace low-level op calls")
+    .hide(true)
+}
+
 fn v8_flags_arg() -> Arg {
   Arg::new("v8-flags")
     .long("v8-flags")
@@ -3802,6 +3815,7 @@ fn permission_args_parse(flags: &mut Flags, matches: &mut ArgMatches) {
     flags.no_prompt = true;
   }
 }
+
 fn unsafely_ignore_certificate_errors_parse(
   flags: &mut Flags,
   matches: &mut ArgMatches,
@@ -3833,6 +3847,7 @@ fn runtime_args_parse(
   seed_arg_parse(flags, matches);
   enable_testing_features_arg_parse(flags, matches);
   env_file_arg_parse(flags, matches);
+  strace_ops_parse(flags, matches);
 }
 
 fn inspect_arg_parse(flags: &mut Flags, matches: &mut ArgMatches) {
@@ -3900,6 +3915,12 @@ fn enable_testing_features_arg_parse(
   }
 }
 
+fn strace_ops_parse(flags: &mut Flags, matches: &mut ArgMatches) {
+  if let Some(patterns) = matches.remove_many::<String>("strace-ops") {
+    flags.strace_ops = Some(patterns.collect());
+  }
+}
+
 fn cached_only_arg_parse(flags: &mut Flags, matches: &mut ArgMatches) {
   if matches.get_flag("cached-only") {
     flags.cached_only = true;
@@ -5400,6 +5421,19 @@ mod tests {
     );
   }
 
+  #[test]
+  fn repl_strace_ops() {
+    // Lightly test this undocumented flag
+    let r = flags_from_vec(svec!["deno", "repl", "--strace-ops"]);
+    assert_eq!(r.unwrap().strace_ops, Some(vec![]));
+    let r =
+      flags_from_vec(svec!["deno", "repl", "--strace-ops=http,websocket"]);
+    assert_eq!(
+      r.unwrap().strace_ops,
+      Some(vec!["http".to_string(), "websocket".to_string()])
+    );
+  }
+
   #[test]
   fn repl_with_flags() {
     #[rustfmt::skip]

cli/args/mod.rs

@@ -1245,6 +1245,10 @@ impl CliOptions {
     &self.flags.subcommand
   }
 
+  pub fn strace_ops(&self) -> &Option<Vec<String>> {
+    &self.flags.strace_ops
+  }
+
   pub fn type_check_mode(&self) -> TypeCheckMode {
     self.flags.type_check_mode
   }

cli/factory.rs

@@ -676,6 +676,7 @@ impl CliFactory {
       hmr: self.options.has_hmr(),
       inspect_brk: self.options.inspect_brk().is_some(),
       inspect_wait: self.options.inspect_wait().is_some(),
+      strace_ops: self.options.strace_ops().clone(),
       is_inspecting: self.options.is_inspecting(),
       is_npm_main: self.options.is_npm_main(),
       location: self.options.location_flag().clone(),

cli/standalone/mod.rs

@@ -459,6 +459,7 @@ pub async fn run(
       hmr: false,
       inspect_brk: false,
       inspect_wait: false,
+      strace_ops: None,
       is_inspecting: false,
       is_npm_main: main_module.scheme() == "npm",
       location: metadata.location,

cli/worker.rs

@@ -92,6 +92,7 @@ pub struct CliMainWorkerOptions {
   pub hmr: bool,
   pub inspect_brk: bool,
   pub inspect_wait: bool,
+  pub strace_ops: Option<Vec<String>>,
   pub is_inspecting: bool,
   pub is_npm_main: bool,
   pub location: Option<Url>,
@@ -580,6 +581,7 @@ impl CliMainWorkerFactory {
       maybe_inspector_server,
       should_break_on_first_statement: shared.options.inspect_brk,
       should_wait_for_inspector_session: shared.options.inspect_wait,
+      strace_ops: shared.options.strace_ops.clone(),
       module_loader,
       fs: shared.fs.clone(),
       npm_resolver: Some(shared.npm_resolver.clone().into_npm_resolver()),

runtime/worker.rs

@@ -7,6 +7,7 @@ use std::sync::atomic::Ordering::Relaxed;
 use std::sync::Arc;
 use std::task::Context;
 use std::task::Poll;
+use std::time::Instant;
 
 use deno_broadcast_channel::InMemoryBroadcastChannel;
 use deno_cache::CreateCache;
@@ -15,6 +16,7 @@ use deno_core::ascii_str;
 use deno_core::error::AnyError;
 use deno_core::error::JsError;
 use deno_core::futures::Future;
+use deno_core::merge_op_metrics;
 use deno_core::v8;
 use deno_core::CompiledWasmModuleStore;
 use deno_core::Extension;
@@ -27,6 +29,7 @@ use deno_core::ModuleCode;
 use deno_core::ModuleId;
 use deno_core::ModuleLoader;
 use deno_core::ModuleSpecifier;
+use deno_core::OpMetricsFactoryFn;
 use deno_core::OpMetricsSummaryTracker;
 use deno_core::RuntimeOptions;
 use deno_core::SharedArrayBufferStore;
@@ -120,6 +123,8 @@ pub struct WorkerOptions {
   // If true, the worker will wait for inspector session before executing
   // user code.
   pub should_wait_for_inspector_session: bool,
+  /// If Some, print a low-level trace output for ops matching the given patterns.
+  pub strace_ops: Option<Vec<String>>,
 
   /// Allows to map error type to a string "class" used to represent
   /// error in JavaScript.
@@ -159,6 +164,7 @@ impl Default for WorkerOptions {
       unsafely_ignore_certificate_errors: Default::default(),
       should_break_on_first_statement: Default::default(),
       should_wait_for_inspector_session: Default::default(),
+      strace_ops: Default::default(),
       compiled_wasm_module_store: Default::default(),
       shared_array_buffer_store: Default::default(),
       maybe_inspector_server: Default::default(),
@@ -181,6 +187,71 @@ impl Default for WorkerOptions {
   }
 }
 
+fn create_op_metrics(
+  enable_op_summary_metrics: bool,
+  strace_ops: Option<Vec<String>>,
+) -> (
+  Option<Rc<OpMetricsSummaryTracker>>,
+  Option<OpMetricsFactoryFn>,
+) {
+  let mut op_summary_metrics = None;
+  let mut op_metrics_factory_fn: Option<OpMetricsFactoryFn> = None;
+  let now = Instant::now();
+  let max_len: Rc<std::cell::Cell<usize>> = Default::default();
+  if let Some(patterns) = strace_ops {
+    /// Match an op name against a list of patterns
+    fn matches_pattern(patterns: &[String], name: &str) -> bool {
+      let mut found_match = false;
+      let mut found_nomatch = false;
+      for pattern in patterns.iter() {
+        if let Some(pattern) = pattern.strip_prefix('-') {
+          if name.contains(pattern) {
+            return false;
+          }
+        } else if name.contains(pattern.as_str()) {
+          found_match = true;
+        } else {
+          found_nomatch = true;
+        }
+      }
+
+      found_match || !found_nomatch
+    }
+
+    op_metrics_factory_fn = Some(Box::new(move |_, _, decl| {
+      // If we don't match a requested pattern, or we match a negative pattern, bail
+      if !matches_pattern(&patterns, decl.name) {
+        return None;
+      }
+
+      max_len.set(max_len.get().max(decl.name.len()));
+      let max_len = max_len.clone();
+      Some(Rc::new(
+        move |op: &deno_core::_ops::OpCtx, event, source| {
+          eprintln!(
+            "[{: >10.3}] {name:max_len$}: {event:?} {source:?}",
+            now.elapsed().as_secs_f64(),
+            name = op.decl().name,
+            max_len = max_len.get()
+          );
+        },
+      ))
+    }));
+  }
+
+  if enable_op_summary_metrics {
+    let summary = Rc::new(OpMetricsSummaryTracker::default());
+    let summary_metrics = summary.clone().op_metrics_factory_fn(|_| true);
+    op_metrics_factory_fn = Some(match op_metrics_factory_fn {
+      Some(f) => merge_op_metrics(f, summary_metrics),
+      None => summary_metrics,
+    });
+    op_summary_metrics = Some(summary);
+  }
+
+  (op_summary_metrics, op_metrics_factory_fn)
+}
+
 impl MainWorker {
   pub fn bootstrap_from_options(
     main_module: ModuleSpecifier,
@@ -209,6 +280,12 @@ impl MainWorker {
       },
     );
 
+    // Get our op metrics
+    let (op_summary_metrics, op_metrics_factory_fn) = create_op_metrics(
+      options.bootstrap.enable_op_summary_metrics,
+      options.strace_ops,
+    );
+
     // Permissions: many ops depend on this
     let enable_testing_features = options.bootstrap.enable_testing_features;
     let exit_code = ExitCode(Arc::new(AtomicI32::new(0)));
@@ -325,18 +402,6 @@ impl MainWorker {
       }
     }
 
-    // Hook up the summary metrics if the user or subcommand requested them
-    let (op_summary_metrics, op_metrics_factory_fn) =
-      if options.bootstrap.enable_op_summary_metrics {
-        let op_summary_metrics = Rc::new(OpMetricsSummaryTracker::default());
-        (
-          Some(op_summary_metrics.clone()),
-          Some(op_summary_metrics.op_metrics_factory_fn(|_| true)),
-        )
-      } else {
-        (None, None)
-      };
-
     extensions.extend(std::mem::take(&mut options.extensions));
 
     #[cfg(all(feature = "include_js_files_for_snapshotting", feature = "dont_create_runtime_snapshot", not(feature = "__runtime_js_sources")))]