"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.

[DanTup]

I added more logging to the server and reproduced the issue:

(16:05:35.359)
1714665935359:Info:calling _createAnalysisContexts
1714665935378:Info:BUILDING ANALYSIS CONTEXTS
1714665935378:Info:destroying old contexts
1714665935378:Info:finished destroying old contexts
(16:05:35.536)
1714665935536:Info:Running pub upgrade!
(16:06:02.129)
1714665962129:Info:Finished running pub upgrade
1714665962129:Info:  pluginFolder = C::\Users\danny\AppData\Local\.dartServer\.plugin_manager\723cb7b2bec3011e09cd16421250ff7a\analyzer_plugin
  exitCode = 0
  stdout = Resolving dependencies...
  _fe_analyzer_shared 67.0.0 (68.0.0 available)
  analyzer 6.4.1 (6.5.0 available)
  custom_lint 0.5.7 (0.6.4 available)
No dependencies changed.
3 packages have newer versions incompatible with dependency constraints.
Try `dart pub outdated` for more information.

  stderr = 

1714665962899:Noti:{"event"::"server.status","params"::{"analysis"::{"isAnalyzing"::true}}}

It appears the issue here is that for plugins, we end up calling pub using Process.runSync which blocks until it completes. This came up before in #49934 where there's no internet connection.

Indeed, if I run pub upgrade in that folder myself, it does frequently hang for 30s. What's odd is that all of the output has already been written, the process just takes a long time to finish:

If I run it with -v then it's writing output for a long time but I'm not sure if it's just buffered and appearing slowly, or if this output is what's happening (I feel like the solve wouldn't have completed if these were during the hang at the end):

IO  : HTTP GET https://pub.dev/api/packages/stack_trace
    | Accept: application/vnd.pub.v2+json
    | X-Pub-OS: windows
    | X-Pub-Command: upgrade
    | X-Pub-Session-ID: 215D5220-86EE-4365-A154-DF8B3A67DC5C
    | user-agent: Dart pub 3.3.0
IO  : Attempt #6 for fetching versions for "stack_trace" from "https://pub.dev/api/packages/stack_trace"
IO  : HTTP GET https://pub.dev/api/packages/stream_channel
    | Accept: application/vnd.pub.v2+json
    | X-Pub-OS: windows
    | X-Pub-Command: upgrade
    | X-Pub-Session-ID: 215D5220-86EE-4365-A154-DF8B3A67DC5C
    | user-agent: Dart pub 3.3.0
IO  : Attempt #7 for fetching versions for "stream_channel" from "https://pub.dev/api/packages/stream_channel"
IO  : HTTP GET https://pub.dev/api/packages/stack_trace
    | Accept: application/vnd.pub.v2+json
    | X-Pub-OS: windows
    | X-Pub-Command: upgrade
    | X-Pub-Session-ID: 215D5220-86EE-4365-A154-DF8B3A67DC5C
    | user-agent: Dart pub 3.3.0
IO  : Attempt #7 for fetching versions for "stack_trace" from "https://pub.dev/api/packages/stack_trace"
IO  : HTTP GET https://pub.dev/api/packages/test_api
    | Accept: application/vnd.pub.v2+json
    | X-Pub-OS: windows
    | X-Pub-Command: upgrade
    | X-Pub-Session-ID: 215D5220-86EE-4365-A154-DF8B3A67DC5C
    | user-agent: Dart pub 3.3.0
IO  : Attempt #7 for fetching versions for "test_api" from "https://pub.dev/api/packages/test_api"
IO  : HTTP GET https://pub.dev/api/packages/boolean_selector
    | Accept: application/vnd.pub.v2+json
    | X-Pub-OS: windows
    | X-Pub-Command: upgrade
    | X-Pub-Session-ID: 215D5220-86EE-4365-A154-DF8B3A67DC5C
    | user-agent: Dart pub 3.3.0
IO  : Attempt #7 for fetching versions for "boolean_selector" from "https://pub.dev/api/packages/boolean_selector"

Unfortunately although it seems to making many attempts for something here, it doesn't contain any information why (are the requests failing?).

So I guess there are two issues here - the known issue that the server startup is blocked on network access for Pub, but also it seems like something is wrong for Pub to be hanging for ~30s when it appears to have completed.

I'll file an issue in pub about the latter (edit: opened dart-lang/pub#4256).

[nank1ro]

@DanTup aren't the dependencies cached?
What I mean is, why every time the analyzer starts does it need to do API calls to pub.dev?

[DanTup]

It turns out the issue here was an unclosed HttpClient with keepalives enabled that could cause dart pub upgrade to sometimes "hang" for 30s when the process completed (see dart-lang/pub#4256 (comment)).

That issue has been recently fixed (in dartdev) and cherry-picked to beta (#55402).

As part of the analyzers plugin changes we should ensure we don't block like this on running external processes. In the short-term, I'm going to open a change to at least make this process execution visible in the instrumentation log to make it easier to know when this is the issue.

@DanTup aren't the dependencies cached?
What I mean is, why every time the analyzer starts does it need to do API calls to pub.dev?

The analyzer isn't calling Pub directly here, it's running dart pub get (in a generated project that runs the plugin). Pub has its own handling to make this fast, but unfortunately this bug wasn't helped by that. There's certainly room for improvement here, but plugins are currently unsupported and should be used understanding that.

Closing this issue as the main issue here has been resolved (as of current beta). There's still #49934 open tracking that plugin support currently depends on network access.