lnicola
commented
1 year ago Are you sure they're this slow most of the time and not just right at the beginning? Is your project public? I suspect something else might be going on.
Open mqudsi opened 1 year ago
lnicola
commented
1 year ago Are you sure they're this slow most of the time and not just right at the beginning? Is your project public? I suspect something else might be going on.
mqudsi
commented
1 year ago Yeah, they're always this slow when completing individual functions or trait methods. Namespace completions of module names is fast, but at the leaf level (going from module to type) it is again slow.
The project is public, I'm working on the fish-shell rewrite to rust. We have autocxx generate ffi wrappers for (not too much of, to be honest) the C++ codebase as well as the rust code itself. The project isn't massive by any means, but it's decently large - here's what scc (a faster tokei) prints:
───────────────────────────────────────────────────────────────────────────────
Language Files Lines Blanks Comments Code Complexity
───────────────────────────────────────────────────────────────────────────────
Fish 1314 78501 7048 10852 60601 4084
ReStructuredText 135 17767 5715 0 12052 0
Rust 88 36122 2929 3844 29349 2828
C Header 87 12023 2165 2895 6963 302
C++ 74 52970 5604 6673 40693 9697
Python 46 8835 565 599 7671 347
Shell 18 757 138 178 441 74
CMake 13 1548 204 312 1032 87
Dockerfile 13 474 87 9 378 88
HTML 11 473 44 9 420 0
JavaScript 7 1149 92 153 904 158
YAML 7 443 33 76 334 0
Autoconf 5 374 82 100 192 52
Markdown 5 408 144 0 264 0
License 4 129 32 0 97 0
CSS 3 1485 216 76 1193 0
Cargo Lock 2 1430 155 4 1271 0
Plain Text 2 9 1 0 8 0
TOML 2 83 13 8 62 0
gitignore 2 108 11 19 78 0
C 1 23 4 0 19 1
Go 1 12 2 0 10 0
Objective C 1 100 19 15 66 7
XML 1 19 0 0 19 0
───────────────────────────────────────────────────────────────────────────────
Total 1842 215242 25303 25822 164117 17725
───────────────────────────────────────────────────────────────────────────────We have some profiling support (https://github.com/rust-lang/rust-analyzer/tree/master/docs/dev#profiling) which may provide more info.
Veykril
commented
1 year ago For this specifically, set RA_PROFILE=handle_completion and trigger a completion that takes too long. Then check the logs and paste the corresponding output here.
mqudsi
commented
1 year ago Thank you both. I was looking through some old issues and was under the impression I'd have to attach a profiler and dig through the dump.
lnicola
commented
1 year ago And please report where you're triggering the completion. Something apparently minor like a proc macro can have a large effect.
Veykril
commented
1 year ago Looking at this though I think I can already guess the problem https://github.com/fish-shell/fish-shell/blob/67d1d80f94107e26585d192d194295180cb9f73b/fish-rust/src/ffi.rs#L20-L136
I imagine this trashes the LRU cache for macro expansions whenever one types causing us to reparse all the macro invocations in there. So this most likely hits https://github.com/rust-lang/rust-analyzer/issues/14743/https://github.com/rust-lang/rust-analyzer/issues/14677 then (which funnily somewhat fits your guess with this being an index problem) or a similar problem where completions reparse macro expansions. Though I'd still like to see the profile to confirm this.
mqudsi
commented
1 year ago I can't get /usr/bin/env RA_PROFILE=handle_completion --log-file /usr/home/mqudsi/rust-analyzer.txt to produce anything but an empty file.
Using /usr/bin/env RA_PROFILE=handle_completion RA_LOG=debug rust-analyzer --log-file /usr/home/mqudsi/rust-analyzer.txt has given me a 7.7GB-and-still-growing file while I attempt to generate the first completion, still stuck after more than a minute (probably IO-bound because it doesn't take that long without EDIT: actually, it just timed out because it stopped at 7.7GiB but didn't produce any completions).RA_LOG=debug
Veykril
commented
1 year ago No need to set RA_LOG, just RA_PROFILE should be fine, I think I made a mistake there though, it should be RA_LOG=handle_completion>* (or RA_LOG=handle_completion>1 if that also doesnt work)
lnicola
commented
1 year ago I haven't tested that handle_completion works, but RA_PROFILE=handle_completion>2000 or RA_PROFILE=*>2000 will show calls that take more than 2 seconds. I used to run it with RA_PROFILE=*>5000 and it catches plenty of stuff.
And I think Veykril made a typo there, it's RA_PROFILE, not RA_LOG. Or it's RA_LOG=handle_completion, but that won't take a duration or enable profiling.
mqudsi
commented
1 year ago I don't know what I'm doing wrong but I can't get it to generate any profiling output. The file is created each time but it remains empty unless rust-analyzer runs into an error (such as when autocxx failed during build.rs execution) in which case I get the error output.
I tried RA_PROFILE=handle_completion, RA_PROFILE=handle_completion>2000, and RA_PROFILE=*>2000. I'm passing the environment variables to rust-analyzer directly in my lsp configuration (not just starting up neovim with them set).
Is the --log-file argument for RA_LOG and not RA_PROFILE?
Veykril
commented
1 year ago The log file might not support the profiling stuff, not sure but it looks like it. Can you not access the server logs from neovim?
mqudsi
commented
1 year ago I'm trying on a much faster machine now and the completions are snappier but still too long to wait for. I was hoping for native logging functionality because neovim's own log unfortunately escapes the content, giving me this:
[START][2023-05-19 14:53:47] LSP logging initiated
[ERROR][2023-05-19 14:53:47] .../vim/lsp/rpc.lua:733 "rpc" "/usr/bin/env" "stderr" "13577ms - handle_completion\n 13568ms - CompletionContext::new\n 5822ms - CompletionContext::expand\n 5814ms - SourceBinder::to_module_def\n 5813ms - crate_def_map:wait\n 5813ms - crate_def_map_query @ fish_rust\n 2541ms - crate_def_map:wait\n 2541ms - crate_def_map_query @ proc_macro\n 2457ms - crate_def_map:wait\n"
[ERROR][2023-05-19 14:53:47] .../vim/lsp/rpc.lua:733 "rpc" "/usr/bin/env" "stderr" " 2457ms - crate_def_map_query @ std\n 264ms - DefCollector::collect (1 calls)\n 0 - DefCollector::finish (1 calls)\n 1933ms - crate_def_map:wait (9 calls)\n 258ms - seed_with_top_level (1 calls)\n 19ms - DefCollector::collect (1 calls)\n 0 - DefCollector::finish (1 calls)\n 64ms - seed_with_top_level (1 calls)\n 1384ms - DefCollector::collect (1 calls)\n 0 - DefCollector::finish (1 calls)\n 1657ms - crate_def_map:wait (24 calls)\n 229ms - seed_with_top_level (1 calls)\n 0 - crate_def_map:wait (1 calls)\n 0 - relevant_crates (1 calls)\n 0 - SourceBinder::to_module_def (3 calls)\n 0 - crate_def_map:wait (1 calls)\n 0 - impl_data_with_diagnostics_query (1 calls)\n 7736ms - CompletionContext::analyze\n 7736ms - Semantics::analyze_impl\n 7736ms - infer:wait @ to_cstring\n 7736ms - infer_query\n 7662ms - deref_by_trait\n 7662ms - trait_solve::wait\n 7662ms - trait_solve_query @ Deref\n 0 - crate_def_map:wait (1 calls)\n 0 - impl_datum (2 calls)\n 7662ms - ???\n 0 - generic_params_query (2 calls)\n 0 - lang_item_query (1 calls)\n 0 - resolve_obligations_as_possible (2 calls)\n 0 - PerNs::filter_visibility (4 calls)\n 0 - crate_def_map:wait (44 calls)\n 0 - deref_by_trait (1 calls)\n 0 - generic_params_query (5 calls)\n 17ms - inherent_impl_crates_query (1 calls)\n 15ms - resolve_obligations_as_possible (100 calls)\n 0 - trait_solve::wait (14 calls)\n 0 - SourceBinder::to_module_def (1 calls)\n 0 - body_with_source_map_query (1 calls)\n 0 - crate_def_map:wait (1 calls)\n 0 - generic_params_query (2 calls)\n 0 - Semantics::analyze_impl (1 calls)\n 0 - SourceBinder::to_module_def (2 calls)\n 0 - crate_def_map:wait (3 calls)\n 0 - Semantics::analyze_impl (1 calls)\n 0 - crate_def_map:wait (3 calls)\n 0 - Semantics::analyze_impl (1 calls)\n 7ms - complete_expr_path (1 calls)\n"
[ERROR][2023-05-19 14:53:47] .../vim/lsp/rpc.lua:733 "rpc" "/usr/bin/env" "stderr" "12383ms - handle_completion\n 12374ms - CompletionContext::new\n 4629ms - CompletionContext::expand\n 4621ms - SourceBinder::to_module_def\n 4620ms - crate_def_map:wait\n 0 - crate_def_map:wait (1 calls)\n 0 - relevant_crates (1 calls)\n 0 - SourceBinder::to_module_def (3 calls)\n 0 - crate_def_map:wait (1 calls)\n 7736ms - CompletionContext::analyze\n 7736ms - Semantics::analyze_impl\n 7736ms - infer:wait @ to_cstring\n 0 - SourceBinder::to_module_def (1 calls)\n 0 - crate_def_map:wait (1 calls)\n 0 - Semantics::analyze_impl (1 calls)\n 0 - SourceBinder::to_module_def (2 calls)\n 0 - crate_def_map:wait (1 calls)\n 0 - Semantics::analyze_impl (1 calls)\n 0 - crate_def_map:wait (3 calls)\n 7ms - parse_query (1 calls)\n 0 - Semantics::analyze_impl (1 calls)\n 7ms - complete_expr_path (1 calls)\n"
[ERROR][2023-05-19 14:54:11] .../vim/lsp/rpc.lua:733 "rpc" "/usr/bin/env" "stderr" '17255ms - handle_completion\n 17236ms - import_on_the_fly_method @ \n 17236ms - import_assets::search_for_imports\n 17236ms - import_assets::search_for\n 17236ms - import_assets::trait_applicable_items\n 15007ms - items_with_name @ Name: , crate: AssocItemsOnly, assoc items: Some("fish_rust"), limit: Some(40)\n 15007ms - find_items\n 14971ms - crate_symbols @ Query { query: "", lowercased: "", only_types: false, libs: false, exact: false, case_sensitive: false, limit: 40 }\n 0 - crate_def_map:wait (1 calls)\n 0 - symbol_index::Query::search (1 calls)\n 14970ms - ???\n 36ms - query_external_importables (1 calls)\n 0 - applicable_inherent_traits (1 calls)\n 0 - env_traits (1 calls)\n 2186ms - get_name_definition (40 calls)\n 41ms - iterate_method_candidates (1 calls)\n 0 - '
[ERROR][2023-05-19 14:54:11] .../vim/lsp/rpc.lua:733 "rpc" "/usr/bin/env" "stderr" "Semantics::analyze_impl (1 calls)\n 0 - import_assets::scope_definitions (1 calls)\n 0 - item::Builder::build (2 calls)\n 0 - render_method (2 calls)\n 1ms - CompletionContext::new (1 calls)\n 0 - crate_def_map:wait (205 calls)\n 0 - deref_by_trait (1 calls)\n 0 - item::Builder::build (9 calls)\n 17ms - iterate_method_candidates (1 calls)\n 0 - resolve_obligations_as_possible (4 calls)\n 0 - trait_solve::wait (3 calls)\n"
[ERROR][2023-05-19 14:54:11] .../vim/lsp/rpc.lua:733 "rpc" "/usr/bin/env" "stderr" "17564ms - handle_completion\n 17469ms - import_on_the_fly_method @ "
[ERROR][2023-05-19 14:54:11] .../vim/lsp/rpc.lua:733 "rpc" "/usr/bin/env" "stderr" '\n 17468ms - import_assets::search_for_imports\n 17468ms - import_assets::search_for\n 17468ms - import_assets::trait_applicable_items\n 15240ms - items_with_name @ Name: , crate: AssocItemsOnly, assoc items: Some("fish_rust"), limit: Some(40)\n 15240ms - find_items\n 15204ms - crate_symbols @ Query { query: "", lowercased: "", only_types: false, libs: false, exact: false, case_sensitive: false, limit: 40 }\n 0 - crate_def_map:wait (1 calls)\n 0 - symbol_index::Query::search (1 calls)\n 15203ms - ???\n 36ms - query_external_importables (1 calls)\n 2023'
[ERROR][2023-05-19 14:54:11] .../vim/lsp/rpc.lua:733 "rpc" "/usr/bin/env" "stderr" "ms - get_name_definition\n 2023ms - classify_name\n 0 - crate_def_map:wait (1 calls)\n 0 - module_to_def (1 calls)\n 2023ms - ???\n 0 - applicable_inherent_traits (1 calls)\n 0 - env_traits (1 calls)\n 163ms - get_name_definition (39 calls)\n 41ms - iterate_method_candidates (1 calls)\n 0 - Semantics::analyze_impl (1 calls)\n 0 - import_assets::scope_definitions (1 calls)\n 0 - crate_def_map:wait (2 calls)\n 0 - item::Builder::build (2 calls)\n 0 - render_method (2 calls)\n 77ms - CompletionContext::new (1 calls)\n 0 - crate_def_map:wait (205 calls)\n 0 - deref_by_trait (1 calls)\n 0 - item::Builder::build (9 calls)\n 17ms - iterate_method_candidates (1 calls)\n 0 - lang_item_query (1 calls)\n 0 - resolve_obligations_as_possible (4 calls)\n 0 - trait_solve::wait (3 calls)\n"If I run it through the shell to try and make it easier on the eyes, I get the following:
[START][2023-05-19 14:53:47] LSP logging initiated
[ERROR][2023-05-19 14:53:47] .../vim/lsp/rpc.lua:733 "rpc" "/usr/bin/env" "stderr" "13577ms - handle_completion
13568ms - CompletionContext::new
5822ms - CompletionContext::expand
5814ms - SourceBinder::to_module_def
5813ms - crate_def_map:wait
5813ms - crate_def_map_query @ fish_rust
2541ms - crate_def_map:wait
2541ms - crate_def_map_query @ proc_macro
2457ms - crate_def_map:wait
"
[ERROR][2023-05-19 14:53:47] .../vim/lsp/rpc.lua:733 "rpc" "/usr/bin/env" "stderr" " 2457ms - crate_def_map_query @ std
264ms - DefCollector::collect (1 calls)
0 - DefCollector::finish (1 calls)
1933ms - crate_def_map:wait (9 calls)
258ms - seed_with_top_level (1 calls)
19ms - DefCollector::collect (1 calls)
0 - DefCollector::finish (1 calls)
64ms - seed_with_top_level (1 calls)
1384ms - DefCollector::collect (1 calls)
0 - DefCollector::finish (1 calls)
1657ms - crate_def_map:wait (24 calls)
229ms - seed_with_top_level (1 calls)
0 - crate_def_map:wait (1 calls)
0 - relevant_crates (1 calls)
0 - SourceBinder::to_module_def (3 calls)
0 - crate_def_map:wait (1 calls)
0 - impl_data_with_diagnostics_query (1 calls)
7736ms - CompletionContext::analyze
7736ms - Semantics::analyze_impl
7736ms - infer:wait @ to_cstring
7736ms - infer_query
7662ms - deref_by_trait
7662ms - trait_solve::wait
7662ms - trait_solve_query @ Deref
0 - crate_def_map:wait (1 calls)
0 - impl_datum (2 calls)
7662ms - ???
0 - generic_params_query (2 calls)
0 - lang_item_query (1 calls)
0 - resolve_obligations_as_possible (2 calls)
0 - PerNs::filter_visibility (4 calls)
0 - crate_def_map:wait (44 calls)
0 - deref_by_trait (1 calls)
0 - generic_params_query (5 calls)
17ms - inherent_impl_crates_query (1 calls)
15ms - resolve_obligations_as_possible (100 calls)
0 - trait_solve::wait (14 calls)
0 - SourceBinder::to_module_def (1 calls)
0 - body_with_source_map_query (1 calls)
0 - crate_def_map:wait (1 calls)
0 - generic_params_query (2 calls)
0 - Semantics::analyze_impl (1 calls)
0 - SourceBinder::to_module_def (2 calls)
0 - crate_def_map:wait (3 calls)
0 - Semantics::analyze_impl (1 calls)
0 - crate_def_map:wait (3 calls)
0 - Semantics::analyze_impl (1 calls)
7ms - complete_expr_path (1 calls)
"
[ERROR][2023-05-19 14:53:47] .../vim/lsp/rpc.lua:733 "rpc" "/usr/bin/env" "stderr" "12383ms - handle_completion
12374ms - CompletionContext::new
4629ms - CompletionContext::expand
4621ms - SourceBinder::to_module_def
4620ms - crate_def_map:wait
0 - crate_def_map:wait (1 calls)
0 - relevant_crates (1 calls)
0 - SourceBinder::to_module_def (3 calls)
0 - crate_def_map:wait (1 calls)
7736ms - CompletionContext::analyze
7736ms - Semantics::analyze_impl
7736ms - infer:wait @ to_cstring
0 - SourceBinder::to_module_def (1 calls)
0 - crate_def_map:wait (1 calls)
0 - Semantics::analyze_impl (1 calls)
0 - SourceBinder::to_module_def (2 calls)
0 - crate_def_map:wait (1 calls)
0 - Semantics::analyze_impl (1 calls)
0 - crate_def_map:wait (3 calls)
7ms - parse_query (1 calls)
0 - Semantics::analyze_impl (1 calls)
7ms - complete_expr_path (1 calls)
"
[ERROR][2023-05-19 14:54:11] .../vim/lsp/rpc.lua:733 "rpc" "/usr/bin/env" "stderr" '17255ms - handle_completion
17236ms - import_on_the_fly_method @
17236ms - import_assets::search_for_imports
17236ms - import_assets::search_for
17236ms - import_assets::trait_applicable_items
15007ms - items_with_name @ Name: , crate: AssocItemsOnly, assoc items: Some("fish_rust"), limit: Some(40)
15007ms - find_items
14971ms - crate_symbols @ Query { query: "", lowercased: "", only_types: false, libs: false, exact: false, case_sensitive: false, limit: 40 }
0 - crate_def_map:wait (1 calls)
0 - symbol_index::Query::search (1 calls)
14970ms - ???
36ms - query_external_importables (1 calls)
0 - applicable_inherent_traits (1 calls)
0 - env_traits (1 calls)
2186ms - get_name_definition (40 calls)
41ms - iterate_method_candidates (1 calls)
0 - '
[ERROR][2023-05-19 14:54:11] .../vim/lsp/rpc.lua:733 "rpc" "/usr/bin/env" "stderr" "Semantics::analyze_impl (1 calls)
0 - import_assets::scope_definitions (1 calls)
0 - item::Builder::build (2 calls)
0 - render_method (2 calls)
1ms - CompletionContext::new (1 calls)
0 - crate_def_map:wait (205 calls)
0 - deref_by_trait (1 calls)
0 - item::Builder::build (9 calls)
17ms - iterate_method_candidates (1 calls)
0 - resolve_obligations_as_possible (4 calls)
0 - trait_solve::wait (3 calls)
"
[ERROR][2023-05-19 14:54:11] .../vim/lsp/rpc.lua:733 "rpc" "/usr/bin/env" "stderr" "17564ms - handle_completion
17469ms - import_on_the_fly_method @ "
[ERROR][2023-05-19 14:54:11] .../vim/lsp/rpc.lua:733 "rpc" "/usr/bin/env" "stderr" '
17468ms - import_assets::search_for_imports
17468ms - import_assets::search_for
17468ms - import_assets::trait_applicable_items
15240ms - items_with_name @ Name: , crate: AssocItemsOnly, assoc items: Some("fish_rust"), limit: Some(40)
15240ms - find_items
15204ms - crate_symbols @ Query { query: "", lowercased: "", only_types: false, libs: false, exact: false, case_sensitive: false, limit: 40 }
0 - crate_def_map:wait (1 calls)
0 - symbol_index::Query::search (1 calls)
15203ms - ???
36ms - query_external_importables (1 calls)
2023'
[ERROR][2023-05-19 14:54:11] .../vim/lsp/rpc.lua:733 "rpc" "/usr/bin/env" "stderr" "ms - get_name_definition
2023ms - classify_name
0 - crate_def_map:wait (1 calls)
0 - module_to_def (1 calls)
2023ms - ???
0 - applicable_inherent_traits (1 calls)
0 - env_traits (1 calls)
163ms - get_name_definition (39 calls)
41ms - iterate_method_candidates (1 calls)
0 - Semantics::analyze_impl (1 calls)
0 - import_assets::scope_definitions (1 calls)
0 - crate_def_map:wait (2 calls)
0 - item::Builder::build (2 calls)
0 - render_method (2 calls)
77ms - CompletionContext::new (1 calls)
0 - crate_def_map:wait (205 calls)
0 - deref_by_trait (1 calls)
0 - item::Builder::build (9 calls)
17ms - iterate_method_candidates (1 calls)
0 - lang_item_query (1 calls)
0 - resolve_obligations_as_possible (4 calls)
0 - trait_solve::wait (3 calls)
"This is all from a quick session trying to complete something in a trait impl (without generics) with no proc macros (which I waited for to complete and provide the popup before typing in anything else), so the first is the super slow call as it builds the info for the first time but the subsequent completions are all with a warmed up rust-analyzer.
rust-analyzer was installed via rustup, but I have just recently started doing that, having always built from source before. Do I need to build from source in debug mode for the missing symbols?
Sorry for the overly technical and perhaps naive title, but it's the best summary I could think of. On a small project,
rust-analyzeris blazing fast and all is well. On a large project,rust-analyzertakes 10+ seconds to generate non-namespace completions.I would expect that if I create a new module in the current crate and have nothing imported,
rust-analyzer(in that module) would not be too much slower than working on an empty module in a new crate, but this isn't the case.