dart-lang / sdk

The Dart SDK, including the VM, JS and Wasm compilers, analysis, core libraries, and more.
https://dart.dev
BSD 3-Clause "New" or "Revised" License
10.07k stars 1.56k forks source link

Analyzer response to LSP requests extremely slow w/ high latency reported #56307

Open josephemorgan opened 1 month ago

josephemorgan commented 1 month ago

I'm intermittently having extremely slow dart analyzer performance with VS code around 10-15 times an hour.

A typical instance starts with me typing to fix an error or triggering autocomplete. When I do so, I get Loading... in the autocomplete pop-up, sometimes the VS Code status bar shows "Analyzing" with a spinner. While the analyzer is loading, error indicators in the editor window don't update (they'll report errors at locations that don't have errors) and autocomplete won't show anything. Sometimes, but not always, my editor will freeze completely until the analyzer unfreezes. The hangs usually last anywhere from 30 seconds to 3 minutes.

I suspect the issue might have something to do with how large the project is, or maybe there's something strange about our project configuration.

The analysis server diagnostics typically looks like this after freezing: image

I understand that "latency" means the server is busy and can't start handling a request, is there any way to determine what it's busy doing?

Please let me know what other information I can provide or what debugging steps I can take.

Dart Info:


If providing this information as part of reporting a bug, please review the information
below to ensure it only contains things you're comfortable posting publicly.

#### General info

- Dart 3.4.4 (stable) (Wed Jun 12 15:54:31 2024 +0000) on "windows_x64"
- on windows / "Windows 10 Enterprise" 10.0 (Build 22631)
- locale is en-US

#### Project info

- sdk constraint: '>=3.3.4 <4.0.0'
- dependencies: accordion, app_links, auto_size_text, badges, barcode_widget, cached_network_image, camera, carousel_slider, chewie, collection, community_charts_flutter, confetti, configurable_expansion_tile_null_safety, connectivity_plus, data_table_2, datetime_picker_formfield_new, device_info_plus, easy_debounce, email_validator, exif, file_picker, firebase_core, firebase_core_platform_interface, firebase_messaging, flutter, flutter_barcode_scanner, flutter_cache_manager, flutter_date_pickers, flutter_expandable_table, flutter_file_dialog, flutter_keyboard_visibility, flutter_local_notifications, flutter_quill, flutter_slidable, flutter_speed_dial, flutter_spinkit, flutter_svg, flutter_typeahead, flutter_uploader, flutter_video_info, geocoding, geolocator, google_maps_flutter, googleapis, hive, horizontal_data_table, http, image, image_gallery_saver, image_network, image_picker, infinite_scroll_pagination, intl, jiffy, keyboard_actions, latlong2, liquid_pull_to_refresh, logger, material_design_icons_flutter, material_symbols_icons, mime, modal_progress_hud_nsn, multi_dropdown, neat_periodic_task, open_filex, package_info_plus, path, path_drawing, path_provider, pdf, percent_indicator, permission_handler, phone_form_field, photo_view, pointer_interceptor, printing, provider, screenshot, scroll_to_index, scrollable_positioned_list, share_plus, shared_preferences, sliding_up_panel, super_tooltip, table_calendar, timeago, toggle_switch, transparent_image, tuple, universal_html, universal_io, url_launcher, uuid, vector_math, version, video_player, video_thumbnail, visibility_detector, wakelock_plus
- dev_dependencies: flutter_launcher_icons, flutter_lints, flutter_test, integration_test, pubspec_dependency_sorter
- elided dependencies: 1

#### Process info

|  Memory | CPU | Elapsed time | Command line |
| ------: | --: | -----------: | ------------ |
|   12 MB |  -- |              | dart.exe     |
| 2828 MB |  -- |              | dart.exe     |
|   34 MB |  -- |              | dart.exe     |
|   15 MB |  -- |              | dart.exe     |
|   68 MB |  -- |              | dart.exe     |
|  167 MB |  -- |              | dart.exe     |
|   95 MB |  -- |              | dart.exe     |

Flutter Doctor:

Doctor summary (to see all details, run flutter doctor -v):
[√] Flutter (Channel stable, 3.22.3, on Microsoft Windows [Version 10.0.22631.3880], locale en-US)
[√] Windows Version (Installed version of Windows is version 10 or higher)
[√] Android toolchain - develop for Android devices (Android SDK version 33.0.2)
[√] Chrome - develop for the web
[√] Visual Studio - develop Windows apps (Visual Studio Professional 2022 17.7.7)
[√] Android Studio (version 2024.1)
[√] VS Code (version unknown)
    X Unable to determine VS Code version.
[√] VS Code, 64-bit edition (version 1.91.1)
[√] VS Code (version 1.92.0-insider)
[√] Connected device (4 available)
[√] Network resources
dart-github-bot commented 1 month ago

Summary: The Dart analyzer in VS Code is experiencing intermittent slowness, causing delays in autocomplete, error reporting, and editor responsiveness. The issue occurs multiple times per hour and lasts for 30 seconds to 3 minutes. The user suspects the project size or configuration might be contributing to the problem.

