From 950b712dda1f56bacad7730ab15ca21e5d714c42 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bartek=20Iwa=C5=84czuk?= Date: Fri, 1 Dec 2023 03:54:59 +0100 Subject: [PATCH] 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 | 9 +-- cli/lsp/language_server.rs | 110 ++++++++++++++++++----------- cli/lsp/performance.rs | 33 ++++++--- cli/lsp/testing/server.rs | 2 +- cli/lsp/tsc.rs | 12 ++-- cli/tests/integration/lsp_tests.rs | 38 +++++----- 6 files changed, 124 insertions(+), 80 deletions(-) diff --git a/cli/lsp/diagnostics.rs b/cli/lsp/diagnostics.rs index 8f96968459..4b43a478ca 100644 --- a/cli/lsp/diagnostics.rs +++ b/cli/lsp/diagnostics.rs @@ -493,8 +493,7 @@ impl DiagnosticsServer { _ = tokio::time::sleep(DELAY) => {} }; - let mark = - performance.mark("update_diagnostics_ts", None::<()>); + let mark = performance.mark("lsp.update_diagnostics_ts"); 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 = - performance.mark("update_diagnostics_deps", None::<()>); + let mark = performance.mark("lsp.update_diagnostics_deps"); 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 = - performance.mark("update_diagnostics_lint", None::<()>); + let mark = performance.mark("lsp.update_diagnostics_lint"); let diagnostics = spawn_blocking({ let token = token.clone(); move || { diff --git a/cli/lsp/language_server.rs b/cli/lsp/language_server.rs index 5ee2ef776c..1104acc9c7 100644 --- a/cli/lsp/language_server.rs +++ b/cli/lsp/language_server.rs @@ -546,9 +546,9 @@ impl Inner { &self, specifier: &ModuleSpecifier, ) -> Result, AnyError> { - let mark = self.performance.mark( - "get_navigation_tree", - Some(json!({ "specifier": specifier })), + let mark = self.performance.mark_with_args( + "lsp.get_navigation_tree", + 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 { lsp_log!("Starting Deno language server..."); - let mark = self.performance.mark("initialize", Some(¶ms)); + let mark = self.performance.mark_with_args("lsp.initialize", ¶ms); // 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(¶ms)); + let mark = self.performance.mark_with_args("lsp.did_open", ¶ms); 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(¶ms)); + let mark = self.performance.mark_with_args("lsp.did_change", ¶ms); let specifier = self .url_map .normalize_url(¶ms.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(¶ms)); + let mark = self.performance.mark_with_args("lsp.did_close", ¶ms); self.diagnostics_state.clear(¶ms.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(¶ms)); + .mark_with_args("lsp.did_change_watched_files", ¶ms); let mut touched = false; let changes: IndexSet = params .changes @@ -1660,7 +1660,9 @@ impl Inner { return Ok(None); } - let mark = self.performance.mark("document_symbol", Some(¶ms)); + let mark = self + .performance + .mark_with_args("lsp.document_symbol", ¶ms); 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(¶ms)); + let mark = self.performance.mark_with_args("lsp.formatting", ¶ms); // 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(¶ms)); + let mark = self.performance.mark_with_args("lsp.hover", ¶ms); let asset_or_doc = self.get_asset_or_document(&specifier)?; let hover = if let Some((_, dep, range)) = asset_or_doc .get_maybe_dependency(¶ms.text_document_position_params.position) @@ -1861,7 +1863,7 @@ impl Inner { return Ok(None); } - let mark = self.performance.mark("code_action", Some(¶ms)); + let mark = self.performance.mark_with_args("lsp.code_action", ¶ms); 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(¶ms)); + let mark = self + .performance + .mark_with_args("lsp.code_action_resolve", ¶ms); 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(¶ms)); + let mark = self.performance.mark_with_args("lsp.code_lens", ¶ms); 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 { - 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(¶ms)); + let mark = self + .performance + .mark_with_args("lsp.document_highlight", ¶ms); 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(¶ms)); + let mark = self.performance.mark_with_args("lsp.references", ¶ms); 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(¶ms)); + let mark = self + .performance + .mark_with_args("lsp.goto_definition", ¶ms); 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(¶ms)); + let mark = self + .performance + .mark_with_args("lsp.goto_definition", ¶ms); 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(¶ms)); + let mark = self.performance.mark_with_args("lsp.completion", ¶ms); 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 { - let mark = self.performance.mark("completion_resolve", Some(¶ms)); + let mark = self + .performance + .mark_with_args("lsp.completion_resolve", ¶ms); let completion_item = if let Some(data) = ¶ms.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(¶ms)); + let mark = self + .performance + .mark_with_args("lsp.goto_implementation", ¶ms); 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(¶ms)); + let mark = self + .performance + .mark_with_args("lsp.folding_range", ¶ms); 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(¶ms)); + let mark = self + .performance + .mark_with_args("lsp.incoming_calls", ¶ms); 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(¶ms)); + let mark = self + .performance + .mark_with_args("lsp.outgoing_calls", ¶ms); 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(¶ms)); + .mark_with_args("lsp.prepare_call_hierarchy", ¶ms); 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(¶ms)); + let mark = self.performance.mark_with_args("lsp.rename", ¶ms); 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(¶ms)); + let mark = self + .performance + .mark_with_args("lsp.selection_range", ¶ms); 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(¶ms)); + let mark = self + .performance + .mark_with_args("lsp.semantic_tokens_full", ¶ms); 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(¶ms)); + .mark_with_args("lsp.semantic_tokens_range", ¶ms); 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(¶ms)); + let mark = self + .performance + .mark_with_args("lsp.signature_help", ¶ms); 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>> { - let mark = self.performance.mark("symbol", Some(¶ms)); + let mark = self.performance.mark_with_args("lsp.symbol", ¶ms); 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(¶ms)) + .mark_with_args("lsp.did_change_configuration", ¶ms) }; 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(¶ms)); + .mark_with_args("lsp.did_change_workspace_folders", ¶ms); 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(¶ms)); + let mark = self.performance.mark_with_args("lsp.cache", ¶ms); 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(¶ms)); + let mark = self.performance.mark_with_args("lsp.inlay_hint", ¶ms); 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> { let mark = self .performance - .mark("virtual_text_document", Some(¶ms)); + .mark_with_args("lsp.virtual_text_document", ¶ms); let specifier = self .url_map .normalize_url(¶ms.text_document.uri, LspUrlKind::File); diff --git a/cli/lsp/performance.rs b/cli/lsp/performance.rs index 717ae792dd..c4e65aa3c9 100644 --- a/cli/lsp/performance.rs +++ b/cli/lsp/performance.rs @@ -132,10 +132,7 @@ impl Performance { .collect() } - /// 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, V: Serialize>( + fn mark_inner, V: Serialize>( &self, name: S, maybe_args: Option, @@ -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>(&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, 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 mark2 = performance.mark("a", None::<()>); - let mark3 = performance.mark("b", None::<()>); + let mark1 = performance.mark("a"); + let mark2 = performance.mark("a"); + 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 mark2 = performance.mark("a", None::<()>); + let mark1 = performance.mark("a"); + let mark2 = performance.mark("a"); performance.measure(mark2); performance.measure(mark1); let averages = performance.averages(); diff --git a/cli/lsp/testing/server.rs b/cli/lsp/testing/server.rs index 562bbfcb08..a72e13a838 100644 --- a/cli/lsp/testing/server.rs +++ b/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 diff --git a/cli/lsp/tsc.rs b/cli/lsp/tsc.rs index 536730a814..0d27db412f 100644 --- a/cli/lsp/tsc.rs +++ b/cli/lsp/tsc.rs @@ -954,9 +954,7 @@ impl TsServer { where R: de::DeserializeOwned, { - let mark = self - .performance - .mark(format!("tsc {}", req.method), None::<()>); + let mark = self.performance.mark(format!("tsc.request.{}", req.method)); let r = self .request_with_cancellation(snapshot, req, Default::default()) .await; @@ -3910,7 +3908,7 @@ fn op_resolve( #[serde] args: ResolveArgs, ) -> Result>, AnyError> { let state = state.borrow_mut::(); - 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) => { @@ -4438,8 +4436,10 @@ fn request( let id = state.last_id; (state.performance.clone(), id) }; - let mark = - performance.mark("request", Some((request.method, request.args.clone()))); + let mark = performance.mark_with_args( + format!("tsc.host.{}", request.method), + request.args.clone(), + ); assert!( request.args.is_array(), "Internal error: expected args to be array" diff --git a/cli/tests/integration/lsp_tests.rs b/cli/tests/integration/lsp_tests.rs index eee82bb783..2dbf4e9f90 100644 --- a/cli/tests/integration/lsp_tests.rs +++ b/cli/tests/integration/lsp_tests.rs @@ -8303,23 +8303,27 @@ fn lsp_performance() { assert_eq!( averages, vec![ - "did_open", - "hover", - "initialize", - "op_load", - "request", - "testing_update", - "tsc $configure", - "tsc $getAssets", - "tsc $getSupportedCodeFixes", - "tsc getQuickInfoAtPosition", - "update_cache", - "update_diagnostics_deps", - "update_diagnostics_lint", - "update_diagnostics_ts", - "update_import_map", - "update_registries", - "update_tsconfig", + "lsp.did_open", + "lsp.hover", + "lsp.initialize", + "lsp.testing_update", + "lsp.update_cache", + "lsp.update_diagnostics_deps", + "lsp.update_diagnostics_lint", + "lsp.update_diagnostics_ts", + "lsp.update_import_map", + "lsp.update_registries", + "lsp.update_tsconfig", + "tsc.host.$configure", + "tsc.host.$getAssets", + "tsc.host.$getDiagnostics", + "tsc.host.$getSupportedCodeFixes", + "tsc.host.getQuickInfoAtPosition", + "tsc.op.op_load", + "tsc.request.$configure", + "tsc.request.$getAssets", + "tsc.request.$getSupportedCodeFixes", + "tsc.request.getQuickInfoAtPosition", ] ); client.shutdown();