Stream: t-compiler/wg-rls-2.0

Topic: Infinite loop when using rust-analyzer on rustc


Jonas Schievink (Apr 08 2020 at 18:36, on Zulip):

I'm currently noticing a problem where rust-analyzer stops responding to any queries and pegs a CPU core seemingly forever. This happens regularly when working on a new file I created in the rust compiler under src/librustc_mir/transform/dag_nrvo.rs. I've posted the contents here but I'm not sure that's enough to reproduce the issue.

Has anybody seen a hang like this before?

Jonas Schievink (Apr 08 2020 at 21:14, on Zulip):

Hmm, I wrote some more code and now the issue seems to be gone

matklad (Apr 08 2020 at 21:16, on Zulip):

might be https://github.com/rust-analyzer/rust-analyzer/issues/3861

Jonas Schievink (Apr 10 2020 at 21:39, on Zulip):

Still seems to be an issue, unfortunately (as of commit 176f7f6)

Jonas Schievink (Apr 10 2020 at 21:43, on Zulip):

Not entirely sure how to reproduce the issue, or how to profile r-a, but running analysis-stats panics with this error:

thread 'main' panicked at 'no value set for FileTextQuery(FileId(9280))'

It also outputs a bunch of cyclic dependency errors (that don't seem to cause any issues so far)

Jonas Schievink (Apr 10 2020 at 22:56, on Zulip):

2958 textDocument/codeAction 132438ms

Jack Huey (Apr 11 2020 at 01:36, on Zulip):

(removed)

Jack Huey (Apr 11 2020 at 01:37, on Zulip):

(whoops)

Edwin Cheng (Apr 11 2020 at 10:06, on Zulip):

That analysis-stats panic might be https://github.com/rust-analyzer/rust-analyzer/issues/3888

Edwin Cheng (Apr 11 2020 at 10:22, on Zulip):

Submitted https://github.com/rust-analyzer/rust-analyzer/pull/3939 to fix that panic.

However, there is another panic related to Chalk ..

Jonas Schievink (May 07 2020 at 21:27, on Zulip):

I've narrowed this down to the "bad offset" crash that was reported a while ago. I've added a backtrace here: https://github.com/rust-analyzer/rust-analyzer/issues/4058#issuecomment-625500413

Jonas Schievink (May 07 2020 at 21:29, on Zulip):

It looks like r-a is still pegging 6 cores after the crash though, which makes it seem like there's more to this

Jonas Schievink (May 07 2020 at 22:24, on Zulip):

Now it froze the Electron renderer process. This code is just cursed.

Jonas Schievink (May 17 2020 at 13:53, on Zulip):

The plot thickens...

    341143ms - add_missing_impl_members_inner
            0ms - Semantics::analyze2 (3 calls)
        10164ms - crate_def_map:wait (82825723 calls)
           10ms - enum_data_query (10 calls)
            0ms - parse_query (1 calls)
        330968ms - ???

5+ minutes for this... is not normal, right?

matklad (May 17 2020 at 13:54, on Zulip):

definitely not

Jonas Schievink (May 17 2020 at 14:13, on Zulip):

Oh, I was editing in a MutVisitor when this happened, that trait has quite a few items (but way fewer than eg. Iterator).

Simon Vandel Sillesen (May 17 2020 at 14:21, on Zulip):

(deleted)

Jonas Schievink (May 17 2020 at 16:53, on Zulip):

Opened https://github.com/rust-analyzer/rust-analyzer/issues/4498 for further investigation

Jonas Schievink (May 17 2020 at 19:00, on Zulip):

Any idea why crate_def_map:wait takes over 100ms per invocation? Seems like it really shouldn't, once the def map is computed once.

matklad (May 17 2020 at 19:03, on Zulip):

I think it means either of the two:

Jonas Schievink (May 17 2020 at 19:04, on Zulip):

You mean verification as in checking that the input didn't change?

matklad (May 17 2020 at 19:05, on Zulip):

yup

Jonas Schievink (May 17 2020 at 21:08, on Zulip):

It looks like find_path is what takes most of the time here

Jonas Schievink (May 17 2020 at 21:42, on Zulip):

Querifying importable_locations_in_crate brought the entire ordeal down to 20 seconds

Jonas Schievink (May 17 2020 at 21:42, on Zulip):

Not sure if that's a good approach though

Jonas Schievink (May 17 2020 at 22:33, on Zulip):

Hmm, I feel like ra_prof sometimes wrongly attributes time spent somewhere. And here the indentation here looks weird (but the times kinda make sense?):

    20399ms - add_missing_impl_members_inner
            0ms - Semantics::analyze2 (3 calls)
            0ms - crate_def_map:wait (2038 calls)
            9ms - enum_data_query (10 calls)
        20366ms - find_path (347 calls)
        0ms - Semantics::analyze2 (4 calls)
        6ms - add_missing_impl_members_inner (1 calls)
matklad (May 17 2020 at 22:34, on Zulip):

sometimes wrongly attributes time spent somewhere.

I had this feeling as well, though I haven't dug into it

matklad (May 17 2020 at 22:35, on Zulip):

The indentation in the example seems ok?

matklad (May 17 2020 at 22:35, on Zulip):

3 outer functions are on the same level

matklad (May 17 2020 at 22:35, on Zulip):

nested funcitons are nested

matklad (May 17 2020 at 22:35, on Zulip):

(-) is the level of indent, not the number

matklad (May 17 2020 at 22:36, on Zulip):

find_path is also used by the auto-import machinery, right? I think I've seen it working surprisingly long, so I bet there's some stupid tihng hidden there

Jonas Schievink (May 17 2020 at 22:37, on Zulip):

matklad said:

(-) is the level of indent, not the number

Oh, okay. I thought the whitespace in the front was.

Jonas Schievink (May 17 2020 at 22:37, on Zulip):

Yeah it is

matklad (May 17 2020 at 22:38, on Zulip):

yeah, < aligned timings look weird. It looks much better if you don't have 20 seconds outliers

matklad (May 17 2020 at 22:39, on Zulip):

Wait, are you runing ra_profile with big cutoff?

Jonas Schievink (May 17 2020 at 22:39, on Zulip):

Yeah, RA_PROFILE='*>1000'

matklad (May 17 2020 at 22:39, on Zulip):

Ah, that explains why we collapse 347 calls

Jonas Schievink (May 17 2020 at 22:39, on Zulip):

I don't understand why 0ms calls are still showing up with that

matklad (May 17 2020 at 22:40, on Zulip):

we show one-level of 0ms calls, to make sure that everything is printed

matklad (May 17 2020 at 22:40, on Zulip):

Like, we skip the children, but we show first-level, to make it clear that the profiling acutlaly works

Jonas Schievink (May 17 2020 at 22:42, on Zulip):

Ah, okay. So probably I'm just misinterpreting the output and it's measuring correctly.

Jonas Schievink (May 17 2020 at 22:43, on Zulip):

Each find_path call still takes around 100ms, and there's a huge number of paths in the default impls, so that explains why it's still slow

Jonas Schievink (May 17 2020 at 22:44, on Zulip):

I think many of those are for the same item, maybe some more aggressive caching would help

Jonas Schievink (May 17 2020 at 22:46, on Zulip):
              173ms - QualifyPaths::get_substitution_inner
                  173ms - find_path
                       10ms - crate_def_map:wait (32769 calls)
                      122ms - find_importable_locations (16384 calls)
matklad (May 17 2020 at 22:50, on Zulip):

I think there are at least three wrong things here:

Jonas Schievink (May 17 2020 at 22:54, on Zulip):

One thing that the find_path code does is looking up a name in every module of every dependency, and in the current crate as well. That might explain the high query counts.

matklad (May 17 2020 at 23:02, on Zulip):

Yeah, that probably is bad

Florian Diebold (May 18 2020 at 07:29, on Zulip):

I originally had a query for this in the find_path PR, we removed it because it wasn't clear it was really necessary :grimacing:

Last update: May 29 2020 at 18:00UTC