Spurious query recomputations during completion

[matklad]

See #8746 (comment)

I think at least to_fragment_kind function causes extra deps on syntax. SHort circuting that gives the following output:

    9ms - SourceBinder::to_module_def
        9ms - crate_def_map:wait
            3ms - item_tree_query (1 calls)
            5ms - ???
   12ms - descend_into_macros
       12ms - Semantics::analyze_impl
            8ms - infer:wait @ name
                8ms - infer_query
                    8ms - deref
                        8ms - deref_by_trait
                            8ms - trait_solve::wait
                                1ms - impl_data_query (123 calls)
                                7ms - ???

One item_tree_query is good. 123 impl_dta_queries is not so good, there's something else in here!

[matklad]

@jonas-schievink do you feel like debugging more of the salsa dep issues? :)

[jonas-schievink]

I have a fix for to_fragment_kind (I hope), but no repro

[jonas-schievink]

opened #8776 for now

[matklad]

Current status:

running 1 test
workspace loading: 336.01ms
initial: 5.99s
change: 34.16µs
cpu profiling is disabled, uncomment `default = [ "cpu_profiler" ]` in Cargo.toml to enable.
   10ms - SourceBinder::to_module_def
       10ms - crate_def_map:wait
            3ms - item_tree_query (1 calls)
            6ms - ???
   21ms - descend_into_macros
       21ms - Semantics::analyze_impl
           14ms - infer:wait @ name
               14ms - infer_query
                   13ms - deref
                       13ms - deref_by_trait
                           13ms - trait_solve::wait
                                4ms - impl_data_query (241 calls)
                                8ms - ???
                    0ms - crate_def_map:wait (36 calls)
                    0ms - deref (5 calls)
                    0ms - resolve_obligations_as_possible (3 calls)
                    0ms - trait_solve::wait (5 calls)
            0ms - SourceBinder::to_module_def (1 calls)
            0ms - body_with_source_map_query (1 calls)
            0ms - crate_def_map:wait (2 calls)
            0ms - impl_data_query (1 calls)
            5ms - parse_macro_expansion (195 calls)
   31ms - import_on_the_fly @ sel
       25ms - import_assets::search_for_imports
           25ms - import_assets::search_for
               25ms - import_assets::path_applicable_imports
                   19ms - items_with_name @ Name: sel, crate: Exclude, assoc items: Some("hir"), limit: Some(40)
                       19ms - find_items
                           16ms - search_dependencies @ Query { query: "sel", lowercased: "sel", name_only: true, assoc_items_only: false, search_mode: Fuzzy, case_sensitive: false, limit: 40, exclude_import_kinds: {AssociatedItem} }
                               15ms - import_map_query (18 calls)
                            0ms - crate_def_map:wait (1 calls)
                    3ms - find_path_prefixed (43 calls)
                    2ms - get_name_definition (40 calls)
                0ms - import_assets::scope_definitions (1 calls)
        0ms - crate_def_map:wait (1 calls)
        5ms - render_resolution (39 calls)
unqualified path completion: 108.78ms
change: 46.90µs
cpu profiling is disabled, uncomment `default = [ "cpu_profiler" ]` in Cargo.toml to enable.
   10ms - SourceBinder::to_module_def
       10ms - crate_def_map:wait
            3ms - item_tree_query (1 calls)
            6ms - ???
   14ms - descend_into_macros
       14ms - Semantics::analyze_impl
           10ms - infer:wait @ name
               10ms - infer_query
                   10ms - deref
                       10ms - deref_by_trait
                           10ms - trait_solve::wait
                                1ms - impl_data_query (144 calls)
                                8ms - ???
                    0ms - crate_def_map:wait (35 calls)
                    0ms - deref (6 calls)
                    0ms - resolve_obligations_as_possible (3 calls)
                    0ms - trait_solve::wait (5 calls)
            0ms - SourceBinder::to_module_def (1 calls)
            0ms - body_with_source_map_query (1 calls)
            0ms - crate_def_map:wait (2 calls)
            0ms - impl_data_query (1 calls)
            2ms - parse_macro_expansion (141 calls)
    7ms - import_on_the_fly @ 
        7ms - import_assets::search_for_imports
            7ms - import_assets::search_for
                7ms - import_assets::trait_applicable_items
                    0ms - crate_def_map:wait (105 calls)
                    0ms - deref (2 calls)
                    0ms - find_path_prefixed (6 calls)
                    0ms - generic_params_query (69 calls)
                    1ms - get_name_definition (40 calls)
                    3ms - items_with_name (1 calls)
                    0ms - trait_solve::wait (52 calls)
                0ms - import_assets::scope_definitions (1 calls)
        0ms - Semantics::analyze_impl (1 calls)
dot completion: 52.42ms
test integrated_benchmarks::integrated_completion_benchmark ... ok

