refactor(lsp): log names (#21413)

This commit changes LSP log names by prefixing them, we now have these
prefixes:
- `lsp.*` - requests coming from the client
- `tsc.request.*` - requests coming from clients that are routed to TSC
- `tsc.op.*` - ops called by the TS host
- `tsc.host.*` - requests that call JavaScript runtime that runs
TypeScript compiler host

Additionall `Performance::mark` was split into `Performance::mark` and 
`Performance::mark_with_args` to reduce verbosity of code and logs.

cli/lsp/diagnostics.rs

@@ -493,8 +493,7 @@ impl DiagnosticsServer {
                     _ = tokio::time::sleep(DELAY) => {}
                   };
 
-                  let mark =
+                  let mark = performance.mark("lsp.update_diagnostics_ts");
-                    performance.mark("update_diagnostics_ts", None::<()>);
                   let diagnostics = generate_ts_diagnostics(
                     snapshot.clone(),
                     &config,
@@ -549,8 +548,7 @@ impl DiagnosticsServer {
                   if let Some(previous_handle) = previous_deps_handle {
                     previous_handle.await;
                   }
-                  let mark =
+                  let mark = performance.mark("lsp.update_diagnostics_deps");
-                    performance.mark("update_diagnostics_deps", None::<()>);
                   let diagnostics = spawn_blocking({
                     let token = token.clone();
                     move || generate_deno_diagnostics(&snapshot, &config, token)
@@ -599,8 +597,7 @@ impl DiagnosticsServer {
                   if let Some(previous_handle) = previous_lint_handle {
                     previous_handle.await;
                   }
-                  let mark =
+                  let mark = performance.mark("lsp.update_diagnostics_lint");
-                    performance.mark("update_diagnostics_lint", None::<()>);
                   let diagnostics = spawn_blocking({
                     let token = token.clone();
                     move || {

cli/lsp/language_server.rs

@@ -546,9 +546,9 @@ impl Inner {
     &self,
     specifier: &ModuleSpecifier,
   ) -> Result<Arc<tsc::NavigationTree>, AnyError> {
-    let mark = self.performance.mark(
+    let mark = self.performance.mark_with_args(
-      "get_navigation_tree",
+      "lsp.get_navigation_tree",
-      Some(json!({ "specifier": specifier })),
+      json!({ "specifier": specifier }),
     );
     let asset_or_doc = self.get_asset_or_document(specifier)?;
     let navigation_tree =
@@ -715,7 +715,7 @@ impl Inner {
   }
 
   pub async fn update_cache(&mut self) -> Result<(), AnyError> {
-    let mark = self.performance.mark("update_cache", None::<()>);
+    let mark = self.performance.mark("lsp.update_cache");
     self.performance.measure(mark);
     let maybe_cache = &self.config.workspace_settings().cache;
     let maybe_global_cache_path = if let Some(cache_str) = maybe_cache {
@@ -844,7 +844,7 @@ impl Inner {
   }
 
   pub async fn update_import_map(&mut self) -> Result<(), AnyError> {
-    let mark = self.performance.mark("update_import_map", None::<()>);
+    let mark = self.performance.mark("lsp.update_import_map");
 
     let maybe_import_map_url = self.resolve_import_map_specifier()?;
     if let Some(import_map_url) = maybe_import_map_url {
@@ -979,7 +979,7 @@ impl Inner {
   }
 
   async fn update_registries(&mut self) -> Result<(), AnyError> {
-    let mark = self.performance.mark("update_registries", None::<()>);
+    let mark = self.performance.mark("lsp.update_registries");
     self.recreate_http_client_and_dependents().await?;
     let workspace_settings = self.config.workspace_settings();
     for (registry, enabled) in workspace_settings.suggest.imports.hosts.iter() {
@@ -1035,7 +1035,7 @@ impl Inner {
   }
 
   async fn update_tsconfig(&mut self) -> Result<(), AnyError> {
-    let mark = self.performance.mark("update_tsconfig", None::<()>);
+    let mark = self.performance.mark("lsp.update_tsconfig");
     let mut tsconfig = TsConfig::new(json!({
       "allowJs": true,
       "esModuleInterop": true,
@@ -1129,7 +1129,7 @@ impl Inner {
     params: InitializeParams,
   ) -> LspResult<InitializeResult> {
     lsp_log!("Starting Deno language server...");
-    let mark = self.performance.mark("initialize", Some(&params));
+    let mark = self.performance.mark_with_args("lsp.initialize", &params);
 
     // exit this process when the parent is lost
     if let Some(parent_pid) = params.process_id {
@@ -1295,7 +1295,7 @@ impl Inner {
     specifier: &ModuleSpecifier,
     params: DidOpenTextDocumentParams,
   ) -> Document {
-    let mark = self.performance.mark("did_open", Some(&params));
+    let mark = self.performance.mark_with_args("lsp.did_open", &params);
     let language_id =
       params
         .text_document
@@ -1324,7 +1324,7 @@ impl Inner {
   }
 
   async fn did_change(&mut self, params: DidChangeTextDocumentParams) {
-    let mark = self.performance.mark("did_change", Some(&params));
+    let mark = self.performance.mark_with_args("lsp.did_change", &params);
     let specifier = self
       .url_map
       .normalize_url(&params.text_document.uri, LspUrlKind::File);
@@ -1367,7 +1367,7 @@ impl Inner {
   }
 
   async fn did_close(&mut self, params: DidCloseTextDocumentParams) {
-    let mark = self.performance.mark("did_close", Some(&params));
+    let mark = self.performance.mark_with_args("lsp.did_close", &params);
     self.diagnostics_state.clear(&params.text_document.uri);
     if params.text_document.uri.scheme() == "deno" {
       // we can ignore virtual text documents closing, as they don't need to
@@ -1506,7 +1506,7 @@ impl Inner {
 
     let mark = self
       .performance
-      .mark("did_change_watched_files", Some(&params));
+      .mark_with_args("lsp.did_change_watched_files", &params);
     let mut touched = false;
     let changes: IndexSet<Url> = params
       .changes
@@ -1660,7 +1660,9 @@ impl Inner {
       return Ok(None);
     }
 
-    let mark = self.performance.mark("document_symbol", Some(&params));
+    let mark = self
+      .performance
+      .mark_with_args("lsp.document_symbol", &params);
     let asset_or_document = self.get_asset_or_document(&specifier)?;
     let line_index = asset_or_document.line_index();
 
@@ -1714,7 +1716,7 @@ impl Inner {
       error!("{}", err);
       LspError::invalid_request()
     })?;
-    let mark = self.performance.mark("formatting", Some(&params));
+    let mark = self.performance.mark_with_args("lsp.formatting", &params);
 
     // spawn a blocking task to allow doing other work while this is occurring
     let text_edits = deno_core::unsync::spawn_blocking({
@@ -1780,7 +1782,7 @@ impl Inner {
       return Ok(None);
     }
 
-    let mark = self.performance.mark("hover", Some(&params));
+    let mark = self.performance.mark_with_args("lsp.hover", &params);
     let asset_or_doc = self.get_asset_or_document(&specifier)?;
     let hover = if let Some((_, dep, range)) = asset_or_doc
       .get_maybe_dependency(&params.text_document_position_params.position)
@@ -1861,7 +1863,7 @@ impl Inner {
       return Ok(None);
     }
 
-    let mark = self.performance.mark("code_action", Some(&params));
+    let mark = self.performance.mark_with_args("lsp.code_action", &params);
     let mut all_actions = CodeActionResponse::new();
     let asset_or_doc = self.get_asset_or_document(&specifier)?;
     let line_index = asset_or_doc.line_index();
@@ -2044,7 +2046,9 @@ impl Inner {
       return Ok(params);
     }
 
-    let mark = self.performance.mark("code_action_resolve", Some(&params));
+    let mark = self
+      .performance
+      .mark_with_args("lsp.code_action_resolve", &params);
     let kind = params.kind.clone().unwrap();
     let data = params.data.clone().unwrap();
 
@@ -2151,7 +2155,7 @@ impl Inner {
       return Ok(None);
     }
 
-    let mark = self.performance.mark("code_lens", Some(&params));
+    let mark = self.performance.mark_with_args("lsp.code_lens", &params);
     let asset_or_doc = self.get_asset_or_document(&specifier)?;
     let settings = self.config.workspace_settings_for_specifier(&specifier);
     let mut code_lenses = Vec::new();
@@ -2208,7 +2212,9 @@ impl Inner {
     &self,
     code_lens: CodeLens,
   ) -> LspResult<CodeLens> {
-    let mark = self.performance.mark("code_lens_resolve", Some(&code_lens));
+    let mark = self
+      .performance
+      .mark_with_args("lsp.code_lens_resolve", &code_lens);
     let result = if code_lens.data.is_some() {
       code_lens::resolve_code_lens(code_lens, self)
         .await
@@ -2239,7 +2245,9 @@ impl Inner {
       return Ok(None);
     }
 
-    let mark = self.performance.mark("document_highlight", Some(&params));
+    let mark = self
+      .performance
+      .mark_with_args("lsp.document_highlight", &params);
     let asset_or_doc = self.get_asset_or_document(&specifier)?;
     let line_index = asset_or_doc.line_index();
     let files_to_search = vec![specifier.clone()];
@@ -2280,7 +2288,7 @@ impl Inner {
       return Ok(None);
     }
 
-    let mark = self.performance.mark("references", Some(&params));
+    let mark = self.performance.mark_with_args("lsp.references", &params);
     let asset_or_doc = self.get_asset_or_document(&specifier)?;
     let line_index = asset_or_doc.line_index();
     let maybe_referenced_symbols = self
@@ -2336,7 +2344,9 @@ impl Inner {
       return Ok(None);
     }
 
-    let mark = self.performance.mark("goto_definition", Some(&params));
+    let mark = self
+      .performance
+      .mark_with_args("lsp.goto_definition", &params);
     let asset_or_doc = self.get_asset_or_document(&specifier)?;
     let line_index = asset_or_doc.line_index();
     let maybe_definition = self
@@ -2372,7 +2382,9 @@ impl Inner {
       return Ok(None);
     }
 
-    let mark = self.performance.mark("goto_definition", Some(&params));
+    let mark = self
+      .performance
+      .mark_with_args("lsp.goto_definition", &params);
     let asset_or_doc = self.get_asset_or_document(&specifier)?;
     let line_index = asset_or_doc.line_index();
     let maybe_definition_info = self
@@ -2418,7 +2430,7 @@ impl Inner {
       return Ok(None);
     }
 
-    let mark = self.performance.mark("completion", Some(&params));
+    let mark = self.performance.mark_with_args("lsp.completion", &params);
     let asset_or_doc = self.get_asset_or_document(&specifier)?;
     // Import specifiers are something wholly internal to Deno, so for
     // completions, we will use internal logic and if there are completions
@@ -2498,7 +2510,9 @@ impl Inner {
     &self,
     params: CompletionItem,
   ) -> LspResult<CompletionItem> {
-    let mark = self.performance.mark("completion_resolve", Some(&params));
+    let mark = self
+      .performance
+      .mark_with_args("lsp.completion_resolve", &params);
     let completion_item = if let Some(data) = &params.data {
       let data: completions::CompletionItemData =
         serde_json::from_value(data.clone()).map_err(|err| {
@@ -2580,7 +2594,9 @@ impl Inner {
       return Ok(None);
     }
 
-    let mark = self.performance.mark("goto_implementation", Some(&params));
+    let mark = self
+      .performance
+      .mark_with_args("lsp.goto_implementation", &params);
     let asset_or_doc = self.get_asset_or_document(&specifier)?;
     let line_index = asset_or_doc.line_index();
 
@@ -2622,7 +2638,9 @@ impl Inner {
       return Ok(None);
     }
 
-    let mark = self.performance.mark("folding_range", Some(&params));
+    let mark = self
+      .performance
+      .mark_with_args("lsp.folding_range", &params);
     let asset_or_doc = self.get_asset_or_document(&specifier)?;
 
     let outlining_spans = self
@@ -2663,7 +2681,9 @@ impl Inner {
       return Ok(None);
     }
 
-    let mark = self.performance.mark("incoming_calls", Some(&params));
+    let mark = self
+      .performance
+      .mark_with_args("lsp.incoming_calls", &params);
     let asset_or_doc = self.get_asset_or_document(&specifier)?;
     let line_index = asset_or_doc.line_index();
 
@@ -2706,7 +2726,9 @@ impl Inner {
       return Ok(None);
     }
 
-    let mark = self.performance.mark("outgoing_calls", Some(&params));
+    let mark = self
+      .performance
+      .mark_with_args("lsp.outgoing_calls", &params);
     let asset_or_doc = self.get_asset_or_document(&specifier)?;
     let line_index = asset_or_doc.line_index();
 
@@ -2753,7 +2775,7 @@ impl Inner {
 
     let mark = self
       .performance
-      .mark("prepare_call_hierarchy", Some(&params));
+      .mark_with_args("lsp.prepare_call_hierarchy", &params);
     let asset_or_doc = self.get_asset_or_document(&specifier)?;
     let line_index = asset_or_doc.line_index();
 
@@ -2814,7 +2836,7 @@ impl Inner {
       return Ok(None);
     }
 
-    let mark = self.performance.mark("rename", Some(&params));
+    let mark = self.performance.mark_with_args("lsp.rename", &params);
     let asset_or_doc = self.get_asset_or_document(&specifier)?;
     let line_index = asset_or_doc.line_index();
 
@@ -2857,7 +2879,9 @@ impl Inner {
       return Ok(None);
     }
 
-    let mark = self.performance.mark("selection_range", Some(&params));
+    let mark = self
+      .performance
+      .mark_with_args("lsp.selection_range", &params);
     let asset_or_doc = self.get_asset_or_document(&specifier)?;
     let line_index = asset_or_doc.line_index();
 
@@ -2890,7 +2914,9 @@ impl Inner {
       return Ok(None);
     }
 
-    let mark = self.performance.mark("semantic_tokens_full", Some(&params));
+    let mark = self
+      .performance
+      .mark_with_args("lsp.semantic_tokens_full", &params);
     let asset_or_doc = self.get_asset_or_document(&specifier)?;
     let line_index = asset_or_doc.line_index();
 
@@ -2927,7 +2953,7 @@ impl Inner {
 
     let mark = self
       .performance
-      .mark("semantic_tokens_range", Some(&params));
+      .mark_with_args("lsp.semantic_tokens_range", &params);
     let asset_or_doc = self.get_asset_or_document(&specifier)?;
     let line_index = asset_or_doc.line_index();
 
@@ -2966,7 +2992,9 @@ impl Inner {
       return Ok(None);
     }
 
-    let mark = self.performance.mark("signature_help", Some(&params));
+    let mark = self
+      .performance
+      .mark_with_args("lsp.signature_help", &params);
     let asset_or_doc = self.get_asset_or_document(&specifier)?;
     let line_index = asset_or_doc.line_index();
     let options = if let Some(context) = params.context {
@@ -3047,7 +3075,7 @@ impl Inner {
     &self,
     params: WorkspaceSymbolParams,
   ) -> LspResult<Option<Vec<SymbolInformation>>> {
-    let mark = self.performance.mark("symbol", Some(&params));
+    let mark = self.performance.mark_with_args("lsp.symbol", &params);
 
     let navigate_to_items = self
       .ts_server
@@ -3322,7 +3350,7 @@ impl tower_lsp::LanguageServer for LanguageServer {
       let inner = self.0.read().await;
       inner
         .performance
-        .mark("did_change_configuration", Some(&params))
+        .mark_with_args("lsp.did_change_configuration", &params)
     };
 
     self.refresh_configuration().await;
@@ -3347,7 +3375,7 @@ impl tower_lsp::LanguageServer for LanguageServer {
       let mut ls = self.0.write().await;
       let mark = ls
         .performance
-        .mark("did_change_workspace_folders", Some(&params));
+        .mark_with_args("lsp.did_change_workspace_folders", &params);
       ls.did_change_workspace_folders(params);
       (ls.performance.clone(), mark)
     };
@@ -3559,7 +3587,7 @@ impl Inner {
       return Ok(None);
     }
 
-    let mark = self.performance.mark("cache", Some(&params));
+    let mark = self.performance.mark_with_args("lsp.cache", &params);
     let roots = if !params.uris.is_empty() {
       params
         .uris
@@ -3665,7 +3693,7 @@ impl Inner {
       return Ok(None);
     }
 
-    let mark = self.performance.mark("inlay_hint", Some(&params));
+    let mark = self.performance.mark_with_args("lsp.inlay_hint", &params);
     let asset_or_doc = self.get_asset_or_document(&specifier)?;
     let line_index = asset_or_doc.line_index();
     let text_span =
@@ -3718,7 +3746,7 @@ impl Inner {
   ) -> LspResult<Option<String>> {
     let mark = self
       .performance
-      .mark("virtual_text_document", Some(&params));
+      .mark_with_args("lsp.virtual_text_document", &params);
     let specifier = self
       .url_map
       .normalize_url(&params.text_document.uri, LspUrlKind::File);

cli/lsp/performance.rs

@@ -132,10 +132,7 @@ impl Performance {
       .collect()
   }
 
-  /// Marks the start of a measurement which returns a performance mark
+  fn mark_inner<S: AsRef<str>, V: Serialize>(
-  /// structure, which is then passed to `.measure()` to finalize the duration
-  /// and add it to the internal buffer.
-  pub fn mark<S: AsRef<str>, V: Serialize>(
     &self,
     name: S,
     maybe_args: Option<V>,
@@ -165,6 +162,24 @@ 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 {
+    self.mark_inner(name, None::<()>)
+  }
+
+  /// 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_with_args<S: AsRef<str>, V: Serialize>(
+    &self,
+    name: S,
+    args: V,
+  ) -> PerformanceMark {
+    self.mark_inner(name, Some(args))
+  }
+
   /// A function which accepts a previously created performance mark which will
   /// be used to finalize the duration of the span being measured, and add the
   /// measurement to the internal buffer.
@@ -201,9 +216,9 @@ mod tests {
   #[test]
   fn test_average() {
     let performance = Performance::default();
-    let mark1 = performance.mark("a", None::<()>);
+    let mark1 = performance.mark("a");
-    let mark2 = performance.mark("a", None::<()>);
+    let mark2 = performance.mark("a");
-    let mark3 = performance.mark("b", None::<()>);
+    let mark3 = performance.mark("b");
     performance.measure(mark2);
     performance.measure(mark1);
     performance.measure(mark3);
@@ -217,8 +232,8 @@ mod tests {
   #[test]
   fn test_averages() {
     let performance = Performance::default();
-    let mark1 = performance.mark("a", None::<()>);
+    let mark1 = performance.mark("a");
-    let mark2 = performance.mark("a", None::<()>);
+    let mark2 = performance.mark("a");
     performance.measure(mark2);
     performance.measure(mark1);
     let averages = performance.averages();

cli/lsp/testing/server.rs

@@ -87,7 +87,7 @@ impl TestServer {
           match update_rx.recv().await {
             None => break,
             Some(snapshot) => {
-              let mark = performance.mark("testing_update", None::<()>);
+              let mark = performance.mark("lsp.testing_update");
               let mut tests = tests.lock();
               // we create a list of test modules we currently are tracking
               // eliminating any we go over when iterating over the document

cli/lsp/tsc.rs

@@ -953,9 +953,7 @@ impl TsServer {
   where
     R: de::DeserializeOwned,
   {
-    let mark = self
+    let mark = self.performance.mark(format!("tsc.request.{}", req.method));
-      .performance
-      .mark(format!("tsc {}", req.method), None::<()>);
     let r = self
       .request_with_cancellation(snapshot, req, Default::default())
       .await;
@@ -3876,7 +3874,7 @@ fn op_load(
   #[serde] args: SpecifierArgs,
 ) -> Result<Option<LoadResponse>, AnyError> {
   let state = state.borrow_mut::<State>();
-  let mark = state.performance.mark("op_load", Some(&args));
+  let mark = state.performance.mark_with_args("tsc.op.op_load", &args);
   let specifier = state.specifier_map.normalize(args.specifier)?;
   if specifier.as_str() == "internal:///missing_dependency.d.ts" {
     return Ok(Some(LoadResponse {
@@ -3901,7 +3899,7 @@ fn op_resolve(
   #[serde] args: ResolveArgs,
 ) -> Result<Vec<Option<(String, String)>>, AnyError> {
   let state = state.borrow_mut::<State>();
-  let mark = state.performance.mark("op_resolve", Some(&args));
+  let mark = state.performance.mark_with_args("tsc.op.op_resolve", &args);
   let referrer = state.specifier_map.normalize(&args.base)?;
   let result = match state.get_asset_or_document(&referrer) {
     Some(referrer_doc) => {
@@ -4429,8 +4427,10 @@ fn request(
     let id = state.last_id;
     (state.performance.clone(), id)
   };
-  let mark =
+  let mark = performance.mark_with_args(
-    performance.mark("request", Some((request.method, request.args.clone())));
+    format!("tsc.host.{}", request.method),
+    request.args.clone(),
+  );
   assert!(
     request.args.is_array(),
     "Internal error: expected args to be array"

cli/tests/integration/lsp_tests.rs

@@ -8303,23 +8303,27 @@ fn lsp_performance() {
   assert_eq!(
     averages,
     vec![
-      "did_open",
+      "lsp.did_open",
-      "hover",
+      "lsp.hover",
-      "initialize",
+      "lsp.initialize",
-      "op_load",
+      "lsp.testing_update",
-      "request",
+      "lsp.update_cache",
-      "testing_update",
+      "lsp.update_diagnostics_deps",
-      "tsc $configure",
+      "lsp.update_diagnostics_lint",
-      "tsc $getAssets",
+      "lsp.update_diagnostics_ts",
-      "tsc $getSupportedCodeFixes",
+      "lsp.update_import_map",
-      "tsc getQuickInfoAtPosition",
+      "lsp.update_registries",
-      "update_cache",
+      "lsp.update_tsconfig",
-      "update_diagnostics_deps",
+      "tsc.host.$configure",
-      "update_diagnostics_lint",
+      "tsc.host.$getAssets",
-      "update_diagnostics_ts",
+      "tsc.host.$getDiagnostics",
-      "update_import_map",
+      "tsc.host.$getSupportedCodeFixes",
-      "update_registries",
+      "tsc.host.getQuickInfoAtPosition",
-      "update_tsconfig",
+      "tsc.op.op_load",
+      "tsc.request.$configure",
+      "tsc.request.$getAssets",
+      "tsc.request.$getSupportedCodeFixes",
+      "tsc.request.getQuickInfoAtPosition",
     ]
   );
   client.shutdown();