Stream: t-compiler/wg-rls-2.0

Topic: cargo check issue


matklad (Jan 27 2020 at 20:43, on Zulip):

@Emil Lauridsen I've finally reproduced the "rust analyzer is suuuper slow and runs cargo check" issue

matklad (Jan 27 2020 at 20:43, on Zulip):

For me, it happens on the stdarch crate, if I hack cache.rs

matklad (Jan 27 2020 at 20:44, on Zulip):

Looks like cargo check tries to check dependencies (quickcheck in particular), and looks like it might be related to build scripts

Emil Lauridsen (Jan 27 2020 at 21:59, on Zulip):

I have a hunch we might be overwhelming the main thread with progress updates, as they get a little spammy when only the current crate is being checked. Cargo reports each crate even if no work is being done for the crate, so we might want to denounce the progress events.
If you can reliably reproduce you can give my cargo-slowdown branch a go and see if the RA_PROFILE numbers say something interesting

Laurențiu Nicola (Jan 27 2020 at 22:19, on Zulip):

One thing I noticed is that the "cargo check" message in the status bar might be displayed longer than the time it takes cargo check to run

Laurențiu Nicola (Jan 27 2020 at 22:22, on Zulip):

Could the progress notifications be delayed by the other work RA is doing?

matklad (Jan 27 2020 at 22:50, on Zulip):

I don’t think the problem is message flooding, I hunk the problem is
repeatedly re-checking dependencies.

Laurențiu Nicola (Jan 27 2020 at 22:54, on Zulip):

It might be a combination of things. I never saw it check too much or not finish at all, but it does appear to take longer than it should

Laurențiu Nicola (Jan 27 2020 at 22:54, on Zulip):

Like 2 seconds or so, while cargo check runs instantly

Laurențiu Nicola (Jan 27 2020 at 22:57, on Zulip):

Oh

Laurențiu Nicola (Jan 27 2020 at 22:57, on Zulip):

It's doing some unbuffered reads

Laurențiu Nicola (Jan 27 2020 at 22:57, on Zulip):

Ouch

Laurențiu Nicola (Jan 27 2020 at 22:59, on Zulip):

pasted image

Laurențiu Nicola (Jan 27 2020 at 22:59, on Zulip):

It might be the output of cargo metadata, but I'm not sure

Laurențiu Nicola (Jan 27 2020 at 22:59, on Zulip):

There's a lot of those

matklad (Jan 27 2020 at 23:02, on Zulip):

Fascinating!

Laurențiu Nicola (Jan 27 2020 at 23:04, on Zulip):

TIL pasting a lot of text makes mutter hang

Laurențiu Nicola (Jan 27 2020 at 23:14, on Zulip):

Yeah, so that's the pipe with the output of cargo check

Laurențiu Nicola (Jan 27 2020 at 23:31, on Zulip):

Filed a PR, but it's just as slow as before :(

Laurențiu Nicola (Jan 27 2020 at 23:58, on Zulip):

Oh, there's a 300 ms timer on the client

Laurențiu Nicola (Jan 27 2020 at 23:58, on Zulip):

That's why it seems to take so long :unamused:

Emil Lauridsen (Jan 28 2020 at 09:48, on Zulip):

I don’t think the problem is message flooding, I hunk the problem is
repeatedly re-checking dependencies.

Cargo doesn't actually re-check dependencies if they haven't changed, it just reports that the package exists and that's where we are in the progress. It uses the same message format though. But upon closer look it also reports if the package is "fresh", e.g. up to date, so we could probably skip reporting fresh packages. Opening a PR shortly

Laurențiu Nicola (Jan 28 2020 at 09:56, on Zulip):

We should also avoid duplicate reports. I didn't notice any difference, but it seems like a good idea to reduce the LSP traffic

Laurențiu Nicola (Jan 28 2020 at 11:12, on Zulip):

But I still don't understand why it seems to take longer in Code than from the command line. My test is pressing Ctrl-S without making any changes in a small project with a hefty amount of dependencies.

Laurențiu Nicola (Jan 28 2020 at 11:13, on Zulip):

I suspect it's just a display issue (the notifications take too much time to be processed), but it might be worth adding some logging code to be sure.

Laurențiu Nicola (Jan 28 2020 at 11:15, on Zulip):

At least it's not burning CPU. htop reports an extra 20 ms of CPU time used by the server when pressing Ctrl-S once.

matklad (Jan 28 2020 at 12:46, on Zulip):

pasted image

matklad (Jan 28 2020 at 12:46, on Zulip):

looks like we might have more concurrent rustc than we want...