bwilkerson commented 1 month ago

@DanTup In case you can help in terms of getting enough information to be able to determine the reason for the long analysis times.

DanTup commented 1 month ago

I understand that "latency" means the server is busy and can't start handling a request, is there any way to determine what it's busy doing?

Latency here is the time difference between use constructing a request to the analysis server (done in the VS Code extension) and the server starting to process it. It generally means the analysis server was busy (it's single threaded) although there is the possibility that the delay could be in the VS Code side (especially if it itself is hanging!) or affected by other VS Code extensions (since all extensions run single-threaded in a single Node process).

Temporarily enabling the analysis server instrumentation log might give some insight into what the server is doing during this period. The file can get very large and will contain contents of your files, so sharing these logs may be difficult, but if you can get a copy of one after this happens, we may be able to provide some idea of what to look for in it (in particular I wonder if something like a context rebuild is happening - something that can occur if a pubspec.yaml or package_config.json changes).

Sometimes, but not always, my editor will freeze completely until the analyzer unfreezes.

Is it only the editor that freezes when this happens, or the system in general? Have you ever been able to view Task Manager (or run code --status in a terminal) while this is happening? VS Code runs all extensions in another process to protect itself from any bad extensions ever hanging the editor (even if they're very slow or running infinite loops) so if VS Code is hanging, there might be something more.

The output of code --status might be useful when you have this project open (even when it's not hanging - although while hanging would be more useful). I notice you have 7 Dart processes in your list before - if you have multiple VS Code windows open, please do the same when running code --status so the stats of both are included.

josephemorgan commented 1 month ago

Latency here is the time difference between use constructing a request to the analysis server (done in the VS Code extension) and the server starting to process it. It generally means the analysis server was busy (it's single threaded) although there is the possibility that the delay could be in the VS Code side (especially if it itself is hanging!) or affected by other VS Code extensions (since all extensions run single-threaded in a single Node process).

Thank you for the info. I also use VSCode for dotnet and Angular development and haven't encountered the issue there, but it's possible that it's a dart specific plugin. Think all I've got installed is the official Dart plugin and the Dart Data Class Generator.

Temporarily enabling the analysis server instrumentation log might give some insight into what the server is doing during this period.

I'll do that today and update this issue with some logs.

Is it only the editor that freezes when this happens, or the system in general? Have you ever been able to view Task Manager (or run code --status in a terminal) while this is happening? VS Code runs all extensions in another process to protect itself from any bad extensions ever hanging the editor (even if they're very slow or running infinite loops) so if VS Code is hanging, there might be something more.

The editor freezing is relatively uncommon, seems like it only happens when I save a file, status bar say something along the lines of "saving and applying code actions". I've never had the system itself freeze, and whenever I've looked at the task manager during one of these episodes, I haven't noticed anything strange. Some high-ish CPU usage, but not like it's pegged at 100% or anything.

The output of code --status might be useful when you have this project open (even when it's not hanging - although while hanging would be more useful). I notice you have 7 Dart processes in your list before - if you have multiple VS Code windows open, please do the same when running code --status so the stats of both are included.

Here's that output, not hanging currently but I'll grab it again as soon as it is:

Version:          Code 1.91.1 (f1e16e1e6214d7c44d078b1f0607b2388f29d729, 2024-07-09T22:06:49.809Z)
OS Version:       Windows_NT x64 10.0.22631
CPUs:             Intel(R) Core(TM) i7-10750H CPU @ 2.60GHz (12 x 2592)
Memory (System):  31.76GB (12.17GB free)
VM:               0%
Screen Reader:    yes
Process Argv:     --crash-reporter-id 0ca3f427-aab5-4c5b-b043-89b5f1cceb7e
GPU Status:       2d_canvas:                              enabled
                  canvas_oop_rasterization:               enabled_on
                  direct_rendering_display_compositor:    disabled_off_ok
                  gpu_compositing:                        enabled
                  multiple_raster_threads:                enabled_on
                  opengl:                                 enabled_on
                  rasterization:                          enabled
                  raw_draw:                               disabled_off_ok
                  skia_graphite:                          disabled_off
                  video_decode:                           enabled
                  video_encode:                           enabled
                  vulkan:                                 disabled_off
                  webgl:                                  enabled
                  webgl2:                                 enabled
                  webgpu:                                 enabled

CPU %   Mem MB     PID  Process
    0      151   20420  code main
    0      110    1428  shared-process
    0      431   12092  extensionHost [1]
    0        4    3212       C:\WINDOWS\system32\cmd.exe /d /s /c ""c:\Users\morganj\.vscode\extensions\vscjava.vscode-gradle-3.15.0\lib\gradle-server.bat" 64097"
    0        6     632         C:\WINDOWS\system32\conhost.exe 0x4
    0       16   21588         "java.exe"  "-Dfile.encoding=UTF-8"    -classpath "c:\Users\morganj\.vscode\extensions\vscjava.vscode-gradle-3.15.0\lib\gradle-server.jar" com.github.badsyntax.gradle.GradleServer 64097
    0     2139   10052       C:\Users\morganj\fvm\versions\3.22.3\bin\cache\dart-sdk\bin\dart.exe language-server --protocol=lsp --client-id=VS-Code --client-version=3.92.0
    0        6   21648         C:\WINDOWS\system32\conhost.exe 0x4
    0       15   11664       java -Dfile.encoding=utf8 -jar c:\Users\morganj\.vscode\extensions\vscjava.vscode-gradle-3.15.0\lib\gradle-language-server.jar
    0        6    1492         C:\WINDOWS\system32\conhost.exe 0x4
    0       15   12484       C:\Users\morganj\fvm\versions\3.22.3\bin\cache\dart-sdk\bin\dart.exe devtools --machine --allow-embedding --dtd-uri ws://127.0.0.1:64047/9YLvBwARxGQndzcX
    0        6   20944         C:\WINDOWS\system32\conhost.exe 0x4
    0       79   12572       "C:\Program Files\Microsoft VS Code\Code.exe" "c:\Program Files\Microsoft VS Code\resources\app\extensions\json-language-features\server\dist\node\jsonServerMain" --node-ipc --clientProcessId=12092
    0        4   19860       electron-nodejs (config.js )
    0        6   14108         C:\WINDOWS\system32\conhost.exe 0x4
    0      112   26084         electron-nodejs (config.js )
    0       66   10180           "c:\Users\morganj\.vscode\extensions\ms-dotnettools.csdevkit-1.9.8-win32-x64\components\vs-green-server\platforms\win32-x64\node_modules\@microsoft\servicehub-controller-net60.win32-x64/Microsoft.ServiceHub.Controller" 6b82d25fbc481d1d2ed7514c707d2d8834b1716bfa49e2165de7076c310ab38b /ControllerCooldownTimeout:30000 "/TelemetrySession:{\"TelemetryLevel\":\"all\",\"IsOptedIn\":false,\"HostName\":\"Default\",\"AppInsightsInstrumentationKey\":null,\"AsimovInstrumentationKey\":null,\"CollectorApiKey\":\"0c6ae279ed8443289764825290e4f9e2-1a736e7c-1324-4338-be46-fc2a58ae4d14-7255\",\"AppId\":1010,\"UserId\":\"9db3f0d7-e564-4a0d-a0d1-141ce41d6a3f\",\"Id\":\"c766d778-5823-44a2-aefb-ad2d612eed681721697226550\",\"ProcessStartTime\":133661708407598265,\"SkuName\":null,\"VSExeVersion\":null,\"BucketFiltersToEnableWatsonForFaults\":[{\"AdditionalProperties\":[{\"Key\":\"DumpType\",\"Value\":\"Heap\"}],\"Id\":\"0bf51120-427a-4d11-9fa3-8825e8a6b42b\",\"WatsonEventType\":\"VisualStudioNonFatalErrors2\",\"BucketParameterFilters\":[\"(?i)servicehub.identityhost.exe\",null,\"(?i)servicehub.host.serviceactivationfailure\",\"(?i)microsoft.servicehub.hostlib.proxyexception\",null,null,null,null,null,null]}],\"BucketFiltersToAddDumpsToFaults\":[{\"AdditionalProperties\":[{\"Key\":\"DumpType\",\"Value\":\"Heap\"}],\"Id\":\"0bf51120-427a-4d11-9fa3-8825e8a6b42b\",\"WatsonEventType\":\"VisualStudioNonFatalErrors2\",\"BucketParameterFilters\":[\"(?i)servicehub.identityhost.exe\",null,\"(?i)servicehub.host.serviceactivationfailure\",\"(?i)microsoft.servicehub.hostlib.proxyexception\",null,null,null,null,null,null]}]}"
    0       76    1932             "c:\Users\morganj\.vscode\extensions\ms-dotnettools.csdevkit-1.9.8-win32-x64\components\vs-green-server\platforms\win32-x64\node_modules\@microsoft\visualstudio-code-servicehost.win32-x64/Microsoft.VisualStudio.Code.ServiceHost.exe" dotnet$C94B8CFE-E3FD-4BAF-A941-2866DBB566FE net.pipe://1018076C939D52D2717834D7A0F41DF38AD89 "/TelemetrySession:{\"TelemetryLevel\":\"all\",\"IsOptedIn\":false,\"HostName\":\"Default\",\"AppInsightsInstrumentationKey\":null,\"AsimovInstrumentationKey\":null,\"CollectorApiKey\":\"0c6ae279ed8443289764825290e4f9e2-1a736e7c-1324-4338-be46-fc2a58ae4d14-7255\",\"AppId\":1010,\"UserId\":\"9db3f0d7-e564-4a0d-a0d1-141ce41d6a3f\",\"Id\":\"c766d778-5823-44a2-aefb-ad2d612eed681721697226550\",\"ProcessStartTime\":133661708407598265,\"SkuName\":null,\"VSExeVersion\":null,\"BucketFiltersToEnableWatsonForFaults\":[{\"AdditionalProperties\":[{\"Key\":\"DumpType\",\"Value\":\"Heap\"}],\"Id\":\"0bf51120-427a-4d11-9fa3-8825e8a6b42b\",\"WatsonEventType\":\"VisualStudioNonFatalErrors2\",\"BucketParameterFilters\":[\"(?i)servicehub.identityhost.exe\",null,\"(?i)servicehub.host.serviceactivationfailure\",\"(?i)microsoft.servicehub.hostlib.proxyexception\",null,null,null,null,null,null]}],\"BucketFiltersToAddDumpsToFaults\":[{\"AdditionalProperties\":[{\"Key\":\"DumpType\",\"Value\":\"Heap\"}],\"Id\":\"0bf51120-427a-4d11-9fa3-8825e8a6b42b\",\"WatsonEventType\":\"VisualStudioNonFatalErrors2\",\"BucketParameterFilters\":[\"(?i)servicehub.identityhost.exe\",null,\"(?i)servicehub.host.serviceactivationfailure\",\"(?i)microsoft.servicehub.hostlib.proxyexception\",null,null,null,null,null,null]}]}"
    0        6    5212               C:\WINDOWS\system32\conhost.exe 0x4
    0      147   19852             "c:\Users\morganj\.vscode\extensions\ms-dotnettools.csdevkit-1.9.8-win32-x64\components\vs-green-server\platforms\win32-x64\node_modules\@microsoft\visualstudio-code-servicehost.win32-x64\Microsoft.VisualStudio.Code.ServiceHost.exe" dotnet.projectSystem$C94B8CFE-E3FD-4BAF-A941-2866DBB566FE net.pipe://1018076C939D52D2717834D7A0F41DF38AD89 "/TelemetrySession:{\"TelemetryLevel\":\"all\",\"IsOptedIn\":false,\"HostName\":\"Default\",\"AppInsightsInstrumentationKey\":null,\"AsimovInstrumentationKey\":null,\"CollectorApiKey\":\"0c6ae279ed8443289764825290e4f9e2-1a736e7c-1324-4338-be46-fc2a58ae4d14-7255\",\"AppId\":1010,\"UserId\":\"9db3f0d7-e564-4a0d-a0d1-141ce41d6a3f\",\"Id\":\"c766d778-5823-44a2-aefb-ad2d612eed681721697226550\",\"ProcessStartTime\":133661708407598265,\"SkuName\":null,\"VSExeVersion\":null,\"BucketFiltersToEnableWatsonForFaults\":[{\"AdditionalProperties\":[{\"Key\":\"DumpType\",\"Value\":\"Heap\"}],\"Id\":\"0bf51120-427a-4d11-9fa3-8825e8a6b42b\",\"WatsonEventType\":\"VisualStudioNonFatalErrors2\",\"BucketParameterFilters\":[\"(?i)servicehub.identityhost.exe\",null,\"(?i)servicehub.host.serviceactivationfailure\",\"(?i)microsoft.servicehub.hostlib.proxyexception\",null,null,null,null,null,null]}],\"BucketFiltersToAddDumpsToFaults\":[{\"AdditionalProperties\":[{\"Key\":\"DumpType\",\"Value\":\"Heap\"}],\"Id\":\"0bf51120-427a-4d11-9fa3-8825e8a6b42b\",\"WatsonEventType\":\"VisualStudioNonFatalErrors2\",\"BucketParameterFilters\":[\"(?i)servicehub.identityhost.exe\",null,\"(?i)servicehub.host.serviceactivationfailure\",\"(?i)microsoft.servicehub.hostlib.proxyexception\",null,null,null,null,null,null]}]}"
    0       45     968               "C:\Program Files\dotnet\dotnet.exe" "c:\Users\morganj\.vscode\extensions\ms-dotnettools.csdevkit-1.9.8-win32-x64\components\CPS\platforms\win32-x64\node_modules\@microsoft\visualstudio-projectsystem-buildhost.win32-x64/Microsoft.VisualStudio.ProjectSystem.Server.BuildHost.dll"
    0        6    6180                 C:\WINDOWS\system32\conhost.exe 0x4
    0        6   18720               C:\WINDOWS\system32\conhost.exe 0x4
    0       13   20148       C:\Users\morganj\fvm\versions\3.22.3\bin\cache\dart-sdk\bin\dart.exe tooling-daemon --machine
    0        6    5532         C:\WINDOWS\system32\conhost.exe 0x4
    0       77   23848       electron-nodejs (serverMain.js )
    0        4   24996       C:\WINDOWS\system32\cmd.exe /c C:\Users\morganj\fvm\versions\3.22.3\bin\flutter.bat debug_adapter
    0        6   26524         C:\WINDOWS\system32\conhost.exe 0x4
    0       37   26600         electron-nodejs (config.js )
    0        4   10688           C:\WINDOWS\system32\cmd.exe /c C:\Users\morganj\fvm\versions\3.22.3\bin\flutter.bat run --machine --start-paused -d emulator-5554 --devtools-server-address http://127.0.0.1:9100/ --target C:\Users\morganj\source\CAFDExGO\mobile_app\lib\main.dart
    0       62    3816             electron-nodejs (config.js )
    0        8    2416               C:\Users\morganj\AppData\Local\Android\sdk\platform-tools\adb.exe -s emulator-5554 shell -x logcat -v time -T "'07-23 10:35:50.197'"
    0        6   14060                 C:\WINDOWS\system32\conhost.exe 0x4
    0       49   13840               electron-nodejs (config.js )
    0        6   10092                 C:\WINDOWS\system32\conhost.exe 0x4
    0        6   19840             C:\WINDOWS\system32\conhost.exe 0x4
    0      181   25184       c:\Users\morganj\.vscode\extensions\ms-dotnettools.csharp-2.34.12-win32-x64\.roslyn\Microsoft.CodeAnalysis.LanguageServer.exe --logLevel Information --razorSourceGenerator c:\Users\morganj\.vscode\extensions\ms-dotnettools.csharp-2.34.12-win32-x64\.razor\Microsoft.CodeAnalysis.Razor.Compiler.dll --razorDesignTimePath c:\Users\morganj\.vscode\extensions\ms-dotnettools.csharp-2.34.12-win32-x64\.razor\Targets\Microsoft.NET.Sdk.Razor.DesignTime.targets --starredCompletionComponentPath c:\Users\morganj\.vscode\extensions\ms-dotnettools.vscodeintellicode-csharp-2.1.11-win32-x64\components\starred-suggestions\platforms\win32-x64\node_modules\@vsintellicode\starred-suggestions-csharp.win32-x64 --devKitDependencyPath c:\Users\morganj\.vscode\extensions\ms-dotnettools.csharp-2.34.12-win32-x64\.roslynDevKit\Microsoft.VisualStudio.LanguageServices.DevKit.dll --sessionId c766d778-5823-44a2-aefb-ad2d612eed681721697226550 --extension c:\Users\morganj\.vscode\extensions\ms-dotnettools.csharp-2.34.12-win32-x64\.xamlTools\Microsoft.VisualStudio.DesignTools.CodeAnalysis.dll --extension c:\Users\morganj\.vscode\extensions\ms-dotnettools.csharp-2.34.12-win32-x64\.xamlTools\Microsoft.VisualStudio.DesignTools.CodeAnalysis.Diagnostics.dll --telemetryLevel all --extensionLogDirectory c:\Users\morganj\AppData\Roaming\Code\logs\20240722T181345\window1\exthost\ms-dotnettools.csharp
    0        4   25404       C:\WINDOWS\system32\cmd.exe /d /s /c ""C:\Users\morganj\fvm\versions\3.22.3\bin\flutter.bat" "daemon""
    0        6    2820         C:\WINDOWS\system32\conhost.exe 0x4
    0       28   12672         electron-nodejs (config.js )
    0        6   22380           C:\Users\morganj\AppData\Local\Android\sdk\emulator\emulator.exe -avd Pixel_7_API_33 -no-snapshot-load
    0        6   11324             C:\WINDOWS\system32\conhost.exe 0x4
    0     2065   24372             C:\Users\morganj\AppData\Local\Android\sdk\emulator\qemu\windows-x86_64\qemu-system-x86_64.exe -avd Pixel_7_API_33 -no-snapshot-load
    0        6    5768               C:\Users\morganj\AppData\Local\Android\sdk\emulator\crashpad_handler.exe --no-rate-limit --database=C:\Users\morganj\AppData\Local\Temp\\AndroidEmulator\emu-crash.db --url=https://clients2.google.com/cr/report --annotation=prod=AndroidEmulator --annotation=ver=standalone-0 --initial-client-data=0x3e0,0x3e4,0x3e8,0x3bc,0xa8,0x7ff70cace3a8,0x7ff70cace3b8,0x7ff70cace378
    0       79   25880       electron-nodejs (tailwindServer.js )
    0       89   26116       electron-nodejs (languageserver.js )
    0       77   26312       electron-nodejs (eslintServer.js )
    0       74   12204  fileWatcher [1]
    0      177   19704     gpu-process
    0       42   20892     utility-network-service
    0      662   25144  window [1] (priorities_new.dart - mobile_app (Workspace) - Visual Studio Code)
    0       25   25964     crashpad-handler
    0       80   25980  ptyHost
    0       79     392       C:\WINDOWS\System32\WindowsPowerShell\v1.0\powershell.exe -noexit -command "try { . \"c:\Program Files\Microsoft VS Code\resources\app\out\vs\workbench\contrib\terminal\browser\media\shellIntegration.ps1\" } catch {}"
    0        5   30276         C:\WINDOWS\system32\cmd.exe /c ""C:\Program Files\Microsoft VS Code\bin\code.cmd" --status"
    0      101   24764           electron-nodejs (cli.js )
    0      129   26284             "C:\Program Files\Microsoft VS Code\Code.exe" --status
    0       90   14752               crashpad-handler
    0       92   19108               utility-network-service
    0      104   21316               gpu-process
    0        7   20596       conpty-agent
    0       29   24984       "C:\Program Files\dotnet\dotnet.exe" watch run C:\Users\morganj\source\CAFDExGO\APIServer-Test/CAFDExGOServer.csproj --property GenerateFullPaths=true
    0       34   26108         "C:\Program Files\dotnet\dotnet.exe" "C:\Program Files\dotnet\sdk\6.0.408\DotnetTools\dotnet-watch\6.0.408-servicing.23177.15\tools\net6.0\any\dotnet-watch.dll" run C:\Users\morganj\source\CAFDExGO\APIServer-Test/CAFDExGOServer.csproj --property GenerateFullPaths=true
    0       48    2812           "C:\Program Files\dotnet\dotnet.exe" run --no-restore C:\Users\morganj\source\CAFDExGO\APIServer-Test/CAFDExGOServer.csproj --property GenerateFullPaths=true
    0      179   25208             "C:\Users\morganj\source\CAFDExGO\APIServer-Test\bin\Debug\net6.0\CAFDExGOServer.exe"  C:\Users\morganj\source\CAFDExGO\APIServer-Test/CAFDExGOServer.csproj
    0        7   25512       conpty-agent

Workspace Stats:
|  Window (priorities_new.dart - mobile_app (Workspace) - Visual Studio Code)
|    Folder (Database): 2304 files
|      File types: svn-base(1332) sql(690) xlsx(3) db(1) db-journal(1) json(1)
|                  docx(1) js(1)
|      Conf files: tasks.json(1)
|    Folder (APIServer-Test): 5211 files
|      File types: svn-base(3446) cs(935) dll(153) pak(60) json(47) cache(10)
|                  exe(8) bin(8) vsidx(7) config(6)
|      Conf files: package.json(4) project.json(2) launch.json(1)
|                  settings.json(1) tasks.json(1) csproj(1) sln(1)
|      Launch Configs: coreclr(2)
|    Folder (mobile_app): more than 20293 files
|      File types: svn-base(2816) png(1773) dart(1737) h(1351) svg(1206)
|                  class(926) jar(919) json(417) xml(377) txt(255)
|      Conf files: cmake(25) sln(14) launch.json(1) settings.json(1)
|      Launch Configs: dart(11)
josephemorgan commented 1 month ago

I also should have mentioned that my teammates have also complained about hangs/slowness in the same project, which is what makes me suspicious that there might be something about the project itself that is causing some issues.

In my initial efforts to debug, I went through analysis_options.yaml and denylisted everything in the workspace directory except for lib, but I still had the issue.

josephemorgan commented 1 month ago

Some additional info:

I dug into the Analysis Server Diagnostics and saw that there are a handful of exceptions. The exceptions throw out an enormous wall of text that starts with: Exception Invalid argument(s): Missing library: package:com.infintech.cafdexgo/assessment/widgets/assessment_date_card.dart Libraries: [dart:async, dart:collection, dart:convert, dart:core, dart:_internal, dart:math, dart:typed_data, dart:isolate, dart:developer, dart:ffi, dart:_http, dart:io, ...

I verified that the indicated library exists at lib/assessment/widgets/assessment_date_card.dart

Stack trace from the diagnostics page looks like this:

#0      LinkedElementFactory.createLibraryElementForReading (package:analyzer/src/summary2/linked_element_factory.dart:153:7)
#1      LinkedElementFactory.elementOfReference (package:analyzer/src/summary2/linked_element_factory.dart:212:14)
#2      LinkedElementFactory.libraryOfUri (package:analyzer/src/summary2/linked_element_factory.dart:241:12)
#3      LinkedElementFactory.libraryOfUri2 (package:analyzer/src/summary2/linked_element_factory.dart:245:19)
#4      ResolutionReader.libraryOfUri (package:analyzer/src/summary2/bundle_reader.dart:1940:28)
#5      LibraryElementLinkedData._readLibraryOrAugmentation (package:analyzer/src/summary2/bundle_reader.dart:587:30)
#6      LibraryElementLinkedData._read (package:analyzer/src/summary2/bundle_reader.dart:536:5)
#7      ElementLinkedData.read (package:analyzer/src/summary2/bundle_reader.dart:256:5)
#8      LibraryElementLinkedData.read (package:analyzer/src/summary2/bundle_reader.dart:520:13)
#9      LibraryElementImpl.exportNamespace (package:analyzer/src/dart/element/element.dart:4176:17)
#10     LibraryElementExtensions.exportedExtensions (package:analysis_server/src/utilities/extensions/element.dart:61:12)
#11     _ImportLibraryContainingExtension.compute (package:analysis_server/src/services/correction/dart/import_library.dart:461:42)
#12     FixProcessor._addFromProducers.compute (package:analysis_server/src/services/correction/fix_processor.dart:123:24)
#13     FixProcessor._addFromProducers (package:analysis_server/src/services/correction/fix_processor.dart:161:17)
<asynchronous suspension>
#14     FixProcessor.compute (package:analysis_server/src/services/correction/fix_processor.dart:75:5)
<asynchronous suspension>
#15     computeFixes (package:analysis_server/src/services/correction/fix_internal.dart:1587:8)
<asynchronous suspension>
#16     DartCodeActionsProducer.getFixActions (package:analysis_server/src/lsp/handlers/code_actions/dart.dart:178:23)
<asynchronous suspension>
#17     OperationPerformanceImpl.runAsync (package:analyzer/src/util/performance/operation_performance.dart:172:14)
<asynchronous suspension>
#18     CodeActionHandler.handle (package:analysis_server/src/lsp/handlers/handler_code_actions.dart:227:16)
<asynchronous suspension>
#19     ServerStateMessageHandler.handleMessage (package:analysis_server/src/lsp/handlers/handlers.dart:396:11)
<asynchronous suspension>
#20     LspAnalysisServer._handleRequestMessage (package:analysis_server/src/lsp/lsp_analysis_server.dart:1010:20)
<asynchronous suspension>
#21     LspAnalysisServer.handleMessage.<anonymous closure>.<anonymous closure> (package:analysis_server/src/lsp/lsp_analysis_server.dart:461:15)
<asynchronous suspension>
#22     OperationPerformanceImpl.runAsync (package:analyzer/src/util/performance/operation_performance.dart:172:14)
<asynchronous suspension>
#23     LspAnalysisServer.handleMessage.<anonymous closure> (package:analysis_server/src/lsp/lsp_analysis_server.dart:444:11)
<asynchronous suspension>

There were 10 similar errors listed, it seems possible that they're connected to the hangs.

bwilkerson commented 1 month ago

@scheglov

scheglov commented 1 month ago

This is the same exception again, I still suspect that this is because we try to do more than one operation concurrently in DAS: analysis and handling requests. The solution is probably using a single scheduler.

josephemorgan commented 1 month ago

I've captured some analysis-server.log output during a time period that I was experiencing a lot of hangs. The worst hangs were happening on save, with the status bar showing "applying quick-fixes," but I did have a period after a save hang was complete where the autocomplete suggestion box was just showing "loading" and inline diagnostics weren't updating.

excerpt.txt

The excerpt that I extracted only covers ~3 minutes but it's about 5600 lines long.

The project that I'm working in does have 442 warnings and >2k infos, could that be why the analyzer is getting stuck?

DanTup commented 1 month ago

Thanks for the log! Running "Fix All" (particularly with a large number of diagnostics) can be an expensive operation (because we compute fixes, apply them to temporary overlays, re-analyze all affected files, and then check if there are more fixes and repeat). From the log it seems you're running this on-save and saved multiple files, which means this operation is occurring multiple times.

That said, I see a lot of diagnostics being sent while the operation is running, and this is unexpected. While we re-analyze during this operation (to look for another round of fixes), the diagnostics from analyzing should be suppressed (because they're based on temporary overlays that don't match what the client has). I'm not sure it accounts for a lot of the time (versus all of the analysis), but it doesn't seem right so I'll try to reproduce.

Something I overlooked in your original screenshot it that the first bar in the graph was blue. Can you confirm that this was a executeCommand request? (if so, this explains the latency on the subsequent requests, since the Fix All command locks the request queue and so any new requests while it is running will be stalled until it completes).

DanTup commented 1 month ago

That said, I see a lot of diagnostics being sent while the operation is running, and this is unexpected.

Digging more, this is actually from an in-process analysis started before the Fix All command. The log shows:

I actually think the issue here might not be related to Fix All itself, but could be that the analysis took a long time after you modified _priorities_utils.dart and that Fix All locks the request queue and then waits for any in-progess analysis before it proceeds. Because you're running Fix All on-save, this means the saving is blocked in VS Code on the analysis.

Is it possible you can try capturing logs and modify the file priorities/_priorities_utils.dart (but do NOT save) and wait for "Analyzing..." to disappear from the status bar before stopping the log, then see what the time difference is between the begin and end analyzing statuses?:

{"jsonrpc":"2.0","method":"$/progress","params":{"token":"ANALYZING","value":{"kind":"begin","title":"Analyzing…"}}}
{"jsonrpc":"2.0","method":"$/progress","params":{"token":"ANALYZING","value":{"kind":"end"}}}

The difference in the previous log is > 10s and this could be a result of how much code needs to be re-analyzed when you modify that file (files that depend on it).

josephemorgan commented 1 month ago

I set disabled Fix All on save in my vscode settings, which will hopefully remove that as a factor.

Is it possible you can try capturing logs and modify the file priorities/_priorities_utils.dart (but do NOT save) and wait for "Analyzing..." to disappear from the status bar before stopping the log, then see what the time difference is between the begin and end analyzing statuses?:

Been trying to do this for a couple of days but I don't actually have any changes to make to that file at the moment, and my contrived examples don't seem to be replicating the issue.

I am having the issue really badly today in another file. Basically, any time I try to trigger code completions to pop up, the analyzer is hanging for around a minute. If I wait for it to return with analysis and change what I'm typing, it immediately freezes again.

I've restarted the language server and captured the log demonstrating this, attaching it below. What I did was: 1) Restart the server 2) Pick a variable, type a few characters, trigger completion 3) Waited until the suggesting window popped-up 4) Once it popped up, I deleted the string that I had used to trigger the completion request and typed a new one 5) Waited again

example.log

I do see one pair of ANALYZING entries in the log that are separated by about 45 seconds, starting on line 2899 and with 225 lines between the begin and end.

Any ideas?

josephemorgan commented 1 month ago

We've got a directory structure that I suspect might be non-standard, looks something like this

Project Root
t pubspec.yaml
t analysis-options.yaml (ignores api-client directory)
d  lib
--- t (App's dart files)
d  api-client (Auto-generated from our backend's openapi spec)
-- t  pubspec.yaml
-- t  analysix_options.yaml (blank)
-- d  lib
------ t api.dart (library ApplicationServer.api)
------ d api (part of ApplicationServer.api) in each file

It's set up with a 2nd project root inside of our app's project root, and then has this as a dependency in the pubspec.yaml:

dependencies:
  ApplicationServer:
    path: ./api-client

It definitely seems like the hangs are happening much more frequently when trying to get diagnostics from models inside of the ApplicationServer library, and I'm not familiar enough with flutter workspace norms to tell if having nested projects where the outside project depends on the inside project could cause that. It also takes a really long time to Go To Definition on any file that's in that library.

DanTup commented 1 month ago

@josephemorgan I wouldn't expect nested projects or path dependencies to cause any additional problems. Changing code in one project may result in code in the other project being re-analyzed, but I don't think this would be different to if they were in the same project (@scheglov may be able to confirm).

Are you able to capture an instrumentation log (see https://github.com/dart-lang/sdk/issues/56307#issuecomment-2248234047) for this issue? That log is captured by the server rather than the client, and includes additional logging (such as file watcher events and analysis context rebuilds). There's some analysis in your log that it's not obvious what the trigger is, so I wonder if this log gives the whole picture.

Like the logs above, the log file can get quite large and it will contain parts from your source files (such as in didOpen and didChange) events, so pleasure ensure there's nothing sensitive in any logs you share. What might be useful is the logs between the largest analysing begin/end, as well as the handful of logs prior to that which might indicate what triggered the analysis.

scheglov commented 1 month ago

@josephemorgan I wouldn't expect nested projects or path dependencies to cause any additional problems. Changing code in one project may result in code in the other project being re-analyzed, but I don't think this would be different to if they were in the same project (@scheglov may be able to confirm).

Yes, when DAS sees a file change, it notifies all AnalysisDrivers about it, if some driver does not care, it is just ignored. Otherwise, if the driver read this file from a sibling package, it will update its state. It does not matter how you slice the code - same packages, nested, siblings.

josephemorgan commented 3 weeks ago

Sorry, know it's been two weeks here, haven't forgotten about this, just been swamped, will try to update with the instrumentation log tomorrow.

josephemorgan commented 2 weeks ago

Here's that instrumentation log:

snippet.log

At this point, I'm pretty confident that the issue ONLY happens when the analysis is operating on files that our in our api library (which is a subfolder in the general project).

LSP responses are totally normal if they're triggered on code from a Flutter library or anything from the /ourapp/lib/ directory.

When the analyzer is triggered against anything from /ourapp/ourapp-server/lib/, it hangs for 60-90 seconds. I'll add that the files in /ourapp/ourapp-server/lib/ very rarely change.

Those files are exported through a file called /ourapp/ourapp-server/lib/api.dart, which looks someting like this:

library OurAppServer.api;

import 'package:OurAppServer/model_base.dart';

import 'dart:async';
import 'dart:convert';
import 'dart:io';

import 'package:http/http.dart';
import 'package:flutter/foundation.dart';
import 'package:intl/intl.dart';
import 'package:meta/meta.dart';

part 'api/some_autogenerated_client.dart' // Few dozen of these, for each controller in our asp.net backend
part 'model/some_autogenerated_model.dart' // close to a thousand of these

And then, of course each of those client or model files have a part of OurAppServer.api

I have no idea if any of this is useful but I can't shake the suspicion that something about the api library configuration is causing issues.

bwilkerson commented 2 weeks ago

close to a thousand of these

That's quite likely the source of the problem.

When the analyzer needs to resolve a file, it ends up analyzing all of the files in the library cycle [1]. Even if you only have one library in the library cycle (which appears to be the case, as long as OurAppServer/model_base.dart doesn't import OurAppServer.api), that's close to a thousand files that all have to be analyzed together.

You might want to consider breaking this single monolithic library up into multiple smaller libraries, organized in such a way that, as much as possible, they are not all dependent on everything else. The smaller a cycle in the library graph is (in terms of number of files), the faster the analysis of that cycle will be.

[1] "cycle" in the sense of a cycle in a graph, where the vertices are the libraries and the edges are defined by the imports between those libraries.

josephemorgan commented 2 weeks ago

I see, that makes sense to me. The code is all auto-generated using openapi-generator-cli from an OpenAPI spec that's auto-generated using swashbuckle, but I imagine that there has to be a way to configure the generators to do some sort of modularization.