Delays in running PowerShell code or F8 not working at all

[arievanderwende]

When selecting PowerShell code in Visual Studio Code and running it either via right click -> Run Selection or by pressing F8, it sometimes takes a long time for the code to run and sometimes it doesn't run at all, whereas other moments (rarely unfortunately) the code runs straight away. There is no other keybinding to F8. It doesn't matter how much code is selected either. It can be as little as: $test = 'Test'. I have hardly any modules loaded; the default Windows modules, AzureRM and AzureAD. I have tried with ScriptAnalyzer disabled ("powershell.scriptAnalysis.enable": false), but that didn't help. The issue is so bad currently, that I just copy/paste the code into the integrated PowerShell window to run it, which works fine, but which is a pain when you need to run parts which consist of multiple lines of code.

Visual Studio Code:
Version: 1.31.1 (system setup)
Commit: 1b8e8302e405050205e69b59abb3559592bb9e60
Date: 2019-02-12T02:20:54.427Z
Electron: 3.1.2
Chrome: 66.0.3359.181
Node.js: 10.2.0
V8: 6.6.346.32
OS: Windows_NT x64 6.3.9600

PowerShell extension: 1.11.0

[SydneyhSmith]

Thanks for reporting this @atyourservers ! It would be really helpful if you could provide logs if this happens again so that we can better diagnose the issues--instructions for how to do this are here

[arievanderwende]

@SydneyhSmith please find the logs attached. I had to redact them quite a bit. Tested it with some test files. Started around 9:20 until 9:35, then had some calls and if I remember correctly, I later tried to run a few more commands, closed everything, redacted the logs and here you go. The issue occurred various times, so hopefully the logs are helpful. Looking forward to hearing from you.

logs.zip

[SydneyhSmith]

@atyourservers thanks for providing the logs that always helps! There is nothing obvious about your environment that would be causing issues but we have had other reports of performance issues that we are hoping to solve soon and this is likely related.

[arievanderwende]

When I just paste code in the integrated PowerShell window it runs straight. It only happens when I try to execute code from the editor window by pressing F8 or via right click -> Run Selection. It's like there is a process of some sort which tries to do something to the code, such as validation, which takes minutes to run. I thought this could be the ScriptAnalyzer, but disabling it didn't have any effect on the issue. Seeing that it sometimes does work fine for a few minutes maximum, it's like a process gets stuck sometimes in the background. More people here are experiencing the same issue. I love Visual Studio Code and the PowerShell extension, but this issue is forcing us to use different tools. Hopefully it can be tackled soon.

[SydneyhSmith]

@atyourservers some people have had success with associating performance issues to code lens, disabling that might be something worth trying. More likely this is due to architectural challenges that we are hoping to resolve soon.

[Mike-Crowley]

I've had this same issue for at least a year with VS Code. As I type this, I'm waiting for an F8 command to run:

$date = get-date

It's been nearly 10 minutes, so now I'm going to have to close and re-open the terminal window, losing all of the content in memory that I've been working on. This happens at least once a day.

It is incredibly frustrating that this software is so unstable while also being touted as the obvious replacement for PowerShell ISE. ISE has been very stable since 1.0.

[rkeithhill]

@atyourservers Looking at your log file, it seems that SymbolReference CodeLens comand resolve results are taking a long time but those requests are supposed to run async (in another runspace) and return results "out-of-band":

 Index Timestamp                  TID  Elapsed (mS) Message
 ----- ---------                  ---  ------------ -------
  3680 2019-02-22 10:14:04.702     19        406351 Name: codeLens/resolve Id: 85, DataSize: 2812
  2592 2019-02-22 10:02:14.489     19        367679 Name: codeLens/resolve Id: 80, DataSize: 2812
  1799 2019-02-22 09:31:26.351     19        354950 Name: codeLens/resolve Id: 28, DataSize: 3258
  1106 2019-02-22 09:25:30.258     19        309606 Name: codeLens/resolve Id: 4, DataSize: 3257
  3124 2019-02-22 10:07:18.058     19        303558 Name: codeLens/resolve Id: 81, DataSize: 2812
  1854 2019-02-22 09:32:54.709     57         88330 Name: evaluate Id: 36, DataSize: 136
  1927 2019-02-22 09:55:34.974     47          7053 Name: evaluate Id: 56, DataSize: 136
  2024 2019-02-22 09:55:55.716      8          2161 Name: evaluate Id: 75, DataSize: 136
  1999 2019-02-22 09:55:47.591     47          1223 Name: evaluate Id: 69, DataSize: 136

