Improve completion time for large code bases

[srawlins]

Large code bases appear to strongly negatively affect code completion time. To be more precise, code completion in libraries with a large namespace, or a large potential namespace (suggesting things that can then be auto-imported) may be much slower than smaller code, even when accounting for the "new protocol" being added to IntelliJ, and which may be used in LSC clients, like VS Code, already.

This task is to measure it, improve it, and decide on a good exit criteria. There are, of course, always ways to improve performance; for this task we must choose a meaningful exit criteria so as to give the task a meaningful priority.

[srawlins]

Some motivating user-filed bugs relating to this:

• https://github.com/dart-lang/sdk/issues/43113
• https://github.com/dart-lang/sdk/issues/40347
• https://github.com/dart-lang/sdk/issues/41641

[srawlins]

I profiled flutter/gallery using the completion_metrics.dart script, and got the following median, p90, and p95 metrics for completions:

                   p50  p90  p95
ms per completion   27   35   40

Those numbers look great.

So, we need more investigation to find if there are reproducible situations which lead to much higher completion times. Perhaps more symbols. Perhaps add some 'changedFile' events preceding the complete request. Perhaps Windows-specific, where stdin/stdout might be slower...

[srawlins]

When I look at flutter_gallery, I see these as the slowest completions, when erasing a whole identifier/keyword and complete where it was:

