Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Improve completion time for large code bases #48788

Open
srawlins opened this issue Apr 11, 2022 · 28 comments
Open

Improve completion time for large code bases #48788

srawlins opened this issue Apr 11, 2022 · 28 comments
Assignees
Labels
analyzer-completion Issues with the analysis server's code completion feature area-analyzer Use area-analyzer for Dart analyzer issues, including the analysis server and code completion. P2 A bug or feature request we're likely to work on type-performance Issue relates to performance or code size

Comments

@srawlins
Copy link
Member

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 srawlins added area-analyzer Use area-analyzer for Dart analyzer issues, including the analysis server and code completion. analyzer-completion Issues with the analysis server's code completion feature type-performance Issue relates to performance or code size P2 A bug or feature request we're likely to work on labels Apr 11, 2022
@srawlins srawlins self-assigned this Apr 11, 2022
@srawlins
Copy link
Member Author

@srawlins
Copy link
Member Author

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

copybara-service bot pushed a commit that referenced this issue Apr 13, 2022
This adds a section to the output like this:

```
### Percentile metrics

                   p50  p90  p95  count > 2s
ms per completion    4    6    7           0
```

Bug: #48788
Change-Id: I868580324b3bc83605aa6466ffd5799625d1a9f3
Reviewed-on: https://dart-review.googlesource.com/c/sdk/+/240941
Commit-Queue: Samuel Rawlins <srawlins@google.com>
Reviewed-by: Brian Wilkerson <brianwilkerson@google.com>
@srawlins
Copy link
Member Author

srawlins commented Apr 20, 2022

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
Copy link
Member

... 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
Copy link
Member Author

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

@srawlins
Copy link
Member Author

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
Copy link

gabrielgarciagava commented May 23, 2023

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.

Screenshot 2023-05-23 at 09 47 35

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

Screenshot 2023-05-23 at 09 49 58

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

@srawlins
Copy link
Member Author

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
Copy link
Member

mraleph commented May 23, 2023

@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
Copy link
Contributor

how much memory the DAS process

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

@srawlins
Copy link
Member Author

srawlins commented May 23, 2023

TIL 🎉 I love it. Thanks @incendial

@gabrielgarciagava
Copy link

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
Copy link

@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
Copy link
Member Author

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
Copy link

gabrielgarciagava commented May 24, 2023

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
Copy link
Member

mraleph commented May 25, 2023

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
Copy link

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

Here it is:

analyzer_report.json.zip

@jensjoha
Copy link
Contributor

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
Copy link

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
Copy link
Contributor

An update on the report: it has 3,277,209 _Entry objects which seems similar to what we saw in #52447 (comment).
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
Copy link

gabrielgarciagava commented Jun 15, 2023

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
Copy link
Contributor

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
Copy link

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

@jensjoha
Copy link
Contributor

I don't think that's currently necessary, thanks though.
That particular leak was fixed in 5aee0f6 so hopefully it'll go away once that makes it into a release.

@gabrielgarciagava
Copy link

Does this leak affect performance as well?

@jensjoha
Copy link
Contributor

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

@jensjoha
Copy link
Contributor

(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
Copy link

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.

copybara-service bot pushed a commit that referenced this issue Jun 16, 2023
…fterContextsCreated` is called

If again and again editing, say, a `pubspec.yaml` with proper timing
there is a "temporary leak" that repairs itself once the analyzer
finishes (some time after the editing stops).

What happens is that old contexts are saved in the
`declarationsTracker` but eventually cleared in the
`afterContextsCreated` call.

In a test on Windows (on Linux I'd currently run into
https://dartbug.com/52703) I opened the entire "pkg" folder and edited
a `pubspec.yaml` file every 5 seconds.
The analyzer went from using something along the lines of 700MB of heap
to using around 2.5 GB of heap after 25 edits and 17GB (!) of heap
shortly before stopping at 250 `pubspec.yaml` edits.
After the editing stopped (and clicking the GC button in observatory)
the heap usage went down to ~650MB heap used.

This fixes the problem by clearing the `declarationsTracker` on the
`afterContextsDestroyed` call too. In the same test it stays at around
300-700MB of heap.

Possibly related to:
#48788
#52447

Change-Id: Ia38cc946a1f36fa8c5b6804f79cbc8dd96c21030
Reviewed-on: https://dart-review.googlesource.com/c/sdk/+/309722
Reviewed-by: Brian Wilkerson <brianwilkerson@google.com>
Reviewed-by: Konstantin Shcheglov <scheglov@google.com>
Commit-Queue: Jens Johansen <jensj@google.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
analyzer-completion Issues with the analysis server's code completion feature area-analyzer Use area-analyzer for Dart analyzer issues, including the analysis server and code completion. P2 A bug or feature request we're likely to work on type-performance Issue relates to performance or code size
Projects
None yet
Development

No branches or pull requests

6 participants