Version 2 completions seem to be much slower

[keithbrink]

Before version 2, completions would take less than a second, most of the time showing up as fast as I can type. Now, they are taking a few seconds:

[joel-wenzel]

Cant speak for @keithbrink but I have noticed a huge change between versions 2.0.4 and 2.0.5. So maybe a regression in 2.0.5? Downgrading to 2.0.4 has a much smoother experience for me

[ascott18]

Similar to #4005

[johnsoncodehk]

I'm looking for a reproduced case to investigate this issue. I've tried reproducing the problem on elk but no luck. (Not a small project)

[johnsoncodehk]

I would like to confirm if volarjs/volar.js@f041c79 is the cause, can you try this version if it solves the problem?

volar-2.0.5-patch.1.vsix.zip

[joel-wenzel]

@johnsoncodehk Still seems relatively slow using that patch instead of the 2.0.4 version

[zcf0508]

I find that the time-consuming of the completionInfo command has been an increase after updating to v2.0.5. This is the log detail.

---

v2.0.5

Info 1516 [11:50:12.797] request:
    {
      "seq": 172,
      "type": "request",
      "command": "completionInfo",
      "arguments": {
        "file": "/Users/project_path/src/views/home/index.vue",
        "line": 1522,
        "offset": 12,
        "includeExternalModuleExports": true,
        "includeInsertTextCompletions": true,
        "triggerCharacter": ".",
        "triggerKind": 2
      }
    }
Info 1517 [11:50:12.798] Starting updateGraphWorker: Project: /Users/project_path/jsconfig.json
Info 1518 [11:50:16.988] Finishing updateGraphWorker: Project: /Users/project_path/jsconfig.json Version: 10:3090 structureChanged: false structureIsReused:: Completely Elapsed: 4189.9907331466675ms
Info 1519 [11:50:16.988] Different program with same set of files
Info 1520 [11:50:17.006] getCompletionData: Get current token: 0.017059326171875
Info 1521 [11:50:17.011] getCompletionData: Is inside comment: 4.906465530395508
Info 1522 [11:50:17.016] getCompletionData: Get previous token: 5.071619033813477
Info 1523 [11:50:17.019] getCompletionsAtPosition: isCompletionListBlocker: 0.002933502197265625
Info 1524 [11:50:17.645] getCompletionData: Semantic work: 625.992335319519
Info 1525 [11:50:17.659] getCompletionsAtPosition: getCompletionEntriesFromSymbols: 7.434052467346191
Perf 1526 [11:50:17.659] 172::completionInfo: elapsed time (in milliseconds) 4861.8858
Info 1527 [11:50:17.660] response:
    {"seq":0,"type":"response","command":"completionInfo","request_seq":172,"success":true,"performanceData":{"updateGraphDurationMs":4189.9907331466675},"body":{"flags":0,"isGlobalCompletion":false,"isMemberCompletion":true,"isNewIdentifierLocation":false,"entries":[
      200+ item
    ]}}

v2.0.4

Info 885  [11:56:49.135] request:
    {
      "seq": 72,
      "type": "request",
      "command": "completionInfo",
      "arguments": {
        "file": "/Users/project_path/src/views/home/index.vue",
        "line": 1522,
        "offset": 10,
        "includeExternalModuleExports": true,
        "includeInsertTextCompletions": true,
        "triggerCharacter": ".",
        "triggerKind": 2
      }
    }
Info 886  [11:56:49.135] Starting updateGraphWorker: Project: /Users/project_path/jsconfig.json
Info 887  [11:56:49.297] Finishing updateGraphWorker: Project: /Users/project_path/jsconfig.json Version: 5:312 structureChanged: false structureIsReused:: Completely Elapsed: 161.7956485748291ms
Info 888  [11:56:49.297] Different program with same set of files
Info 889  [11:56:49.319] getCompletionData: Get current token: 0.02961254119873047
Info 890  [11:56:49.325] getCompletionData: Is inside comment: 5.706437110900879
Info 891  [11:56:49.331] getCompletionData: Get previous token: 5.605751037597656
Info 892  [11:56:49.333] getCompletionsAtPosition: isCompletionListBlocker: 0.0025234222412109375
Info 893  [11:56:49.915] getCompletionData: Semantic work: 581.1785526275635
Info 894  [11:56:49.942] getCompletionsAtPosition: getCompletionEntriesFromSymbols: 20.872543334960938
Perf 895  [11:56:49.943] 72::completionInfo: elapsed time (in milliseconds) 808.0886
Info 896  [11:56:49.943] response:
    {"seq":0,"type":"response","command":"completionInfo","request_seq":72,"success":true,"performanceData":{"updateGraphDurationMs":161.7956485748291},"body":{"flags":0,"isGlobalCompletion":false,"isMemberCompletion":true,"isNewIdentifierLocation":false,"entries":[
      200+ item
    ]}}

[skywalker512]

I'm looking for a reproduced case to investigate this issue. I've tried reproducing the problem on elk but no luck. (Not a small project)

I tried elk and found no significant difference between 2.0.5 and 2.0.4, but the issue was reproduced in the following repository.
(However, it seems that elk also has this issue, as seen from the flame graph, just not as prominent.)

https://github.com/skywalker512/voalr-2-reproduced

It is the same operation, vscode prompts the members of a certain object.

CPU profile has been sent to your email. @johnsoncodehk

• 2.0.4

• 2.0.5

[johnsoncodehk]

@skywalker512 I can confirm this, thanks!

[johnsoncodehk]

Fixed by volarjs/volar.js@7be3ea4, it turns out that TS plugin should never proxy getScriptVersion.

volarjs/volar.js@7be3ea4#diff-3a0f14bc13ef75cf8bc9812cecdb89c5374109739247662c09f5ed4afa55f9dbL99-L105

This will introduce a regression. When the vue file holding global types is deleted (usually the first open vue file), the next taker will not be able to update its virtual code in time to inject global types before its content is changed. This can be temporarily solved by restarting the TS server.