Stream: t-compiler/rust-analyzer

Topic: Poor type inference performance on chained method calls


Jonas Schievink [he/him] (Oct 06 2020 at 17:07, on Zulip):

I noticed that type inference for r-a's on_request method shows up in profiles a lot:

                 9870ms - infer:wait @ on_request
                     9870ms - infer_query
                            0ms - body_with_source_map_query (1 calls)
                            0ms - crate_def_map:wait (560 calls)
                            0ms - generic_params_query (43 calls)
                         9824ms - trait_solve_query (337 calls)

It contains a lot of chained method calls, and rustc has historically had problems with that. Maybe chalk does too?

matklad (Oct 06 2020 at 17:11, on Zulip):

Not only rustc: kotlinc OOMs on IntelliJ Rust here: https://github.com/intellij-rust/intellij-rust/blob/master/src/main/kotlin/org/rust/ide/formatter/impl/spacing.kt#L35-L36

detrumi (Oct 06 2020 at 20:07, on Zulip):

Interesting! Would love to have a repro so we can use it as a chalk benchmark, but that might be hard with the amount of types involved

detrumi (Oct 06 2020 at 20:10, on Zulip):

Simply chaining some method calls does not do the trick, but maybe there's some blowup somewhere with all the type parameters and callbacks

Jonas Schievink [he/him] (Oct 06 2020 at 20:19, on Zulip):

Oh, every single method call in the chain ends with a ?, that might explain it

Jonas Schievink [he/him] (Oct 06 2020 at 20:20, on Zulip):

There aren't really many type params involved, and no deeply nested types should be created by this, but I can see why all the ? chaining might be bad

Jonas Schievink [he/him] (Oct 06 2020 at 20:28, on Zulip):

Hmm, so here's a more detailed profile:

                 7328ms - infer:wait @ on_request
                     7328ms - infer_query
                          198ms - trait_solve_query @ Debug
                                0ms - crate_def_map:wait (64 calls)
                                0ms - generic_params_query (4 calls)
                                0ms - impl_datum (1 calls)
                                0ms - item_tree_query (16 calls)
                                1ms - parse_macro_query (17 calls)
                              196ms - ???
                          181ms - trait_solve_query @ Debug
                          184ms - trait_solve_query @ Debug
                          178ms - trait_solve_query @ Debug
                          183ms - trait_solve_query @ Debug
                          179ms - trait_solve_query @ Debug
                          181ms - trait_solve_query @ Debug
                          179ms - trait_solve_query @ Debug
                          180ms - trait_solve_query @ Debug
                          179ms - trait_solve_query @ Debug
                          181ms - trait_solve_query @ Debug
                          179ms - trait_solve_query @ Debug
                          181ms - trait_solve_query @ Debug
                          182ms - trait_solve_query @ Debug
                          182ms - trait_solve_query @ Debug
                          179ms - trait_solve_query @ Debug
                          183ms - trait_solve_query @ Debug
                          180ms - trait_solve_query @ Debug
                          185ms - trait_solve_query @ Debug
                          179ms - trait_solve_query @ Debug
                          181ms - trait_solve_query @ Debug
                          178ms - trait_solve_query @ Debug
                          180ms - trait_solve_query @ Debug
                          181ms - trait_solve_query @ Debug
                          180ms - trait_solve_query @ Debug
                          182ms - trait_solve_query @ Debug
                          182ms - trait_solve_query @ Debug
                          179ms - trait_solve_query @ Debug
                          181ms - trait_solve_query @ Debug
                          181ms - trait_solve_query @ Debug
                          184ms - trait_solve_query @ Debug
                          181ms - trait_solve_query @ Debug
                          183ms - trait_solve_query @ Debug
                          181ms - trait_solve_query @ Debug
                          184ms - trait_solve_query @ Debug
                          179ms - trait_solve_query @ Debug
                          183ms - trait_solve_query @ Debug
                          180ms - trait_solve_query @ Debug
                          180ms - trait_solve_query @ Debug
                            0ms - body_with_source_map_query (1 calls)
                            0ms - crate_def_map:wait (542 calls)
                            0ms - generic_params_query (39 calls)
                          225ms - trait_solve_query (293 calls)

I guess all the time is spent proving that the request parameters implement Debug?

detrumi (Oct 06 2020 at 20:30, on Zulip):

Probably the Debug bound here:

    pub(crate) fn on<R>(
        &mut self,
        f: fn(GlobalStateSnapshot, R::Params) -> Result<R::Result>,
    ) -> Result<&mut Self>
    where
        R: lsp_types::request::Request + 'static,
        R::Params: DeserializeOwned + Send + fmt::Debug + 'static,
        R::Result: Serialize + 'static,
    {
Jonas Schievink [he/him] (Oct 06 2020 at 20:31, on Zulip):

yeah

Jonas Schievink [he/him] (Oct 06 2020 at 20:33, on Zulip):

I feel like this shouldn't take that long? All the Debugs are derived on non-generic types, so I'd expect almost all of them to be proven immediately (unless I grossly misunderstand how the trait system works)

detrumi (Oct 06 2020 at 20:38, on Zulip):

There's some log output like impls_for_trait returned 4822 impls, but it's hard to judge the amount of work being done with such huge output

Jonas Schievink [he/him] (Oct 06 2020 at 20:41, on Zulip):

More verbose logs look like this:

  185ms - trait_solve_query @ <<SelectionRangeRequest as Request>::Params as Debug>
  180ms - trait_solve_query @ <<MatchingBrace as Request>::Params as Debug>
  182ms - trait_solve_query @ <<MemoryUsage as Request>::Params as Debug>
  182ms - trait_solve_query @ <<AnalyzerStatus as Request>::Params as Debug>
  177ms - trait_solve_query @ <<SyntaxTree as Request>::Params as Debug>
  188ms - trait_solve_query @ <<ExpandMacro as Request>::Params as Debug>

It seems like it might just be doing a bunch of work for every single Debug impl?

detrumi (Oct 06 2020 at 20:51, on Zulip):

Yeah, it might be searching all types in scope to check for possible answers there

detrumi (Oct 06 2020 at 20:51, on Zulip):

starting to look more like a bug than a perf problem

Florian Diebold (Oct 07 2020 at 07:31, on Zulip):

it's probably the same problem that slows Diesel down, which has been waiting on https://github.com/rust-lang/chalk/pull/401 to be fixed

Last update: Jul 29 2021 at 09:45UTC