Observation 1: The legacy protocol answered completion requests via a
`server.resolveForCompletion` call, and the LSP protocol answered
completion requests via a `server.getResolvedUnit` call where the idea
is that resolving for completion requires less and is therefore faster.
Solution: Make the LSP protocol use `server.resolveForCompletion` too.
Observation 2: Completion requests often come right after change request
making timing important and the `await driver.applyPendingFileChanges()`
call done in the analysis server "pushed" the timing making the
`server.resolveForCompletion` actually finished after it had already
resolved the whole thing.
Solution: Don't do that - the driver adds it to the queue of work, the
work is done later in `performWork` called from
`AnalysisDriverScheduler._run` where `_applyPendingFileChanges` is
always called anyway (which is the call that completes the
`applyPendingFileChanges`call).
Observation 3: If there is no change yet to be processed, a
`resolveForCompletion` call is slower than a `getResolvedUnit` because
the resolved unit is cached (assuming it's a priority file) and the
`resolveForCompletion` call always parses the file again.
Solution: Respond to the `resolveForCompletion` call with the resolved
unit data if it's available in the cache. The cache is always cleared
when changes happen anyway.
Benchmarks on this stuff is a bit weird because it's timing related - so
while I'd say this is overall just better there are also runs where we
get "bad timing" and the runtimes are therefore not better. In an
attempt to clear it up I've run the benchmarks 25 times each, and
attempted to put the data in two different buckets as needed.
*lsp_type_in_big_file of size 16,000*
```
Fully done after last type (ms):
Difference at 95.0% confidence
-1419.2 +/- 322.074
-16.8866% +/- 3.83225%
(Student's t, pooled s = 566.238)
Whole typing time (ms):
Difference at 95.0% confidence
-1418.88 +/- 322.037
-13.9661% +/- 3.16983%
(Student's t, pooled s = 566.172)
Uncancelled completion response time (ms):
Difference at 95.0% confidence
-1590.48 +/- 682.753
-28.0194% +/- 12.028%
(Student's t, pooled s = 1200.35)
```
The `Uncancelled completion response time` has a big "+/-" so attempting
to "good and bad bucketize" it I get:
good bucket:
```
Difference at 95.0% confidence
-1929.8 +/- 347.712
-35.9528% +/- 6.47797%
(Student's t, pooled s = 543.261)
```
bad bucket (though truthfully there wasn't a clear cutoff before):
```
No difference proven at 95.0% confidence
```
which sort of makes sense: If the completion runs before a (new) change
starts processing we now `resolveForCompletion` instead which is faster,
but if completion runs after the change has started processing we
essentially - both before and after - do nothing (except wait for the
calculation to finish) because we just load the data from cache.
*lsp_type_in_big_file_ask_for_completion, 16,000*
```
Completion #1 (ms):
No difference proven at 95.0% confidence
```
Ehh. There's a clear cutoff in the now, so taking the 8 (how the cutoff
happens to be) fastest from each I get
```
Difference at 95.0% confidence
-1034.12 +/- 75.3617
-37.673% +/- 2.74542%
(Student's t, pooled s = 70.2673)
```
Moving on.
```
Completion #2 (ms):
Difference at 95.0% confidence
-1076.28 +/- 178.446
-37.2601% +/- 6.17769%
(Student's t, pooled s = 313.726)
```
here 2 in the "now" has bad timing, removing them from the statistics
gives
```
Difference at 95.0% confidence
-1182.39 +/- 104.543
-40.9334% +/- 3.6192%
(Student's t, pooled s = 179.748)
```
Moving on.
```
Completion #3 (ms):
Difference at 95.0% confidence
-735.6 +/- 292.553
-25.6471% +/- 10.2%
(Student's t, pooled s = 514.336)
and removing the 8 bad ones:
Difference at 95.0% confidence
-1195.69 +/- 99.305
-41.6884% +/- 3.46232%
(Student's t, pooled s = 156.306)
```
Continuing like this:
```
Completion #4 (ms):
Difference at 95.0% confidence
-948.4 +/- 265.704
-32.9887% +/- 9.24214%
(Student's t, pooled s = 467.134)
and removing the 5 bad ones:
Difference at 95.0% confidence
-1252.87 +/- 86.5425
-43.5793% +/- 3.01026%
(Student's t, pooled s = 143.022)
Completion #5 (ms):
Difference at 95.0% confidence
-1067.88 +/- 199.266
-37.0011% +/- 6.90439%
(Student's t, pooled s = 350.329)
and removing the 3 bad ones:
Difference at 95.0% confidence
-1236.76 +/- 69.5776
-42.8527% +/- 2.4108%
(Student's t, pooled s = 118.18)
```
Moving on to the "Completion without change" I realize just now that the
benchmark for the first entry is broken - it doesn't wait until the
previous change has been processed, meaning that in the 3 cases where we
got bad timing in "Completion #5 (ms)" we see about the same result as
before, but in the 22 other cases we see bad results because it has to
wait until the previous change has been processed. For the remaining
(2-5) there is no virtually change which makes sense because both before
and now it just fetches the resolved unit from cache.
*legacy_type_in_big_file_ask_for_completion*
```
Completion #1 (ms):
Difference at 95.0% confidence
-1817.08 +/- 60.6836
-48.0638% +/- 1.60515%
(Student's t, pooled s = 106.688)
Completion #2 (ms):
Difference at 95.0% confidence
-2208.56 +/- 48.4844
-55.4647% +/- 1.21761%
(Student's t, pooled s = 85.2403)
Completion #3 (ms):
Difference at 95.0% confidence
-2159.68 +/- 69.4145
-53.0717% +/- 1.70578%
(Student's t, pooled s = 122.037)
Completion #4 (ms):
Difference at 95.0% confidence
-2264.44 +/- 73.2112
-53.5455% +/- 1.73117%
(Student's t, pooled s = 128.712)
Completion #5 (ms):
Difference at 95.0% confidence
-2147.4 +/- 68.5023
-50.9254% +/- 1.62453%
(Student's t, pooled s = 120.434)
```
The first "Completion without change" suffers from the same as before
and I will skip it here.
```
Completion without change #2 (ms):
Difference at 95.0% confidence
-416.28 +/- 28.2024
-61.3512% +/- 4.15646%
(Student's t, pooled s = 49.5826)
Completion without change #3 (ms):
Difference at 95.0% confidence
-687.24 +/- 21.9848
-92.6499% +/- 2.96387%
(Student's t, pooled s = 38.6514)
Completion without change #4 (ms):
Difference at 95.0% confidence
-637.32 +/- 26.482
-95.2703% +/- 3.95868%
(Student's t, pooled s = 46.5579)
Completion without change #5 (ms):
Difference at 95.0% confidence
-702.32 +/- 18.7277
-95.8301% +/- 2.55535%
(Student's t, pooled s = 32.925)
```
I don't know why there doesn't appear to be any timing related issues
here (maybe sending and receiving the entire big file (in legacy vs in
lsp where a small 'diff' is send) taking more time pushes the timing,
but I'm guessing) - nor do I know why now "Completion without change #2"
is slower (~250 ms) than the subsequent ones (~30 ms).
Change-Id: I4c21d658efccbcf197eedb69f466b2942b78c4b9
Reviewed-on: https://dart-review.googlesource.com/c/sdk/+/457364
Reviewed-by: Brian Wilkerson <brianwilkerson@google.com>
Reviewed-by: Johnni Winther <johnniwinther@google.com>
Commit-Queue: Jens Johansen <jensj@google.com>
Jens Johansen
6b4210d9ca