Powershell: native commands doesn't return to prompt immediately sometimes

[vors]

Steps to reproduce

I don't have repro, but it happens fairly consistent with me on macOS.
Maybe every 1 of 100 or so. Running it in the loop doesn't repro it.
I understand that's it not an actionable bug report, but I hitted it about 5 times in a last week and it's pretty frustrating, so I'd like to at least start the conversation about it. It could be not a powershell problem all together, but I tend to think that it's probably PS.

git branch 

Expected behavior

Print branches and return back to prompt

Actual behavior

Print branches and don't return to prompt for a very long time (perception like a hang, but eventually it returns to promp).

Environment data

> $PSVersionTable
Name                           Value                                                                                                                     
----                           -----                                                                                                                     
PSVersion                      6.0.0-beta                                                                                                                
PSEdition                      Core                                                                                                                      
BuildVersion                   3.0.0.0                                                                                                                   
CLRVersion                                                                                                                                               
GitCommitId                    v6.0.0-beta.1                                                                                                             
OS                             Darwin 16.6.0 Darwin Kernel Version 16.6.0: Fri Apr 14 16:21:16 PDT 2017; root:xnu-3789.60.24~6/RELEASE_X86_64            
Platform                       Unix                                                                                                                      
PSCompatibleVersions           {1.0, 2.0, 3.0, 4.0...}                                                                                                   
PSRemotingProtocolVersion      2.3                                                                                                                       
SerializationVersion           1.1.0.1                                                                                                                   
WSManStackVersion              3.0              

[iSazonov]

Sometime I see any artifacts between VS Code and GitHub Desktop. So maybe the Issue is due to multiple git clients?

[vors]

Happens with other native executables too, i.e. python test runner

[vors]

Same with arc which is a tool for Phabricator.
I'm very much convinced it's a PS problem.

[iSazonov]

Maybe delayed sleep on waiting external process?

[vors]

This happens consistently on all native executables but very rarely.
I never can attach debugger quick enough to troubleshoot it.

This is currently my biggest usability problem with powershell.

[iSazonov]

Can we inject a trace hook?
We can use WPT (WPR/WPA) on Windows. Have Unix an equivalent?

[vors]

I captured some debug info attaching to the process and pausing it
No symbols unfortunately

The PSReadLine one seems suspicious, cc @lzybkr

System.Private.CoreLib.ni.dll!System.Threading.WaitHandle.WaitAny(System.Threading.WaitHandle[] waitHandles, int millisecondsTimeout, bool exitContext) (/Unknown Source:0)
Microsoft.PowerShell.PSReadLine.dll!Microsoft.PowerShell.PSConsoleReadLine.ReadKeyThreadProc() (/Unknown Source:0)
System.Private.CoreLib.ni.dll!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state) (/Unknown Source:0)
[Native to Managed Transition] (/Unknown Source:0)

[lzybkr]

The PSReadline thread is probably not interesting, it's probably waiting for a signal to start reading keys.

[vors]

Yes I realised it after reading some code. Maybe ApplicationInsight has something to do with it?

[iSazonov]

Running it in the loop doesn't repro it.

Maybe we need console IO (type emulation) to repo it?

[SteveL-MSFT]

@vors the AppInsight code only runs once at startup

[vors]

@SteveL-MSFT do you know where this appinsight call stack on Thread#1 coming from? I skimmed thru telemetry code and indeed it seems that it should be only relevant on a startup.

[SteveL-MSFT]

cc @JamesWTruher

[vors]

At the first glance it looks not quite as a deadlock, but as a problem where all thread wait for a signal and some of them have timeout set for this wait, so it's eventually resolves itself. Not quite sure what's the proper name for this concurrent issue.

[vors]

I'm hitting it few times a day and it's ruining the powershell on mac so badly.
This issue is very hard to tolerate.

[JamesWTruher]

I have seen this as well, although not as often as @vors is seeing it. The app insights call happens only at startup and only if the semaphore file is present in $PSHOME. Would dtruss help? Can you use it to inspect what's going on?

[vors]

For me it's not only on a srartup, maybe the app insights is a red herring.

[vors]

Removing DELETE_ME_TO_DISABLE_CONSOLEHOST_TELEMETRY didn't affect the problem

[SteveL-MSFT]

Maybe after we enable tracing we can narrow this down

[dgc]