The evaluate is executing:

        "expression": "$userName = 'XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX' # Some Comment\r\n$password = 'XXXXXXXXXXPasswordRedactedXXXXXXXXXX'\r\n#$userName = 'YYYYYYYY-YYYY-YYYY-YYYY-YYYYYYYYYYYY' # Some Comment\r\n#$password = 'YYYYYYYYYYPasswordRedactedYYYYYYYYYYY'\r\n$aesKey = 00,00,KeyRedacted,00,00\r\n$securePassword = $password | ConvertTo-SecureString -Key $aesKey\r\n$securePassword.MakeReadOnly()\r\n$environment = 'e'\r\n#$keyVaultName = 'name-of-some-key-vault'\r\n$location = 'northeurope'\r\n$resourceGroupName = 'name-of-some-resource-group'\r\n#$resourceGroupName = 'name-of-some-other-resource-group'\r\n#$subnetName = ''\r\n$subscriptionName = 'Name Of The Subscription'\r\n#$subscriptionId = 'IIIIIIII-IIII-IIII-IIII-IIIIIIIIIIII'\r\n$virtualNetworkName = 'name-of-some-vnet'\r\nConnect-AzureSubscription -Password $securePassword -SubscriptionName $subscriptionName -UserName $userName"

Does this correspond to one of your lengthy F8 atttempts?

BTW the evaluate above that takes ~88 secs shows how this request is executed async:

Index Timestamp            ThreadId LogMessageType Message
----- ---------            -------- -------------- -------
 1834 2/22/2019 9:31:26 AM       19        Request Name: evaluate Id: 36, DataSize: 1017
 1835 2/22/2019 9:31:26 AM       19   Notification Name: powerShell/executionStatusChanged Source: Server, DataSize: 369
 1836 2/22/2019 9:31:26 AM       19            Log Attempting to execute command(s):    ...
 1837 2/22/2019 9:31:26 AM       19        Request Name: textDocument/hover Id: 37, DataSize: 341
 1838 2/22/2019 9:31:26 AM       19            Log Resolved path: c:\Users\MyUserName\Documents\CustomerName\Demo-App...
 1839 2/22/2019 9:31:26 AM       19       Response Name: textDocument/hover Id: 37, DataSize: 128
 1840 2/22/2019 9:31:26 AM       28            Log Session state changed --    ...
 1841 2/22/2019 9:31:26 AM       19   Notification Name: $/cancelRequest Source: Client, Id: 37
 1842 2/22/2019 9:31:26 AM       19            Log MessageDispatcher: No handler registered for Event type '$/cancelR...
 1843 2/22/2019 9:31:26 AM       19        Request Name: textDocument/hover Id: 38, DataSize: 341
 1844 2/22/2019 9:31:26 AM       19            Log Resolved path: c:\Users\MyUserName\Documents\CustomerName\Demo-App...
 1845 2/22/2019 9:31:26 AM       19       Response Name: textDocument/hover Id: 38, DataSize: 128
 1846 2/22/2019 9:31:26 AM       19   Notification Name: $/cancelRequest Source: Client, Id: 38
 1847 2/22/2019 9:31:26 AM       19            Log MessageDispatcher: No handler registered for Event type '$/cancelR...
 1848 2/22/2019 9:32:54 AM       28            Log Session state changed --    ...
 1849 2/22/2019 9:32:54 AM       19            Log Execution completed successfully., DataSize: 33
 1850 2/22/2019 9:32:54 AM       57            Log Attempting to execute command(s):    ...
 1851 2/22/2019 9:32:54 AM       19   Notification Name: powerShell/executionStatusChanged Source: Server, DataSize: 369
 1852 2/22/2019 9:32:54 AM       63            Log Session state changed --    ...
 1853 2/22/2019 9:32:54 AM       19   Notification Name: powerShell/executionStatusChanged Source: Server, DataSize: 372
 1854 2/22/2019 9:32:54 AM       57       Response Name: evaluate Id: 36, DataSize: 136
 1855 2/22/2019 9:32:54 AM       63            Log Session state changed --    ...
 1856 2/22/2019 9:32:54 AM       63            Log Execution completed successfully., DataSize: 33
 1857 2/22/2019 9:32:54 AM       19   Notification Name: powerShell/executionStatusChanged Source: Server, DataSize: 372