Laurențiu Nicola (Jan 28 2020 at 12:49, on Zulip):

Are those two running instances of cargo check?

Laurențiu Nicola (Jan 28 2020 at 12:51, on Zulip):

You should make sure to not run it twice -- that can happen if you save twice in a row.

matklad (Jan 28 2020 at 12:52, on Zulip):

I have auto-save on 100ms

Laurențiu Nicola (Jan 28 2020 at 12:53, on Zulip):

The code tries to kill the one that's already running, but not too hard

Laurențiu Nicola (Jan 28 2020 at 12:53, on Zulip):

So it might spawn another one while it's still running

Laurențiu Nicola (Jan 28 2020 at 12:58, on Zulip):

There are some other things that could trigger rebuilding, like different RUSTFLAGS. That can happen if you set them in your .profile, since Code won't read it. Picking the wrong manifest might also explain it, although I didn't see it happen.

Laurențiu Nicola (Jan 28 2020 at 13:01, on Zulip):

Maybe we should add a "submit bug report" feature that saves things like the platform, environment variables (for both the server and in a shell), the output of cargo metadata and so on :pensive:.

Florian Diebold (Jan 28 2020 at 13:33, on Zulip):

could we wait until the canceled one is finished before we start a new check?

Florian Diebold (Jan 28 2020 at 13:35, on Zulip):

for the rebuilding problem, having a different target folder would help, though I really like being able to cargo check on the command line (or using emacs' cargo integration) and getting instant results because it already ran

Florian Diebold (Jan 28 2020 at 13:36, on Zulip):

though admittedly that's kind of a workaround for the fact that I don't get a global error list from the LSP :thinking: (I think VS Code has that, right?)

Emil Lauridsen (Jan 28 2020 at 13:37, on Zulip):

The duplicate checks might have to do with the order of drops, give me a minute

matklad (Jan 28 2020 at 13:38, on Zulip):

though admittedly that's kind of a workaround for the fact that I don't get a global error list from the LSP

We actually should move away from a global list for cargo check. Rather, we should only check the crates which are currently opened. Hacking on ra_syntax with cargo check enabled is pretty painful, b/c it rebulids everyhing

matklad (Jan 28 2020 at 13:38, on Zulip):

but yeah, the core problem is that it does seem to rebuilds the deps in this case

Emil Lauridsen (Jan 28 2020 at 13:39, on Zulip):

It rebuilds dependants yes, not dependencies, unless something is wonky with target

Emil Lauridsen (Jan 28 2020 at 13:40, on Zulip):

e.g the things that depend on the crate you're editing if they're in the same workspace

Laurențiu Nicola (Jan 28 2020 at 13:41, on Zulip):

We could also check only the modified crate, but that's going to miss some errors and, more importantly, it might pick the wrong features and rebuild everything

Laurențiu Nicola (Jan 28 2020 at 13:41, on Zulip):

I ran into that in https://github.com/rust-analyzer/rust-analyzer/issues/1925

matklad (Jan 28 2020 at 13:41, on Zulip):

Ah, ok, there's many test targets in the workspace I am working on, that's why I see a ton of rustc

Emil Lauridsen (Jan 28 2020 at 13:43, on Zulip):

There's definitely something wrong with drop order as well, that results in not waiting for the first check to cancel before starting a new one, going to fix that too

std::Veetaha (Jan 28 2020 at 13:43, on Zulip):

@matklad if are you hacking with ra_syntax now, please let me know...

Laurențiu Nicola (Jan 28 2020 at 13:44, on Zulip):

I think self.watcher = WatchThread::new(&self.options, &self.workspace_root); is going to start a new thread without waiting for the previous one

Emil Lauridsen (Jan 28 2020 at 13:45, on Zulip):

@Laurențiu Nicola The drop impl cancels the running process and waits for it, but it is run after creating the new watch thread, which is an issues resulting in two cargo instances

matklad (Jan 28 2020 at 13:45, on Zulip):

@std::Veetaha no, I don't plant to touch ra_syntax in the nearset future

matklad (Jan 28 2020 at 13:46, on Zulip):

Actually the two cargo visible instances might be an artifact of how htop works

Emil Lauridsen (Jan 28 2020 at 13:46, on Zulip):

Actually the two cargo visible instances might be an artifact of how htop works

It might just be a second thread yea, but there is a theoretical bug anyways

Emil Lauridsen (Jan 28 2020 at 13:51, on Zulip):

New PR is up for the drop issue

Florian Diebold (Jan 28 2020 at 13:59, on Zulip):

We actually should move away from a global list for cargo check. Rather, we should only check the crates which are currently opened. Hacking on ra_syntax with cargo check enabled is pretty painful, b/c it rebulids everyhing

sure, I just meant global as in more than just the current file though ;)

