"dart analyze" and analysis server sometimes hang for ~30seconds when analysis server plugins are enabled

[mraleph]

User @nank1ro reported they see 30s timings when analyzing https://github.com/nank1ro/flutter-shadcn-ui repo from command line using dart analyze. Doing dart analyze twice shows the same ~30s timings on both runs - which is unexpected. User is using M1 2020 Mac. They also report bad IDE experience where it takes multiple minutes to finish analysis on large projects.

I have asked them to purge ~/.dartServer and that changed the picture for CLI run: second run took only 2s, which is more inline with what I would have expected. This did not translate to IDE experience improvements - closing and reopening IDE (VS Code) still suffers from long initial analysis.

I wonder if the analysis cache got into some wrong state somehow? Is there a way to diagnose this?

/cc @scheglov @DanTup

Twitter thread is https://twitter.com/nank1ro/status/1785963202062237773

[DanTup]

If VS Code initial analysis is slow even after it's been analyzed before, it would be interesting to see a complete instrumentation log for that period.

@nank1ro

1. Open the project in VS Code
2. Press F1 to open the command palette
3. Run the Preferences: Open Workspace Settings command
4. Add "dart.analyzerInstrumentationLogFile": "logs/analyzer.txt",
5. Save the settings and restart VS Code
6. Wait for initial analysis to complete
7. Make a copy of that log file
8. Remove the log setting

Please also include:

• The Dart extension version in VS Code
• The SDK version you're using
• The has of the commit for https://github.com/nank1ro/flutter-shadcn-ui you're testing with
• Which OS/platform you're on (and whether it involves anything like WSL, remote workspaces, etc.)

[nank1ro]

analyzer-copy.txt
Dart extension version: v3.88.0
Dart SDK version: 3.3.4 (stable) (Tue Apr 16 19:56:12 2024 +0000) on "macos_arm64"
Commit hash: 23f1daa98b6f735838f842fdc5c4ba0d875ff81a branch: test/dart-analyzer
MacBook Pro M1, 2020 16 GB

[nank1ro]

I also recorded a video to showcase the problem
https://x.com/nank1ro/status/1786011479059099749

[DanTup]

@nank1ro thanks - taking a look. But could you confirm if the issue occurs if you disable the custom_lint plugin? There were some comments in another issue that some versions of it were causing perf issues:

• Dart Analyzer very slow/stuck #55281 (comment)
• Dart Analyzer very slow/stuck #55281 (comment)

I don't know the cause of those issues (including whether it's a custom_lint issue or analyzer issue), but it may help narrow down the issue.

[nank1ro]

I disabled custom_lint and become much faster. Maybe I should update it on flutter_solidart

[DanTup]

@nank1ro does "much faster" mean "faster but still quite slow" or did it solve the issue entirely?

I couldn't reproduce the issue but I wonder if we have different versions of some dependencies - are you able to provide a copy of the pubspec.lock files for both the main project and the example project (when in the "bad" state) so I can test with the same versions? It would be good to understand exactly why it causes a delay (from your log, it seems that there is an almost exactly 30 second delay before initial analysis starts).

[nank1ro]

The issue is solved. Now I activated again custom_lint then upgraded it from the version 0.5.7 to 0.6.4 and everything works smooth.
Thanks for all your help

[DanTup]

@nank1ro great, I'll close this then. I am still interested in your pubspec.locks if you can provide them though. I tried pinning custom_lint to 0.5.7 with your project but was still unable to reproduce the issue - I'd be interested in understanding exactly what the problem was (because perhaps the analysis server can handle it better even if the issue was a misbehaving plugin). Thanks!

[nank1ro]

files.zip

Here are the files.
I reverted the changes and the bug happens systematically to me.
Even the time dart analyze command became slow again with each execution, taking 30 seconds each time.

[DanTup]

Thanks! Unfortunately even with those files I don't seem to be able to repro the issue. I tried pinning analyzer with a dependency override to 5.12.0 suspecting maybe this upgrade of the package may be what fixed the problem. Everything is still very fast though - around 5-10s for a first analysis after I wipe out the .dartServer\.analysis-driver and only 2-3s in subsequent loads.