[rkeithhill]

The codeLens/resolve for symbol references appears to run synchronously - blocking all other LSP messages until the CA request finishes. These are consecutive LSP JsonRpc request/response messages pairs. Check out the timestamp diffs:

# $log = Parse-PsesLog .\EditorServices.log
# $log | Where {$_.LogMessageType -eq 'Request' -or $_.LogMessageType -eq 'Response' -or $_.LogMessageType -eq 'Notification'} | ft Index,Timestamp,TID,LogMessageType,Message

   46 2/22/2019 9:20:20 AM             Request Name: codeLens/resolve Id: 4, DataSize: 553
 1106 2/22/2019 9:25:30 AM            Response Name: codeLens/resolve Id: 4, DataSize: 3257
...
 1269 2/22/2019 9:25:31 AM             Request Name: codeLens/resolve Id: 28, DataSize: 554
 1799 2/22/2019 9:31:26 AM            Response Name: codeLens/resolve Id: 28, DataSize: 3258
...
 2062 2/22/2019 9:56:06 AM             Request Name: codeLens/resolve Id: 80, DataSize: 551
 2592 2/22/2019 10:02:14 AM           Response Name: codeLens/resolve Id: 80, DataSize: 2812
...
 2596 2/22/2019 10:02:14 AM            Request Name: codeLens/resolve Id: 81, DataSize: 551
 3124 2/22/2019 10:07:18 AM           Response Name: codeLens/resolve Id: 81, DataSize: 2812
...
 3152 2/22/2019 10:07:18 AM            Request Name: codeLens/resolve Id: 85, DataSize: 551
 3680 2/22/2019 10:14:04 AM           Response Name: codeLens/resolve Id: 85, DataSize: 2812

Between index 46 and 1106, we seem to be opening a lot of files:

 Index Timestamp                  TID LogMessageType  LogLevel    Message
 ----- ---------                  --- --------------  --------    -------
    46 2019-02-22 09:20:20.652     19 Request         Verbose     Name: codeLens/resolve Id: 4, DataSize: 553
    47 2019-02-22 09:20:20.673     19 Log             Verbose     Resolved path: c:\Users\MyUserName\Documents\Custo...
    48 2019-02-22 09:22:01.161      4 Log             Verbose     Attempting to execute command(s):
    49 2019-02-22 09:22:01.161     28 Log             Verbose     Session state changed --
    50 2019-02-22 09:22:01.176     28 Log             Verbose     Session state changed --
    51 2019-02-22 09:22:01.176     28 Log             Verbose     Execution completed successfully., DataSize: 33
    52 2019-02-22 09:22:24.514      6 Log             Verbose     Found 6 violations, DataSize: 18
    53 2019-02-22 09:22:24.544      6 Log             Verbose     Script analysis of c:\Users\MyUserName\Documents\C...
    54 2019-02-22 09:25:09.815     19 Log             Verbose     Resolved path: u:\My Documents\Repository\Azure\Cu...
    55 2019-02-22 09:25:09.840     19 Log             Verbose     Opened file on disk: u:\My Documents\Repository\Az...
    56 2019-02-22 09:25:09.840     19 Log             Verbose     Resolved path: u:\My Documents\Repository\Azure\Cu...
    57 2019-02-22 09:25:09.863     19 Log             Verbose     Opened file on disk: u:\My Documents\Repository\Az...
    58 2019-02-22 09:25:09.863     19 Log             Verbose     Resolved path: u:\My Documents\Repository\Azure\Cu...

