feat(lsp): add internal debugging logging (#10438)

Ref: #10368

cli/logger.rs

@@ -0,0 +1,92 @@
+// Copyright 2018-2021 the Deno authors. All rights reserved. MIT license.
+
+use std::io::Write;
+use std::sync::atomic::AtomicBool;
+use std::sync::atomic::Ordering;
+use std::sync::Arc;
+
+lazy_static::lazy_static! {
+  pub static ref LSP_DEBUG_FLAG: Arc<AtomicBool> = Arc::new(AtomicBool::new(false));
+}
+
+struct CliLogger(env_logger::Logger);
+
+impl CliLogger {
+  pub fn new(logger: env_logger::Logger) -> Self {
+    Self(logger)
+  }
+
+  pub fn filter(&self) -> log::LevelFilter {
+    self.0.filter()
+  }
+}
+
+impl log::Log for CliLogger {
+  fn enabled(&self, metadata: &log::Metadata) -> bool {
+    if metadata.target() == "deno::lsp::performance"
+      && metadata.level() == log::Level::Debug
+    {
+      LSP_DEBUG_FLAG.load(Ordering::Relaxed)
+    } else {
+      self.0.enabled(metadata)
+    }
+  }
+
+  fn log(&self, record: &log::Record) {
+    if self.enabled(record.metadata()) {
+      self.0.log(record);
+    }
+  }
+
+  fn flush(&self) {
+    self.0.flush();
+  }
+}
+
+pub(crate) fn init(maybe_level: Option<log::Level>) {
+  let log_level = maybe_level.unwrap_or(log::Level::Info);
+  let logger = env_logger::Builder::from_env(
+    env_logger::Env::default()
+      .default_filter_or(log_level.to_level_filter().to_string()),
+  )
+  // https://github.com/denoland/deno/issues/6641
+  .filter_module("rustyline", log::LevelFilter::Off)
+  // wgpu crates (gfx_backend), have a lot of useless INFO and WARN logs
+  .filter_module("wgpu", log::LevelFilter::Error)
+  .filter_module("gfx", log::LevelFilter::Error)
+  // used to make available the lsp_debug which is then filtered out at runtime
+  // in the cli logger
+  .filter_module("deno::lsp::performance", log::LevelFilter::Debug)
+  .format(|buf, record| {
+    let mut target = record.target().to_string();
+    if let Some(line_no) = record.line() {
+      target.push(':');
+      target.push_str(&line_no.to_string());
+    }
+    if record.level() <= log::Level::Info
+      || (record.target() == "deno::lsp::performance"
+        && record.level() == log::Level::Debug)
+    {
+      // Print ERROR, WARN, INFO and lsp_debug logs as they are
+      writeln!(buf, "{}", record.args())
+    } else {
+      // Add prefix to DEBUG or TRACE logs
+      writeln!(
+        buf,
+        "{} RS - {} - {}",
+        record.level(),
+        target,
+        record.args()
+      )
+    }
+  })
+  .build();
+
+  let cli_logger = CliLogger::new(logger);
+  let max_level = cli_logger.filter();
+  let r = log::set_boxed_logger(Box::new(cli_logger));
+  if r.is_ok() {
+    log::set_max_level(max_level);
+  }
+  r.expect("Could not install logger.");
+}

cli/lsp/config.rs

@@ -113,10 +113,10 @@ pub struct WorkspaceSettings {
   /// Code lens specific settings for the workspace.
   #[serde(default)]
   pub code_lens: CodeLensSettings,
-  #[serde(default)]
 
-  /// Suggestion (auto-completion) settings for the workspace.
-  pub suggest: CompletionSettings,
+  /// A flag that indicates if internal debug logging should be made available.
+  #[serde(default)]
+  pub internal_debug: bool,
 
   /// A flag that indicates if linting is enabled for the workspace.
   #[serde(default)]
@@ -124,6 +124,9 @@ pub struct WorkspaceSettings {
 
   /// A flag that indicates if Dene should validate code against the unstable
   /// APIs for the workspace.
+  #[serde(default)]
+  pub suggest: CompletionSettings,
+
   #[serde(default)]
   pub unstable: bool,
 }

cli/lsp/diagnostics.rs

@@ -98,13 +98,15 @@ async fn update_diagnostics(
   snapshot: &language_server::StateSnapshot,
   ts_server: &tsc::TsServer,
 ) {
-  let mark = snapshot.performance.mark("update_diagnostics");
+  let mark = snapshot.performance.mark("update_diagnostics", None::<()>);
   let lint_enabled = snapshot.config.workspace_settings.lint;
 
   let lint = async {
     let collection = collection.clone();
     if lint_enabled {
-      let mark = snapshot.performance.mark("update_diagnostics_lint");
+      let mark = snapshot
+        .performance
+        .mark("update_diagnostics_lint", None::<()>);
       let diagnostics =
         generate_lint_diagnostics(snapshot.clone(), collection.clone()).await;
       {
@@ -125,7 +127,9 @@ async fn update_diagnostics(
 
   let ts = async {
     let collection = collection.clone();
-    let mark = snapshot.performance.mark("update_diagnostics_ts");
+    let mark = snapshot
+      .performance
+      .mark("update_diagnostics_ts", None::<()>);
     let diagnostics =
       generate_ts_diagnostics(snapshot.clone(), collection.clone(), ts_server)
         .await
@@ -151,7 +155,9 @@ async fn update_diagnostics(
 
   let deps = async {
     let collection = collection.clone();
-    let mark = snapshot.performance.mark("update_diagnostics_deps");
+    let mark = snapshot
+      .performance
+      .mark("update_diagnostics_deps", None::<()>);
     let diagnostics =
       generate_dependency_diagnostics(snapshot.clone(), collection.clone())
         .await

cli/lsp/language_server.rs

@@ -26,6 +26,7 @@ use std::collections::HashMap;
 use std::env;
 use std::path::PathBuf;
 use std::rc::Rc;
+use std::sync::atomic::Ordering;
 use std::sync::Arc;
 use tokio::fs;
 
@@ -33,6 +34,7 @@ use crate::config_file::ConfigFile;
 use crate::config_file::TsConfig;
 use crate::deno_dir;
 use crate::import_map::ImportMap;
+use crate::logger;
 use crate::media_type::MediaType;
 
 use super::analysis;
@@ -198,7 +200,9 @@ impl Inner {
     &mut self,
     specifier: ModuleSpecifier,
   ) -> Result<LineIndex, AnyError> {
-    let mark = self.performance.mark("get_line_index");
+    let mark = self
+      .performance
+      .mark("get_line_index", Some(json!({ "specifier": specifier })));
     let result = if specifier.scheme() == "asset" {
       if let Some(asset) = self.get_asset(&specifier).await? {
         Ok(asset.line_index)
@@ -222,7 +226,10 @@ impl Inner {
     &self,
     specifier: &ModuleSpecifier,
   ) -> Option<LineIndex> {
-    let mark = self.performance.mark("get_line_index_sync");
+    let mark = self.performance.mark(
+      "get_line_index_sync",
+      Some(json!({ "specifier": specifier })),
+    );
     let maybe_line_index = if specifier.scheme() == "asset" {
       if let Some(Some(asset)) = self.assets.get(specifier) {
         Some(asset.line_index.clone())
@@ -264,7 +271,10 @@ impl Inner {
     &mut self,
     specifier: &ModuleSpecifier,
   ) -> Result<tsc::NavigationTree, AnyError> {
-    let mark = self.performance.mark("get_navigation_tree");
+    let mark = self.performance.mark(
+      "get_navigation_tree",
+      Some(json!({ "specifier": specifier })),
+    );
     if let Some(navigation_tree) = self.navigation_trees.get(specifier) {
       self.performance.measure(mark);
       Ok(navigation_tree.clone())
@@ -297,7 +307,7 @@ impl Inner {
   }
 
   pub async fn update_import_map(&mut self) -> Result<(), AnyError> {
-    let mark = self.performance.mark("update_import_map");
+    let mark = self.performance.mark("update_import_map", None::<()>);
     let (maybe_import_map, maybe_root_uri) = {
       let config = &self.config;
       (
@@ -346,8 +356,19 @@ impl Inner {
     Ok(())
   }
 
+  pub fn update_debug_flag(&self) -> bool {
+    logger::LSP_DEBUG_FLAG
+      .compare_exchange(
+        !self.config.workspace_settings.internal_debug,
+        self.config.workspace_settings.internal_debug,
+        Ordering::Acquire,
+        Ordering::Relaxed,
+      )
+      .is_ok()
+  }
+
   async fn update_registries(&mut self) -> Result<(), AnyError> {
-    let mark = self.performance.mark("update_registries");
+    let mark = self.performance.mark("update_registries", None::<()>);
     for (registry, enabled) in
       self.config.workspace_settings.suggest.imports.hosts.iter()
     {
@@ -364,7 +385,7 @@ impl Inner {
   }
 
   async fn update_tsconfig(&mut self) -> Result<(), AnyError> {
-    let mark = self.performance.mark("update_tsconfig");
+    let mark = self.performance.mark("update_tsconfig", None::<()>);
     let mut tsconfig = TsConfig::new(json!({
       "allowJs": true,
       "esModuleInterop": true,
@@ -458,7 +479,7 @@ impl Inner {
     params: InitializeParams,
   ) -> LspResult<InitializeResult> {
     info!("Starting Deno language server...");
-    let mark = self.performance.mark("initialize");
+    let mark = self.performance.mark("initialize", Some(&params));
 
     let capabilities = capabilities::server_capabilities(&params.capabilities);
 
@@ -492,6 +513,7 @@ impl Inner {
       config.update_capabilities(&params.capabilities);
     }
 
+    self.update_debug_flag();
     if let Err(err) = self.update_tsconfig().await {
       warn!("Updating tsconfig has errored: {}", err);
     }
@@ -568,7 +590,7 @@ impl Inner {
   }
 
   async fn did_open(&mut self, params: DidOpenTextDocumentParams) {
-    let mark = self.performance.mark("did_open");
+    let mark = self.performance.mark("did_open", Some(&params));
     let specifier = self.url_map.normalize_url(&params.text_document.uri);
 
     // we only query the individual resource file if the client supports it
@@ -612,7 +634,7 @@ impl Inner {
   }
 
   async fn did_change(&mut self, params: DidChangeTextDocumentParams) {
-    let mark = self.performance.mark("did_change");
+    let mark = self.performance.mark("did_change", Some(&params));
     let specifier = self.url_map.normalize_url(&params.text_document.uri);
     match self.documents.change(
       &specifier,
@@ -631,7 +653,7 @@ impl Inner {
   }
 
   async fn did_close(&mut self, params: DidCloseTextDocumentParams) {
-    let mark = self.performance.mark("did_close");
+    let mark = self.performance.mark("did_close", Some(&params));
     if params.text_document.uri.scheme() == "deno" {
       // we can ignore virtual text documents opening, as they don't need to
       // be tracked in memory, as they are static assets that won't change
@@ -652,7 +674,9 @@ impl Inner {
     &mut self,
     params: DidChangeConfigurationParams,
   ) {
-    let mark = self.performance.mark("did_change_configuration");
+    let mark = self
+      .performance
+      .mark("did_change_configuration", Some(&params));
 
     if self.config.client_capabilities.workspace_configuration {
       let specifiers: Vec<ModuleSpecifier> =
@@ -694,6 +718,7 @@ impl Inner {
       }
     }
 
+    self.update_debug_flag();
     if let Err(err) = self.update_import_map().await {
       self
         .client
@@ -723,7 +748,9 @@ impl Inner {
     &mut self,
     params: DidChangeWatchedFilesParams,
   ) {
-    let mark = self.performance.mark("did_change_watched_files");
+    let mark = self
+      .performance
+      .mark("did_change_watched_files", Some(&params));
     // if the current import map has changed, we need to reload it
     if let Some(import_map_uri) = &self.maybe_import_map_uri {
       if params.changes.iter().any(|fe| *import_map_uri == fe.uri) {
@@ -757,7 +784,7 @@ impl Inner {
     if !self.config.specifier_enabled(&specifier) {
       return Ok(None);
     }
-    let mark = self.performance.mark("document_symbol");
+    let mark = self.performance.mark("document_symbol", Some(&params));
 
     let line_index =
       if let Some(line_index) = self.get_line_index_sync(&specifier) {
@@ -796,7 +823,7 @@ impl Inner {
     &self,
     params: DocumentFormattingParams,
   ) -> LspResult<Option<Vec<TextEdit>>> {
-    let mark = self.performance.mark("formatting");
+    let mark = self.performance.mark("formatting", Some(&params));
     let specifier = self.url_map.normalize_url(&params.text_document.uri);
     let file_text = self
       .documents
@@ -855,7 +882,7 @@ impl Inner {
     if !self.config.specifier_enabled(&specifier) {
       return Ok(None);
     }
-    let mark = self.performance.mark("hover");
+    let mark = self.performance.mark("hover", Some(&params));
 
     let line_index =
       if let Some(line_index) = self.get_line_index_sync(&specifier) {
@@ -897,7 +924,7 @@ impl Inner {
       return Ok(None);
     }
 
-    let mark = self.performance.mark("code_action");
+    let mark = self.performance.mark("code_action", Some(&params));
     let fixable_diagnostics: Vec<&Diagnostic> = params
       .context
       .diagnostics
@@ -1003,7 +1030,7 @@ impl Inner {
     &mut self,
     params: CodeAction,
   ) -> LspResult<CodeAction> {
-    let mark = self.performance.mark("code_action_resolve");
+    let mark = self.performance.mark("code_action_resolve", Some(&params));
     let result = if let Some(data) = params.data.clone() {
       let code_action_data: CodeActionData =
         from_value(data).map_err(|err| {
@@ -1055,7 +1082,7 @@ impl Inner {
       return Ok(None);
     }
 
-    let mark = self.performance.mark("code_lens");
+    let mark = self.performance.mark("code_lens", Some(&params));
     let line_index = self.get_line_index_sync(&specifier).unwrap();
     let navigation_tree =
       self.get_navigation_tree(&specifier).await.map_err(|err| {
@@ -1177,7 +1204,7 @@ impl Inner {
     &mut self,
     params: CodeLens,
   ) -> LspResult<CodeLens> {
-    let mark = self.performance.mark("code_lens_resolve");
+    let mark = self.performance.mark("code_lens_resolve", Some(&params));
     if let Some(data) = params.data.clone() {
       let code_lens_data: CodeLensData = serde_json::from_value(data)
         .map_err(|err| LspError::invalid_params(err.to_string()))?;
@@ -1366,7 +1393,7 @@ impl Inner {
       return Ok(None);
     }
 
-    let mark = self.performance.mark("document_highlight");
+    let mark = self.performance.mark("document_highlight", Some(&params));
     let line_index =
       if let Some(line_index) = self.get_line_index_sync(&specifier) {
         line_index
@@ -1415,7 +1442,7 @@ impl Inner {
     if !self.config.specifier_enabled(&specifier) {
       return Ok(None);
     }
-    let mark = self.performance.mark("references");
+    let mark = self.performance.mark("references", Some(&params));
     let line_index =
       if let Some(line_index) = self.get_line_index_sync(&specifier) {
         line_index
@@ -1470,7 +1497,7 @@ impl Inner {
     if !self.config.specifier_enabled(&specifier) {
       return Ok(None);
     }
-    let mark = self.performance.mark("goto_definition");
+    let mark = self.performance.mark("goto_definition", Some(&params));
     let line_index =
       if let Some(line_index) = self.get_line_index_sync(&specifier) {
         line_index
@@ -1513,7 +1540,7 @@ impl Inner {
     if !self.config.specifier_enabled(&specifier) {
       return Ok(None);
     }
-    let mark = self.performance.mark("completion");
+    let mark = self.performance.mark("completion", Some(&params));
     // Import specifiers are something wholly internal to Deno, so for
     // completions, we will use internal logic and if there are completions
     // for imports, we will return those and not send a message into tsc, where
@@ -1583,7 +1610,7 @@ impl Inner {
     &mut self,
     params: CompletionItem,
   ) -> LspResult<CompletionItem> {
-    let mark = self.performance.mark("completion_resolve");
+    let mark = self.performance.mark("completion_resolve", Some(&params));
     let completion_item = if let Some(data) = &params.data {
       let data: completions::CompletionItemData =
         serde_json::from_value(data.clone()).map_err(|err| {
@@ -1629,7 +1656,7 @@ impl Inner {
     if !self.config.specifier_enabled(&specifier) {
       return Ok(None);
     }
-    let mark = self.performance.mark("goto_implementation");
+    let mark = self.performance.mark("goto_implementation", Some(&params));
     let line_index =
       if let Some(line_index) = self.get_line_index_sync(&specifier) {
         line_index
@@ -1677,7 +1704,7 @@ impl Inner {
     if !self.config.specifier_enabled(&specifier) {
       return Ok(None);
     }
-    let mark = self.performance.mark("folding_range");
+    let mark = self.performance.mark("folding_range", Some(&params));
 
     let line_index =
       if let Some(line_index) = self.get_line_index_sync(&specifier) {
@@ -1734,7 +1761,7 @@ impl Inner {
     if !self.config.specifier_enabled(&specifier) {
       return Ok(None);
     }
-    let mark = self.performance.mark("incoming_calls");
+    let mark = self.performance.mark("incoming_calls", Some(&params));
 
     let line_index =
       if let Some(line_index) = self.get_line_index_sync(&specifier) {
@@ -1788,7 +1815,7 @@ impl Inner {
     if !self.config.specifier_enabled(&specifier) {
       return Ok(None);
     }
-    let mark = self.performance.mark("outgoing_calls");
+    let mark = self.performance.mark("outgoing_calls", Some(&params));
 
     let line_index =
       if let Some(line_index) = self.get_line_index_sync(&specifier) {
@@ -1845,7 +1872,9 @@ impl Inner {
     if !self.config.specifier_enabled(&specifier) {
       return Ok(None);
     }
-    let mark = self.performance.mark("prepare_call_hierarchy");
+    let mark = self
+      .performance
+      .mark("prepare_call_hierarchy", Some(&params));
 
     let line_index =
       if let Some(line_index) = self.get_line_index_sync(&specifier) {
@@ -1922,7 +1951,7 @@ impl Inner {
     if !self.config.specifier_enabled(&specifier) {
       return Ok(None);
     }
-    let mark = self.performance.mark("rename");
+    let mark = self.performance.mark("rename", Some(&params));
 
     let line_index =
       if let Some(line_index) = self.get_line_index_sync(&specifier) {
@@ -2010,7 +2039,7 @@ impl Inner {
     if !self.config.specifier_enabled(&specifier) {
       return Ok(None);
     }
-    let mark = self.performance.mark("selection_range");
+    let mark = self.performance.mark("selection_range", Some(&params));
 
     let line_index =
       if let Some(line_index) = self.get_line_index_sync(&specifier) {
@@ -2052,7 +2081,7 @@ impl Inner {
     if !self.config.specifier_enabled(&specifier) {
       return Ok(None);
     }
-    let mark = self.performance.mark("semantic_tokens_full");
+    let mark = self.performance.mark("semantic_tokens_full", Some(&params));
 
     let line_index =
       if let Some(line_index) = self.get_line_index_sync(&specifier) {
@@ -2099,7 +2128,9 @@ impl Inner {
     if !self.config.specifier_enabled(&specifier) {
       return Ok(None);
     }
-    let mark = self.performance.mark("semantic_tokens_range");
+    let mark = self
+      .performance
+      .mark("semantic_tokens_range", Some(&params));
 
     let line_index =
       if let Some(line_index) = self.get_line_index_sync(&specifier) {
@@ -2147,7 +2178,7 @@ impl Inner {
     if !self.config.specifier_enabled(&specifier) {
       return Ok(None);
     }
-    let mark = self.performance.mark("signature_help");
+    let mark = self.performance.mark("signature_help", Some(&params));
     let line_index =
       if let Some(line_index) = self.get_line_index_sync(&specifier) {
         line_index
@@ -2427,7 +2458,7 @@ impl Inner {
   /// Similar to `deno cache` on the command line, where modules will be cached
   /// in the Deno cache, including any of their dependencies.
   async fn cache(&mut self, params: CacheParams) -> LspResult<Option<Value>> {
-    let mark = self.performance.mark("cache");
+    let mark = self.performance.mark("cache", Some(&params));
     let referrer = self.url_map.normalize_url(&params.referrer.uri);
     if !params.uris.is_empty() {
       for identifier in &params.uris {
@@ -2495,7 +2526,9 @@ impl Inner {
     &mut self,
     params: VirtualTextDocumentParams,
   ) -> LspResult<Option<String>> {
-    let mark = self.performance.mark("virtual_text_document");
+    let mark = self
+      .performance
+      .mark("virtual_text_document", Some(&params));
     let specifier = self.url_map.normalize_url(&params.text_document.uri);
     let contents = if specifier.as_str() == "deno:/status.md" {
       let mut contents = String::new();

cli/lsp/mod.rs

@@ -1,4 +1,5 @@
 // Copyright 2018-2021 the Deno authors. All rights reserved. MIT license.
+
 use deno_core::error::AnyError;
 use lspower::LspService;
 use lspower::Server;

cli/lsp/performance.rs

@@ -2,6 +2,8 @@
 
 use deno_core::serde::Deserialize;
 use deno_core::serde::Serialize;
+use deno_core::serde_json::json;
+use log::debug;
 use std::cmp;
 use std::collections::HashMap;
 use std::collections::VecDeque;
@@ -132,11 +134,29 @@ impl Performance {
   /// Marks the start of a measurement which returns a performance mark
   /// structure, which is then passed to `.measure()` to finalize the duration
   /// and add it to the internal buffer.
-  pub fn mark<S: AsRef<str>>(&self, name: S) -> PerformanceMark {
+  pub fn mark<S: AsRef<str>, V: Serialize>(
+    &self,
+    name: S,
+    maybe_args: Option<V>,
+  ) -> PerformanceMark {
     let name = name.as_ref();
     let mut counts = self.counts.lock().unwrap();
     let count = counts.entry(name.to_string()).or_insert(0);
     *count += 1;
+    let msg = if let Some(args) = maybe_args {
+      json!({
+        "type": "mark",
+        "name": name,
+        "count": count,
+        "args": args,
+      })
+    } else {
+      json!({
+        "type": "mark",
+        "name": name,
+      })
+    };
+    debug!("{},", msg);
     PerformanceMark {
       name: name.to_string(),
       count: *count,
@@ -149,6 +169,15 @@ impl Performance {
   /// measurement to the internal buffer.
   pub fn measure(&self, mark: PerformanceMark) -> Duration {
     let measure = PerformanceMeasure::from(mark);
+    debug!(
+      "{},",
+      json!({
+        "type": "measure",
+        "name": measure.name,
+        "count": measure.count,
+        "duration": measure.duration.as_millis() as u32,
+      })
+    );
     let duration = measure.duration;
     let mut measures = self.measures.lock().unwrap();
     measures.push_front(measure);
@@ -171,9 +200,9 @@ mod tests {
   #[test]
   fn test_average() {
     let performance = Performance::default();
-    let mark1 = performance.mark("a");
-    let mark2 = performance.mark("a");
-    let mark3 = performance.mark("b");
+    let mark1 = performance.mark("a", None::<()>);
+    let mark2 = performance.mark("a", None::<()>);
+    let mark3 = performance.mark("b", None::<()>);
     performance.measure(mark2);
     performance.measure(mark1);
     performance.measure(mark3);
@@ -187,8 +216,8 @@ mod tests {
   #[test]
   fn test_averages() {
     let performance = Performance::default();
-    let mark1 = performance.mark("a");
-    let mark2 = performance.mark("a");
+    let mark1 = performance.mark("a", None::<()>);
+    let mark2 = performance.mark("a", None::<()>);
     performance.measure(mark2);
     performance.measure(mark1);
     let averages = performance.averages();

cli/lsp/tsc.rs

@@ -1832,7 +1832,7 @@ where
   })
 }
 
-#[derive(Debug, Deserialize)]
+#[derive(Debug, Deserialize, Serialize)]
 #[serde(rename_all = "camelCase")]
 struct SourceSnapshotArgs {
   specifier: String,
@@ -1846,14 +1846,17 @@ fn op_dispose(
   state: &mut State,
   args: SourceSnapshotArgs,
 ) -> Result<bool, AnyError> {
-  let mark = state.state_snapshot.performance.mark("op_dispose");
+  let mark = state
+    .state_snapshot
+    .performance
+    .mark("op_dispose", Some(&args));
   let specifier = resolve_url(&args.specifier)?;
   state.snapshots.remove(&(specifier, args.version.into()));
   state.state_snapshot.performance.measure(mark);
   Ok(true)
 }
 
-#[derive(Debug, Deserialize)]
+#[derive(Debug, Deserialize, Serialize)]
 #[serde(rename_all = "camelCase")]
 struct GetChangeRangeArgs {
   specifier: String,
@@ -1868,10 +1871,13 @@ fn op_get_change_range(
   state: &mut State,
   args: GetChangeRangeArgs,
 ) -> Result<Value, AnyError> {
-  let mark = state.state_snapshot.performance.mark("op_get_change_range");
+  let mark = state
+    .state_snapshot
+    .performance
+    .mark("op_get_change_range", Some(&args));
   let specifier = resolve_url(&args.specifier)?;
   cache_snapshot(state, &specifier, args.version.clone())?;
-  if let Some(current) = state
+  let r = if let Some(current) = state
     .snapshots
     .get(&(specifier.clone(), args.version.clone().into()))
   {
@@ -1879,11 +1885,9 @@ fn op_get_change_range(
       .snapshots
       .get(&(specifier, args.old_version.clone().into()))
     {
-      state.state_snapshot.performance.measure(mark);
       Ok(text::get_range_change(prev, current))
     } else {
       let new_length = current.encode_utf16().count();
-      state.state_snapshot.performance.measure(mark);
       // when a local file is opened up in the editor, the compiler might
       // already have a snapshot of it in memory, and will request it, but we
       // now are working off in memory versions of the document, and so need
@@ -1897,7 +1901,6 @@ fn op_get_change_range(
       }))
     }
   } else {
-    state.state_snapshot.performance.measure(mark);
     Err(custom_error(
       "MissingSnapshot",
       format!(
@@ -1905,16 +1908,23 @@ fn op_get_change_range(
         args
       ),
     ))
-  }
+  };
+
+  state.state_snapshot.performance.measure(mark);
+  r
 }
 
 fn op_get_length(
   state: &mut State,
   args: SourceSnapshotArgs,
 ) -> Result<usize, AnyError> {
-  let mark = state.state_snapshot.performance.mark("op_get_length");
+  let mark = state
+    .state_snapshot
+    .performance
+    .mark("op_get_length", Some(&args));
   let specifier = resolve_url(&args.specifier)?;
-  if let Some(Some(asset)) = state.state_snapshot.assets.get(&specifier) {
+  let r = if let Some(Some(asset)) = state.state_snapshot.assets.get(&specifier)
+  {
     Ok(asset.length)
   } else {
     cache_snapshot(state, &specifier, args.version.clone())?;
@@ -1922,12 +1932,13 @@ fn op_get_length(
       .snapshots
       .get(&(specifier, args.version.into()))
       .unwrap();
-    state.state_snapshot.performance.measure(mark);
     Ok(content.encode_utf16().count())
-  }
+  };
+  state.state_snapshot.performance.measure(mark);
+  r
 }
 
-#[derive(Debug, Deserialize)]
+#[derive(Debug, Deserialize, Serialize)]
 #[serde(rename_all = "camelCase")]
 struct GetTextArgs {
   specifier: String,
@@ -1940,7 +1951,10 @@ fn op_get_text(
   state: &mut State,
   args: GetTextArgs,
 ) -> Result<String, AnyError> {
-  let mark = state.state_snapshot.performance.mark("op_get_text");
+  let mark = state
+    .state_snapshot
+    .performance
+    .mark("op_get_text", Some(&args));
   let specifier = resolve_url(&args.specifier)?;
   let content =
     if let Some(Some(content)) = state.state_snapshot.assets.get(&specifier) {
@@ -1961,7 +1975,10 @@ fn op_resolve(
   state: &mut State,
   args: ResolveArgs,
 ) -> Result<Vec<Option<(String, String)>>, AnyError> {
-  let mark = state.state_snapshot.performance.mark("op_resolve");
+  let mark = state
+    .state_snapshot
+    .performance
+    .mark("op_resolve", Some(&args));
   let mut resolved = Vec::new();
   let referrer = resolve_url(&args.base)?;
   let sources = &mut state.state_snapshot.sources;
@@ -2069,7 +2086,7 @@ fn op_script_names(
   )
 }
 
-#[derive(Debug, Deserialize)]
+#[derive(Debug, Deserialize, Serialize)]
 #[serde(rename_all = "camelCase")]
 struct ScriptVersionArgs {
   specifier: String,
@@ -2079,27 +2096,32 @@ fn op_script_version(
   state: &mut State,
   args: ScriptVersionArgs,
 ) -> Result<Option<String>, AnyError> {
-  let mark = state.state_snapshot.performance.mark("op_script_version");
+  let mark = state
+    .state_snapshot
+    .performance
+    .mark("op_script_version", Some(&args));
   let specifier = resolve_url(&args.specifier)?;
-  if specifier.scheme() == "asset" {
-    return if state.state_snapshot.assets.contains_key(&specifier) {
+  let r = if specifier.scheme() == "asset" {
+    if state.state_snapshot.assets.contains_key(&specifier) {
       Ok(Some("1".to_string()))
     } else {
       Ok(None)
-    };
+    }
   } else if let Some(version) =
     state.state_snapshot.documents.version(&specifier)
   {
-    return Ok(Some(version.to_string()));
+    Ok(Some(version.to_string()))
   } else {
     let sources = &mut state.state_snapshot.sources;
     if let Some(version) = sources.get_script_version(&specifier) {
-      return Ok(Some(version));
-    }
+      Ok(Some(version))
+    } else {
+      Ok(None)
     }
+  };
 
   state.state_snapshot.performance.measure(mark);
-  Ok(None)
+  r
 }
 
 /// Create and setup a JsRuntime based on a snapshot. It is expected that the
@@ -2498,6 +2520,7 @@ pub fn request(
   state_snapshot: StateSnapshot,
   method: RequestMethod,
 ) -> Result<Value, AnyError> {
+  let performance = state_snapshot.performance.clone();
   let id = {
     let op_state = runtime.op_state();
     let mut op_state = op_state.borrow_mut();
@@ -2507,6 +2530,7 @@ pub fn request(
     state.last_id
   };
   let request_params = method.to_value(id);
+  let mark = performance.mark("request", Some(request_params.clone()));
   let request_src = format!("globalThis.serverRequest({});", request_params);
   runtime.execute("[native_code]", &request_src)?;
 
@@ -2514,6 +2538,7 @@ pub fn request(
   let mut op_state = op_state.borrow_mut();
   let state = op_state.borrow_mut::<State>();
 
+  performance.measure(mark);
   if let Some(response) = state.response.clone() {
     state.response = None;
     Ok(response.data)

cli/main.rs

@@ -21,6 +21,7 @@ mod http_util;
 mod import_map;
 mod info;
 mod lockfile;
+mod logger;
 mod lsp;
 mod media_type;
 mod module_graph;
@@ -67,8 +68,6 @@ use deno_runtime::worker::MainWorker;
 use deno_runtime::worker::WorkerOptions;
 use log::debug;
 use log::info;
-use log::Level;
-use log::LevelFilter;
 use std::collections::HashSet;
 use std::env;
 use std::io::Read;
@@ -1170,43 +1169,6 @@ fn init_v8_flags(v8_flags: &[String]) {
   }
 }
 
-fn init_logger(maybe_level: Option<Level>) {
-  let log_level = match maybe_level {
-    Some(level) => level,
-    None => Level::Info, // Default log level
-  };
-  env_logger::Builder::from_env(
-    env_logger::Env::default()
-      .default_filter_or(log_level.to_level_filter().to_string()),
-  )
-  // https://github.com/denoland/deno/issues/6641
-  .filter_module("rustyline", LevelFilter::Off)
-  // wgpu crates (gfx_backend), have a lot of useless INFO and WARN logs
-  .filter_module("wgpu", LevelFilter::Error)
-  .filter_module("gfx", LevelFilter::Error)
-  .format(|buf, record| {
-    let mut target = record.target().to_string();
-    if let Some(line_no) = record.line() {
-      target.push(':');
-      target.push_str(&line_no.to_string());
-    }
-    if record.level() <= Level::Info {
-      // Print ERROR, WARN, INFO logs as they are
-      writeln!(buf, "{}", record.args())
-    } else {
-      // Add prefix to DEBUG or TRACE logs
-      writeln!(
-        buf,
-        "{} RS - {} - {}",
-        record.level(),
-        target,
-        record.args()
-      )
-    }
-  })
-  .init();
-}
-
 fn get_subcommand(
   flags: Flags,
 ) -> Pin<Box<dyn Future<Output = Result<(), AnyError>>>> {
@@ -1363,7 +1325,8 @@ pub fn main() {
   if !flags.v8_flags.is_empty() {
     init_v8_flags(&*flags.v8_flags);
   }
-  init_logger(flags.log_level);
+
+  logger::init(flags.log_level);
 
   unwrap_or_exit(tokio_util::run_basic(get_subcommand(flags)));
 }

cli/tsc.rs

@@ -13,6 +13,7 @@ use deno_core::error::Context;
 use deno_core::op_sync;
 use deno_core::resolve_url_or_path;
 use deno_core::serde::Deserialize;
+use deno_core::serde::Serialize;
 use deno_core::serde_json;
 use deno_core::serde_json::json;
 use deno_core::serde_json::Value;
@@ -350,7 +351,7 @@ fn op_load(state: &mut State, args: Value) -> Result<Value, AnyError> {
   )
 }
 
-#[derive(Debug, Deserialize)]
+#[derive(Debug, Deserialize, Serialize)]
 #[serde(rename_all = "camelCase")]
 pub struct ResolveArgs {
   /// The base specifier that the supplied specifier strings should be resolved