Files
zed/crates/project/tests/integration/lsp_store.rs
T
Shuhei KadowakiandKirill Bulatov 8b2baadb09 lsp: Show request durations in RPC messages (#61018)
Language server performance issues can be difficult to diagnose because
request timings are not shown alongside the corresponding JSON-RPC
traffic. Annotate responses in the "LSP Logs / RPC Messages" view with
their end-to-end duration, making it easier to identify slow methods,
latency outliers, and cancellation behavior in the language server
process launched by Zed.

Capture timestamps at the transport boundary, correlate decoded request
IDs separately by direction, preserve timing across cancellation, bound
stale request tracking, and forward host-measured durations to remote
clients.

## Self-Review Checklist:

- [x] I've reviewed my own diff for quality, security, and relxability
- [x] Unsafe blocks (if any) have justifying comments
- [x] The content adheres to Zed's UI standards
([UX/UI](https://github.com/zed-industries/zed/blob/main/CONTRIBUTING.md#uiux-checklist)
and
[icon](https://github.com/zed-industries/zed/blob/main/crates/icons/README.md)
guidelines)
- [x] Tests cover the new/changed behavior
- [x] Performance impact has been considered and is acceptable

## Showcase

<details>
<summary>Example trace</summary>

```
// Send:
{"jsonrpc":"2.0","id":61,"method":"textDocument/documentHighlight","params":{"textDocument":{"uri":"file:///Users/aviatesk/julia/packages/worktrees/JETLS/placid-wren/JETLS/src/analysis/Analyzer.jl"},"position":{"line":378,"character":3}}}

// Receive (took 7.698042ms):
{"jsonrpc":"2.0","id":61,"result":[]}

// Send:
{"jsonrpc":"2.0","id":62,"method":"textDocument/codeAction","params":{"textDocument":{"uri":"file:///Users/aviatesk/julia/packages/worktrees/JETLS/placid-wren/JETLS/src/analysis/Analyzer.jl"},"range":{"start":{"line":378,"character":3},"end":{"line":378,"character":3}},"context":{"diagnostics":[]}}}

// Receive (took 5.632167ms):
{"jsonrpc":"2.0","id":62,"result":[{"title":"Show macro expansion for `@static`","command":{"title":"Show macro expansion for `@static`","command":"jetls.openMacroExpansion","arguments":["jetls-macro-expansion:/macro-expanded.jl?source=file%253A%252F%252F%252FUsers%252Faviatesk%252Fjulia%252Fpackages%252Fworktrees%252FJETLS%252Fplacid-wren%252FJETLS%252Fsrc%252Fanalysis%252FAnalyzer.jl&start=14278&stop=15609"]}},{"title":"Expand all macros in this top-level form","command":{"title":"Expand all macros in this top-level form","command":"jetls.openMacroExpansion","arguments":["jetls-macro-expansion:/macro-expanded.jl?source=file%253A%252F%252F%252FUsers%252Faviatesk%252Fjulia%252Fpackages%252Fworktrees%252FJETLS%252Fplacid-wren%252FJETLS%252Fsrc%252Fanalysis%252FAnalyzer.jl&start=14278&stop=15609&mode=toplevel"]}},{"title":"Show inferred type annotations","command":{"title":"Show inferred type annotations","command":"jetls.openTypeAnnotation","arguments":["jetls-type-annotation:/type-annotated.jl?source=file%253A%252F%252F%252FUsers%252Faviatesk%252Fjulia%252Fpackages%252Fworktrees%252FJETLS%252Fplacid-wren%252FJETLS%252Fsrc%252Fanalysis%252FAnalyzer.jl&start=14278&stop=15609"]}}]}

// Send:
{"jsonrpc":"2.0","id":63,"method":"textDocument/documentHighlight","params":{"textDocument":{"uri":"file:///Users/aviatesk/julia/packages/worktrees/JETLS/placid-wren/JETLS/src/analysis/Analyzer.jl"},"position":{"line":379,"character":3}}}

// Receive (took 3.473792ms):
{"jsonrpc":"2.0","id":63,"result":[]}

// Send:
{"jsonrpc":"2.0","id":64,"method":"textDocument/codeAction","params":{"textDocument":{"uri":"file:///Users/aviatesk/julia/packages/worktrees/JETLS/placid-wren/JETLS/src/analysis/Analyzer.jl"},"range":{"start":{"line":379,"character":3},"end":{"line":379,"character":3}},"context":{"diagnostics":[]}}}

// Receive (took 4.472375ms):
{"jsonrpc":"2.0","id":64,"result":[{"title":"Show macro expansion for `@static`","command":{"title":"Show macro expansion for `@static`","command":"jetls.openMacroExpansion","arguments":["jetls-macro-expansion:/macro-expanded.jl?source=file%253A%252F%252F%252FUsers%252Faviatesk%252Fjulia%252Fpackages%252Fworktrees%252FJETLS%252Fplacid-wren%252FJETLS%252Fsrc%252Fanalysis%252FAnalyzer.jl&start=14278&stop=15609"]}},{"title":"Expand all macros in this top-level form","command":{"title":"Expand all macros in this top-level form","command":"jetls.openMacroExpansion","arguments":["jetls-macro-expansion:/macro-expanded.jl?source=file%253A%252F%252F%252FUsers%252Faviatesk%252Fjulia%252Fpackages%252Fworktrees%252FJETLS%252Fplacid-wren%252FJETLS%252Fsrc%252Fanalysis%252FAnalyzer.jl&start=14278&stop=15609&mode=toplevel"]}},{"title":"Show inferred type annotations","command":{"title":"Show inferred type annotations","command":"jetls.openTypeAnnotation","arguments":["jetls-type-annotation:/type-annotated.jl?source=file%253A%252F%252F%252FUsers%252Faviatesk%252Fjulia%252Fpackages%252Fworktrees%252FJETLS%252Fplacid-wren%252FJETLS%252Fsrc%252Fanalysis%252FAnalyzer.jl&start=14278&stop=15609"]}}]}

// Send:
{"jsonrpc":"2.0","id":65,"method":"textDocument/documentHighlight","params":{"textDocument":{"uri":"file:///Users/aviatesk/julia/packages/worktrees/JETLS/placid-wren/JETLS/src/analysis/Analyzer.jl"},"position":{"line":380,"character":0}}}

// Receive (took 1.186541ms):
{"jsonrpc":"2.0","id":65,"result":[]}

// Send:
{"jsonrpc":"2.0","id":66,"method":"textDocument/codeAction","params":{"textDocument":{"uri":"file:///Users/aviatesk/julia/packages/worktrees/JETLS/placid-wren/JETLS/src/analysis/Analyzer.jl"},"range":{"start":{"line":380,"character":0},"end":{"line":380,"character":0}},"context":{"diagnostics":[]}}}

// Receive (took 2.552708ms):
{"jsonrpc":"2.0","id":66,"result":[]}

// Send:
{"jsonrpc":"2.0","id":67,"method":"textDocument/documentHighlight","params":{"textDocument":{"uri":"file:///Users/aviatesk/julia/packages/worktrees/JETLS/placid-wren/JETLS/src/analysis/Analyzer.jl"},"position":{"line":401,"character":0}}}

// Receive (took 1.490084ms):
{"jsonrpc":"2.0","id":67,"result":[]}

// Send:
{"jsonrpc":"2.0","id":68,"method":"textDocument/codeAction","params":{"textDocument":{"uri":"file:///Users/aviatesk/julia/packages/worktrees/JETLS/placid-wren/JETLS/src/analysis/Analyzer.jl"},"range":{"start":{"line":401,"character":0},"end":{"line":401,"character":0}},"context":{"diagnostics":[]}}}

// Receive (took 2.819125ms):
{"jsonrpc":"2.0","id":68,"result":[]}

// Send:
{"jsonrpc":"2.0","id":69,"method":"textDocument/documentHighlight","params":{"textDocument":{"uri":"file:///Users/aviatesk/julia/packages/worktrees/JETLS/placid-wren/JETLS/src/analysis/Analyzer.jl"},"position":{"line":400,"character":0}}}

// Receive (took 3.501375ms):
{"jsonrpc":"2.0","id":69,"result":[]}

// Send:
{"jsonrpc":"2.0","id":70,"method":"textDocument/documentHighlight","params":{"textDocument":{"uri":"file:///Users/aviatesk/julia/packages/worktrees/JETLS/placid-wren/JETLS/src/analysis/Analyzer.jl"},"position":{"line":399,"character":0}}}

// Receive (took 2.903333ms):
{"jsonrpc":"2.0","id":70,"result":[]}

// Send:
{"jsonrpc":"2.0","id":71,"method":"textDocument/documentHighlight","params":{"textDocument":{"uri":"file:///Users/aviatesk/julia/packages/worktrees/JETLS/placid-wren/JETLS/src/analysis/Analyzer.jl"},"position":{"line":399,"character":14}}}

// Receive (took 3.166ms):
{"jsonrpc":"2.0","id":71,"result":[{"range":{"start":{"line":389,"character":19},"end":{"line":389,"character":22}},"kind":3},{"range":{"start":{"line":399,"character":11},"end":{"line":399,"character":14}},"kind":2}]}

// Send:
{"jsonrpc":"2.0","id":72,"method":"textDocument/codeAction","params":{"textDocument":{"uri":"file:///Users/aviatesk/julia/packages/worktrees/JETLS/placid-wren/JETLS/src/analysis/Analyzer.jl"},"range":{"start":{"line":399,"character":14},"end":{"line":399,"character":14}},"context":{"diagnostics":[]}}}

// Receive (took 3.169625ms):
{"jsonrpc":"2.0","id":72,"result":[{"title":"Show inferred type annotations","command":{"title":"Show inferred type annotations","command":"jetls.openTypeAnnotation","arguments":["jetls-type-annotation:/type-annotated.jl?source=file%253A%252F%252F%252FUsers%252Faviatesk%252Fjulia%252Fpackages%252Fworktrees%252FJETLS%252Fplacid-wren%252FJETLS%252Fsrc%252Fanalysis%252FAnalyzer.jl&start=15676&stop=16556"]}}]}

// Send:
{"jsonrpc":"2.0","id":73,"method":"textDocument/hover","params":{"textDocument":{"uri":"file:///Users/aviatesk/julia/packages/worktrees/JETLS/placid-wren/JETLS/src/analysis/Analyzer.jl"},"position":{"line":399,"character":14}}}

// Receive (took 1.234396208s):
{"jsonrpc":"2.0","id":73,"result":{"contents":{"kind":"markdown","value":"```julia\n(local) ret :: Compiler.RTEffects  # Core.PartialStruct(Compiler.RTEffects, Any[Any, Any, Compiler.Effects, Core.Const(nothing)])\n```\n"},"range":{"start":{"line":399,"character":11},"end":{"line":399,"character":14}}}}

// Send:
{"jsonrpc":"2.0","id":74,"method":"textDocument/hover","params":{"textDocument":{"uri":"file:///Users/aviatesk/julia/packages/worktrees/JETLS/placid-wren/JETLS/src/analysis/Analyzer.jl"},"position":{"line":399,"character":14}}}

// Receive (took 11.429875ms):
{"jsonrpc":"2.0","id":74,"result":{"contents":{"kind":"markdown","value":"```julia\n(local) ret :: Compiler.RTEffects  # Core.PartialStruct(Compiler.RTEffects, Any[Any, Any, Compiler.Effects, Core.Const(nothing)])\n```\n"},"range":{"start":{"line":399,"character":11},"end":{"line":399,"character":14}}}}

// Send:
{"jsonrpc":"2.0","id":75,"method":"textDocument/documentHighlight","params":{"textDocument":{"uri":"file:///Users/aviatesk/julia/packages/worktrees/JETLS/placid-wren/JETLS/src/analysis/Analyzer.jl"},"position":{"line":401,"character":0}}}

// Receive (took 1.098667ms):
{"jsonrpc":"2.0","id":75,"result":[]}

// Send:
{"jsonrpc":"2.0","id":76,"method":"textDocument/codeAction","params":{"textDocument":{"uri":"file:///Users/aviatesk/julia/packages/worktrees/JETLS/placid-wren/JETLS/src/analysis/Analyzer.jl"},"range":{"start":{"line":401,"character":0},"end":{"line":401,"character":0}},"context":{"diagnostics":[]}}}

// Receive (took 4.117459ms):
{"jsonrpc":"2.0","id":76,"result":[]}
```

</details>

---

Release Notes:

- Improved LSP Logs by showing request durations alongside RPC
responses, making slow language server behavior easier to diagnose.

---------

Co-authored-by: Kirill Bulatov <kirill@zed.dev>
2026-07-21 16:55:55 +00:00

294 lines
8.4 KiB
Rust

use std::{
path::Path,
time::{Duration, Instant},
};
use fs::FakeFs;
use futures::StreamExt;
use gpui::TestAppContext;
use language::{CodeLabel, FakeLspAdapter, HighlightId, rust_lang};
use lsp::Uri;
use project::{
Project,
lsp_store::{log_store::TestRpcRequestTracker, *},
};
use serde_json::json;
use util::path;
use crate::init_test;
#[gpui::test]
async fn test_removing_invisible_worktree_cleans_reused_lsp_bookkeeping(cx: &mut TestAppContext) {
init_test(cx);
cx.executor().allow_parking();
let fs = FakeFs::new(cx.executor());
fs.insert_tree(path!("/the-root"), json!({ "main.rs": "fn main() {}" }))
.await;
fs.insert_tree(
path!("/the-registry"),
json!({ "dep": { "src": { "dep.rs": "pub fn dep() {}" } } }),
)
.await;
let project = Project::test(fs, [path!("/the-root").as_ref()], cx).await;
let language_registry = project.read_with(cx, |project, _| project.languages().clone());
language_registry.add(rust_lang());
let mut fake_servers = language_registry.register_fake_lsp("Rust", FakeLspAdapter::default());
let (_visible_buffer, _visible_handle) = project
.update(cx, |project, cx| {
project.open_local_buffer_with_lsp(path!("/the-root/main.rs"), cx)
})
.await
.unwrap();
fake_servers.next().await.unwrap();
cx.run_until_parked();
let server_id = project.read_with(cx, |project, cx| {
project
.lsp_store()
.read(cx)
.language_server_statuses()
.next()
.unwrap()
.0
});
let external_buffer = project
.update(cx, |project, cx| {
project.open_local_buffer_via_lsp(
Uri::from_file_path(path!("/the-registry/dep/src/dep.rs")).unwrap(),
server_id,
cx,
)
})
.await
.unwrap();
cx.run_until_parked();
let invisible_worktree_id =
external_buffer.read_with(cx, |buffer, cx| buffer.file().unwrap().worktree_id(cx));
project.read_with(cx, |project, cx| {
let worktree = project.worktree_for_id(invisible_worktree_id, cx).unwrap();
assert!(!worktree.read(cx).is_visible());
assert!(
project
.lsp_store()
.read(cx)
.has_language_server_seed_for_worktree(invisible_worktree_id)
);
});
project.update(cx, |project, cx| {
project.remove_worktree(invisible_worktree_id, cx);
});
cx.run_until_parked();
project.read_with(cx, |project, cx| {
let lsp_store = project.lsp_store();
let lsp_store = lsp_store.read(cx);
assert!(
lsp_store
.language_server_statuses()
.any(|(status_server_id, _)| status_server_id == server_id)
);
assert!(!lsp_store.has_language_server_seed_for_worktree(invisible_worktree_id));
});
}
#[test]
fn test_rpc_request_tracker_distinguishes_request_directions() {
let mut tracker = TestRpcRequestTracker::new();
let started_at = Instant::now();
assert_eq!(
tracker.observe(
false,
r#"{"jsonrpc":"2.0","id":1,"method":"textDocument/hover"}"#,
started_at,
),
None
);
assert_eq!(
tracker.observe(
true,
r#"{"jsonrpc":"2.0","id":1,"method":"workspace/configuration"}"#,
started_at + Duration::from_millis(10),
),
None
);
assert_eq!(
tracker.observe(
false,
r#"{"jsonrpc":"2.0","id":1,"result":[]}"#,
started_at + Duration::from_millis(30),
),
Some(Duration::from_millis(20))
);
assert_eq!(
tracker.observe(
true,
r#"{"jsonrpc":"2.0","id":1,"result":null}"#,
started_at + Duration::from_millis(50),
),
Some(Duration::from_millis(50))
);
}
#[test]
fn test_rpc_request_tracker_decodes_ids_and_times_cancelled_requests() {
let mut tracker = TestRpcRequestTracker::new();
let started_at = Instant::now();
tracker.observe(
true,
r#"{"jsonrpc":"2.0","id":"foo\u002fbar","method":"workspace/configuration"}"#,
started_at,
);
assert_eq!(
tracker.observe(
false,
r#"{"jsonrpc":"2.0","id":"foo/bar","result":[]}"#,
started_at + Duration::from_millis(25),
),
Some(Duration::from_millis(25))
);
tracker.observe(
false,
r#"{"jsonrpc":"2.0","id":7,"method":"textDocument/hover"}"#,
started_at,
);
tracker.observe(
false,
r#"{"jsonrpc":"2.0","method":"$/cancelRequest","params":{"id":7}}"#,
started_at + Duration::from_millis(1),
);
assert_eq!(tracker.pending_request_count(), 1);
assert_eq!(
tracker.observe(
true,
r#"{"jsonrpc":"2.0","id":7,"error":{"code":-32800,"message":"Request was cancelled"}}"#,
started_at + Duration::from_millis(10),
),
Some(Duration::from_millis(10))
);
assert_eq!(tracker.pending_request_count(), 0);
}
#[test]
fn test_rpc_request_tracker_bounds_unanswered_requests() {
let mut tracker = TestRpcRequestTracker::new();
let started_at = Instant::now();
let max_pending_requests = TestRpcRequestTracker::max_pending_requests();
for id in 0..=max_pending_requests {
tracker.observe(
false,
&format!(r#"{{"jsonrpc":"2.0","id":{id},"method":"textDocument/hover"}}"#),
started_at + Duration::from_nanos(id as u64),
);
}
assert_eq!(tracker.pending_request_count(), max_pending_requests);
assert_eq!(
tracker.observe(
true,
r#"{"jsonrpc":"2.0","id":0,"result":null}"#,
started_at + Duration::from_secs(1),
),
None
);
assert!(
tracker
.observe(
true,
r#"{"jsonrpc":"2.0","id":1,"result":null}"#,
started_at + Duration::from_secs(1),
)
.is_some()
);
}
#[test]
fn test_rpc_log_duration_proto_roundtrip() {
let log_type = LanguageServerLogType::Rpc {
received: true,
elapsed: Some(Duration::from_micros(1234)),
};
assert_eq!(
LanguageServerLogType::from_proto(log_type.to_proto()),
log_type
);
}
#[test]
fn test_glob_literal_prefix() {
assert_eq!(glob_literal_prefix(Path::new("**/*.js")), Path::new(""));
assert_eq!(
glob_literal_prefix(Path::new("node_modules/**/*.js")),
Path::new("node_modules")
);
assert_eq!(
glob_literal_prefix(Path::new("foo/{bar,baz}.js")),
Path::new("foo")
);
assert_eq!(
glob_literal_prefix(Path::new("foo/bar/baz.js")),
Path::new("foo/bar/baz.js")
);
#[cfg(target_os = "windows")]
{
assert_eq!(glob_literal_prefix(Path::new("**\\*.js")), Path::new(""));
assert_eq!(
glob_literal_prefix(Path::new("node_modules\\**/*.js")),
Path::new("node_modules")
);
assert_eq!(
glob_literal_prefix(Path::new("foo/{bar,baz}.js")),
Path::new("foo")
);
assert_eq!(
glob_literal_prefix(Path::new("foo\\bar\\baz.js")),
Path::new("foo/bar/baz.js")
);
}
}
#[test]
fn test_multi_len_chars_normalization() {
let mut label = CodeLabel::new(
"myElˇ (parameter) myElˇ: {\n foo: string;\n}".to_string(),
0..6,
vec![(0..6, HighlightId::new(1))],
);
ensure_uniform_list_compatible_label(&mut label);
assert_eq!(
label,
CodeLabel::new(
"myElˇ (parameter) myElˇ: { foo: string; }".to_string(),
0..6,
vec![(0..6, HighlightId::new(1))],
)
);
}
#[test]
fn test_trailing_newline_in_completion_documentation() {
let doc =
lsp::Documentation::String("Inappropriate argument value (of correct type).\n".to_string());
let completion_doc: CompletionDocumentation = doc.into();
assert!(
matches!(completion_doc, CompletionDocumentation::SingleLine(s) if s == "Inappropriate argument value (of correct type).")
);
let doc = lsp::Documentation::String(" some value \n".to_string());
let completion_doc: CompletionDocumentation = doc.into();
assert!(matches!(
completion_doc,
CompletionDocumentation::SingleLine(s) if s == "some value"
));
}