Stream: t-compiler/wg-rls-2.0

Topic: Profiling RA in Vscode


Bastian Köcher (Aug 26 2019 at 14:09, on Zulip):

Hey, is there currently an easy way to profile RA when it runs inside as Vscode extension?
Completion taking huge amount of time and I would like too look into it :)

matklad (Aug 26 2019 at 14:11, on Zulip):

https://github.com/rust-analyzer/rust-analyzer/tree/master/docs/dev#profiling

matklad (Aug 26 2019 at 14:11, on Zulip):

Note that the first completion is expected to be slow, as we don't store analysis results to disk yet

matklad (Aug 26 2019 at 14:11, on Zulip):

subsequents completions should be more or less instant

Bastian Köcher (Aug 26 2019 at 14:13, on Zulip):

Where does it print the profiling output?

Bastian Köcher (Aug 26 2019 at 14:14, on Zulip):

When I have a workspace, will the first completion be slow in every crate or just for the whole workspace?

matklad (Aug 26 2019 at 14:15, on Zulip):

To stderr

matklad (Aug 26 2019 at 14:16, on Zulip):

it should be visible in the Output pane of vs code

matklad (Aug 26 2019 at 14:16, on Zulip):

When I have a workspace, will the first completion be slow in every crate or just for the whole workspace?

In the first crate it would be the slowest one, as it would need to analyse stdlib. First completions in other crates would be much faster, but still can trigger analysis of new crates

Bastian Köcher (Aug 26 2019 at 14:17, on Zulip):

So, I now had one completion and just tried again to get the same completion in the same file. It again takes some time :D

matklad (Aug 26 2019 at 14:18, on Zulip):

That does sound like a bug!

Bastian Köcher (Aug 26 2019 at 14:18, on Zulip):

And now I'm at 11% RAM(32GB) usage.

Bastian Köcher (Aug 26 2019 at 14:19, on Zulip):

Okay, when I write self. press ctrl + space it shows the result after some time

matklad (Aug 26 2019 at 14:19, on Zulip):

High RAM usage is sort of expected at the moment, unfortunatelly

Bastian Köcher (Aug 26 2019 at 14:19, on Zulip):

Second time ctrl + space the result is instant

matklad (Aug 26 2019 at 14:19, on Zulip):

could you show what RA_PROF gives?

Bastian Köcher (Aug 26 2019 at 14:19, on Zulip):

But if I remove the . and add the . again it takes again some time to build

Bastian Köcher (Aug 26 2019 at 14:20, on Zulip):

I have started vscode like: RA_PROFILE=* code

Bastian Köcher (Aug 26 2019 at 14:20, on Zulip):

But I don't see any profiling output in the output pane

matklad (Aug 26 2019 at 14:23, on Zulip):

pasted image

matklad (Aug 26 2019 at 14:23, on Zulip):

So that's the pane I am talking about

matklad (Aug 26 2019 at 14:23, on Zulip):

if it is empty, that could mean that you are using some very old version of rust-analyzer that doesn't have profilng enabled?

Bastian Köcher (Aug 26 2019 at 14:47, on Zulip):

I did now know that there are multiple outputs you can select at the right side :face_palm: Sorry!

Bastian Köcher (Aug 26 2019 at 14:48, on Zulip):
', /build/rust-analyzer-0c35d82329bc0952bd179ec37933c0955fd5ed26-vendor/salsa/src/runtime.rs:424:9
stack backtrace:
   0: std::sys_common::backtrace::print
   1: std::panicking::default_hook::{{closure}}
   2: std::panicking::default_hook
   3: std::panicking::rust_panic_with_hook
   4: std::panicking::begin_panic
   5: salsa::runtime::Runtime<DB>::report_unexpected_cycle
   6: ra_hir::ty::lower::<impl ra_hir::ty::Ty>::from_hir_path
   7: ra_hir::ty::lower::<impl ra_hir::ty::Ty>::from_hir
   8: ra_hir::ty::lower::type_for_def
   9: salsa::runtime::Runtime<DB>::execute_query_implementation
  10: salsa::derived::slot::Slot<DB,Q,MP>::read_upgrade
  11: salsa::derived::slot::Slot<DB,Q,MP>::read
  12: <salsa::derived::DerivedStorage<DB,Q,MP> as salsa::plumbing::QueryStorageOps<DB,Q>>::try_fetch
  13: ra_hir::ty::lower::<impl ra_hir::ty::Ty>::from_hir_path
  14: ra_hir::ty::lower::<impl ra_hir::ty::Ty>::from_hir
  15: ra_hir::ty::infer::infer_query
  16: salsa::runtime::Runtime<DB>::execute_query_implementation
  17: salsa::derived::slot::Slot<DB,Q,MP>::read_upgrade
  18: salsa::derived::slot::Slot<DB,Q,MP>::read
  19: <salsa::derived::DerivedStorage<DB,Q,MP> as salsa::plumbing::QueryStorageOps<DB,Q>>::try_fetch
  20: ra_hir::source_binder::SourceAnalyzer::new
  21: <ra_syntax::algo::visit::Vis<V,N,F> as ra_syntax::algo::visit::Visitor>::accept
  22: ra_ide_api::inlay_hints::get_inlay_hints
  23: <core::iter::adapters::flatten::Flatten<I> as core::iter::traits::iterator::Iterator>::next
  24: <alloc::vec::Vec<T> as alloc::vec::SpecExtend<T,I>>::from_iter
  25: std::panicking::try::do_call
  26: __rust_maybe_catch_panic
  27: ra_db::CheckCanceled::catch_canceled
  28: ra_ide_api::Analysis::inlay_hints
  29: ra_lsp_server::main_loop::handlers::handle_inlay_hints
  30: <F as threadpool::FnBox>::call_box
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
          0ms - infer_query
          0ms - main_loop_inner/loop-turn
