Skip to content

CodeLens blocking execution of code and also auto formatting i.e. F8/Format Document not working #1326

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
brwilkinson opened this issue May 19, 2018 · 32 comments

Comments

@brwilkinson
Copy link

brwilkinson commented May 19, 2018

System Details

code -v 

1.23.1
d0182c3417d225529c6d5ad24b7572815d0de9ac
x64

$pseditor.EditorServicesVersion

1.7.0.0

code --list-extensions --show-versions
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]
[email protected]

$PSVersionTable

Name                           Value
----                           -----
PSVersion                      6.1.0-preview.2
PSEdition                      Core
GitCommitId                    v6.1.0-preview.2
OS                             Microsoft Windows 10.0.17672
Platform                       Win32NT
PSCompatibleVersions           {1.0, 2.0, 3.0, 4.0...}
PSRemotingProtocolVersion      2.3
SerializationVersion           1.1.0.1
WSManStackVersion              3.0

Issue Description

When I press F8, nothing happens, I only see output after 30 seconds up to 3 minutes.

The Integrated console just shows the last of the debug output

#-- Waiting for EditorServicesHost to complete execution ---------------------

However if I actually change the ps1 file that is open I see in the powershell extension log , that things are happening.
E.g. formatting and it also shows the language service is connected.

5/19/2018 2:32:24 PM [NORMAL] - Connecting to language service on port 13493...
5/19/2018 2:32:24 PM [NORMAL] - Language service connected.
5/19/2018 2:35:17 PM [VERBOSE] - Formatting on type at position {"line":35,"character":0} -

However the logs in the integrated console/terminal shows the same thing as the logs that I have attached.

#-- Waiting for EditorServicesHost to complete execution ---------------------

The F8 is non responsive. . . the commands are being queued somewhere however since after around ~2 minutes I will see the output.

E.g.
if I have this in the ps1 file, then I press F8 twice, nothing happens, then around 2 minutes later I see the output

gps -id $pid

 NPM(K)    PM(M)      WS(M)     CPU(s)      Id  SI ProcessName
 ------    -----      -----     ------      --  -- -----------
     99   524.29     519.61     101.13    5652   1 pwsh

 NPM(K)    PM(M)      WS(M)     CPU(s)      Id  SI ProcessName
 ------    -----      -----     ------      --  -- -----------
     99   524.38     519.73     101.17    5652   1 pwsh

I can type in the terminal the whole time.

e.g. typing in the terminal/console

Get-date
> Saturday, May 19, 2018 2:39:00 PM

However if I am pressing F8 on the ps1 script, nothing happens again. . . for about 2 minutes. . . then the result returns again.

I have this experience 100% of the time with both ps 6 and ps 5.1.

Sometimes I can write code for up to 15 minutes without this occurring. . . Mostly the Integrated Console is just unusable.

This is not a new issue, it has always been like this. Also I do screen shares with customers that I work with daily and I see the exact same issues with all of them. There are also references to this issue in pretty much Every Video from the PowerShell Conferences in both US and EU that have been published.
If you have a Windows 10 machine try it for yourself, it's easy to repro.

Between VSCode.exe --> winpty-agent.exe --> conhost.exe --> pwsh.exe --> The PowerShell extension --> PowerShell EditorServices I am not really sure where to look.

For the past two weeks I have been trying anything I can think off to work out what is causing the issue. . . including migrating my workflow to use pscore 6.0 and also using the Insider version, plus removing all extensions.

The main reason I am reporting is now is because, I actually decided to turn off the debug logging, incase it was part of the problem. . . so I switched it off. . .

"powershell.developer.editorServicesLogLevel": "Error",

Then for the first time ever, when I actually switched it on again, I actually started to see the diagnostics logs, that I had actually never seen before 😊

"powershell.developer.editorServicesLogLevel": "Diagnostic",

So I hope with these I can actually determine what is causing this long term issue.
Although for some reason the logs only seem to show the startup ? the last thing I see is:

#-- Waiting for EditorServicesHost to complete execution ---------------------

