[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 <[email protected]>
Reviewed-by: Phil Quitslund <[email protected]>

Author: jensjoha

pkg/analysis_server/tool/benchmark_tools/big_chain_benchmark/files/copy_me/plugin.dart

@@ -0,0 +1,36 @@
+// Copyright (c) 2025, the Dart project authors. Please see the AUTHORS file
+// for details. All rights reserved. Use of this source code is governed by a
+// BSD-style license that can be found in the LICENSE file.
+
+import 'dart:isolate';
+
+void main(List<String> args, SendPort sendPort) {
+  var receivePort = ReceivePort();
+  sendPort.send(receivePort.sendPort);
+  receivePort.listen((data) async {
+    var requestTime = DateTime.now().millisecondsSinceEpoch;
+    var requestMap = data as Map<String, Object>;
+    var id = requestMap["id"];
+    var method = requestMap["method"];
+
+    if (method == "plugin.versionCheck") {
+      var jsonObject = <String, Object>{};
+      jsonObject["id"] = id!;
+      jsonObject["requestTime"] = requestTime;
+      Map<String, Object> resultData = {};
+      resultData["isCompatible"] = true;
+      resultData["name"] = "benchmark_helper_plugin";
+      resultData["version"] = "0.0.1";
+      resultData["interestingFiles"] = ["**/*.dart"];
+      jsonObject["result"] = resultData;
+      sendPort.send(jsonObject);
+    } else {
+      await Future.delayed(const Duration(seconds: 1));
+      var jsonObject = <String, Object>{};
+      jsonObject["id"] = id!;
+      jsonObject["error"] = "too slow working on $method";
+      jsonObject["requestTime"] = requestTime;
+      sendPort.send(jsonObject);
+    }
+  });
+}

pkg/analysis_server/tool/benchmark_tools/big_chain_benchmark/legacy_with_plugin_that_times_out.dart

@@ -0,0 +1,109 @@
+// Copyright (c) 2025, the Dart project authors. Please see the AUTHORS file
+// for details. All rights reserved. Use of this source code is governed by a
+// BSD-style license that can be found in the LICENSE file.
+
+import '../language_server_benchmark.dart';
+import '../legacy_messages.dart';
+import 'utils.dart';
+
+/// 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.
+Future<void> main(List<String> args) async {
+  await runHelper(
+    args,
+    LegacyWithPluginThatTimesOutBencmark.new,
+    runAsLsp: false,
+    includePlugin: true,
+    // The number of files isn't important here.
+    numberOfFileOptions: [10],
+  );
+}
+
+class LegacyWithPluginThatTimesOutBencmark extends DartLanguageServerBenchmark {
+  @override
+  final Uri rootUri;
+  @override
+  final Uri cacheFolder;
+
+  final RunDetails runDetails;
+
+  LegacyWithPluginThatTimesOutBencmark(
+    super.args,
+    this.rootUri,
+    this.cacheFolder,
+    this.runDetails,
+  ) : super(useLspProtocol: false);
+
+  @override
+  LaunchFrom get launchFrom => LaunchFrom.Dart;
+
+  @override
+  Future<void> afterInitialization() async {
+    // The main file is an open tab.
+    await send(
+      LegacyMessages.setPriorityFiles(largestIdSeen + 1, [
+        runDetails.mainFile.uri,
+      ]),
+    );
+
+    // Does this change anything?
+    await Future.delayed(const Duration(milliseconds: 100));
+
+    // The user starts typing - types 'ge' in the empty line in main...
+    await send(
+      LegacyMessages.updateContent(
+        largestIdSeen + 1,
+        runDetails.mainFile.uri,
+        runDetails.mainFileTypingContent,
+      ),
+    );
+
+    for (var i = 0; i < 3; i++) {
+      // Send 'getAssists'...
+      var getAssistsStopwatch = Stopwatch()..start();
+      var getAssistsFuture = (await send(
+        LegacyMessages.getAssists(
+          largestIdSeen + 1,
+          runDetails.orderedFileCopies.last.uri,
+          runDetails.typingAtOffset,
+        ),
+      ))!.completer.future.then((_) => getAssistsStopwatch.stop());
+
+      // ...and ask for completion.
+      var firstCompletionStopwatch = Stopwatch()..start();
+      var completionResult =
+          await (await send(
+            LegacyMessages.getSuggestions2(
+              largestIdSeen + 1,
+              runDetails.mainFile.uri,
+              runDetails.typingAtOffset,
+            ),
+          ))!.completer.future;
+      firstCompletionStopwatch.stop();
+      List<dynamic> completionItems =
+          completionResult['result']['suggestions'] as List;
+      durationInfo.add(
+        DurationInfo(
+          'Completion call ${i + 1}',
+          firstCompletionStopwatch.elapsed,
+        ),
+      );
+      if (verbosity >= 0) {
+        print(
+          'Got ${completionItems.length} completion items '
+          'in ${firstCompletionStopwatch.elapsed}',
+        );
+      }
+
+      // This should be complete already.
+      await getAssistsFuture;
+
+      // This is not really the interesting part (it's slow because of the plugin
+      // that times out), but let's include it anyway.
+      durationInfo.add(
+        DurationInfo('getAssists call ${i + 1}', getAssistsStopwatch.elapsed),
+      );
+    }
+  }
+}

pkg/analysis_server/tool/benchmark_tools/big_chain_benchmark/lsp_with_plugin_that_times_out.dart

@@ -0,0 +1,110 @@
+// Copyright (c) 2025, the Dart project authors. Please see the AUTHORS file
+// for details. All rights reserved. Use of this source code is governed by a
+// BSD-style license that can be found in the LICENSE file.
+
+import '../language_server_benchmark.dart';
+import '../lsp_messages.dart';
+import 'utils.dart';
+
+/// 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.
+Future<void> main(List<String> args) async {
+  await runHelper(
+    args,
+    LspWithPluginThatTimesOutBencmark.new,
+    runAsLsp: true,
+    includePlugin: true,
+    // The number of files isn't important here.
+    numberOfFileOptions: [10],
+  );
+}
+
+class LspWithPluginThatTimesOutBencmark extends DartLanguageServerBenchmark {
+  @override
+  final Uri rootUri;
+  @override
+  final Uri cacheFolder;
+
+  final RunDetails runDetails;
+
+  LspWithPluginThatTimesOutBencmark(
+    super.args,
+    this.rootUri,
+    this.cacheFolder,
+    this.runDetails,
+  ) : super(useLspProtocol: true);
+
+  @override
+  LaunchFrom get launchFrom => LaunchFrom.Dart;
+
+  @override
+  Future<void> afterInitialization() async {
+    await send(
+      LspMessages.open(runDetails.mainFile.uri, 1, runDetails.mainFile.content),
+    );
+
+    // Does this change anything?
+    await Future.delayed(const Duration(milliseconds: 100));
+
+    // The user starts typing - types 'ge' in the empty line in main...
+    await send(
+      LspMessages.didChange(
+        runDetails.mainFile.uri,
+        version: 2,
+        insertAtLine: 3 /* line 0-indexed; at blank line inside main */,
+        insertAtCharacter: 2,
+        insert: 'ge',
+      ),
+    );
+
+    for (var i = 0; i < 3; i++) {
+      // Send 'textDocument/codeAction'...
+      var codeActionStopwatch = Stopwatch()..start();
+      var codeActionFuture = (await send(
+        LspMessages.codeAction(
+          largestIdSeen + 1,
+          runDetails.mainFile.uri,
+          line: 3,
+          character: 4 /* after the 'ge' just typed */,
+        ),
+      ))!.completer.future.then((_) => codeActionStopwatch.stop());
+
+      // ...and ask for completion.
+      var firstCompletionStopwatch = Stopwatch()..start();
+      var completionResult =
+          await (await send(
+            LspMessages.completion(
+              runDetails.mainFile.uri,
+              largestIdSeen + 1,
+              line: 3,
+              character: 4 /* after the 'ge' just typed */,
+            ),
+          ))!.completer.future;
+      firstCompletionStopwatch.stop();
+      List<dynamic> completionItems =
+          completionResult['result']['items'] as List;
+      durationInfo.add(
+        DurationInfo(
+          'Completion call ${i + 1}',
+          firstCompletionStopwatch.elapsed,
+        ),
+      );
+      if (verbosity >= 0) {
+        print(
+          'Got ${completionItems.length} completion items '
+          'in ${firstCompletionStopwatch.elapsed}',
+        );
+      }
+
+      // This should be complete already.
+      await codeActionFuture;
+
+      // This is not really the interesting part (it's slow because of the plugin
+      // that times out), but let's include it anyway.
+      durationInfo.add(
+        DurationInfo('codeAction call ${i + 1}', codeActionStopwatch.elapsed),
+      );
+    }
+  }
+}