Powershell: Powershell jobs surprisingly slow...
On about 25% of the laptops in our group, the following command run in a _new powershell window_ is surprisingly slow -- 20 to 30 seconds for 10 empty jobs:
PS C:\temp> (measure-command { 1..10 | %{ start-job { $null } }; get-job | wait-job; get-job | remove-job } ).totalseconds
21.6354752
PS C:\temp>
Note that if you run the command a second time, it is up to 10x faster. But if you wait a minute or two and try again, or open a new window and try again, it is slow again. 100% repeatable for systems with the issue (about 75% of the laptops in our group do _not_ have the issue, and I am guessing it is because they have more cores -- I have 4 cores, 16GB RAM, and Samsung EVO SSD.)
I have done a bunch of analysis here, and I am convinced the following happens... For starters, the parent powershell launches 10 children, one at a time, with maybe a half of a second between each launch. Then one or two of the children might start running, but most of them just sit there waiting for most of the 20'ish seconds. Then the remaining 8 or 9 powershells start running at the same intervals as they launched -- like a half second between each run (as if the overall delay time is fixed for each process). Then all processes complete together.
Note that the system is idle for 90% of the time, at 0% CPU, while we wait 20 seconds for the empty jobs to complete. This is the bug -- an idle system waiting for over 15 seconds doing nothing.
You can see this by changing "$false" above to "c:\xxx.exe" -- then in procmon or xperf, you can see the (failed) references to c:\xxx.exe very close to the end of the trace.
It is possible this is because I have 4 cores in my system:
PS C:\temp> (get-process -id 0).threads.count
4
PS C:\temp>
I am [email protected]. I have tons of xperf and procmon traces, and have done a lot of initial digging into this -- it seems to be excess cleverness in the clr threadpool implementation that brings on pathologies in certain CPU configurations... Please reach out to me before closing this as not repro or not important -- we're now moving away from powershell jobs for all our testing infrastructure (to C#, since if we have to go out-of-box to get powershell to work, it's not worth the risk -- we run our tests in VSO). I hate to see folks be unable to use powershell for something as simple as launching background jobs -- this is 100% something folks should reliably be able to use powershell for! I hope we can fix this!!!
Below/attached is xperf/wpa trace showing the 10 children processes start up sequentially, and then hang idle for 15 seconds, and then eventually shut down (also somewhat sequentially).
rtestardi
All 14 comments
ETL and PML traces of above are here (internal to Microsoft): "\scratch2\scratch\richardt\profile.jobxxx3.zip"
If you want help going thru them, just e-mail/teams (richardt) or call (303-546-1449). I can also gather any additional xperf info you might need. The xperf command I used was:
xperf -on base+cswitch+DISPATCHER+DPC+INTERRUPT+latency+fileio+DISK_IO+DISK_IO_INIT+SYSCALL -stackwalk profile+CSwitch+ReadyThread+FileCreate+FileRead+FileWrite+DiskReadInit+DiskWriteInit+SyscallEnter+SyscallExit -BufferSize 2048 -MaxBuffers 2048; measure-command { 1..10 | %{ start-job { c:\xxx.exe } }; get-job | wait-job; get-job | remove-job }; xperf -d profile.jobxxx3.etl
rtestardi
on 22 Jan 2020
/cc @PaulHigin Could you please look the issue?
iSazonov
on 22 Jan 2020
Hi Paul,
I have confirmed the folks who see this all have either 4 or 6 cores on their (older) laptops...
It seems the real issue might be how the Threadpool is being used by powershell -- by blocking tasks reading named pipes that hold the thread -- on systems with less cores, there are less threads, so we can essentially deadlock until the threadpool decides to grow, which takes time...
Can you explain to me when powershell reads and writes named pipes, with respect to job processing???
(I see no indication yet of "Windows proper" being the problem, though I have also gotten into ratholes tracing thru conhost.exe, condrv.sys, named pipes, cert stores, security callbacks, etc. -- there's a lot going on! :-)
Do you have a contact for the .NET CLR Threadpool, so we can understand under what conditions it expands the threadcount? (And how it picks the initial threadcount? Might there be an environment variable or registry setting we can tweak to confirm we really have root cause here?)
Does powershell happen to have any tracing that would help us isolate the issue? Like when threadpool tasks start and stop (so we can see how long they are blocked on a queue)?
Might there be a way to eliminate the console entirely from the jobs (or reuse the existing one) so we can rule out conhost.exe and friends from the picture?
If I look at child powershell process 18544 in "\scratch2\scratch\richardt\profile.jobxxx3.zip" between 14.5 seconds (when activity appeared to stop) and 34.6 seconds (when the job accessed c:\xxx.exe, so I know it was actually running), I see the same stack I see in all our performance bugs -- someone is busy-waiting Sleep(0) as if it is a spinlock, and there is never any work to do, so we just burn a core context switching (to me this is a .NET CLR Threadpool bug in and of itself, but it is not our bug):
Line # | New Process | Switch-In Time (s) | New Thread Id | New Thread Stack | Readying Process | Readying Thread Id | Count | Ready (µs) | Waits (µs) | % CPU Usage
-- | -- | -- | -- | -- | -- | -- | -- | -- | -- | --
251 | | 14.516068200 | | ntdll.dll!RtlUserThreadStart | | | 1 | 23.900 | 0.000 | 0.00
252 | | 14.516068200 | | kernel32.dll!BaseThreadInitThunk | | | 1 | 23.900 | 0.000 | 0.00
253 | | 14.516068200 | | clr.dll!Thread::intermediateThreadProc | | | 1 | 23.900 | 0.000 | 0.00
254 | | 14.516068200 | | clr.dll!ThreadpoolMgr::WorkerThreadStart | | | 1 | 23.900 | 0.000 | 0.00
255 | | 14.516068200 | | clr.dll!ThreadpoolMgr::UnfairSemaphore::Wait | | | 1 | 23.900 | 0.000 | 0.00
256 | | 14.516068200 | | clr.dll!EESleepEx | | | 1 | 23.900 | 0.000 | 0.00
257 | | 14.516068200 | | KernelBase.dll!SleepEx | | | 1 | 23.900 | 0.000 | 0.00
258 | | 14.516068200 | | ntdll.dll!ZwDelayExecution | | | 1 | 23.900 | 0.000 | 0.00
259 | | 14.516068200 | | ntoskrnl.exe!KiSystemServiceExitPico | | | 1 | 23.900 | 0.000 | 0.00
260 | | 14.516068200 | | ntoskrnl.exe!NtDelayExecution | | | 1 | 23.900 | 0.000 | 0.00
261 | | 14.516068200 | | ntoskrnl.exe!KeDelayExecutionThread | | | 1 | 23.900 | 0.000 | 0.00
262 | | 14.516068200 | | ntoskrnl.exe!KiSwapContext | | | 1 | 23.900 | 0.000 | 0.00
263 | | 14.516068200 | | ntoskrnl.exe!SwapContext | | | 1 | 23.900 | 0.000 | 0.00
So we need to filter all those out when using wpa.
The thread that actually accesses c:\xxx.exe is 12816, which has just recently awoken from a 19 second wait! This is its wakeup:
Line # | New Process | New Thread Id | Switch-In Time (s) | New Thread Stack | Readying Thread Id | Ready Thread Stack | Count | Ready (µs) | Waits (µs) | % CPU Usage
-- | -- | -- | -- | -- | -- | -- | -- | -- | -- | --
1 | powershell.exe (18544) | 12816 | | | | | 3 | 479.300 | 19,095,187.100 | 0.00
2 | | | 33.611416600 | [Root] | | | 1 | 13.000 | 19,095,187.100 | 0.00
3 | | | 33.611416600 | ntdll.dll!RtlUserThreadStart | | | 1 | 13.000 | 19,095,187.100 | 0.00
4 | | | 33.611416600 | kernel32.dll!BaseThreadInitThunk | | | 1 | 13.000 | 19,095,187.100 | 0.00
5 | | | 33.611416600 | clr.dll!Thread::intermediateThreadProc | | | 1 | 13.000 | 19,095,187.100 | 0.00
6 | | | 33.611416600 | clr.dll!ThreadpoolMgr::WorkerThreadStart | | | 1 | 13.000 | 19,095,187.100 | 0.00
7 | | | 33.611416600 | clr.dll!ThreadpoolMgr::UnfairSemaphore::Wait | | | 1 | 13.000 | 19,095,187.100 | 0.00
8 | | | 33.611416600 | clr.dll!CLRSemaphore::Wait | | | 1 | 13.000 | 19,095,187.100 | 0.00
9 | | | 33.611416600 | KernelBase.dll!WaitForSingleObjectEx | | | 1 | 13.000 | 19,095,187.100 | 0.00
10 | | | 33.611416600 | ntdll.dll!ZwWaitForSingleObject | | | 1 | 13.000 | 19,095,187.100 | 0.00
11 | | | 33.611416600 | ntoskrnl.exe!KiSystemServiceExitPico | | | 1 | 13.000 | 19,095,187.100 | 0.00
12 | | | 33.611416600 | ntoskrnl.exe!NtWaitForSingleObject | | | 1 | 13.000 | 19,095,187.100 | 0.00
13 | | | 33.611416600 | ntoskrnl.exe!KeWaitForSingleObject | | | 1 | 13.000 | 19,095,187.100 | 0.00
14 | | | 33.611416600 | ntoskrnl.exe!KiCommitThreadWait | | | 1 | 13.000 | 19,095,187.100 | 0.00
15 | | | 33.611416600 | ntoskrnl.exe!KiSwapThread | | | 1 | 13.000 | 19,095,187.100 | 0.00
16 | | | 33.611416600 | ntoskrnl.exe!KiSwapContext | | | 1 | 13.000 | 19,095,187.100 | 0.00
17 | | | 33.611416600 | ntoskrnl.exe!SwapContext | | | 1 | 13.000 | 19,095,187.100 | 0.00
18 | | | 33.611416600 | | 11596 | [Root] | 1 | 13.000 | 19,095,187.100 | 0.00
19 | | | 33.611416600 | | | ntdll.dll!RtlUserThreadStart | 1 | 13.000 | 19,095,187.100 | 0.00
20 | | | 33.611416600 | | | kernel32.dll!BaseThreadInitThunk | 1 | 13.000 | 19,095,187.100 | 0.00
21 | | | 33.611416600 | | | powershell.exe!__wmainCRTStartup | 1 | 13.000 | 19,095,187.100 | 0.00
22 | | | 33.611416600 | | | powershell.exe!wmain | 1 | 13.000 | 19,095,187.100 | 0.00
23 | | | 33.611416600 | | | powershell.exe!LaunchManagedMonad | 1 | 13.000 | 19,095,187.100 | 0.00
24 | | | 33.611416600 | | | clr.dll!InternalDispatchImpl_Invoke_Wrapper | 1 | 13.000 | 19,095,187.100 | 0.00
25 | | | 33.611416600 | | | clr.dll!InternalDispatchImpl_Invoke_CallBack | 1 | 13.000 | 19,095,187.100 | 0.00
26 | | | 33.611416600 | | | clr.dll!InternalDispatchImpl_Invoke | 1 | 13.000 | 19,095,187.100 | 0.00
27 | | | 33.611416600 | | | clr.dll!DispatchInfo::InvokeMember | 1 | 13.000 | 19,095,187.100 | 0.00
28 | | | 33.611416600 | | | clr.dll!DispatchInfo::InvokeMemberDebuggerWrapper | 1 | 13.000 | 19,095,187.100 | 0.00
29 | | | 33.611416600 | | | clr.dll!DispatchInfo::InvokeMemberWorker | 1 | 13.000 | 19,095,187.100 | 0.00
30 | | | 33.611416600 | | | clr.dll!MethodDescCallSite::CallTargetWorker | 1 | 13.000 | 19,095,187.100 | 0.00
31 | | | 33.611416600 | | | clr.dll!CallDescrWorkerWithHandler | 1 | 13.000 | 19,095,187.100 | 0.00
32 | | | 33.611416600 | | | clr.dll!CallDescrWorkerInternal | 1 | 13.000 | 19,095,187.100 | 0.00
33 | | | 33.611416600 | | | mscorlib.ni.dll!
34 | | | 33.611416600 | | | mscorlib.ni.dll!
35 | | | 33.611416600 | | | clr.dll!RuntimeMethodHandle::InvokeMethod | 1 | 13.000 | 19,095,187.100 | 0.00
36 | | | 33.611416600 | | | clr.dll!CallDescrWorkerReflectionWrapper | 1 | 13.000 | 19,095,187.100 | 0.00
37 | | | 33.611416600 | | | clr.dll!CallDescrWorkerWithHandler | 1 | 13.000 | 19,095,187.100 | 0.00
38 | | | 33.611416600 | | | clr.dll!CallDescrWorkerInternal | 1 | 13.000 | 19,095,187.100 | 0.00
39 | | | 33.611416600 | | | Microsoft.PowerShell.ConsoleHost.ni.dll!
40 | | | 33.611416600 | | | Microsoft.PowerShell.ConsoleHost.ni.dll!
41 | | | 33.611416600 | | | System.Management.Automation.ni.dll!
42 | | | 33.611416600 | | | System.Management.Automation.ni.dll!
43 | | | 33.611416600 | | | System.Management.Automation.ni.dll!
44 | | | 33.611416600 | | | mscorlib.ni.dll!
45 | | | 33.611416600 | | | mscorlib.ni.dll!
46 | | | 33.611416600 | | | mscorlib.ni.dll!
47 | | | 33.611416600 | | | mscorlib.ni.dll!
48 | | | 33.611416600 | | | clr.dll!ThreadPoolNative::RequestWorkerThread | 1 | 13.000 | 19,095,187.100 | 0.00
49 | | | 33.611416600 | | | clr.dll!ThreadpoolMgr::SetAppDomainRequestsActive | 1 | 13.000 | 19,095,187.100 | 0.00
50 | | | 33.611416600 | | | clr.dll!ManagedPerAppDomainTPCount::SetAppDomainRequestsActive | 1 | 13.000 | 19,095,187.100 | 0.00
51 | | | 33.611416600 | | | clr.dll!ThreadpoolMgr::MaybeAddWorkingWorker | 1 | 13.000 | 19,095,187.100 | 0.00
52 | | | 33.611416600 | | | clr.dll!ThreadpoolMgr::UnfairSemaphore::Release | 1 | 13.000 | 19,095,187.100 | 0.00
53 | | | 33.611416600 | | | clr.dll!CLRSemaphore::Release | 1 | 13.000 | 19,095,187.100 | 0.00
54 | | | 33.611416600 | | | KernelBase.dll!ReleaseSemaphore | 1 | 13.000 | 19,095,187.100 | 0.00
55 | | | 33.611416600 | | | ntdll.dll!ZwReleaseSemaphore | 1 | 13.000 | 19,095,187.100 | 0.00
56 | | | 33.611416600 | | | ntoskrnl.exe!KiSystemServiceExitPico | 1 | 13.000 | 19,095,187.100 | 0.00
57 | | | 33.611416600 | | | ntoskrnl.exe!NtReleaseSemaphore | 1 | 13.000 | 19,095,187.100 | 0.00
58 | | | 33.611416600 | | | ntoskrnl.exe!KeReleaseSemaphore | 1 | 13.000 | 19,095,187.100 | 0.00
59 | | | 33.611416600 | | | ntoskrnl.exe!KiExitDispatcher | 1 | 13.000 | 19,095,187.100 | 0.00
Thread 11596 was holding the semaphore this whole time, it seems!
And thread 11596 in the child powershell, in turn, had been waiting for 19 seconds for the parent powershell to write to a named pipe:
Line # | New Thread Id | New Process | Switch-In Time (s) | New Thread Stack | Readying Process | Readying Thread Id | Ready Thread Stack | Count | Ready (µs) | Waits (µs) | % CPU Usage
-- | -- | -- | -- | -- | -- | -- | -- | -- | -- | -- | --
1 | 11596 | powershell.exe (18544) | | | | | | 4 | 13.900 | 19,533,237.300 | 0.00
2 | | | 33.611308700 | [Root] | | | | 1 | 13.200 | 19,533,237.300 | 0.00
3 | | | 33.611308700 | ntdll.dll!RtlUserThreadStart | | | | 1 | 13.200 | 19,533,237.300 | 0.00
4 | | | 33.611308700 | kernel32.dll!BaseThreadInitThunk | | | | 1 | 13.200 | 19,533,237.300 | 0.00
5 | | | 33.611308700 | powershell.exe!__wmainCRTStartup | | | | 1 | 13.200 | 19,533,237.300 | 0.00
6 | | | 33.611308700 | powershell.exe!wmain | | | | 1 | 13.200 | 19,533,237.300 | 0.00
7 | | | 33.611308700 | powershell.exe!LaunchManagedMonad | | | | 1 | 13.200 | 19,533,237.300 | 0.00
8 | | | 33.611308700 | clr.dll!InternalDispatchImpl_Invoke_Wrapper | | | | 1 | 13.200 | 19,533,237.300 | 0.00
9 | | | 33.611308700 | clr.dll!InternalDispatchImpl_Invoke_CallBack | | | | 1 | 13.200 | 19,533,237.300 | 0.00
10 | | | 33.611308700 | clr.dll!InternalDispatchImpl_Invoke | | | | 1 | 13.200 | 19,533,237.300 | 0.00
11 | | | 33.611308700 | clr.dll!DispatchInfo::InvokeMember | | | | 1 | 13.200 | 19,533,237.300 | 0.00
12 | | | 33.611308700 | clr.dll!DispatchInfo::InvokeMemberDebuggerWrapper | | | | 1 | 13.200 | 19,533,237.300 | 0.00
13 | | | 33.611308700 | clr.dll!DispatchInfo::InvokeMemberWorker | | | | 1 | 13.200 | 19,533,237.300 | 0.00
14 | | | 33.611308700 | clr.dll!MethodDescCallSite::CallTargetWorker | | | | 1 | 13.200 | 19,533,237.300 | 0.00
15 | | | 33.611308700 | clr.dll!CallDescrWorkerWithHandler | | | | 1 | 13.200 | 19,533,237.300 | 0.00
16 | | | 33.611308700 | clr.dll!CallDescrWorkerInternal | | | | 1 | 13.200 | 19,533,237.300 | 0.00
17 | | | 33.611308700 | mscorlib.ni.dll!
18 | | | 33.611308700 | mscorlib.ni.dll!
19 | | | 33.611308700 | clr.dll!RuntimeMethodHandle::InvokeMethod | | | | 1 | 13.200 | 19,533,237.300 | 0.00
20 | | | 33.611308700 | clr.dll!CallDescrWorkerReflectionWrapper | | | | 1 | 13.200 | 19,533,237.300 | 0.00
21 | | | 33.611308700 | clr.dll!CallDescrWorkerWithHandler | | | | 1 | 13.200 | 19,533,237.300 | 0.00
22 | | | 33.611308700 | clr.dll!CallDescrWorkerInternal | | | | 1 | 13.200 | 19,533,237.300 | 0.00
23 | | | 33.611308700 | Microsoft.PowerShell.ConsoleHost.ni.dll!
24 | | | 33.611308700 | Microsoft.PowerShell.ConsoleHost.ni.dll!
25 | | | 33.611308700 | System.Management.Automation.ni.dll!
26 | | | 33.611308700 | System.Management.Automation.ni.dll!
27 | | | 33.611308700 | mscorlib.ni.dll!
28 | | | 33.611308700 | mscorlib.ni.dll!
29 | | | 33.611308700 | mscorlib.ni.dll!
30 | | | 33.611308700 | mscorlib.ni.dll!
31 | | | 33.611308700 | mscorlib.ni.dll!
32 | | | 33.611308700 | KernelBase.dll!ReadFile | | | | 1 | 13.200 | 19,533,237.300 | 0.00
33 | | | 33.611308700 | ntdll.dll!ZwReadFile | | | | 1 | 13.200 | 19,533,237.300 | 0.00
34 | | | 33.611308700 | ntoskrnl.exe!KiSystemServiceExitPico | | | | 1 | 13.200 | 19,533,237.300 | 0.00
35 | | | 33.611308700 | ntoskrnl.exe!NtReadFile | | | | 1 | 13.200 | 19,533,237.300 | 0.00
36 | | | 33.611308700 | ntoskrnl.exe!IopSynchronousServiceTail | | | | 1 | 13.200 | 19,533,237.300 | 0.00
37 | | | 33.611308700 | ntoskrnl.exe!KeWaitForSingleObject | | | | 1 | 13.200 | 19,533,237.300 | 0.00
38 | | | 33.611308700 | ntoskrnl.exe!KiCommitThreadWait | | | | 1 | 13.200 | 19,533,237.300 | 0.00
39 | | | 33.611308700 | ntoskrnl.exe!KiSwapThread | | | | 1 | 13.200 | 19,533,237.300 | 0.00
40 | | | 33.611308700 | ntoskrnl.exe!KiSwapContext | | | | 1 | 13.200 | 19,533,237.300 | 0.00
41 | | | 33.611308700 | ntoskrnl.exe!SwapContext | | | | 1 | 13.200 | 19,533,237.300 | 0.00
42 | | | 33.611308700 | | powershell.exe (10300) | 5396 | [Root] | 1 | 13.200 | 19,533,237.300 | 0.00
43 | | | 33.611308700 | | | | ntdll.dll!RtlUserThreadStart | 1 | 13.200 | 19,533,237.300 | 0.00
44 | | | 33.611308700 | | | | kernel32.dll!BaseThreadInitThunk | 1 | 13.200 | 19,533,237.300 | 0.00
45 | | | 33.611308700 | | | | clr.dll!Thread::intermediateThreadProc | 1 | 13.200 | 19,533,237.300 | 0.00
46 | | | 33.611308700 | | | | clr.dll!ThreadpoolMgr::WorkerThreadStart | 1 | 13.200 | 19,533,237.300 | 0.00
47 | | | 33.611308700 | | | | clr.dll!ThreadpoolMgr::ExecuteWorkRequest | 1 | 13.200 | 19,533,237.300 | 0.00
48 | | | 33.611308700 | | | | clr.dll!ManagedPerAppDomainTPCount::DispatchWorkItem | 1 | 13.200 | 19,533,237.300 | 0.00
49 | | | 33.611308700 | | | | clr.dll!ManagedThreadBase_FullTransitionWithAD | 1 | 13.200 | 19,533,237.300 | 0.00
50 | | | 33.611308700 | | | | clr.dll!ManagedThreadBase_DispatchOuter | 1 | 13.200 | 19,533,237.300 | 0.00
51 | | | 33.611308700 | | | | clr.dll!ManagedThreadBase_DispatchMiddle | 1 | 13.200 | 19,533,237.300 | 0.00
52 | | | 33.611308700 | | | | clr.dll!ManagedThreadBase_DispatchInner | 1 | 13.200 | 19,533,237.300 | 0.00
53 | | | 33.611308700 | | | | clr.dll!QueueUserWorkItemManagedCallback | 1 | 13.200 | 19,533,237.300 | 0.00
54 | | | 33.611308700 | | | | clr.dll!MethodDescCallSite::CallTargetWorker | 1 | 13.200 | 19,533,237.300 | 0.00
55 | | | 33.611308700 | | | | clr.dll!CallDescrWorkerWithHandler | 1 | 13.200 | 19,533,237.300 | 0.00
56 | | | 33.611308700 | | | | clr.dll!CallDescrWorkerInternal | 1 | 13.200 | 19,533,237.300 | 0.00
57 | | | 33.611308700 | | | | mscorlib.ni.dll!
58 | | | 33.611308700 | | | | mscorlib.ni.dll!
59 | | | 33.611308700 | | | | mscorlib.ni.dll!
60 | | | 33.611308700 | | | | mscorlib.ni.dll!
61 | | | 33.611308700 | | | | System.Management.Automation.ni.dll!
62 | | | 33.611308700 | | | | System.Management.Automation.ni.dll!
63 | | | 33.611308700 | | | | System.Management.Automation.ni.dll!
64 | | | 33.611308700 | | | | System.Management.Automation.ni.dll!
65 | | | 33.611308700 | | | | System.Management.Automation.ni.dll!
66 | | | 33.611308700 | | | | System.Management.Automation.ni.dll!
67 | | | 33.611308700 | | | | System.Management.Automation.ni.dll!
68 | | | 33.611308700 | | | | System.Management.Automation.ni.dll!
69 | | | 33.611308700 | | | | System.Management.Automation.ni.dll!
70 | | | 33.611308700 | | | | System.Management.Automation.ni.dll!
71 | | | 33.611308700 | | | | System.Management.Automation.ni.dll!
72 | | | 33.611308700 | | | | System.Management.Automation.ni.dll!
73 | | | 33.611308700 | | | | System.Management.Automation.ni.dll!
74 | | | 33.611308700 | | | | System.Management.Automation.ni.dll!
75 | | | 33.611308700 | | | | System.Management.Automation.ni.dll!
76 | | | 33.611308700 | | | | System.Management.Automation.ni.dll!
77 | | | 33.611308700 | | | | System.Management.Automation.ni.dll!
78 | | | 33.611308700 | | | | System.Management.Automation.ni.dll!
79 | | | 33.611308700 | | | | System.Management.Automation.ni.dll!
80 | | | 33.611308700 | | | | System.Management.Automation.ni.dll!
81 | | | 33.611308700 | | | | mscorlib.ni.dll!
82 | | | 33.611308700 | | | | mscorlib.ni.dll!
83 | | | 33.611308700 | | | | mscorlib.ni.dll!
84 | | | 33.611308700 | | | | mscorlib.ni.dll!
85 | | | 33.611308700 | | | | mscorlib.ni.dll!
86 | | | 33.611308700 | | | | mscorlib.ni.dll!
87 | | | 33.611308700 | | | | mscorlib.ni.dll!
88 | | | 33.611308700 | | | | KernelBase.dll!WriteFile | 1 | 13.200 | 19,533,237.300 | 0.00
89 | | | 33.611308700 | | | | ntdll.dll!ZwWriteFile | 1 | 13.200 | 19,533,237.300 | 0.00
90 | | | 33.611308700 | | | | ntoskrnl.exe!KiSystemServiceExitPico | 1 | 13.200 | 19,533,237.300 | 0.00
91 | | | 33.611308700 | | | | ntoskrnl.exe!NtWriteFile | 1 | 13.200 | 19,533,237.300 | 0.00
92 | | | 33.611308700 | | | | FLTMGR.SYS!FltpFastIoWrite | 1 | 13.200 | 19,533,237.300 | 0.00
93 | | | 33.611308700 | | | | FLTMGR.SYS!FltpPerformFastIoCall | 1 | 13.200 | 19,533,237.300 | 0.00
94 | | | 33.611308700 | | | | Npfs.SYS!NpFastWrite | 1 | 13.200 | 19,533,237.300 | 0.00
95 | | | 33.611308700 | | | | ntoskrnl.exe!IofCompleteRequest | 1 | 13.200 | 19,533,237.300 | 0.00
96 | | | 33.611308700 | | | | ntoskrnl.exe!IopfCompleteRequest | 1 | 13.200 | 19,533,237.300 | 0.00
97 | | | 33.611308700 | | | | ntoskrnl.exe!KiExitDispatcher | 1 | 13.200 | 19,533,237.300 | 0.00
Could you possibly give me any idea why the parent powershell (10300, 5396) would be writing to a named pipe opened by the child powershell?
It seems the child is waiting 19 seconds for this write, and only then the child will actually start its job work (opening c:\xxx.exe in this trace -- I replaced "$false" with "c:\xxx.exe").
What is weirder, is the parent powershell thread (10300, 5396) had just recently itself woken from a 10 second sleep waiting on a write to a named pipe from a different child process!
So there is no way the parent powershell thread could have been prompt signaling the child process above!!!
This seems to be the issue -- powershell has blocking tasks using a limited thread pool (that likely only has on the order of 4-6 threads on our systems!).
Line # | New Thread Id | New Process | Switch-In Time (s) | New Thread Stack | Readying Process | Readying Thread Id | Ready Thread Stack | Count | Ready (µs) | Waits (µs) | % CPU Usage
-- | -- | -- | -- | -- | -- | -- | -- | -- | -- | -- | --
1 | 5396 | powershell.exe (10300) | | | | | | 188 | 60,911.700 | 14,972,274.300 | 0.02
132 | | | 33.575797000 | [Root] | | | | 1 | 12.100 | 10,487,552.400 | 0.00
133 | | | 33.575797000 | ntdll.dll!RtlUserThreadStart | | | | 1 | 12.100 | 10,487,552.400 | 0.00
134 | | | 33.575797000 | kernel32.dll!BaseThreadInitThunk | | | | 1 | 12.100 | 10,487,552.400 | 0.00
135 | | | 33.575797000 | clr.dll!Thread::intermediateThreadProc | | | | 1 | 12.100 | 10,487,552.400 | 0.00
136 | | | 33.575797000 | clr.dll!ThreadpoolMgr::WorkerThreadStart | | | | 1 | 12.100 | 10,487,552.400 | 0.00
137 | | | 33.575797000 | clr.dll!ThreadpoolMgr::ExecuteWorkRequest | | | | 1 | 12.100 | 10,487,552.400 | 0.00
138 | | | 33.575797000 | clr.dll!ManagedPerAppDomainTPCount::DispatchWorkItem | | | | 1 | 12.100 | 10,487,552.400 | 0.00
139 | | | 33.575797000 | clr.dll!ManagedThreadBase_FullTransitionWithAD | | | | 1 | 12.100 | 10,487,552.400 | 0.00
140 | | | 33.575797000 | clr.dll!ManagedThreadBase_DispatchOuter | | | | 1 | 12.100 | 10,487,552.400 | 0.00
141 | | | 33.575797000 | clr.dll!ManagedThreadBase_DispatchMiddle | | | | 1 | 12.100 | 10,487,552.400 | 0.00
142 | | | 33.575797000 | clr.dll!ManagedThreadBase_DispatchInner | | | | 1 | 12.100 | 10,487,552.400 | 0.00
143 | | | 33.575797000 | clr.dll!QueueUserWorkItemManagedCallback | | | | 1 | 12.100 | 10,487,552.400 | 0.00
144 | | | 33.575797000 | clr.dll!MethodDescCallSite::CallTargetWorker | | | | 1 | 12.100 | 10,487,552.400 | 0.00
145 | | | 33.575797000 | clr.dll!CallDescrWorkerWithHandler | | | | 1 | 12.100 | 10,487,552.400 | 0.00
146 | | | 33.575797000 | clr.dll!CallDescrWorkerInternal | | | | 1 | 12.100 | 10,487,552.400 | 0.00
147 | | | 33.575797000 | mscorlib.ni.dll!
148 | | | 33.575797000 | mscorlib.ni.dll!
149 | | | 33.575797000 | mscorlib.ni.dll!
150 | | | 33.575797000 | mscorlib.ni.dll!
151 | | | 33.575797000 | mscorlib.ni.dll!
152 | | | 33.575797000 | mscorlib.ni.dll!
153 | | | 33.575797000 | mscorlib.ni.dll!
154 | | | 33.575797000 | mscorlib.ni.dll!
155 | | | 33.575797000 | mscorlib.ni.dll!
156 | | | 33.575797000 | mscorlib.ni.dll!
157 | | | 33.575797000 | mscorlib.ni.dll!
158 | | | 33.575797000 | mscorlib.ni.dll!
159 | | | 33.575797000 | KernelBase.dll!ReadFile | | | | 1 | 12.100 | 10,487,552.400 | 0.00
160 | | | 33.575797000 | ntdll.dll!ZwReadFile | | | | 1 | 12.100 | 10,487,552.400 | 0.00
161 | | | 33.575797000 | ntoskrnl.exe!KiSystemServiceExitPico | | | | 1 | 12.100 | 10,487,552.400 | 0.00
162 | | | 33.575797000 | ntoskrnl.exe!NtReadFile | | | | 1 | 12.100 | 10,487,552.400 | 0.00
163 | | | 33.575797000 | ntoskrnl.exe!IopSynchronousServiceTail | | | | 1 | 12.100 | 10,487,552.400 | 0.00
164 | | | 33.575797000 | ntoskrnl.exe!KeWaitForSingleObject | | | | 1 | 12.100 | 10,487,552.400 | 0.00
165 | | | 33.575797000 | ntoskrnl.exe!KiCommitThreadWait | | | | 1 | 12.100 | 10,487,552.400 | 0.00
166 | | | 33.575797000 | ntoskrnl.exe!KiSwapThread | | | | 1 | 12.100 | 10,487,552.400 | 0.00
167 | | | 33.575797000 | ntoskrnl.exe!KiSwapContext | | | | 1 | 12.100 | 10,487,552.400 | 0.00
168 | | | 33.575797000 | ntoskrnl.exe!SwapContext | | | | 1 | 12.100 | 10,487,552.400 | 0.00
169 | | | 33.575797000 | | powershell.exe (4552) | 20584 | [Root] | 1 | 12.100 | 10,487,552.400 | 0.00
170 | | | 33.575797000 | | | | ntdll.dll!RtlUserThreadStart | 1 | 12.100 | 10,487,552.400 | 0.00
171 | | | 33.575797000 | | | | kernel32.dll!BaseThreadInitThunk | 1 | 12.100 | 10,487,552.400 | 0.00
172 | | | 33.575797000 | | | | clr.dll!Thread::intermediateThreadProc | 1 | 12.100 | 10,487,552.400 | 0.00
173 | | | 33.575797000 | | | | clr.dll!ThreadpoolMgr::WorkerThreadStart | 1 | 12.100 | 10,487,552.400 | 0.00
174 | | | 33.575797000 | | | | clr.dll!ThreadpoolMgr::ExecuteWorkRequest | 1 | 12.100 | 10,487,552.400 | 0.00
175 | | | 33.575797000 | | | | clr.dll!ManagedPerAppDomainTPCount::DispatchWorkItem | 1 | 12.100 | 10,487,552.400 | 0.00
176 | | | 33.575797000 | | | | clr.dll!ManagedThreadBase_FullTransitionWithAD | 1 | 12.100 | 10,487,552.400 | 0.00
177 | | | 33.575797000 | | | | clr.dll!ManagedThreadBase_DispatchOuter | 1 | 12.100 | 10,487,552.400 | 0.00
178 | | | 33.575797000 | | | | clr.dll!ManagedThreadBase_DispatchMiddle | 1 | 12.100 | 10,487,552.400 | 0.00
179 | | | 33.575797000 | | | | clr.dll!ManagedThreadBase_DispatchInner | 1 | 12.100 | 10,487,552.400 | 0.00
180 | | | 33.575797000 | | | | clr.dll!QueueUserWorkItemManagedCallback | 1 | 12.100 | 10,487,552.400 | 0.00
181 | | | 33.575797000 | | | | clr.dll!MethodDescCallSite::CallTargetWorker | 1 | 12.100 | 10,487,552.400 | 0.00
182 | | | 33.575797000 | | | | clr.dll!CallDescrWorkerWithHandler | 1 | 12.100 | 10,487,552.400 | 0.00
183 | | | 33.575797000 | | | | clr.dll!CallDescrWorkerInternal | 1 | 12.100 | 10,487,552.400 | 0.00
184 | | | 33.575797000 | | | | mscorlib.ni.dll!
185 | | | 33.575797000 | | | | mscorlib.ni.dll!
186 | | | 33.575797000 | | | | mscorlib.ni.dll!
187 | | | 33.575797000 | | | | mscorlib.ni.dll!
188 | | | 33.575797000 | | | | System.Management.Automation.ni.dll!
189 | | | 33.575797000 | | | | System.Management.Automation.ni.dll!
190 | | | 33.575797000 | | | | System.Management.Automation.ni.dll!
191 | | | 33.575797000 | | | | System.Management.Automation.ni.dll!
192 | | | 33.575797000 | | | | System.Management.Automation.ni.dll!
193 | | | 33.575797000 | | | | System.Management.Automation.ni.dll!
194 | | | 33.575797000 | | | | mscorlib.ni.dll!
195 | | | 33.575797000 | | | | mscorlib.ni.dll!
196 | | | 33.575797000 | | | | mscorlib.ni.dll!
197 | | | 33.575797000 | | | | mscorlib.ni.dll!
198 | | | 33.575797000 | | | | mscorlib.ni.dll!
199 | | | 33.575797000 | | | | mscorlib.ni.dll!
200 | | | 33.575797000 | | | | KernelBase.dll!WriteFile | 1 | 12.100 | 10,487,552.400 | 0.00
201 | | | 33.575797000 | | | | ntdll.dll!ZwWriteFile | 1 | 12.100 | 10,487,552.400 | 0.00
202 | | | 33.575797000 | | | | ntoskrnl.exe!KiSystemServiceExitPico | 1 | 12.100 | 10,487,552.400 | 0.00
203 | | | 33.575797000 | | | | ntoskrnl.exe!NtWriteFile | 1 | 12.100 | 10,487,552.400 | 0.00
204 | | | 33.575797000 | | | | FLTMGR.SYS!FltpFastIoWrite | 1 | 12.100 | 10,487,552.400 | 0.00
205 | | | 33.575797000 | | | | FLTMGR.SYS!FltpPerformFastIoCall | 1 | 12.100 | 10,487,552.400 | 0.00
206 | | | 33.575797000 | | | | Npfs.SYS!NpFastWrite | 1 | 12.100 | 10,487,552.400 | 0.00
207 | | | 33.575797000 | | | | ntoskrnl.exe!IofCompleteRequest | 1 | 12.100 | 10,487,552.400 | 0.00
208 | | | 33.575797000 | | | | ntoskrnl.exe!IopfCompleteRequest | 1 | 12.100 | 10,487,552.400 | 0.00
209 | | | 33.575797000 | | | | ntoskrnl.exe!KiExitDispatcher | 1 | 12.100 | 10,487,552.400 | 0.00
210 | | | 33.575797000 | | | | | 1 | 12.100 | 10,487,552.400 | 0.00
It we look at the worker threads in both the parent powershell (10300), and the children powershells, we can see the thread pools slowly adding threads until the deadlock is broken!!!
Notice each powershell gets 4 worker threads to begin with, in green.
Then the parent and children start ping-ponging back and forth trying to make progress, while lots of calls are stuck reading from the named pipes!
They slowly grow their thread pools, in teal.
Line # | New Process | New Thread Id | Switch-In Time (s) | Count | Ready (µs) | Waits (µs) | % CPU Usage
-- | -- | -- | -- | -- | -- | -- | --
1 | powershell.exe (10300) | | 0.420658600 | 1756 | 68,080.100 | 33,155,652.800 | 0.15
2 | | 15172 | 0.420658600 | 188 | 52,156.700 | 33,155,652.800 | 0.01
3 | | 5396 | 0.421009000 | 185 | 60,911.700 | 14,972,274.300 | 0.02
4 | | 10988 | 0.423323900 | 126 | 60,771.200 | 33,114,942.400 | 0.01
5 | | 11196 | 0.423577800 | 229 | 51,997.500 | 14,468,807.100 | 0.02
6 | | 16648 | 8.073045400 | 20 | 36,961.400 | 14,991,243.900 | 0.00
7 | | 15372 | 13.126511000 | 62 | 43,214.700 | 16,459,406.800 | 0.01
8 | | 4880 | 19.069705800 | 25 | 621.800 | 11,503,918.600 | 0.01
9 | | 10080 | 23.065956500 | 37 | 36,785.400 | 9,509,707.300 | 0.01
10 | | 2292 | 24.068922800 | 42 | 43,012.600 | 9,511,462.100 | 0.01
11 | | 17856 | 27.578991200 | 233 | 36,883.900 | 6,031,377.400 | 0.01
12 | | 19648 | 30.564375500 | 24 | 68,080.100 | 4,008,105.100 | 0.00
13 | | 19272 | 30.565023300 | 20 | 60,584.600 | 14,486,609.100 | 0.00
14 | | 23436 | 30.574434200 | 53 | 43,634.800 | 13,509,866.600 | 0.01
15 | | 21932 | 31.573278400 | 48 | 36,574.200 | 10,496,899.400 | 0.01
16 | | 21116 | 33.636043000 | 33 | 44,993.900 | 7,561,225.100 | 0.01
17 | | 22624 | 34.571503300 | 58 | 60,086.000 | 0.000 | 0.00
18 | | 19148 | 34.572190600 | 31 | 48,808.300 | 4,985,619.600 | 0.00
19 | | 1696 | 34.577699400 | 26 | 49,029.000 | 3,007,711.600 | 0.00
20 | | 10596 | 34.578177700 | 13 | 49,468.900 | 2,004,739.400 | 0.00
21 | | 2608 | 34.578218300 | 15 | 58,259.300 | 1,000,024.500 | 0.00
22 | | 5896 | 34.725669100 | 13 | 44,782.300 | 7,649,402.700 | 0.00
23 | | 6976 | 34.753137800 | 19 | 43,013.400 | 9,682,528.100 | 0.00
24 | | 19840 | 34.771297300 | 22 | 37,818.500 | 12,693,052.600 | 0.00
25 | | 15316 | 34.775245600 | 29 | 43,678.300 | 16,708,601.000 | 0.00
26 | | 16076 | 34.776745700 | 30 | 43,220.700 | 19,698,598.400 | 0.00
27 | | 10608 | 34.842859000 | 71 | 42,690.800 | 14,770,391.500 | 0.00
28 | | 21020 | 34.858426600 | 104 | 36,577.200 | 6,276,214.000 | 0.00
29 | powershell.exe (4552) | | 1.089180200 | 3642 | 56,915.000 | 20,005,878.000 | 0.90
30 | | 20584 | 1.089180200 | 1473 | 30,244.700 | 14,506,361.000 | 0.46
31 | | 12396 | 1.090133600 | 849 | 56,915.000 | 19,997,445.900 | 0.20
32 | | 5644 | 1.092526200 | 712 | 30,120.600 | 20,005,878.000 | 0.18
33 | | 12324 | 1.110159300 | 608 | 34,018.100 | 14,769,277.500 | 0.06
34 | powershell.exe (7668) | | 2.426267300 | 4226 | 34,876.800 | 14,482,255.000 | 0.90
35 | | 5440 | 2.426267300 | 1419 | 20,971.400 | 14,474,065.600 | 0.41
36 | | 13496 | 2.436236000 | 675 | 34,818.600 | 14,482,255.000 | 0.21
37 | | 23168 | 2.444223000 | 642 | 34,876.800 | 14,469,553.700 | 0.07
38 | | 19980 | 2.453957800 | 1490 | 34,823.900 | 14,472,431.800 | 0.21
39 | powershell.exe (12688) | | 3.855834200 | 3581 | 60,173.500 | 20,014,413.600 | 0.88
40 | | 17404 | 3.855834200 | 1120 | 19,403.500 | 20,003,945.100 | 0.41
41 | | 13280 | 3.900124300 | 604 | 40,092.800 | 20,003,262.200 | 0.19
42 | | 18972 | 3.923708800 | 1186 | 30,556.800 | 20,011,644.600 | 0.20
43 | | 14312 | 3.985540200 | 605 | 37,782.500 | 20,014,413.600 | 0.06
44 | | 11380 | 29.590410300 | 48 | 36,462.900 | 4,974,501.400 | 0.01
45 | | 18288 | 29.590437500 | 5 | 169.300 | 1,276.600 | 0.01
46 | | 22212 | 29.596775400 | 13 | 60,173.500 | 4,964,916.800 | 0.00
47 | powershell.exe (13860) | | 5.189127500 | 3548 | 55,943.100 | 20,006,347.700 | 0.89
48 | | 4540 | 5.189127500 | 1351 | 20,589.000 | 20,000,245.100 | 0.41
49 | | 6996 | 5.190163500 | 892 | 28,486.100 | 19,997,241.900 | 0.36
50 | | 3632 | 5.200365800 | 429 | 28,529.600 | 20,006,080.200 | 0.02
51 | | 7080 | 5.200498900 | 437 | 26,289.500 | 20,006,347.700 | 0.05
52 | | 13052 | 30.575804900 | 136 | 9,591.300 | 3.900 | 0.01
53 | | 17864 | 30.582149400 | 76 | 39,753.000 | 3,953,391.300 | 0.02
54 | | 12212 | 30.595325000 | 76 | 55,943.100 | 3,952,152.600 | 0.00
55 | | 21828 | 30.609519000 | 151 | 1,010.400 | 0.000 | 0.00
56 | powershell.exe (7048) | | 6.475105100 | 4425 | 62,012.900 | 20,009,790.000 | 0.91
57 | | 4140 | 6.475105100 | 1343 | 13,570.200 | 20,002,641.800 | 0.43
58 | | 15280 | 6.506993600 | 682 | 27,312.100 | 19,996,060.700 | 0.07
59 | | 9436 | 6.510695500 | 805 | 27,285.000 | 20,007,343.000 | 0.20
60 | | 11528 | 6.560950900 | 1137 | 12,886.100 | 20,009,790.000 | 0.18
61 | | 8896 | 30.574623600 | 96 | 62,012.900 | 3,948,821.400 | 0.02
62 | | 23028 | 30.594669900 | 90 | 39,989.000 | 3,950,226.900 | 0.01
63 | | 19208 | 30.596124700 | 164 | 5,459.700 | 0.000 | 0.00
64 | | 22068 | 30.597052600 | 108 | 40,027.700 | 4,025,926.900 | 0.00
65 | powershell.exe (10056) | | 7.828373100 | 3150 | 68,117.500 | 20,004,205.400 | 0.88
66 | | 7680 | 7.828373100 | 1127 | 33,318.100 | 19,998,758.000 | 0.41
67 | | 14020 | 7.828401900 | 643 | 60,934.600 | 19,994,966.200 | 0.24
68 | | 22880 | 7.836492300 | 293 | 58,791.700 | 20,004,205.400 | 0.01
69 | | 3268 | 7.836600300 | 980 | 58,882.800 | 20,002,736.400 | 0.18
70 | | 19792 | 31.573571700 | 23 | 68,117.500 | 2,982,617.500 | 0.01
71 | | 9292 | 31.573599500 | 60 | 44,001.100 | 2,994,550.100 | 0.02
72 | | 22636 | 31.590702600 | 24 | 832.700 | 3,097,816.700 | 0.01
73 | powershell.exe (18232) | | 9.089165300 | 5246 | 79,574.300 | 20,018,972.300 | 0.92
74 | | 8396 | 9.089165300 | 1145 | 79,574.300 | 20,000,395.100 | 0.24
75 | | 17628 | 9.090100000 | 1772 | 43,805.000 | 20,007,029.000 | 0.42
76 | | 5484 | 9.099732300 | 449 | 79,397.000 | 20,008,596.400 | 0.02
77 | | 916 | 9.107255600 | 1470 | 49,167.300 | 20,018,972.300 | 0.20
78 | | 19316 | 32.577481100 | 91 | 58,304.200 | 1,976,679.900 | 0.03
79 | | 11456 | 32.577921400 | 206 | 67,939.300 | 1,978,535.500 | 0.00
80 | | 3896 | 32.585216400 | 113 | 63,103.300 | 2,014,736.200 | 0.00
81 | powershell.exe (16820) | | 10.760492500 | 3838 | 67,815.600 | 20,013,499.500 | 0.86
82 | | 16444 | 10.760492500 | 1147 | 26,830.000 | 20,010,635.700 | 0.38
83 | | 12832 | 10.779058300 | 1235 | 11,505.300 | 20,013,499.500 | 0.37
84 | | 12148 | 10.828990800 | 317 | 43,789.500 | 20,002,151.000 | 0.02
85 | | 21448 | 10.838265000 | 668 | 25,076.700 | 20,000,178.700 | 0.05
86 | | 17008 | 33.584340100 | 106 | 67,815.600 | 929,435.600 | 0.00
87 | | 6940 | 33.584482600 | 150 | 46,815.100 | 918,478.700 | 0.03
88 | | 22084 | 33.597786600 | 215 | 46,703.100 | 948,137.000 | 0.00
89 | powershell.exe (22060) | | 12.209247300 | 4301 | 64,406.100 | 20,012,003.500 | 0.88
90 | | 2960 | 12.209247300 | 1276 | 60,521.200 | 19,993,259.800 | 0.43
91 | | 13724 | 12.213388700 | 703 | 64,396.900 | 20,005,305.200 | 0.06
92 | | 19168 | 12.221495500 | 739 | 64,406.100 | 20,007,111.200 | 0.18
93 | | 13432 | 12.226942000 | 1236 | 23,247.400 | 20,012,003.500 | 0.19
94 | | 15920 | 33.634005900 | 113 | 48,017.000 | 916,136.200 | 0.01
95 | | 12440 | 33.637295400 | 78 | 46,993.100 | 920,273.800 | 0.00
96 | | 12516 | 33.640861000 | 156 | 3,916.100 | 931,911.200 | 0.02
97 | powershell.exe (18544) | | 13.610125000 | 3055 | 68,074.800 | 19,095,187.100 | 0.83
98 | | 12816 | 13.610125000 | 849 | 60,873.700 | 19,095,187.100 | 0.35
99 | | 2496 | 13.611820500 | 558 | 68,074.800 | 19,083,736.300 | 0.05
100 | | 2964 | 13.611950600 | 1019 | 60,749.300 | 19,082,378.000 | 0.39
101 | | 20676 | 13.620439400 | 629 | 14,292.700 | 19,091,233.600 | 0.03
rtestardi
on 22 Jan 2020
Adding @daxian-dbw who is looking at this perf issue.
PowerShell doesn't write directly to named pipes, but communicates between parent and child processes via dotNet Process class stdIn/stdOut reader/writers, which I assume use named pipes.
PowerShell uses the remoting protocol (PSRP) to communicate between parent/client processes for running commands/script and transferring data.
PowerShell uses dotNet Process stdIn/sdtOut to communicate between processes, and I don't know if dotNet uses threadpool threads.
PowerShell does use threadpool threads for other async tasks, including waiting for connection handshake and initialization of remote sessions. But I don't know of any case where new session creation is blocked for multiple seconds. I would need to see stack of stalled threads to know more.
But it is still not clear to me that this is a PowerShell issue, and it is just waiting for processes to be created for each job. Again, I would need a repro or stack information to know what stalled threads are doing.
PaulHigin
on 22 Jan 2020
Since the delay is so long, if you can take a process dump of parent/child, that would help determine what threads are waiting for.
PaulHigin
on 22 Jan 2020
Hi Paul,
Powershell depends on threadpool tasks running promptly in order to launch jobs, so I'm pretty sure this is a powershell bug -- you are using the one shared threadpool for two fundamentally different kinds of tasks -- long-lived blocking tasks, and transient tasks -- that always results in exactly this problem with a shared threadpool. It may be you have to find lower level mechanisms that are "task friendly" and do not block your task threads, or move the blocking tasks to their own private threadpool.
Of course, if the lower level system were different, powershell would not have this issue. But it isn't, :-)
And this experiment seems to confirm it (too bad I can't paste a table in here):
WORKAROUND:
20 min threads (so blocked threads don't prevent queued tasks from running)
C:\temp>set ComPlus_ThreadPool_ForceMinWorkerThreads=20
C:\temp>powershell
Windows PowerShell
Copyright (C) Microsoft Corporation. All rights reserved.
Try the new cross-platform PowerShell https://aka.ms/pscore6
PS C:\temp> measure-command { 1..10 | %{ start-job { $null } }; get-job | wait-job; get-job | remove-job };
Days : 0
Hours : 0
Minutes : 0
Seconds : 2
Milliseconds : 949
Ticks : 29491029
TotalDays : 3.41331354166667E-05
TotalHours : 0.00081919525
TotalMinutes : 0.049151715
TotalSeconds : 2.9491029
TotalMilliseconds : 2949.1029
NO WORKAROUND:
default (4) min threads (4 blocked threads can prevent queued tasks from running until threadpool expansion)
C:\temp>powershell
Windows PowerShell
Copyright (C) Microsoft Corporation. All rights reserved.
Try the new cross-platform PowerShell https://aka.ms/pscore6
PS C:\temp> measure-command { 1..10 | %{ start-job { $null } }; get-job | wait-job; get-job | remove-job };
Days : 0
Hours : 0
Minutes : 0
Seconds : 21
Milliseconds : 632
Ticks : 216328858
TotalDays : 0.000250380622685185
TotalHours : 0.00600913494444444
TotalMinutes : 0.360548096666667
TotalSeconds : 21.6328858
TotalMilliseconds : 21632.8858
rtestardi
on 22 Jan 2020
Sure, I can get you a dump -- the ETL also has every single thread wait in it as well, so you can see where threads are waiting (as I did above), as well as where they had been waiting earlier.
The dump is here: "\scratch2\scratch\richardt\powershell.cmp.zip"
rtestardi
on 22 Jan 2020
Well, PowerShell or dotNet on which PowerShell runs. But @daxian-dbw just found a reliable repro (this is the best thing to give us), so I can get a stack and take a look. Will let you know what I find.
PaulHigin
on 22 Jan 2020
PPS and possibly one more observation...
If you search for ZwReadFile above, you'll find two different call stacks -- one under wmain (of the child powershell), and one under ntdll.dll!RtlUserThreadStart -> clr.dll!ThreadpoolMgr::ExecuteWorkRequest (of the parent powershell).
It is the latter that is an issue, I believe, since it ties up a worker thread indefinitely.
If the reader (whose call stack is hidden from us in mscorlib.ni.dll) had been async-aware, there would have been no issue (it would have just queued a continuation task when the read completed, and left the worker thread to do other work).
Maybe that's the simple fix?
From: Richard Testardi
Sent: Wednesday, January 22, 2020 2:57 PM
Good news is that we are able to repro the issue consistently now, by running
set ComPlus_ThreadPool_ForceMinWorkerThreads=4.
Awesome.
I think the real issue is you don't want long-lived non-asynchronous tasks (like read from pipe) competing for the same small number of threads in the common threadpool as transient tasks.
Either all tasks in the threadpool have to be async (relinquishing the thread when blocked, which read from pipe does not), or long-lived and transient tasks need to be in two separate threadpools.
If folks prefer dumps to ETL files, I put one here, part way into a 26 second hang: "\scratch2\scratch\richardt\powershell.cmp.zip"
Thanks!
-- Rich
rtestardi
on 22 Jan 2020
Ok, I have looked into this and discussed with @daxian-dbw . The problem is worker pool thread starvation, caused by .Net System.Diagnostics.Process. It is only the background job transport that uses System.Diagnostics.Process that causes the problem. Other PowerShell remoting transports do not exhibit the problem. When a System.Diagnostics.Process object is created with redirected StdOutput and StdError (which PowerShell uses), a thread pool thread is requested for each. So when 10 PowerShell jobs are run, 20 thread pool threads are requested and remain for the lifetime of the jobs. This is an abuse of thread pool threads since the lifetime of the created process and therefore the reader threads is unknown.
In addition, PowerShell uses thread pool threads to process job remoting protocol messages, which are normally handled very quickly and the thread is released.
When a lot of background jobs are created (as per repro), this thread starvation can cause PowerShell job initialization to deadlock until the thread pool allocates more threads. The workaround is to ensure the thread pool minimum threads setting is set to a reasonable value for running many jobs (e.g., ‘set ComPlus_ThreadPool_ForceMinWorkerThreads=20’). However, PowerShell can help alleviate this problem by using dedicated threads for protocol message processing, and I’ll work on a fix for this. We will also submit an issue to .Net about System.Diagnostics.Process using thread pool threads for stdout/error readers.
@rtestardi thanks for bringing this to our attention and performing the initial analysis!
PaulHigin
on 23 Jan 2020
Actually, @daxian-dbw pointed out that it is actually the System.Diagnostics.Process.OutputDataReceived event handler that uses the thread pool thread. This code can be re-written to use PowerShell dedicated threads to read the stdout/error streams.
Also we need to look at the base transport message processing, which may not need to use thread pool threads.
PaulHigin
on 23 Jan 2020
When a System.Diagnostics.Process object is created with redirected StdOutput and StdError (which PowerShell uses), a thread pool thread is requested for each.
More specifically, PowerShell simply uses Process.OutputDataReceived and Process.ErrorDataReceived events to handle the output and error from the child process asynchronously.
The System.Diagnostics.Process type handles those two events by using an AsyncStreamReader for each of those 2 pipes, which eventually creates a task that calls FileStream.ReadAsync on the base stream.
So the FileStream.ReadAsync calls will be running on thread pool threads.
Even though ReadAsync is being called, I don’t think it’s able to actually read from a pipe asynchronously. Hence, those 2 thread pool threads get held indefinitely.
Below is a simple program demonstrating this behavior, along with the thread activity screenshot when it “hangs”:
```c#
class Program
{
static void Main(string[] args)
{
var startInfo = new ProcessStartInfo() {
FileName = "powershell",
Arguments = "-noprofile -c sleep 30",
RedirectStandardOutput = true,
RedirectStandardError = true
};
var process = Process.Start(startInfo);
process.OutputDataReceived += DataReceived;
process.ErrorDataReceived += DataReceived;
process.BeginOutputReadLine();
process.BeginErrorReadLine();
Console.ReadKey();
Console.WriteLine("DONE");
}
static void DataReceived(object sender, DataReceivedEventArgs e)
{
Console.WriteLine(e.Data);
}
}
```
I don’t know if that’s by design on the .NET side …
But yes, what PowerShell can do is to not depend on those 2 events, but instead, create our own dedicated threads to read the in-coming messages from the output and error pipes for each child process.
And actually, it turned out that’s what we already do for the remoting connection over SSH.
daxian-dbw
on 23 Jan 2020
Even though ReadAsync is being called, I don’t think it’s able to actually read from a pipe asynchronously.
Wow, it seems the underlying Win32 API (CreatePipe()) only allows the pipe handle to be created in "synchronous" mode -- you'd have to use the NT API to open it for async, which would mean you're in somewhat uncharted waters.
So, agreed, dedicated threads (or not using pipes :-) are the only real solutions here.
rtestardi
on 28 Jan 2020
:tada:This issue was addressed in #11713, which has now been successfully released as v7.1.0-preview.2.:tada:
Handy links:
![msftbot[bot] picture](https://avatars2.githubusercontent.com/in/26612?v=4&s=40)
msftbot[bot]
on 23 Apr 2020
Related issues
manofspirit
·
3Comments
mklement0
·
3Comments
garegin16
·
3Comments
SteveL-MSFT
·
3Comments
concentrateddon
·
3Comments
Most helpful comment
Hi Paul,
Powershell depends on threadpool tasks running promptly in order to launch jobs, so I'm pretty sure this is a powershell bug -- you are using the one shared threadpool for two fundamentally different kinds of tasks -- long-lived blocking tasks, and transient tasks -- that always results in exactly this problem with a shared threadpool. It may be you have to find lower level mechanisms that are "task friendly" and do not block your task threads, or move the blocking tasks to their own private threadpool.
Of course, if the lower level system were different, powershell would not have this issue. But it isn't, :-)
And this experiment seems to confirm it (too bad I can't paste a table in here):
WORKAROUND:
20 min threads (so blocked threads don't prevent queued tasks from running)
C:\temp>set ComPlus_ThreadPool_ForceMinWorkerThreads=20
C:\temp>powershell
Windows PowerShell
Copyright (C) Microsoft Corporation. All rights reserved.
Try the new cross-platform PowerShell https://aka.ms/pscore6
PS C:\temp> measure-command { 1..10 | %{ start-job { $null } }; get-job | wait-job; get-job | remove-job };
Days : 0
Hours : 0
Minutes : 0
Seconds : 2
Milliseconds : 949
Ticks : 29491029
TotalDays : 3.41331354166667E-05
TotalHours : 0.00081919525
TotalMinutes : 0.049151715
TotalSeconds : 2.9491029
TotalMilliseconds : 2949.1029
NO WORKAROUND:
default (4) min threads (4 blocked threads can prevent queued tasks from running until threadpool expansion)
C:\temp>powershell
Windows PowerShell
Copyright (C) Microsoft Corporation. All rights reserved.
Try the new cross-platform PowerShell https://aka.ms/pscore6
PS C:\temp> measure-command { 1..10 | %{ start-job { $null } }; get-job | wait-job; get-job | remove-job };
Days : 0
Hours : 0
Minutes : 0
Seconds : 21
Milliseconds : 632
Ticks : 216328858
TotalDays : 0.000250380622685185
TotalHours : 0.00600913494444444
TotalMinutes : 0.360548096666667
TotalSeconds : 21.6328858
TotalMilliseconds : 21632.8858