I have tried both

"terminal.integrated.rendererType": "canvas",

and
"terminal.integrated.rendererType": "dom",
these do not make any difference.

My extension are set to auto update, I deleted any extensions that I don't actually use everyday.
I have worked in both VSCode and the VSCode Insiders and this is the same issue on both.

Logs attached, they actually just show extactly what I now see in the console which is up to the following line and then nothing after ?

#-- Waiting for EditorServicesHost to complete execution ---------------------

I am not sure if that is normal of if the editorservices have hung ? The formatting seems to be working so I don't think they have hung, there is just nothing extra in the logs.

One other thing however if I do select a single line of code and then choose Format Selection, then all I see in the status bar is "Formatting PowerShell document …." which also lasts about 2 minutes.

So now if I . . .

  1. Press F8 on a line of code 5 times . . . I wait. . .

  2. While I am waiting if I do a format selection I see the "Formatting PowerShell document …." . . I wait.

  3. After a few minutes, the two both complete at the same time, which I guess is expected.

  4. Sometimes (like right now) the format and the F8 work fine/ as I would expect, however the good times only last around another 3 minutes, it starts again then go back to 1) . . . same issue again. I just waited two minutes and it's locked again, I just don't see any new logs anywhere ? only those startup logs ? which I have attached.

If I restart the current session, I see the new editor services startup. . . I see the integrated console has finished loading, I press F8 on the line of code, nothing. it's just the same, I wait. then eventually the command writes out.

One more detail, if I am on the Output "PowerShell extension Log" and I press F8 on the script, it flips be back to the Integrated console/terminal, however there is no output . . . until a minute later, then the results from pressing the F8 returns.

Are there any logs for EditorServices other than what appear to be startup logs?

happy to video screen capture of this or do a screen share. . .

@brwilkinson brwilkinson changed the title F8 is not working 'Waiting for EditorServicesHost to complete execution'. F8 is not working 'Waiting for EditorServicesHost to complete execution' ? May 19, 2018
@rkeithhill
Copy link
Contributor

rkeithhill commented May 19, 2018