... from here to 1105 it is Resolved path / ALL Open file on disk log messages that takes ~20 secoconds.

  1102 2019-02-22 09:25:30.029     19 Log             Verbose     Resolved path: u:\My Documents\Repository\Azure\Te...
  1103 2019-02-22 09:25:30.084     19 Log             Verbose     Opened file on disk: u:\My Documents\Repository\Az...
  1104 2019-02-22 09:25:30.084     19 Log             Verbose     Resolved path: u:\My Documents\Repository\Azure\Te...
  1105 2019-02-22 09:25:30.116     19 Log             Verbose     Opened file on disk: u:\My Documents\Repository\Az...
  1106 2019-02-22 09:25:30.258     19 Response        Verbose     Name: codeLens/resolve Id: 4, DataSize: 3257
  1107 2019-02-22 09:25:30.260     19 Notification    Verbose     Name: powerShell/executionStatusChanged Source: Se...
  1108 2019-02-22 09:25:30.263     19 Notification    Verbose     Name: powerShell/executionStatusChanged Source: Se...
  1109 2019-02-22 09:25:30.269     19 Notification    Verbose     Name: textDocument/publishDiagnostics Source: Serv...

There is a 1 min 40 sec gap between index 47 and 48. There is a 2 min 35 sec gap between index 53 and 54. Index 53 indicates script analysis has finished but it doesn't get a chance to send VSCode the diagnosit results until index 1109, almost three minutes later.

This is also puzzling, we get the request to resolve the codelens command here and begin symbol reference analysis:

    46 2019-02-22 09:20:20.652     19 Request         Verbose     Name: codeLens/resolve Id: 4, DataSize: 553
    47 2019-02-22 09:20:20.673     19 Log             Verbose     Resolved path: c:\Users\MyUserName\Documents\Custo...

but then there are only code analysis messages:

    48 2019-02-22 09:22:01.161      4 Log             Verbose     Attempting to execute command(s): prompt
    49 2019-02-22 09:22:01.161     28 Log             Verbose     Session state changed --
    50 2019-02-22 09:22:01.176     28 Log             Verbose     Session state changed --
    51 2019-02-22 09:22:01.176     28 Log             Verbose     Execution completed successfully., DataSize: 33
    52 2019-02-22 09:22:24.514      6 Log             Verbose     Found 6 violations, DataSize: 18
    53 2019-02-22 09:22:24.544      6 Log             Verbose     Script analysis of c:\Users\MyUserName\Documents\C...

Then after than 2 min 35 sec gap, we start back with the symbol reference analysis:

    54 2019-02-22 09:25:09.815     19 Log             Verbose     Resolved path: u:\My Documents\Repository\Azure\Cu...

So the question is, why the gap? Does this have something to do with the file being on the u: drive? Or maybe the code analysis causes some sort of deadlock? Any ideas @rjmholt?

BTW the message from index 47 comes from the Workspace.GetFile() call in HandleCodeLensResolveRequestAsync and just a few lines later we enter into the ResolveCodeLensProvider.ResolveCodeLensAsync() method which eventually returns a result at index 1106 ~5 minutes later.

[rkeithhill]

So are folks still seeing issues like this if you disable code analysis with the setting:

 "powershell.scriptAnalysis.enable": false

I'm beginning to wonder if this is an issue with the symbol reference code lens provider or some interaction between it and the Pester code lens provider.

[arievanderwende]

@atyourservers some people have had success with associating performance issues to code lens, disabling that might be something worth trying. More likely this is due to architectural challenges that we are hoping to resolve soon.

@SydneyhSmith Disabling CodeLens using "editor.codeLens": false solves the issue!

The codeLens/resolve for symbol references appears to run synchronously - blocking all other LSP messages until the CA request finishes. These are consecutive LSP JsonRpc request/response messages pairs. Check out the timestamp diffs:

<cut>

Between index 46 and 1106, we seem to be opening a lot of files:

<cut>

... from here to 1105 it is Resolved path / ALL Open file on disk log messages that takes ~20 secoconds.

<cut>

There is a 1 min 40 sec gap between index 47 and 48. There is a 2 min 35 sec gap between index 53 and 54. Index 53 indicates script analysis has finished but it doesn't get a chance to send VSCode the diagnosit results until index 1109, almost three minutes later.

<cut>

This is also puzzling, we get the request to resolve the codelens command here and begin symbol reference analysis:

<cut>

but then there are only code analysis messages:

<cut>

So the question is, why the gap? Does this have something to do with the file being on the u: drive? Or maybe the code analysis causes some sort of deadlock? Any ideas @rjmholt?