thread '<unnamed>' panicked at 'Internal error, cycle detected:
- __SalsaDatabaseKey { kind: HirDatabaseStorage(type_for_def((TypeAlias(TypeAlias { id: TypeAliasId(12441) }), Types))) }

', /build/rust-analyzer-0c35d82329bc0952bd179ec37933c0955fd5ed26-vendor/salsa/src/runtime.rs:424:9
stack backtrace:
   0: std::sys_common::backtrace::print
   1: std::panicking::default_hook::{{closure}}
   2: std::panicking::default_hook
   3: std::panicking::rust_panic_with_hook
   4: std::panicking::begin_panic
   5: salsa::runtime::Runtime<DB>::report_unexpected_cycle
   6: ra_hir::ty::lower::<impl ra_hir::ty::Ty>::from_hir_path
   7: ra_hir::ty::lower::<impl ra_hir::ty::Ty>::from_hir
   8: ra_hir::ty::lower::type_for_def
   9: salsa::runtime::Runtime<DB>::execute_query_implementation
  10: salsa::derived::slot::Slot<DB,Q,MP>::read_upgrade
  11: salsa::derived::slot::Slot<DB,Q,MP>::read
  12: <salsa::derived::DerivedStorage<DB,Q,MP> as salsa::plumbing::QueryStorageOps<DB,Q>>::try_fetch
  13: ra_hir::ty::lower::<impl ra_hir::ty::Ty>::from_hir_path
  14: ra_hir::ty::lower::<impl ra_hir::ty::Ty>::from_hir
  15: ra_hir::ty::infer::infer_query
  16: salsa::runtime::Runtime<DB>::execute_query_implementation
  17: salsa::derived::slot::Slot<DB,Q,MP>::read_upgrade
  18: salsa::derived::slot::Slot<DB,Q,MP>::read
  19: <salsa::derived::DerivedStorage<DB,Q,MP> as salsa::plumbing::QueryStorageOps<DB,Q>>::try_fetch
  20: ra_hir::source_binder::SourceAnalyzer::new
  21: <ra_syntax::algo::visit::Vis<V,N,F> as ra_syntax::algo::visit::Visitor>::accept
  22: ra_ide_api::inlay_hints::get_inlay_hints
  23: <core::iter::adapters::flatten::Flatten<I> as core::iter::traits::iterator::Iterator>::next
  24: <alloc::vec::Vec<T> as alloc::vec::SpecExtend<T,I>>::from_iter
  25: std::panicking::try::do_call
  26: __rust_maybe_catch_panic
  27: ra_db::CheckCanceled::catch_canceled
  28: ra_ide_api::Analysis::inlay_hints
  29: ra_lsp_server::main_loop::handlers::handle_inlay_hints
  30: <F as threadpool::FnBox>::call_box
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
          1ms - infer_query
          0ms - main_loop_inner/loop-turn
thread '<unnamed>' panicked at 'Internal error, cycle detected:
- __SalsaDatabaseKey { kind: HirDatabaseStorage(type_for_def((TypeAlias(TypeAlias { id: TypeAliasId(12441) }), Types))) }
Bastian Köcher (Aug 26 2019 at 14:48, on Zulip):

Is this expected?

matklad (Aug 26 2019 at 14:49, on Zulip):

Not really. There's a known bug about not handling cycles properly, but I think it shouldn't be triggered for type aliass

Bastian Köcher (Aug 26 2019 at 16:21, on Zulip):

Sorry for the delay:

Bastian Köcher (Aug 26 2019 at 16:21, on Zulip):

https://pastebin.com/WR3rqdZX

Bastian Köcher (Aug 26 2019 at 16:25, on Zulip):

After removing and adding . I get this:
https://paste.ee/p/NNOvv

matklad (Aug 26 2019 at 16:26, on Zulip):

9549ms - trait_solve_query

yeah, seems like "chalk is slow" problem

matklad (Aug 26 2019 at 16:27, on Zulip):

I guess we should maybe put the fuel back in @Florian Diebold ?

Florian Diebold (Aug 26 2019 at 16:37, on Zulip):

:disappointed:

Florian Diebold (Aug 26 2019 at 16:37, on Zulip):

but yeah

Bastian Köcher (Aug 26 2019 at 17:12, on Zulip):

Okay :) No stress! Do you need the code?^^

Bastian Köcher (Aug 26 2019 at 17:44, on Zulip):

What is a sensible default value for the LRU cache size?

matklad (Aug 26 2019 at 18:06, on Zulip):

Default value is sensible enough. There’s no super huge gains to be had from larger LRU, I use twice the default just because

Last update: Nov 12 2019 at 15:40UTC