The most helpful logs are under your ~\.vscode\extensions\ms-vscode.powershell-1.7.0\logs dir. Find the sub-dir with the latest date (after repro'ing the problem), zip it up and attach it. The main file we need is the EditorServices.log file in that directory.

@brwilkinson
Copy link
Author

@rkeithhill are you okay if I use the Insiders version ? or would you prefer if I provide logs from the standard version?

@rkeithhill
Copy link
Contributor

rkeithhill commented May 19, 2018

Either would be fine. But in the case of Insiders the dir will be under ~\.vscode-insiders\....

@brwilkinson
Copy link
Author

brwilkinson commented May 19, 2018

Thanks @rkeithhill

I restarted the current session to start a fresh set of logs. I have a nice clean repro. . .

The steps I took were:

  1. Started the session again PS 6.1 5/19/2018 4:06:29 PM
  2. I already had a script open Stop-AzureRMRGDP.ps1
    That script has a sample line of code in it: gps -id $pid
    I did F8 on that line. . . at 5/19/2018 4:06:34 PM (nothing happened)
    I waited a few seconds, then I went to the output tab and made a change in the file
    I can see there it was logged . . .
    vscode-powershell.log 5/19/2018 4:07:31 PM [VERBOSE] - Formatting on type at position
  3. Back to the Terminal, nothing output as yet, it's been about 3 minutes.
    I pressed F8 a few more times.
  4. I see in the vscode-powershell.log
    5/19/2018 4:10:40 PM [VERBOSE] - No formattable range returned.
    At this time the first output was shown in the Terminal for the first F8 that I did on gps -id $pid
  5. There are still around 2 F8's that have not been output as yet.
  6. I see in the vscode-powershell.log
    5/19/2018 4:13:13 PM [VERBOSE] - No formattable range returned.
    At this time the output from the 3 F8's that I did earlier were returned.

I hope this is helpful for the timings when you look into the EditorServices.log that is attached.

@brwilkinson
Copy link
Author

By the way here is the full output from the session, it appears that I pressed F8 Five times, based on the returned output. The four initial and the one half way down.

#-- Waiting for EditorServicesHost to complete execution ---------------------
AZ:\> gps -id $pid
gps -id $pid
gps -id $pid
gps -id $pid

 NPM(K)    PM(M)      WS(M)     CPU(s)      Id  SI ProcessName
 ------    -----      -----     ------      --  -- -----------
    109   770.01     524.68     212.92   22496   1 pwsh

gps -id $pid

 NPM(K)    PM(M)      WS(M)     CPU(s)      Id  SI ProcessName
 ------    -----      -----     ------      --  -- -----------
    108   527.65     546.02     430.88   22496   1 pwsh

 NPM(K)    PM(M)      WS(M)     CPU(s)      Id  SI ProcessName
 ------    -----      -----     ------      --  -- -----------
    108   527.65     546.03     430.91   22496   1 pwsh

 NPM(K)    PM(M)      WS(M)     CPU(s)      Id  SI ProcessName
 ------    -----      -----     ------      --  -- -----------
    108   527.65     546.03     430.95   22496   1 pwsh

 NPM(K)    PM(M)      WS(M)     CPU(s)      Id  SI ProcessName
 ------    -----      -----     ------      --  -- -----------
    108   527.65     546.03     430.95   22496   1 pwsh

@brwilkinson
Copy link
Author

brwilkinson commented May 19, 2018

gc $Home\Desktop\1526767589-74dc5124-5067-4b8d-8a55-af9f05b1bd761526761220289\EditorServices.log | sls 'Attempting to execute command' -Context 2,2

2018-05-19 16:06:35 Attempting to execute command(s):

      Import-Module C:\Users\benwilk\.vscode-insiders\extensions\ms-vscode.powershell-1.7.0\modules\PowerShellEditorServices\bin\Core\..\..\Commands\PowerShellEditorServices.Commands.psd1

2018-05-19 16:06:35 Attempting to execute command(s):

      Import-Module PowerShellEditorServices.VSCode

2018-05-19 16:06:36 Attempting to execute command(s):

      D:\OneDrive\Documents\PowerShell\profile.ps1

2018-05-19 16:06:36 Attempting to execute command(s):

      prompt

2018-05-19 16:10:40 Attempting to execute command(s):

      gps -id $pid

2018-05-19 16:10:40 Attempting to execute command(s):

      gps -id $pid

2018-05-19 16:10:40 Attempting to execute command(s):

      gps -id $pid

2018-05-19 16:10:40 ttempting to execute command(s):

      gps -id $pid

2018-05-19 16:14:56 Attempting to execute command(s):

      gps -id $pid

@brwilkinson
Copy link
Author

Let me know if I repro with get-date would be more helpful?

@brwilkinson
Copy link
Author

brwilkinson commented May 19, 2018

Also these are my profile settings for the autoformat

        "editor.formatOnSave": false,
        "editor.formatOnType": true,
        "editor.formatOnPaste": false,

I attached another repro with just F8 on get-date

#-- Waiting for EditorServicesHost to complete execution ---------------------
AZ:\> Get-Date
Get-Date
Get-Date
Get-Date
Get-Date

Saturday, May 19, 2018 5:03:52 PM

Saturday, May 19, 2018 5:05:36 PM

Saturday, May 19, 2018 5:05:36 PM

Saturday, May 19, 2018 5:05:36 PM

Saturday, May 19, 2018 5:05:36 PM
5/19/2018 5:02:23 PM [NORMAL] - Language service connected.
5/19/2018 5:02:46 PM [VERBOSE] - Formatting on type at position {"line":32,"character":0} - file:///d%3A/OneDrive/Documents/PowerShell/Modules/BRW/Stop-AzureRMRGDP.ps1...
5/19/2018 5:02:47 PM [VERBOSE] - Formatting on type at position {"line":33,"character":0} - file:///d%3A/OneDrive/Documents/PowerShell/Modules/BRW/Stop-AzureRMRGDP.ps1...
5/19/2018 5:02:47 PM [VERBOSE] - Formatting on type at position {"line":34,"character":0} - file:///d%3A/OneDrive/Documents/PowerShell/Modules/BRW/Stop-AzureRMRGDP.ps1...
5/19/2018 5:03:52 PM [VERBOSE] - No formattable range returned.
5/19/2018 5:03:52 PM [VERBOSE] - No formattable range returned.
5/19/2018 5:05:36 PM [VERBOSE] - Document formatting finished in 103.588s

@TylerLeonhardt
Copy link
Member

Just out of curiosity, if you disable the formatOnType, does the issue still happen?

@brwilkinson
Copy link
Author

Hey @tylerl0706 yes tried that.. Still the same, just nothing gets logged, because the format isn't triggered, however the delay is still there. Whatever is blocking stops the formatting as well as the execution. Once that block has completed, both occur/run straight away.

@rkeithhill
Copy link
Contributor

@tylerl0706 yeah, we need threadsafe logging:

  {
      "jsonrpc": "2.0",
      "method": "textDocument/publishDiagnostics",
      "params": {
        "uri": "file:///d%3A/On

    Session state changed --mmand(s):
op-AzureRMRGDP.ps1",
     
    
gnos

        Old state: Ready

    },
    
    
2018-05-19 17:05:36 [VERBOSE        Result: NotFinished
line 61 of C:\projects\powershelleditorservices\src\PowerShellEditorServices.Protocol\MessageProtocol\MessageWriter.cs
   }
        },
        "o
 

2018-05-19 17:05:36 [VERBOSE] - Method "ExecuteCnStand" anged" a491 of C171 of C:\projects\powershelleditorservices\src\PowerShellEditorServices\Session\PowerSext.cs
ext.cs
ecution completed successfully.

  {
      "jsonrpc": "2.0",
      "method": "textDocument/publishDiagnostics",
      "params": {
        "uri": "file:///d%3A/On

    Session state changed --mmand(s):
op-AzureRMRGDP.ps1",
     
    
gnos

        Old state: Ready

    },

@TylerLeonhardt
Copy link
Member

Oh wow. Well @rjmholt is actively working on this! 😃

@rkeithhill
Copy link
Contributor

rkeithhill commented May 20, 2018

@brwilkinson Dang. I can't repro this on my Win 10 PC using PS 6.1 preview 2.

What happens if you create a new, empty .ps1 file in it, place that one line - gps -id $pid - in it and use F8 to execute it. Do you still see the issue?

Also what do these two commands return: Get-Module and (Get-Runspace -id 4).CreatePipeline("Get-Module PSScriptAnalyzer").Invoke()?

@brwilkinson
Copy link
Author

brwilkinson commented May 20, 2018

@rkeithhill perhaps try writing and loading a small function?!

I can repro with the following:

new blank script: D:\OneDrive\Foo.ps1 (BTW I also tested outside of onedrive path, this issue still occurs).

get-date (F8 works)

gps (F8 works)

gmo | foreach Name (F8 works)

Microsoft.PowerShell.Management
Microsoft.PowerShell.Security
Microsoft.PowerShell.Utility
posh-git
PowerShellEditorServices.Commands
PowerShellEditorServices.VSCode

(Get-Runspace -id 4).CreatePipeline("Get-Module PSScriptAnalyzer").Invoke() (F8 works)

ModuleType Version    Name                                ExportedCommands
---------- -------    ----                                ----------------
Script     1.16.1     PSScriptAnalyzer                    {Get-ScriptAnalyzerRule, Invoke-Formatter, Invoke-ScriptAnalyzer}

Type in a function foo (breaks, does not execute on F8)

function foo {

    get-date
}

still waiting . . . (still broken)

Original load of the function still waiting + 5 minute later

made a test change to the file, just pressed enter to make / delete a line, nothing logged, since I have all auto formatting disabled.

Still waiting .. . . +7 minutes.

finally loads the function,

foo               

date is returned, not blocked right now.

Sunday, May 20, 2018 12:40:20 PM

This is the full output from the terminal

VERBOSE: Invoking Start-EditorServicesHost
VERBOSE: Start-EditorServicesHost returned Microsoft.PowerShell.EditorServices.Host.EditorServicesHost
VERBOSE: Processing object of type [Hashtable] at depth 0
VERBOSE: Processing object of type [Int32] at depth 1
VERBOSE: Processing object of type [Int32] at depth 1
VERBOSE: Writing session file with contents:
VERBOSE: {"status":"started","debugServicePort":11866,"debugServiceTransport":"Tcp","languageServicePort":12356,"languageServiceTransport":"Tcp"}
VERBOSE: Wrote out session file
VERBOSE:
#-- Waiting for EditorServicesHost to complete execution ---------------------
AZ:\> gmo

ModuleType Version    Name                                ExportedCommands
---------- -------    ----                                ----------------
Manifest   3.1.0.0    Microsoft.PowerShell.Management     {Add-Content, Clear-Content, Clear-Item, Clear-ItemProperty...}
Manifest   3.0.0.0    Microsoft.PowerShell.Security       {ConvertFrom-SecureString, ConvertTo-SecureString, Get-Acl, Get-AuthenticodeSignature...}
Manifest   3.1.0.0    Microsoft.PowerShell.Utility        {Add-Member, Add-Type, Clear-Variable, Compare-Object...}
Script     0.7.3      posh-git                            {Add-PoshGitToProfile, Add-SshKey, Enable-GitColors, Expand-GitCommand...}
Script     0.2.0      PowerShellEditorServices.Commands   {ConvertFrom-ScriptExtent, ConvertTo-ScriptExtent, Find-Ast, Get-Token...}
Script     0.2.0      PowerShellEditorServices.VSCode     {Close-VSCodeHtmlContentView, New-VSCodeHtmlContentView, Set-VSCodeHtmlContentView, Show-VSCodeHtmlContentView...}


AZ:\> gmo | foreach Name
Microsoft.PowerShell.Management
Microsoft.PowerShell.Security
Microsoft.PowerShell.Utility
posh-git
PowerShellEditorServices.Commands
PowerShellEditorServices.VSCode
AZ:\> (Get-Runspace -id 4).CreatePipeline("Get-Module PSScriptAnalyzer").Invoke()

ModuleType Version    Name                                ExportedCommands
---------- -------    ----                                ----------------
Script     1.16.1     PSScriptAnalyzer                    {Get-ScriptAnalyzerRule, Invoke-Formatter, Invoke-ScriptAnalyzer}


AZ:\> function foo {

    get-date
}
AZ:\> foo

Sunday, May 20, 2018 12:40:20 PM

@rkeithhill
Copy link
Contributor

You can try disabling code analysis by appending this to your workspace or user settings file:

 "powershell.scriptAnalysis.enable": false

@brwilkinson
Copy link
Author

I tried disabling scriptanalysis, I restarted VSCode and it does appear to actually be disabled
"powershell.scriptAnalysis.enable": false

however that did not make any difference.

Let me know if there are any other settings that I can change?!

Are the codeFormatting rules also disabled when scriptanalysis is turned off? Otherwise I can disable all of those rules?

@rkeithhill
Copy link
Contributor

It looks like code formatting is controlled separately from the powershell.scriptAnalysis.enable setting. But I'm not seeing a way to disable code formatting. :-( That's unfortunate and may be something we need to add as it would come in handy when debugging and trying to narrow down a problem we can't repo. @tylerl0706 Thoughts?

@brwilkinson
Copy link
Author

which setting provides this functionality i.e. 0 references ?

image

@brwilkinson
Copy link
Author

brwilkinson commented May 20, 2018

I think I have more of an idea where the issue stems.

Here are the repro steps.

get-date
gps
dir

they are all good.

as soon as I put the function keyword the extra line space is created to insert the setting shown below (0 references).

However the line is blank while the process that is causing the delay is running.

So I just see the blank line (between line 10 and 11)

image

eventually I see . . the 0 references

image

then F8 on gps works fine.

If I switch out tabs then come back, no blank line by function, then it starts the search again.

I am blocked while that process runs.

If that process starts on one script/tab, I am also blocked on other scripts/tabs while it runs.

@brwilkinson
Copy link
Author

@rkeithhill Thanks for your assistance in finding this I have been searching and trying so many things every day for several weeks (even months, perhaps a year) and now that I see it, it's so clear.

@brwilkinson
Copy link
Author

brwilkinson commented May 20, 2018

Okay I looked through many other open issues and see similar things . .

I disabled codeLens:
"editor.codeLens": false

The issue seems much better . . .

For now I would say codeLens is the likely root cause of this issue.

@brwilkinson brwilkinson changed the title F8 is not working 'Waiting for EditorServicesHost to complete execution' ? CodeLens blocking execution of code and also auto formatting i.e. F8 is not working. May 20, 2018
@brwilkinson brwilkinson changed the title CodeLens blocking execution of code and also auto formatting i.e. F8 is not working. CodeLens blocking execution of code and also auto formatting i.e. F8/Format Document not working May 20, 2018
@brwilkinson
Copy link
Author

@rkeithhill @tylerl0706 @rjmholt Let me know if you are able to repro on the CodeLens issue, with some function in a ps script and the delay in resolving the references lookup?!

@TylerLeonhardt
Copy link
Member

This is likely related to some other perf issues we are currently fighting. @rjmholt has been addressing the thread-safe logging, I've been working on canceling requests that take too long.

we'll follow up when we have something to share here 👍

@rjmholt rjmholt added this to the 2.0.0 milestone May 24, 2018
@brwilkinson
Copy link
Author

brwilkinson commented Mar 16, 2019

Did this ever get resolved, since I still have this exact same issue with daily use of the extension?

It's really frustrating restarting the extension every 5 minutes. . in order to use it?

It's impossible to actually write any code?

@brwilkinson
Copy link
Author

Linking to this more recent issue #1769

@SydneyhSmith
Copy link
Collaborator

Going to close this as a result of the major architectural changes we made in the omnisharp port....please let us know if this is not fixed in the PowerShell Preview Extension

@tropez1971
Copy link

As of 9/28/2020 I'm having this issue, running the latest VScode version. My frustration led me to this post.

@ghost ghost added the Needs: Maintainer Attention Maintainer attention needed! label Sep 28, 2020
@tropez1971
Copy link

I tried disabling CodeLens, issue still came back.

@brwilkinson
Copy link
Author

@tropez1971 are you able to confirm the version of vscode that you are using?

@tropez1971
Copy link

1.49.2

I also just swapped out my PowerShell Extension (v2020.6.0) for the PowerShell Preview Extension (v2020.9.0) and the issue still persists.

@tropez1971
Copy link

tropez1971 commented Sep 28, 2020

And to be clear, here is the issue I'm running into, which seems to be the same as the OP. I open VSCode, then I open various .ps1 files for work. If I highlight code in one of my open .ps1 files, then right-click on it and execute just that code (aka F8), the first few times I do it after a fresh restart it seems to work. Then all of a sudden it stops working, code doesn't execute.

If I copy that same code to the clipboard, then paste it into the terminal window at the bottom, it executes fine, and immediately.

If I wait a short bit, varying time, eventually I see the code from my F8 press earlier show up and attempt to execute but it's delayed by minutes before it actually makes its way to the terminal.

So right now I'm just copying the code I want to run, and pasting it into the terminal window at the bottom which is a pain in the butt, but at least it prevents random script sections from running at a later time when I don't want them to because I pressed f8 on some code 5 minutes earlier.

@SydneyhSmith
Copy link
Collaborator

Thanks @tropez1971 sounds like a slightly different issue, however it is one that we are working on with PowerShell/PowerShellEditorServices#1295

@SydneyhSmith SydneyhSmith removed the Needs: Maintainer Attention Maintainer attention needed! label Oct 8, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

6 participants