BTW the message from index 47 comes from the Workspace.GetFile() call in HandleCodeLensResolveRequestAsync and just a few lines later we enter into the ResolveCodeLensProvider.ResolveCodeLensAsync() method which eventually returns a result at index 1106 ~5 minutes later.

@rkeithhill I'm not opening a lot of files... I don't open more than six files at a time. It seems like in the background a lot of files are being opened, maybe by CodeLens...!? But it's not me doing it! These files are just there in my repository, that's all. Sounds like you found part of the issue here...

So are folks still seeing issues like this if you disable code analysis with the setting:

 "powershell.scriptAnalysis.enable": false

I'm beginning to wonder if this is an issue with the symbol reference code lens provider or some interaction between it and the Pester code lens provider.

@rkeithhill I've just fixed a typo in my opening post, where I wrote "powershell.scriptAnalysis.enable": true, which had to be "powershell.scriptAnalysis.enable": false. Sorry for that. I tried with it disabled already, as written in my opening post, but it didn't make any difference. Disabling CodeLens however solves the issue. I will keep CodeLens disabled for now as a workaround. I will share this workaround with a few collegues as well, as I'm not the only one with this issue here.

[arievanderwende]

Just experienced a delay when running two simple Measure-Command cmdlets. Will add "powershell.scriptAnalysis.enable": false to my settings again to see if the delays stay away then.

[fourpastmidnight]

Disabling Code Lens has really sped up my development of PowerShell in VS Code, not just running code via F8. This became really noticeable around v1.31 of VS Code for me, too. Unfortunately, it hasn't helped me with debugging problems I've been having since v1.31 of VS Code. (The debugger won't attach around the 3rd debug run, and attempting to stop the debug process results in a debug adapter not found error, requiring a restart of VS Code to resolve.) But at least the editing experience is much better despite needing to disable Code Lens.

[brwilkinson]

I would just like to add, I have been running with codelens disabled for over a year #1326

I still see performance issues, . . . and freezes. . . I can repro this 100% of the time.

I will have to also add/try: "powershell.scriptAnalysis.enable": false

At this stage, we have no formatting or code analysis in the extension... so hopefully we can find the root cause of these issue, since they are tools that we would prefer to have enabled. . . This is an ongoing issue, since Code/PS Extension was first released.

[rkeithhill]

@brwilkinson The code analysis perf issues are due to PSScriptAnalyzer perf. There is a release coming out of PSSA that will improve the perf of PSSA. There is also a PR that @glennsarti is working on that will reduce the scope of files being analyzed for symbol references. That should help some as well. If you are running into perf issues with both code lens and code analysis disabled, please attach log files. That is our primary way to track the root cause of perf issues unless we have solid way to repro perf issues.

[brwilkinson]

Thanks @rkeithhill . . .

I am trying out: "powershell.scriptAnalysis.enable": false . . . for now and will share any feedback...

I'll keep an eye on the updates. . .

[brwilkinson]

okay disabling 'scriptAnalysis' definitely helps . . . however the freezes have not gone all together.

I will share some more logs here...

[rkeithhill]

@brwilkinson Can you update to the latest 1.18.0 release of PSScriptAnalyzer and re-enable codeAnalysis. This version of PSSA is significantly more performant.

[brwilkinson]

Thanks @rkeithhill I have installed 1.18.0, will give it a run. . . keep you posted.

[brwilkinson]

@rkeithhill Looking good so far. . . Thank you. . .

It's still a definite no for Codelens. . . however for now with that disabled and psscriptanalyzer updated the following are working pretty well . . .

• Formatting is fast
• ScriptAnalyzer rules process fast
• F8 actually works . . . without delays 😁
• Intellisense actually works . . . with only a very minor delay on the very first time you use it on a function. I haven't seen this before at all. . so that is amazing. . .

I'll provide another update once I actually write some proper code, rather than just running some code and tests. . . however there is definitely a major improvement without any doubt.

[rkeithhill]

Thanks for the feedback. Yeah, I wouldn't expect any change for the reference code lens as that is implemented separately. I think there will be a feature in the next version to allow you to exclude folders from reference analysis. That might help if you have dirs (like output or import dirs) that don't need to be analyzed.

[SydneyhSmith]

Going to close this as a duplicate of #1326

[tropez1971]

I tried disabling CodeLens, issue still persists.