I appear to have a consistent reproduction of this now on a VM (which I've just backed up in case it starts being inconsistent again.)

• VirtualBox 5.1.26
• PuTTY Release 0.70

VM details:

$ cat /etc/redhat-release
CentOS Linux release 7.3.1611 (Core)

$ screen -v
Screen version 4.01.00devel (GNU) 2-May-06

PS /home/dgc> $PSVersionTable

Name                           Value
----                           -----
PSVersion                      6.0.0-beta
PSEdition                      Core
GitCommitId                    v6.0.0-beta.6
OS                             Linux 3.10.0-514.el7.x86_64 #1 SMP Tue Nov 22...
Platform                       Unix
PSCompatibleVersions           {1.0, 2.0, 3.0, 4.0...}
PSRemotingProtocolVersion      2.3
SerializationVersion           1.1.0.1
WSManStackVersion              3.0

It happens all the time when I use GNU screen. I'm fairly sure that it wasn't this consistent in earlier versions of PowerShell.

The steps I took:

1. Boot the VM
2. Log into the VM via PuTTY
3. Start a screen session with "screen"
4. Run PowerShell with "powershell"
5. Try a native command with "cat /etc/redhat-release"

I get the expected output but the cursor just sits in column 0 on the next line like this:

A combination of waiting and hitting Ctrl-C repeatedly will usually break out of it and then it looks like this:

[SteveL-MSFT]

@dgc I think your repro is this issue https://github.com/PowerShell/PowerShell/issues/2364, try setting TERM

[dgc]

@SteveL-MSFT Yes, it is.

The problem was resolved when:

• I set TERM to "xterm" which resolved the problem on the packaged version of Screen (from 2006!?)
• I built Screen 4.06.01 (July 2017) and it worked correctly without having to change TERM.

[vors]

Just captured this state in a debugger.

This stack seems like this WaitForExit() call doesn't return https://github.com/PowerShell/PowerShell/blob/40577cb61ffdb4b94c8d5251bac7e07872fefc22/src/System.Management.Automation/engine/NativeCommandProcessor.cs#L698

@SteveL-MSFT are there pdbs available somewhere? I'd like to get one for v6.0.0-beta.6 on macOS if possible.

[SteveL-MSFT]

@vors I don't believe we publish the pdbs. Best thing to do is to build it yourself unfortunately.

[vors]

ok, so I captured it with the symbols (v6.0.0-beta.6).

Here are non-empty threads (whatever it means in the VSCode terms):

Pipeline Execution Thread is blocked on https://github.com/PowerShell/PowerShell/blob/40577cb61ffdb4b94c8d5251bac7e07872fefc22/src/System.Management.Automation/engine/NativeCommandProcessor.cs#L698

Thread 6 https://github.com/PowerShell/PowerShell/blob/414d56170b7abe7b602d1692de4b570671c8b7e6/src/System.Management.Automation/engine/hostifaces/pipelinebase.cs#L387

Thread 7 (probably unrelated PSReadLine Wait)
https://github.com/PowerShell/PowerShell/blob/414d56170b7abe7b602d1692de4b570671c8b7e6/src/Microsoft.PowerShell.PSReadLine/ReadLine.cs#L102

There is also Thread 1 with AppInsight stuff and Wait (see screenshot), but there is no our code in the stacktrace of it.

That doesn't quite seems like a dead-lock for me anymore. I just think that dotnet core may have a problem sometimes with _nativeProcess.WaitForExit();.
But I could not repro it separately to report :(

[iSazonov]

Maybe related https://github.com/dotnet/corefx/issues/19470

[SteveL-MSFT]

@iSazonov I think your comment on System.DirectoryServices is for https://github.com/PowerShell/PowerShell/issues/3266?

[iSazonov]

@SteveL-MSFT Yes, sorry.

[SteveL-MSFT]

Just got a MacBook Pro and I've noticed this with just the git commands. Pretty annoying.

[vors]

Also in another case I noticed that there are 2 threads that are waiting on the same ManualResetEvent. The second one is thru https://github.com/PowerShell/PowerShell/blob/2a9cd7211fbcaee170eedab572ed88645aee0bd8/src/System.Management.Automation/engine/hostifaces/LocalPipeline.cs#L861

[SteveL-MSFT]

As part of https://github.com/PowerShell/PowerShell/pull/4995, I'm changing it to reuse threads by default whereas previously it was creating a new thread everytime. It might help this situation.

[vors]

One more observation about this situation is that once one powershell process hangs on a git command, others will too with very high probability

[vors]

JFYI, still seeing it on 6.0.0-rc, so the thread reusing doesn't seems to help

[SteveL-MSFT]

Without a clear repro, moving to 6.1.0

[vors]

FWIW it happens much more frequently after a system wake up. On mac while laptop is closed, system does hibernation. This native call hang is the first thing in the morning that greets me almost every day. But it also happens in a steady state sporadically.

[vors]

I stop seeing this recently. Perhaps dotnet finally get around to solve it.

[SteveL-MSFT]

I haven't experienced myself in a long time. Let's close this and if it repros we can reopen.