4ms - impl_data_query (241 calls) -- these seems spurious to me. I think we see them because impl_data_query creates an Expander, which needs AstIdMap, which depends on syntax.

[jonas-schievink]

hmm, AstIdMap shouldn't change though, maybe it's because the expander also calls Hygiene::new?

[matklad]

Seems to be fixed on master, submitted various small fixes in #9743.

Current status:

running 1 test
workspace loading: 11.20s
initial: 1.94s
change: 34.91µs
cpu profiling is disabled, uncomment `default = [ "cpu_profiler" ]` in Cargo.toml to enable.
  109ms - unqualified path completion
        6ms - parse_query @ FileId(175)
       11ms - SourceBinder::to_module_def
           11ms - crate_def_map:wait
                4ms - item_tree_query (1 calls)
                7ms - ???
            0   - relevant_crates (1 calls)
       15ms - descend_into_macros
           15ms - Semantics::analyze_impl
               10ms - infer:wait @ name
                   10ms - infer_query
                        9ms - deref
                            9ms - deref_by_trait
                                9ms - trait_solve::wait
                                    0   - impl_data_query (60 calls)
                                    9ms - ???
                        0   - crate_def_map:wait (35 calls)
                        0   - deref (2 calls)
                        0   - deref_by_trait (1 calls)
                        0   - resolve_obligations_as_possible (21 calls)
                        0   - trait_solve::wait (11 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)
                4ms - parse_macro_expansion (199 calls)
            0   - SourceBinder::to_module_def (2 calls)
       10ms - iterate_method_candidates
            0   - crate_def_map:wait (690 calls)
            0   - deref (1 calls)
            0   - generic_params_query (217 calls)
            4ms - render_method (27 calls)
            3ms - trait_solve::wait (71 calls)
       22ms - import_on_the_fly @ sel
           11ms - import_assets::search_for_imports
               11ms - import_assets::search_for
                   11ms - import_assets::path_applicable_imports
                        2ms - find_path_prefixed (46 calls)
                        2ms - get_name_definition (40 calls)
                        5ms - items_with_name (1 calls)
                    0   - import_assets::scope_definitions (1 calls)
            0   - crate_def_map:wait (1 calls)
           10ms - render_resolution (34 calls)
        0   - Semantics::analyze_impl (1 calls)
        0   - crate_def_map:wait (147 calls)
        0   - deref (1 calls)
        3ms - descend_into_macros (1 calls)
        0   - infer:wait (1 calls)
        0   - item::Builder::build (15 calls)
       25ms - parse_query (29 calls)
        6ms - render_resolution (333 calls)
        7ms - ???
change: 64.72µs
cpu profiling is disabled, uncomment `default = [ "cpu_profiler" ]` in Cargo.toml to enable.
   50ms - dot completion
        6ms - parse_query @ FileId(175)
       11ms - SourceBinder::to_module_def
           11ms - crate_def_map:wait
                4ms - item_tree_query (1 calls)
                7ms - ???
            0   - relevant_crates (1 calls)
       14ms - descend_into_macros
           14ms - Semantics::analyze_impl
               10ms - infer:wait @ name
                   10ms - infer_query
                        9ms - deref_by_trait
                            9ms - trait_solve::wait
                                0   - impl_data_query (60 calls)
                                9ms - ???
                        0   - crate_def_map:wait (34 calls)
                        0   - deref (3 calls)
                        0   - deref_by_trait (1 calls)
                        0   - resolve_obligations_as_possible (23 calls)
                        0   - trait_solve::wait (11 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)
                3ms - parse_macro_expansion (170 calls)
            0   - SourceBinder::to_module_def (2 calls)
        8ms - import_on_the_fly @ 
            8ms - import_assets::search_for_imports
                8ms - import_assets::search_for
                    8ms - import_assets::trait_applicable_items
                        0   - applicable_inherent_traits (1 calls)
                        0   - deref (1 calls)
                        1ms - get_name_definition (40 calls)
                        4ms - items_with_name (1 calls)
                        1ms - iterate_method_candidates (1 calls)
                    0   - import_assets::scope_definitions (1 calls)
            0   - Semantics::analyze_impl (1 calls)
        0   - Semantics::analyze_impl (3 calls)
        0   - crate_def_map:wait (59 calls)
        0   - deref (1 calls)
        3ms - descend_into_macros (1 calls)
        0   - item::Builder::build (13 calls)
        4ms - iterate_method_candidates (1 calls)
        0   - lang_item_query (1 calls)
        0   - trait_solve::wait (2 calls)
.

In the first case, 25ms - parse_query (29 calls) feels suspect, but I convinced myself its ok in 0875601.

In the second case, impl_data_query (60 calls) is just imp datas for the changed file.

I don't know what 7ms - ??? and 9ms - ??? are. I suspect those are salsa re-validating queries.