Skip to content

Investigate completion and highlight performance #10369

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
Tracked by #10724
lnicola opened this issue Sep 27, 2021 · 8 comments
Closed
Tracked by #10724

Investigate completion and highlight performance #10369

lnicola opened this issue Sep 27, 2021 · 8 comments
Labels
A-perf performance issues Broken Window Bugs / technical debt to be addressed immediately C-bug Category: bug

Comments

@lnicola
Copy link
Member

lnicola commented Sep 27, 2021

Highlight seems slow lately, possibly due to descend_into_macros, even on code outside macros. Example (repeatedly typing and removing a character at the end of Config::json_schema in crates/rust-analyzer/src/config.rs:

  411ms - handle_semantic_tokens_full_delta
      410ms - highlight
           26ms - Semantics::analyze_impl
               26ms - SourceBinder::to_module_def
                   26ms - crate_def_map:wait
                       10ms - item_tree_query (9 calls)
                       16ms - ???
                    0   - crate_def_map:wait (3 calls)
                    0   - relevant_crates (1 calls)
                0   - crate_def_map:wait (1 calls)
          163ms - descend_into_macros
               85ms - body_with_source_map_query
                    0   - crate_def_map:wait (633 calls)
                    2ms - item_tree_query (158 calls)
                    0   - parse_macro_expansion (1 calls)
                   82ms - ???
               76ms - body_with_source_map_query
                    0   - crate_def_map:wait (633 calls)
                    2ms - item_tree_query (158 calls)
                   74ms - ???
                0   - Semantics::analyze_impl (1 calls)
                0   - SourceBinder::to_module_def (13 calls)
                0   - crate_def_map:wait (4 calls)
                0   - parse_macro_expansion (3 calls)
            1ms - Semantics::analyze_impl (462 calls)
            0   - SourceBinder::to_module_def (250 calls)
            0   - classify_lifetime (7 calls)
            0   - classify_lifetime_ref (7 calls)
            1ms - classify_name (370 calls)
           28ms - classify_name_ref (1157 calls)
            0   - crate_def_map:wait (1726 calls)
          176ms - descend_into_macros (2137 calls)
            0   - infer:wait (410 calls)
            0   - module_to_def (10 calls)
            0   - source_file_to_def (1 calls)
            2ms - trait_solve::wait (454 calls)
@lnicola lnicola mentioned this issue Sep 27, 2021
Closed
4 tasks
@lnicola
Copy link
Member Author

lnicola commented Sep 27, 2021 •
edited
Loading

A couple more:

Profile 
   75ms - publish_diagnostics
       75ms - diagnostics
           59ms - Module::diagnostics @ "semantics"
               24ms - infer:wait @ find_root
                    0   - crate_def_map:wait (1 calls)
                   24ms - ???
                3ms - BodyValidationDiagnostic::collect (136 calls)
               11ms - body_with_source_map_query (133 calls)
                0   - crate_def_map:wait (1126 calls)
               14ms - infer:wait (271 calls)
                0   - validate_module_item (142 calls)
           10ms - SourceBinder::to_module_def (1 calls)
            4ms - parse_query (1 calls)
   78ms - handle_completion
       34ms - descend_into_macros
           34ms - Semantics::analyze_impl
               33ms - infer:wait @ descend_into_macros_impl
                   33ms - infer_query
                       22ms - trait_solve::wait
                        0   - crate_def_map:wait (877 calls)
                        0   - deref (90 calls)
                        2ms - resolve_obligations_as_possible (687 calls)
                        0   - trait_solve::wait (257 calls)
                0   - SourceBinder::to_module_def (1 calls)
                0   - body_with_source_map_query (1 calls)
                0   - crate_def_map:wait (2 calls)
                0   - impl_data_query (1 calls)
            0   - SourceBinder::to_module_def (2 calls)
       22ms - iterate_method_candidates
            0   - crate_def_map:wait (597 calls)
            0   - deref (2 calls)
           17ms - render_method (129 calls)
            0   - trait_solve::wait (141 calls)
        0   - Semantics::analyze_impl (5 calls)
       10ms - SourceBinder::to_module_def (3 calls)
        0   - crate_def_map:wait (59 calls)
        6ms - import_on_the_fly (1 calls)
        0   - item::Builder::build (12 calls)
        0   - trait_solve::wait (2 calls)
   96ms - handle_semantic_tokens_full_delta
       94ms - highlight
           11ms - Semantics::analyze_impl
               11ms - SourceBinder::to_module_def
                   11ms - crate_def_map:wait
                        3ms - item_tree_query (2 calls)
                    0   - relevant_crates (1 calls)
                0   - crate_def_map:wait (1 calls)
           20ms - infer:wait @ in_type_ns
            3ms - Semantics::analyze_impl (900 calls)
            0   - SourceBinder::to_module_def (293 calls)
            0   - classify_lifetime (34 calls)
            0   - classify_lifetime_ref (27 calls)
            4ms - classify_name (617 calls)
           17ms - classify_name_ref (1810 calls)
            0   - crate_def_map:wait (3211 calls)
           12ms - descend_into_macros (588 calls)
            1ms - infer:wait (1257 calls)
            0   - module_to_def (1 calls)
            0   - source_file_to_def (1 calls)
            1ms - trait_solve::wait (1376 calls)
           18ms - ???
  112ms - handle_inlay_hints
      112ms - inlay_hints
           34ms - descend_into_macros
               34ms - Semantics::analyze_impl
                   11ms - SourceBinder::to_module_def
                       11ms - crate_def_map:wait
                        0   - relevant_crates (1 calls)
                   23ms - infer:wait @ in_type_ns
                    0   - body_with_source_map_query (1 calls)
                    0   - crate_def_map:wait (2 calls)
                    0   - impl_data_query (1 calls)
                0   - SourceBinder::to_module_def (2 calls)
           15ms - Semantics::analyze_impl (4065 calls)
            0   - crate_def_map:wait (2407 calls)
           33ms - descend_into_macros (4586 calls)
            8ms - parse_macro_expansion (4 calls)
            2ms - parse_query (1 calls)
            0   - trait_solve::wait (12 calls)
           16ms - ???
  118ms - handle_semantic_tokens_full_delta
      117ms - highlight
           22ms - Semantics::analyze_impl
               22ms - SourceBinder::to_module_def
                   21ms - crate_def_map:wait
                    0   - crate_def_map:wait (3 calls)
                    0   - relevant_crates (1 calls)
                0   - crate_def_map:wait (1 calls)
           35ms - classify_name_ref @ crate
               35ms - Semantics::analyze_impl
                   35ms - infer:wait @ position
                    0   - SourceBinder::to_module_def (1 calls)
                    0   - crate_def_map:wait (1 calls)
            2ms - Semantics::analyze_impl (504 calls)
            0   - SourceBinder::to_module_def (106 calls)
            3ms - classify_name (400 calls)
           25ms - classify_name_ref (2464 calls)
            1ms - crate_def_map:wait (3584 calls)
           11ms - descend_into_macros (292 calls)
            0   - infer:wait (1005 calls)
            0   - module_to_def (24 calls)
            0   - source_file_to_def (1 calls)
            1ms - trait_solve::wait (1122 calls)
           14ms - ???
  134ms - handle_semantic_tokens_full_delta
      132ms - highlight
           22ms - Semantics::analyze_impl
               22ms - SourceBinder::to_module_def
                   21ms - crate_def_map:wait
                    0   - crate_def_map:wait (3 calls)
                    0   - relevant_crates (1 calls)
                0   - crate_def_map:wait (1 calls)
           34ms - classify_name_ref @ crate
               34ms - Semantics::analyze_impl
                   34ms - infer:wait @ handle_analyzer_status
                    0   - SourceBinder::to_module_def (1 calls)
                    0   - crate_def_map:wait (1 calls)
            3ms - Semantics::analyze_impl (919 calls)
            0   - SourceBinder::to_module_def (134 calls)
            4ms - classify_name (684 calls)
           23ms - classify_name_ref (2990 calls)
            0   - crate_def_map:wait (4736 calls)
           24ms - descend_into_macros (391 calls)
            0   - infer:wait (1830 calls)
            0   - source_file_to_def (1 calls)
            1ms - trait_solve::wait (1996 calls)
           16ms - ???
  171ms - handle_semantic_tokens_full_delta
      170ms - highlight
           21ms - Semantics::analyze_impl
               21ms - SourceBinder::to_module_def
                   21ms - crate_def_map:wait
                    0   - crate_def_map:wait (3 calls)
                    0   - relevant_crates (1 calls)
                0   - crate_def_map:wait (1 calls)
           34ms - classify_name
               34ms - Semantics::analyze_impl
                   34ms - infer:wait @ main_loop
                        1ms - impl_data_query (26 calls)
                       33ms - ???
                    0   - SourceBinder::to_module_def (1 calls)
                    0   - crate_def_map:wait (1 calls)
                0   - SourceBinder::to_module_def (1 calls)
            1ms - Semantics::analyze_impl (364 calls)
            0   - SourceBinder::to_module_def (58 calls)
            1ms - classify_name (194 calls)
            8ms - classify_name_ref (1224 calls)
            0   - crate_def_map:wait (1949 calls)
           93ms - descend_into_macros (416 calls)
            0   - infer:wait (544 calls)
            0   - source_file_to_def (1 calls)
            0   - trait_solve::wait (570 calls)
   17ms - handle_code_action
        0   - Semantics::analyze_impl (10 calls)
        0   - SourceBinder::to_module_def (1 calls)
        0   - add_missing_impl_members_inner (2 calls)
        0   - classify_name_ref (1 calls)
        0   - crate_def_map:wait (1 calls)
        0   - descend_into_macros (10 calls)
        6ms - diagnostics (1 calls)
        5ms - import_assets::search_for_imports (1 calls)
        5ms - import_assets::search_for_relative_paths (1 calls)
  306ms - handle_semantic_tokens_full_delta
      305ms - highlight
           22ms - Semantics::analyze_impl
               22ms - SourceBinder::to_module_def
                   21ms - crate_def_map:wait
                    0   - crate_def_map:wait (3 calls)
                    0   - relevant_crates (1 calls)
                0   - crate_def_map:wait (1 calls)
           18ms - parse_macro_expansion
               16ms - macro_expand
            1ms - Semantics::analyze_impl (462 calls)
            0   - SourceBinder::to_module_def (250 calls)
            0   - classify_lifetime (7 calls)
            0   - classify_lifetime_ref (7 calls)
            2ms - classify_name (370 calls)
           34ms - classify_name_ref (1157 calls)
            0   - crate_def_map:wait (1726 calls)
          213ms - descend_into_macros (2138 calls)
            0   - infer:wait (410 calls)
            0   - module_to_def (10 calls)
            2ms - parse_macro_expansion (5 calls)
            0   - source_file_to_def (1 calls)
            0   - trait_solve::wait (454 calls)
   68ms - publish_diagnostics
       68ms - diagnostics
           54ms - Module::diagnostics @ "semantics"
               18ms - infer:wait @ find_root
                    0   - crate_def_map:wait (1 calls)
                   18ms - ???
                2ms - BodyValidationDiagnostic::collect (136 calls)
                9ms - body_with_source_map_query (134 calls)
                0   - crate_def_map:wait (1126 calls)
               20ms - infer:wait (271 calls)
                0   - validate_module_item (142 calls)
            9ms - SourceBinder::to_module_def (1 calls)
            3ms - parse_query (1 calls)
   80ms - handle_semantic_tokens_full_delta
       79ms - highlight
           15ms - infer:wait @ in_type_ns
           12ms - Semantics::analyze_impl (902 calls)
            0   - SourceBinder::to_module_def (293 calls)
            0   - classify_lifetime (34 calls)
            0   - classify_lifetime_ref (27 calls)
            3ms - classify_name (617 calls)
           13ms - classify_name_ref (1809 calls)
            0   - crate_def_map:wait (3212 calls)
            7ms - descend_into_macros (588 calls)
            7ms - infer:wait (1257 calls)
            0   - module_to_def (1 calls)
            0   - source_file_to_def (1 calls)
            1ms - trait_solve::wait (1376 calls)
           15ms - ???
   11ms - publish_diagnostics
       11ms - diagnostics
           10ms - Module::diagnostics (1 calls)
            0   - SourceBinder::to_module_def (1 calls)
   88ms - handle_semantic_tokens_full_delta
       86ms - highlight
           21ms - Semantics::analyze_impl
               21ms - SourceBinder::to_module_def
                   21ms - crate_def_map:wait
                    0   - crate_def_map:wait (3 calls)
                    0   - relevant_crates (1 calls)
                0   - crate_def_map:wait (1 calls)
           22ms - classify_name_ref @ crate
               22ms - Semantics::analyze_impl
                   22ms - infer:wait @ position
                        0   - impl_data_query (27 calls)
                       22ms - ???
                    0   - SourceBinder::to_module_def (1 calls)
                    0   - crate_def_map:wait (1 calls)
            1ms - Semantics::analyze_impl (504 calls)
            0   - SourceBinder::to_module_def (106 calls)
            2ms - classify_name (400 calls)
           17ms - classify_name_ref (2464 calls)
            0   - crate_def_map:wait (3584 calls)
            7ms - descend_into_macros (292 calls)
            0   - infer:wait (1005 calls)
            0   - module_to_def (24 calls)
            0   - source_file_to_def (1 calls)
            1ms - trait_solve::wait (1122 calls)
           10ms - ???
  111ms - handle_inlay_hints
      110ms - inlay_hints
           27ms - descend_into_macros
               27ms - Semantics::analyze_impl
                   16ms - infer:wait @ in_type_ns
                   10ms - SourceBinder::to_module_def (1 calls)
                    0   - body_with_source_map_query (1 calls)
                    0   - crate_def_map:wait (2 calls)
                    0   - impl_data_query (1 calls)
                0   - SourceBinder::to_module_def (2 calls)
           14ms - Semantics::analyze_impl (4066 calls)
            0   - crate_def_map:wait (2407 calls)
           32ms - descend_into_macros (4586 calls)
           19ms - parse_macro_expansion (5 calls)
            0   - trait_solve::wait (12 calls)
           16ms - ???
  128ms - handle_semantic_tokens_full_delta
      126ms - highlight
           21ms - Semantics::analyze_impl
               21ms - SourceBinder::to_module_def
                   21ms - crate_def_map:wait
                    0   - crate_def_map:wait (3 calls)
                    0   - relevant_crates (1 calls)
                0   - crate_def_map:wait (1 calls)
           22ms - classify_name_ref @ crate
               22ms - Semantics::analyze_impl
                   22ms - infer:wait @ handle_analyzer_status
                    0   - SourceBinder::to_module_def (1 calls)
                    0   - crate_def_map:wait (1 calls)
            3ms - Semantics::analyze_impl (919 calls)
            0   - SourceBinder::to_module_def (134 calls)
            4ms - classify_name (684 calls)
           26ms - classify_name_ref (2990 calls)
            0   - crate_def_map:wait (4736 calls)
           25ms - descend_into_macros (391 calls)
            0   - infer:wait (1830 calls)
            0   - source_file_to_def (1 calls)
            1ms - trait_solve::wait (1996 calls)
           19ms - ???
  156ms - handle_semantic_tokens_full_delta
      155ms - highlight
           21ms - Semantics::analyze_impl
               21ms - SourceBinder::to_module_def
                   21ms - crate_def_map:wait
                    0   - crate_def_map:wait (3 calls)
                    0   - relevant_crates (1 calls)
                0   - crate_def_map:wait (1 calls)
           22ms - classify_name
               22ms - Semantics::analyze_impl
                   22ms - infer:wait @ main_loop
                    0   - SourceBinder::to_module_def (1 calls)
                    0   - crate_def_map:wait (1 calls)
                0   - SourceBinder::to_module_def (1 calls)
            1ms - Semantics::analyze_impl (364 calls)
            0   - SourceBinder::to_module_def (58 calls)
            1ms - classify_name (194 calls)
            8ms - classify_name_ref (1224 calls)
            0   - crate_def_map:wait (1949 calls)
           91ms - descend_into_macros (416 calls)
            0   - infer:wait (544 calls)
            0   - source_file_to_def (1 calls)
            0   - trait_solve::wait (570 calls)
  261ms - handle_semantic_tokens_full_delta
      260ms - highlight
           21ms - Semantics::analyze_impl
               21ms - SourceBinder::to_module_def
                   21ms - crate_def_map:wait
                    0   - crate_def_map:wait (3 calls)
                    0   - relevant_crates (1 calls)
                0   - crate_def_map:wait (1 calls)
            1ms - Semantics::analyze_impl (462 calls)
            0   - SourceBinder::to_module_def (250 calls)
            0   - classify_lifetime (7 calls)
            0   - classify_lifetime_ref (7 calls)
            1ms - classify_name (370 calls)
           30ms - classify_name_ref (1157 calls)
            0   - crate_def_map:wait (1726 calls)
          187ms - descend_into_macros (2138 calls)
            0   - infer:wait (410 calls)
            0   - module_to_def (10 calls)
            9ms - parse_macro_expansion (6 calls)
            0   - source_file_to_def (1 calls)
            0   - trait_solve::wait (454 calls)

@lnicola lnicola added A-perf performance issues Broken Window Bugs / technical debt to be addressed immediately C-bug Category: bug labels Oct 12, 2021
@petr-tik
Copy link
Contributor

hey, i have contributed before and am interested in some perf investigation/improvement work.

I can have a look at why descend_into_macros is slow on code outside a macro, would appreciate any tips on interpreting the profiler results and potential perf improvements.

@Veykril
Copy link
Member

Veykril commented Oct 16, 2021

Note the function is not necessarily slow outside of macros, highlighting triggers over the entire file every time and the file in question here has a pretty big macro input.

You should be able to test the file out by using it in an integrated benchmark in crates\rust-analyzer\src\integrated_benchmarks.rs, that should also give you more profiler results.

Also see the Zulip thread here https://rust-lang.zulipchat.com/#narrow/stream/185405-t-compiler.2Frust-analyzer/topic/.60descend_into_macros.60.20seems.20slow

@petr-tik
Copy link
Contributor

thanks! Will have a look at the benchmark.

aside - it's a shame rust-lang chooses a closed platform like zulip that requires a sign-up.

@lnicola
Copy link
Member Author

lnicola commented Oct 16, 2021

The discussions are publicly available at https://zulip-archive.rust-lang.org/stream/185405-t-compiler/rust-analyzer/topic/.60descend_into_macros.60.20seems.20slow.html ... unfortunately, IMO.

@petr-tik
Copy link
Contributor

thanks!

@Veykril
Copy link
Member

Veykril commented Nov 5, 2021 •
edited
Loading

highlighting crates/rust-analyzer/src/config.rs now looks like the following on my machine:

  317ms - highlight
       82ms - classify_name_ref @ Self
           82ms - Semantics::analyze_impl
               82ms - infer:wait @ default
                   82ms - infer_query
                       64ms - trait_solve::wait
                            3ms - trait_impls_in_crate_query (1 calls)
                           60ms - ???
                        0   - crate_def_map:wait (122 calls)
                        0   - crate_lang_items_query (1 calls)
                        0   - generic_params_query (7 calls)
                       15ms - impl_data_query (264 calls)
                        0   - resolve_obligations_as_possible (15 calls)
                        0   - trait_solve::wait (2 calls)
                0   - SourceBinder::to_module_def (1 calls)
                0   - body_with_source_map_query (1 calls)
                0   - crate_def_map:wait (1 calls)
       42ms - Semantics::analyze_impl (656 calls)
        0   - SourceBinder::to_module_def (288 calls)
        0   - classify_lifetime (12 calls)
        0   - classify_lifetime_ref (10 calls)
       62ms - classify_name (417 calls)
       46ms - classify_name_ref (1350 calls)
        0   - crate_def_map:wait (4258 calls)
       24ms - descend_into_macros (2190 calls)
        0   - generic_params_query (71 calls)
        0   - impl_data_query (1 calls)
       25ms - infer:wait (506 calls)
        0   - module_to_def (10 calls)
        0   - source_file_to_def (1 calls)
       10ms - trait_solve::wait (554 calls)

@lnicola lnicola mentioned this issue Nov 8, 2021
Closed
3 tasks
@jhgg jhgg mentioned this issue Nov 23, 2021
Closed
@Veykril
Copy link
Member

Veykril commented Dec 4, 2021

Closing this as the cause for this specific issue has been addressed again mainly and completion performance is tracked in another issue.

@Veykril Veykril closed this as completed Dec 4, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
A-perf performance issues Broken Window Bugs / technical debt to be addressed immediately C-bug Category: bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@lnicola @Veykril @petr-tik