Laurențiu Nicola (Jan 28 2020 at 14:05, on Zulip):

Yup, things are a little better after #2923

Emil Lauridsen (Jan 28 2020 at 14:08, on Zulip):

With regards to checking just the current crate it's a bit of "plague vs cholera": longer check times but error messages when you break something in a consumer crate. It would hurt some of my workflows a bit, but if we added a "run full check" command as well, it wouldn't be too bad

matklad (Jan 28 2020 at 14:10, on Zulip):

Yeah, I think this needs to be configurable. Probably something like:

Emil Lauridsen (Jan 28 2020 at 14:11, on Zulip):

There is some challenge to finding the correct Cargo.toml for a given source file, but that should be solvable.

Laurențiu Nicola (Jan 28 2020 at 14:12, on Zulip):

@Emil Lauridsen We might also want to use package_id instead of target.name. The first one includes the version (and registry, unfortunately), but works for build scripts. target.name is build-script-build for those.

Laurențiu Nicola (Jan 28 2020 at 14:14, on Zulip):

I also made this change:

diff --git i/editors/code/src/status_display.ts w/editors/code/src/status_display.ts
index c75fddf9..191f356e 100644
--- i/editors/code/src/status_display.ts
+++ w/editors/code/src/status_display.ts
@@ -20,6 +20,7 @@ class StatusDisplay implements vscode.Disposable {
     private i = 0;
     private statusBarItem: vscode.StatusBarItem;
     private command: string;
+    private spinner: string;
     private timer?: NodeJS.Timeout;

     constructor(command: string) {
@@ -28,6 +29,7 @@ class StatusDisplay implements vscode.Disposable {
             10,
         );
         this.command = command;
+        this.spinner = "";
         this.statusBarItem.hide();
     }

@@ -37,11 +39,8 @@ class StatusDisplay implements vscode.Disposable {
         this.timer =
             this.timer ||
             setInterval(() => {
-                if (this.packageName) {
-                    this.statusBarItem!.text = `${this.frame()} cargo ${this.command} [${this.packageName}]`;
-                } else {
-                    this.statusBarItem!.text = `${this.frame()} cargo ${this.command}`;
-                }
+                this.spinner = this.frame();
+                this.refreshText();
             }, 300);

         this.statusBarItem.show();
@@ -65,6 +64,14 @@ class StatusDisplay implements vscode.Disposable {
         this.statusBarItem.dispose();
     }

+    refreshText() {
+        if (this.packageName) {
+            this.statusBarItem!.text = `${this.spinner} cargo ${this.command} [${this.packageName}]`;
+        } else {
+            this.statusBarItem!.text = `${this.spinner} cargo ${this.command}`;
+        }
+    }
+
     handleProgressNotification(params: WorkDoneProgressBegin | WorkDoneProgressReport | WorkDoneProgressEnd) {
         switch (params.kind) {
             case 'begin':
@@ -74,6 +81,7 @@ class StatusDisplay implements vscode.Disposable {
             case 'report':
                 if (params.message) {
                     this.packageName = params.message;
+                    this.refreshText();
                 }
                 break;

It keeps the spinner refreshing on a timer, but updates the package name when it changes. It feels a bit nicer, but might be slower during the initial analysis.

Laurențiu Nicola (Jan 28 2020 at 17:46, on Zulip):

Ah, another issue here is that cargo only tells us when an artifact finishes, not when it starts. So the crate we display in the status bar might be the one that just finished, not the one that's being checked.

matklad (Jan 29 2020 at 08:33, on Zulip):

FOUND IT!

matklad (Jan 29 2020 at 08:33, on Zulip):

https://github.com/rust-analyzer/rust-analyzer/commit/b8245e47e98ee4d287087f10a0d493bdc3964951

matklad (Jan 29 2020 at 08:33, on Zulip):

we were scheduling diagnostics computation on the main loop

matklad (Jan 29 2020 at 08:33, on Zulip):

naturally, if the main loop computes diagnostics, there's nothing to cancel it

Emil Lauridsen (Jan 29 2020 at 08:34, on Zulip):

we were scheduling diagnostics computation on the main loop

Oh god. that's horrible

Emil Lauridsen (Jan 29 2020 at 08:34, on Zulip):

great job finding it

matklad (Jan 29 2020 at 08:34, on Zulip):

it was actually easy to find, once I've got back to the situation where it's easy to reproduce

matklad (Jan 29 2020 at 08:35, on Zulip):

basically,

fn loop_turn(
    ...
) -> Result<()> {
    eprintln!("event = {:?}", event);
    let _p = ra_prof::print_time("event");

was all I used for debugging, the gun was smoking:

event = AddDiagnostic("file:///home/matklad/projects/stdarch/crates/core_arch/src/x86/mod.rs", DiagnosticWithFixes { diagnostic: Diagnostic { range: Range { start: Position { line: 354, character: 0 }, end: Position { line: 354, character: 56 } }, severity: Some(Error), code: Some(String("E0545")), source: Some("rustc"), message: "incorrect \'issue\'", related_information: None, tags: None }, suggested_fixes: [] })
event: 933.389429ms
Emil Lauridsen (Jan 29 2020 at 08:35, on Zulip):

oh boy

Emil Lauridsen (Jan 29 2020 at 08:36, on Zulip):

thank god it's something stupid, that's fairly easy to fix

matklad (Jan 29 2020 at 08:36, on Zulip):

Also, I have a confession to make: I can't use logs for debugging :-(

In theory, one should not recompile the code and just run with appropirate log level and see the problem.

In practice, it is soooo much easier for me to insert a printf than to figure out how to filter out the messages I need

Emil Lauridsen (Jan 29 2020 at 08:38, on Zulip):

I know that feeling very well

matklad (Jan 29 2020 at 08:39, on Zulip):

Also, we should probably log::error!() if turn_start.elapsed() >= 250ms, I though we were doing that actually

Edwin Cheng (Jan 29 2020 at 08:39, on Zulip):

@maklad What is the procedure of your debug steps ? I have the same problem for debug this kind of thing in RA.

matklad (Jan 29 2020 at 08:40, on Zulip):

One day, we should do if loop_start.elapsed() > 16ms { panic!("zero tolerance for lags") }....

matklad (Jan 29 2020 at 08:41, on Zulip):

@Edwin Cheng good question! Let me write this to the docs/dev once I get to work place...

matklad (Jan 29 2020 at 09:21, on Zulip):

Also, let me cc @David Barsky on the https://rust-lang.zulipchat.com/#narrow/stream/185405-t-compiler.2Fwg-rls-2.2E0/topic/cargo.20check.20issue/near/186865368 and https://github.com/sebasmagri/env_logger/issues/144, just to plant these ideas into your head for the tracing thing

bjorn3 (Jan 29 2020 at 09:29, on Zulip):

One day, we should do if loop_start.elapsed() > 16ms { panic!("zero tolerance for lags") }....

That would be horrible on very slow computers, or if you paused ra for a bit of time during debugging though. It did better be disableable.

Laurențiu Nicola (Jan 29 2020 at 10:16, on Zulip):

What about people with 240 Hz displays? :stuck_out_tongue_wink: Oof. I even looked at that code, but thought that "publishing" diagnostics is okay. Actually, I'm not even sure what the problem is.

matklad (Jan 29 2020 at 10:20, on Zulip):

handlers::publish_diagnostics also computes diagnostics

Laurențiu Nicola (Jan 29 2020 at 10:21, on Zulip):

Ah, the Analysis::diagnostics call?

matklad (Jan 29 2020 at 10:21, on Zulip):

yup

Laurențiu Nicola (Jan 29 2020 at 10:22, on Zulip):

Yeah, that's.. easy to miss.

matklad (Jan 29 2020 at 13:47, on Zulip):

Dumped my debugging workflows to https://github.com/rust-analyzer/rust-analyzer/pull/2940#issuecomment-579761669

Nothing to smart, just stick eprintlns everywhere and either drive through cargo test (good case) or cargo xtask install --server (slow case).

David Barsky (Jan 29 2020 at 14:11, on Zulip):

@matklad yowza! Glad you figured that one out :)! I'm going to cc Eliza on that issue as I think that'd be absolutely up her wheelhouse and the 35 minute compile times she sees on linkerd2-proxy.

David Barsky (Jan 29 2020 at 14:20, on Zulip):

For the module/line number filtering: we absolutely have the infrastructure for complex filters (c.f. https://docs.rs/tracing-subscriber/0.2.0-alpha.4/tracing_subscriber/filter/struct.EnvFilter.html#examples) and support for regexes/line numbers, which is being documented in https://github.com/tokio-rs/tracing/pull/368/. i'm mostly unsure how that should be hooked up to an IDE.

Last update: Sep 22 2020 at 02:45UTC