1. 874 ms /Users/srawlins/code/flutter-gallery/lib/pages/home.dart:738:3, completing PageController

   class _CarouselState extends State<_Carousel>
       with RestorationMixin, SingleTickerProviderStateMixin {
     ^? _controller;
   

2. 859 ms /Users/srawlins/code/flutter-gallery/lib/pages/home.dart:330:3, completing Timer

   class _AnimatedHomePageState extends State<_AnimatedHomePage>
       with RestorationMixin, SingleTickerProviderStateMixin {
     late AnimationController _animationController;
     ^? _launchTimer;
   

3. 783 ms /Users/srawlins/code/flutter-gallery/lib/pages/demo.dart:95:3, completing bool

   class _GalleryDemoPageState extends State<GalleryDemoPage>
       with RestorationMixin, TickerProviderStateMixin {
     final RestorableInt _demoStateIndex = RestorableInt(_DemoState.normal.index);
     final RestorableInt _configIndex = RestorableInt(0);
   
     ^? _isDesktop;
   

4. 608 ms /Users/srawlins/code/flutter-gallery/lib/pages/settings.dart:40:3, completing _ExpandableSetting

   class _SettingsPageState extends State<SettingsPage> {
     ^? _expandedSettingId;
   

5. 504 ms /Users/srawlins/code/flutter-gallery/lib/studies/rally/login.dart:288:3, completing BoxDecoration

   class _ThumbButtonState extends State<_ThumbButton> {
     ^? borderDecoration;
   

6. 371 ms /Users/srawlins/code/flutter-gallery/lib/demos/material/data_table_demo.dart:68:3, completing _DessertDataSource

   class _DataTableDemoState extends State<DataTableDemo> with RestorationMixin {
     final _RestorableDessertSelections _dessertSelections =
         _RestorableDessertSelections();
     final RestorableInt _rowIndex = RestorableInt(0);
     final RestorableInt _rowsPerPage =
         RestorableInt(PaginatedDataTable.defaultRowsPerPage);
     final RestorableBool _sortAscending = RestorableBool(true);
     final RestorableIntN _sortColumnIndex = RestorableIntN(null);
     ^? _dessertsDataSource;
   

7. 293 ms /Users/srawlins/code/flutter-gallery/lib/feature_discovery/feature_discovery.dart:138:3, completing OverlayEntry

   class _FeatureDiscoveryState extends State<FeatureDiscovery>
       with TickerProviderStateMixin {
     bool showOverlay = false;
     FeatureDiscoveryStatus status = FeatureDiscoveryStatus.closed;
   
     late AnimationController openController;
     late AnimationController rippleController;
     late AnimationController tapController;
     late AnimationController dismissController;
   
     late Animations animations;
     ^? overlay;
   

8. 227 ms /Users/srawlins/code/flutter-gallery/lib/feature_discovery/feature_discovery.dart:138:3, completing Matrix4

   class _TransformationsDemoState extends State<TransformationsDemo>
       with TickerProviderStateMixin {
     final GlobalKey _targetKey = GlobalKey();
     // The radius of a hexagon tile in pixels.
     static const _kHexagonRadius = 16.0;
     // The margin between hexagons.
     static const _kHexagonMargin = 1.0;
     // The radius of the entire board in hexagons, not including the center.
     static const _kBoardRadius = 8;
   
     Board _board = Board(
       boardRadius: _kBoardRadius,
       hexagonRadius: _kHexagonRadius,
       hexagonMargin: _kHexagonMargin,
     );
   
     final TransformationController _transformationController =
         TransformationController();
     Animation<Matrix4>? _animationReset;
     late AnimationController _controllerReset;
     ^? _homeMatrix;
   

9. 207 ms /Users/srawlins/code/flutter-gallery/lib/demos/material/tabs_demo.dart:37:3, completing TabController

   class __TabsScrollableDemoState extends State<_TabsScrollableDemo>
       with SingleTickerProviderStateMixin, RestorationMixin {
     ^? _tabController;
   

10. 207 ms /Users/srawlins/code/flutter-gallery/lib/data/gallery_options.dart:231:3, completing Timer

    class _ModelBindingState extends State<ModelBinding> {
      late GalleryOptions currentModel;
      ^? _timeDilationTimer;
    

Notes:

• These 10 slowest completions were the only 10 which took more than 200 ms. In this data set, with 33k completions, the median time was 27 ms; the p90 time was 40 ms; the p95 time was 45 ms.
• Some of these may be artifacts of the completion_metrics.dart script; e.g. is there slow performance early in a file, when there is perhaps less stuff hot in the cache?
• Aside from any artifacts of the script, there is a clear signal: every slowest completion is at the front of a line inside a class. They are all at the front of a field, without an initializer, without any modifiers (like final), and with a nullable type. Curious that none are at the front of a method, setter, getter? Curious that none are at the front of a field with an initializer?

[bwilkerson]

... is there slow performance early in a file, when there is perhaps less stuff hot in the cache?

I wouldn't expect that to be the case because if we're removing part of the file before completing then we're having to analyze the whole file before every completion. But I'm not an expert in performance questions.

... every slowest completion is at the front of a line inside a class.

That's definitely interesting. Can we tell what the performance is if completion is happening between complete members? I'm wondering whether it's because we're at the level of a class member or whether the AST we're seeing after recovering from the error is causing the problem. If it's the former, then that's an opportunity; if it's the latter, then I don't expect that users are in this situation very often.

Curious that none are at the front of a method, setter, getter?

The return type is optional for methods, setters, and getters, so no recovery is required. (Although I would expect recovery if the type were nullable and the question mark isn't being deleted.)

Curious that none are at the front of a field with an initializer?

That case might well recover better because the presence of the initializer seems like a clear signal that we have a field declaration.

[srawlins]

These were done with the default overlay, none, so no overlays are created, and the code should always be error-free.

[srawlins]

When I use the --overlay=remove-rest-of-file option, the completions get noticeably slower for the slowest: p95 is still just 39ms which is great. But there are now over 100 completions which take longer than 483 ms. The top 10 are:

1. 2586 ms to complete at lib/demos/reference/motion_demo_fade_scale_transition.dart:12:58
2. 1623 ms to complete at lib/demos/reference/transformations_demo_board.dart:119:8
3. 1457 ms to complete at lib/demos/reference/colors_demo.dart:110:13
4. 1324 ms to complete at lib/demos/reference/motion_demo_fade_scale_transition.dart:49:12
5. 1253 ms to complete at lib/demos/reference/motion_demo_container_transition.dart:409:14
6. 1253 ms to complete at lib/demos/reference/motion_demo_shared_x_axis_transition.dart:51:13
7. 1086 ms to complete at lib/demos/reference/typography_demo.dart:122:30
8. 1074 ms to compute at lib/demos/reference/motion_demo_fade_scale_transition.dart:12:9
9. 963 ms to compute at lib/demos/reference/motion_demo_shared_x_axis_transition.dart:52:22
10. 907 ms to compute at lib/demos/reference/motion_demo_fade_scale_transition.dart:47:13

[gabrielgarciagava]

I am experiencing very high latency in our code base. Things like >60000 ms. There is no task (being reported in the Analysis Server Diagnostics) that is taking this 60000ms, so it is something happening under the hood that I cannot see through the diagnostics page.

It is happening very often, but it is specially bad when we add or remove a dependency in a deeper level of the contexts being analyzed, for example.

The code completion time is also affected by slowness (not latency this time).

Let me know what kind of information I can provide to help investigating that.

[srawlins]

Great data, @gabrielgarciagava ! Could you also report:

• the number of Contexts you have (from the Contexts page, undocumented right now 😞 )
• whether your are running any Dart analyzer plugins (the primary one is Dart Code Metrics) (from the Plugins page, also undocumented
• how much memory the DAS process (some dart process) is using (e.g. from Activity Monitor or Process Explorer or ps...)
• your OS
• your Dart version
• Are you using VS Code or IntelliJ or...
• The number of .dart files in your workspace (wherever the IDE window is rooted), something like find . -name "*.dart" | wc -l should do the trick.

[mraleph]

@gabrielgarciagava additionally to what @srawlins have said. If you are running on new enough analyzer (e.g. Flutter master will certainly have it) then there should be "Collect Report" option at the top of the "Analysis Server Diagnostics" page.

[incendial]

how much memory the DAS process

Shouldn't dart info provide this info instead of relying on Activity Monitor?

[srawlins]

TIL 🎉 I love it. Thanks @incendial

[gabrielgarciagava]

• the number of Contexts you have (from the Contexts page, undocumented right now 😞 )

134

• whether your are running any Dart analyzer plugins (the primary one is Dart Code Metrics) (from the Plugins page, also undocumented

No plugins.

• how much memory the DAS process (some dart process) is using (e.g. from Activity Monitor or Process Explorer or ps...)
• your OS
• your Dart version

Output of dart info with all those details

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.0.1 (stable) (Tue May 16 11:57:19 2023 +0000) on "macos_arm64"
- on macos / Version 13.3.1 (Build 22E261)
- locale is en-NL

#### Project info

- sdk constraint: '>=2.12.0 <3.0.0'
- dependencies: flutter
- dev_dependencies: 

#### Process info

|  Memory |    CPU | Elapsed time | Command line                                                                               |
| ------: | -----: | -----------: | ------------------------------------------------------------------------------------------ |
|   72 MB |   0.0% |        08:20 | dart devtools --machine --try-ports 10 --allow-embedding                                   |
|   74 MB |   0.0% |        07:07 | dart devtools --machine --try-ports 10 --allow-embedding                                   |
| 8527 MB | 142.2% |        08:20 | dart language-server --protocol=lsp --client-id=VS-Code --client-version=3.64.0 --instrumentation-log-file=<path>/analyzerInstrumentationLogFile.txt |
|  389 MB |   0.0% |        07:07 | dart language-server --protocol=lsp --client-id=VS-Code --client-version=3.64.0 --instrumentation-log-file=<path>/analyzerInstrumentationLogFile.txt |
|  180 MB |  55.8% |        00:04 | dart pub outdated --show-all --json                                                        |
|   96 MB |   0.0% |        08:20 | flutter_tools.snapshot daemon                                                              |
|   91 MB |   0.1% |        07:07 | flutter_tools.snapshot daemon                                                              |

• Are you using VS Code or IntelliJ or...

VSCode

• The number of .dart files in your workspace (wherever the IDE window is rooted), something like find . -name "*.dart" | wc -l should do the trick.

7601

[gabrielgarciagava]

@gabrielgarciagava additionally to what @srawlins have said. If you are running on new enough analyzer (e.g. Flutter master will certainly have it) then there should be "Collect Report" option at the top of the "Analysis Server Diagnostics" page.

I am afraid I cannot handle this file. At least not before checking with the legal parts of the company. I see there are package names there, so I need to take care what can be shared and what cannot. Let me know if there is a specific section of the file that is specially useful for you, then I can edit it accordingly.

[srawlins]

CC @bwilkerson @scheglov I find this data very interesting:

• 18 seconds to perform a completion
• 134 analysis contexts (😮 )
• only 7600 files
• only 8.5GB memory used (sorry for using the word "only", but for 134 contexts, this seems pretty low; even with only 7600 local source files, I would imagine that 134 copies of the Flutter SDK and the Dart SDK would really slam that memory higher)

If, broadly speaking, we find that multiple contexts can linearly slow down completion (and other responses, as seen above), that would also boost the priority of improving the multi-context situation.

[gabrielgarciagava]

Sobre extra context, in case it helps.

For the 8.5GB, I had started the IDE and added a new dependency in one of the contexts that impacts a lot of other contexts. No more than that. Just saying that the IDE was not running for so long, not sure if it has any impact in the memory. Well, you can see that in the elapsed time.

Second, for the high number of contexts, we do divide our code in a lot of small packages within the same repository.

[mraleph]

I am afraid I cannot handle this file. At least not before checking with the legal parts of the company. I see there are package names there, so I need to take care what can be shared and what cannot. Let me know if there is a specific section of the file that is specially useful for you, then I can edit it accordingly.

Ah, it was an oversight to include context names which might be project specific. You can scrape this information by running the following script (it will also scrape lint and plugin names for good measure):

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

// Usage: dart scrape.dart report.json
void main(List<String> args) {
  final data = jsonDecode(File(args.first).readAsStringSync());
  for (var entry in data['contexts']) {
    entry['name'] = '@@@';
    entry['lints'] = entry['lints'].length;
    entry['plugins'] = entry['plugins'].length;
  }
  File(args.first).writeAsStringSync(JsonEncoder.withIndent('  ').convert(data));
}

The rest of the report just contains information about the analyser state itself and should not contain any user data.

[gabrielgarciagava]

@mraleph Thanks for the script. Looks good to me now.

Here it is:

analyzer_report.json.zip

[jensjoha]

Thanks!

Initial glance over the report:

• Current RSS (memory usage): ~2.7GB
• Max RSS: ~8.8GB
• 134 contexts
• 12,966 uniquely known files
• 347,043 combined "known files" in the 134 contexts
• 347,043 FileState objects. (Good --- it fits with the number above :))

It seems to me that in this case at least, the memory usage has successfully gone down again.

These numbers seem rather similar to what I see when loading https://github.com/kodecocodes/rwf-materials.git from cache.

[gabrielgarciagava]

Thanks for checking the data. Please let me know if I can help providing more data to you.

Those slow times are being a hassle for the day to day work, but I'm also not sure if this issue has high priority for you guys or not. It looks like not so many people are currently affected by this problem, right?

[jensjoha]

An update on the report: it has 3,277,209 _Entry objects which seems similar to what we saw in https://github.com/dart-lang/sdk/issues/52447#issuecomment-1589181296. Here the uptime is only ~15 minutes though, so how it has accumulated that many is a good question. Have you (or some script etc) continually been rewriting pubspec.yaml, analysis_options.yaml, BUILD or .dart_tool/package_config.json files?

[gabrielgarciagava]

We don't have anything running continually like you said.

However, we do have one script that runs pub get on a multiple packages. For this 15min experiment I did run it once. To give you extra context, what the script does is propagating pubspeck.lock changes to packages that are dependent of it. Then it runs pub get for each of the affected packages.

In this experiment, I did modify the pubspec of one deep down dependency. I think around 50 packages were updated and thus had run pub get.

[jensjoha]

That's probably enough --- if 50 packages were updated with enough time between each update (say a few seconds which doesn't seem unlikely) that would probably do it.

[gabrielgarciagava]

Cool. Should I try to create a "small" project sample with multiple packages that uses this kind of script to share with you?

[jensjoha]

I don't think that's currently necessary, thanks though. That particular leak was fixed in https://github.com/dart-lang/sdk/commit/5aee0f61b6301099bb25a36d2b2ff197541d3c5b so hopefully it'll go away once that makes it into a release.

[gabrielgarciagava]

Does this leak affect performance as well?

[jensjoha]

Unfortunately I don't think that's the cause of the 60+ seconds latency you reported above, no.

[jensjoha]

(though, with a big enough leak we might get in trouble with the amount of memory available on the system, leading to swapping etc which certainly would impact performance).

[gabrielgarciagava]

Ok. I was wondering if all those _Entry could be part of some loops, or maybe notifying things all the time. That could affect performance.

In any case, after your fix is released, I will do another run with the analyzer diagnostics and post it here.

[mraleph]

@gabrielgarciagava what is your current experience with analyzer latency on your code base?

[gabrielgarciagava]

Still quite bad. Codegens, changing branch, updating dependencies, all of these degrades de performance for the next couple of minutes, for example.

I am following a bit the progress of "workspaces". I even gave it a try on the master branch 1 or 2 weeks ago. It is hard to say for sure if it improved because I did had to do some quick tweaks to be able to run, and I also did not spend much time experimenting, but it sounds promising.

I did some codegens (which is something that currently degrades a lot the performance for a couple of minutes), and the analyzer seems to respond very quickly after that.