Use hierarchical indexes to speed up module-local completions

[mqudsi]

Sorry for the overly technical and perhaps naive title, but it's the best summary I could think of. On a small project, rust-analyzer is blazing fast and all is well. On a large project, rust-analyzer takes 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.

[lnicola]

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]

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
───────────────────────────────────────────────────────────────────────────────

[lnicola]

We have some profiling support (https://github.com/rust-lang/rust-analyzer/tree/master/docs/dev#profiling) which may provide more info.

[Veykril]

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]

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]

And please report where you're triggering the completion. Something apparently minor like a proc macro can have a large effect.

[Veykril]

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 #14743 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]

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 RA_LOG=debug EDIT: actually, it just timed out because it stopped at 7.7GiB but didn't produce any completions).

[Veykril]

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]

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]

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]

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]

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?