commit f6fcd37cb88a974a24ef48510f2cbf00b8560279
author Jens Johansen <jensj@google.com> Mon Mar 31 23:29:39 2025 -0700
committer Commit Queue <dart-scoped@luci-project-accounts.iam.gserviceaccount.com> Mon Mar 31 23:29:39 2025 -0700
tree a95edda6a746eeaab147bd022befb0b39d53e19b
parent fdc469778c05cb869a8ea9c19db30ba1eeebcefb

[analyzer] Add benchmark with plugin that times out

TL;DR: Add benchmark that shows the Dart 3.7
(https://dart-review.googlesource.com/c/sdk/+/386581 specifically)
introduced a regression.

Details: We've observed that sometimes the plugin that users has
installed times out (takes > 500 ms to answer).

This benchmark simulates that and shows the worse handling of this
introduced in Dart 3.7.

Running 10 iterations each of lsp_with_plugin_that_times_out.dart with
params 10, ImportChain:

Comparing 3.5.4 with 3.6.2

```
Initial analysis: -7.1855% +/- 2.9168% (-0.09 +/- 0.04)
peak virtual memory size: 11.8795% +/- 1.6185% (313.00 +/- 42.64)
total program size (virtual): 12.4293% +/- 1.2818% (323.10 +/- 33.32)
peak resident set size ("high water mark"): -7.4081% +/- 0.9050% (-38.90 +/- 4.75)
size of memory portions (rss): -6.3154% +/- 1.3641% (-32.00 +/- 6.91)
```

I'll note that this is only 10 files and we probably shouldn't put too
much weight on the initial analysis time here. Equivalently memory
probably isn't super interesting.

Comparing 3.6.2 with 3.7.2

```
Initial analysis: -45.8697% +/- 2.7193% (-0.53 +/- 0.03)
Completion call 1: 652.8573% +/- 1.3303% (0.97 +/- 0.00)
codeAction call 1: -0.7637% +/- 0.5174% (-0.01 +/- 0.01)
Completion call 2: 807.2503% +/- 0.7116% (0.89 +/- 0.00)
codeAction call 2: 0.2624% +/- 0.0456% (0.00 +/- 0.00)
Completion call 3: 868.9361% +/- 0.3199% (0.90 +/- 0.00)
codeAction call 3: 0.1433% +/- 0.0287% (0.00 +/- 0.00)
peak virtual memory size: -7.1307% +/- 3.4799% (-210.20 +/- 102.58)
total program size (virtual): -8.1674% +/- 3.5673% (-238.70 +/- 104.26)
peak resident set size ("high water mark"): -1.2546% +/- 0.7151% (-6.10 +/- 3.48)
size of memory portions (rss): -7.6891% +/- 0.9209% (-36.50 +/- 4.37)
```

Again I'll note that this is only 10 files and we probably shouldn't put
too much weight on the initial analysis time here - although we've seen
this improve in other benchmarks too so I do believe we have an
improvement here.
And again memory probably isn't super interesting because of the few
files.
The codeAction calls are basically the same which makes sense: In all
cases it's dominated by the plugin that times out.
The codeAction call does two calls to the plugin and it takes around
1000 ms (a timeout of 500 ms on each plugin call).

Here we see the regression in 3.7 clearly though (cut-out from above):

```
Completion call 1: 652.8573% +/- 1.3303% (0.97 +/- 0.00)
Completion call 2: 807.2503% +/- 0.7116% (0.89 +/- 0.00)
Completion call 3: 868.9361% +/- 0.3199% (0.90 +/- 0.00)
```

Because of https://dart-review.googlesource.com/c/sdk/+/386581 we only
do one request at a time. Before we would interleave the requests,
something like this:

```
Request 1: codeAction:
|--|waiting for plugin|--|waiting for plugin|--|

Request 2: completion:
 |..--|
```

(I'm trying to ascii-draw that when the codeAction is just awaiting the
plugin the completion request can be executed)

Now instead we're doing this:

```
Request 1: codeAction:
|--|waiting for plugin|--|waiting for plugin|--|

Request 2: completion:
 |..............................................--|
```

(I'm trying to ascii-draw that when the codeAction has to finish before
the completion request can be executed)

I'll also note that while it's here shown trough a plugin that times out
the same will likely happen in other circumstances as well. E.g. the
completion resolves with a special call `resolveForCompletion` which in
`performWork` gets priority over other things - but when not
interleaving requests that has very little effect.

For good measure, comparing 3.7.2 with HEAD

```
Completion call 1: 0.6851% +/- 0.2074% (0.01 +/- 0.00)
codeAction call 1: 0.6962% +/- 0.1876% (0.01 +/- 0.00)
peak virtual memory size: -11.7293% +/- 4.7947% (-321.10 +/- 131.26)
total program size (virtual): -12.1763% +/- 4.9125% (-326.80 +/- 131.85)
peak resident set size ("high water mark"): -14.7469% +/- 0.6980% (-70.80 +/- 3.35)
size of memory portions (rss): -10.4518% +/- 0.8927% (-45.80 +/- 3.91)
```

Not a whole lot of change for the time-related things on this benchmark.

Running legacy_with_plugin_that_times_out.dart shows the same thing
(here there's only 1 plugin call instead of 2 though; here only looking
at completion calls):

```
Comparing 3.5.4 with 3.6.2
Completion call 1: -6.1695% +/- 3.6147% (-0.03 +/- 0.02)
Completion call 2: -14.4462% +/- 8.8828% (-0.02 +/- 0.01)
Completion call 3: -16.7707% +/- 7.5412% (-0.03 +/- 0.01)

Comparing 3.6.2 with 3.7.2
Completion call 1: 139.2436% +/- 3.8814% (0.70 +/- 0.02)
Completion call 2: 1128.6580% +/- 14.8207% (1.41 +/- 0.02)
Completion call 3: 589.1425% +/- 11.9186% (0.78 +/- 0.02)

Comparing 3.7.2 with HEAD
no change on completion calls.
```

For fun, lets try to comment out `await completer.future;` in
`pkg/analysis_server/lib/src/server/message_scheduler.dart` that was
introduced in https://dart-review.googlesource.com/c/sdk/+/386581
(again only looking at completion calls):

legacy_with_plugin_that_times_out.dart:

```
Comparing 3.7.2 with HEAD (with commented out await)
Completion call 1: -58.5720% +/- 1.9196% (-0.70 +/- 0.02)
Completion call 2: -82.8149% +/- 1.1050% (-1.27 +/- 0.02)
Completion call 3: -85.6439% +/- 1.5128% (-0.79 +/- 0.01)
```

If looking at the values instead of the percent it looks to almost undo
the change from 3.6.2 to 3.7.2, so let's for good measure compare 3.6.2
with that:

```
Comparing 3.6.2 with HEAD (with commented out await)
Completion call 2: 95.7654% +/- 11.4279% (0.12 +/- 0.01)
```

So one of the calls is slower, but just double, not 10x. I haven't
looked into why.

And for lsp_with_plugin_that_times_out.dart:

```
Comparing 3.7.2 with HEAD (with commented out await)
Completion call 1: -92.9578% +/- 0.5505% (-1.04 +/- 0.01)
Completion call 2: -99.6372% +/- 0.0534% (-1.00 +/- 0.00)
Completion call 3: -99.6370% +/- 0.0429% (-1.00 +/- 0.00)
```

The 1000 ms wait time is gone.

And again let's for good measure compare 3.6.2 with that:

```
Comparing 3.6.2 with HEAD (with commented out await)
Completion call 1: -45.4578% +/- 2.4320% (-0.07 +/- 0.00)
Completion call 2: -96.6303% +/- 0.2481% (-0.11 +/- 0.00)
Completion call 3: -96.2054% +/- 0.3875% (-0.10 +/- 0.00)
```

Here all the completion calls are faster. I haven't looked into why.

Change-Id: I7c312f77b51bb4df68eedeb9bc6e27c2b0175cbf
Reviewed-on: https://dart-review.googlesource.com/c/sdk/+/418263
Commit-Queue: Jens Johansen <jensj@google.com>
Reviewed-by: Phil Quitslund <pquitslund@google.com>