I also couldn't see any obvious paths in code where we might be waiting for plugins where the delay was in the logs here (around the time we're building analysis contexts). Maybe @scheglov or @bwilkerson have more ideas what could have gone wrong here (although it might not be worth spending too much effort on if plugin changes might mean changes to how these are loaded in future).

[mraleph]

@DanTup Here is what I get on Flutter stable:

╭─~/s/t/flutter-shadcn-ui ⟨main ✔⟩
╰─» time dart analyze
Analyzing flutter-shadcn-ui...         30.8s
No issues found!

________________________________________________________
Executed in   31.09 secs    fish           external
   usr time    4.29 secs    0.10 millis    4.29 secs
   sys time    0.84 secs    1.13 millis    0.84 secs

╭─~/s/t/flutter-shadcn-ui ⟨main ✔⟩ ⟨31s91ms⟩
╰─» time dart analyze
Analyzing flutter-shadcn-ui...         2.2s
No issues found!

________________________________________________________
Executed in    2.42 secs    fish           external
   usr time    3.38 secs    0.07 millis    3.38 secs
   sys time    0.64 secs    1.09 millis    0.64 secs

╭─~/s/t/flutter-shadcn-ui ⟨main ✔⟩
╰─» time dart analyze
Analyzing flutter-shadcn-ui...         29.2s
No issues found!

________________________________________________________
Executed in   29.42 secs    fish           external
   usr time    3.64 secs  102.00 micros    3.64 secs
   sys time    0.71 secs  694.00 micros    0.71 secs

╭─~/s/t/flutter-shadcn-ui ⟨main ✔⟩ ⟨29s419ms⟩
╰─» time dart analyze
Analyzing flutter-shadcn-ui...         2.4s
No issues found!

________________________________________________________
Executed in    2.67 secs    fish           external
   usr time    3.49 secs   75.00 micros    3.49 secs
   sys time    0.65 secs  405.00 micros    0.65 secs

╭─~/s/t/flutter-shadcn-ui ⟨main ✔⟩
╰─» time dart analyze
Analyzing flutter-shadcn-ui...         2.2s
No issues found!

________________________________________________________
Executed in    2.47 secs    fish           external
   usr time    3.38 secs    0.12 millis    3.38 secs
   sys time    0.65 secs    1.74 millis    0.65 secs

╭─~/s/t/flutter-shadcn-ui ⟨main ✔⟩
╰─» time dart analyze
Analyzing flutter-shadcn-ui...         2.2s
No issues found!

________________________________________________________
Executed in    2.44 secs    fish           external
   usr time    3.39 secs    0.12 millis    3.39 secs
   sys time    0.63 secs    2.15 millis    0.63 secs

╭─~/s/t/flutter-shadcn-ui ⟨main ✔⟩
╰─» time dart analyze
Analyzing flutter-shadcn-ui...         2.2s
No issues found!

________________________________________________________
Executed in    2.44 secs    fish           external
   usr time    3.38 secs    0.14 millis    3.38 secs
   sys time    0.64 secs    1.23 millis    0.64 secs

╭─~/s/t/flutter-shadcn-ui ⟨main ✔⟩
╰─» time dart analyze
Analyzing flutter-shadcn-ui...         30.4s
No issues found!

________________________________________________________
Executed in   30.62 secs    fish           external
   usr time    3.66 secs   64.00 micros    3.66 secs
   sys time    0.71 secs  964.00 micros    0.71 secs

This seems extremely strange - I just sit there at run the same command without changing any files and randomly analysis time skyrockets. Maybe analyzer folks can recognize the problem?

[DanTup]

@mraleph were you using the pubspec.lock's from above or a clean solve? I didn't realise it was this intermittent, I'll do some more testing.

Edit: Turns out I can repro this from the CLI using Stable dart (~30s reliably) but using a bleeding-edge build, it's around 5-10s. It's possible this is something that was already discovered and fixed, but I'll try to confirm.