Slow deployment, high powershell.exe CPU

We have windows service deploys that seem to take a lot longer than they should. In some of our environments, it only takes 1-2 minutes for the deploy to run, but in other environments it can take 30 minutes. The actual powershell portions of the script seem to run really fast, but in between each step of the step, it’ll take 2-3 minutes. As I’ve watched the server processes during this time, the powershell process is basically 100% of one CPU (IE on a two proc server it takes 50% cpu and on a 8 proc server it takes 12-13%). I’m having a hard time figuring out what it is doing during this time.

Is this something that you’ve seen before? We have a lot of variables and shared-modules in the project. Can these things cause this? I’ve tried deploying these windows services from a separate project which just has the one step in it and fewer variables and no shared modules and it can run the same step in about 1 minute which seems to indicate that maybe it has something to do with what is this project.

Hi Dan,

Thanks for getting in touch, and welcome!

I’m sorry to see you’re hitting this inconvenient issue. From memory we’ve seen similar issues which stemmed from either missing indexes in the Octopus database, or even high fragmentation on the same database. I’d be interested in ruling that out to get started.

Would you be willing to run a system integrity check (in your web portal under Configuration > Diagnostics) and send the resulting task log? That’ll include any potential missing indexes and getting those rebuilt might help.

There’s also a community step template to query the Octopus db and output the fragmentation of each table.

Feel free to mark this thread as private, or email any private info to support@octopus.com.

I look forward to hearing back!

Best regards,

Kenny

I can try to get that information (I’m not an admin of the system so will need to get an admin to run that), but I’m not sure how high CPU in our powershell.exe processes would be caused by high fragmentation at the database.

Some additional information. I figured out how to attach the Powershell ISE debugger to the process and found that when it was taking the high CPU, it was in the Decrypt-Variables function looping through all of the lines from the $Encrypted variable. When it was done, the $parameters dictionary had 5363 items in it. The $Encrypted.Length was 1,952,856. I’m not sure if these are high amounts or not, but it did take some time to go through all of $Encrypted.

Hi Dan,

Thanks for following up! Very interesting finding there, and I appreciate the update. I think that will get us pointed in the right direction. I’d like to get a look at the whole deployment context - would you be willing to send a copy of a task log in which you’ve hit this issue?

Your mention of Decrypt-Variables rang a vague bell from a couple years ago so I’m wondering if you might be hitting the same as is reported in another private thread. It was determined there to be tied to the (now quite old) version of Calamari you’re running (if there’s an upgrade available that would be worth a shot right away). Anyway, the logs will give us that information and more if you’re still getting bogged down and I might end up wanting to raise this internally for more eyes.

I look forward to hearing back!

Best regards,

Kenny

I sent the task log to support@octopus.com referencing this thread and the URL for this thread.

I also wonder if maybe there might be something on our machines that might be slowing down the running of powershell. I’ve only looked at one machine, so it might do this on all machines, but when I would look at the stack of the running thread through sysinternals Procexp.exe, I kept on seeing this method being called:

SystemPolicy.GetSystemLockdownPolicy() which eventually checks to see if wldp.dll exists in the system32 directory. When I run procmon.exe, I can see this check being made many times per second. When I was debugging the script, I could see that this gets checked often multiple times per line. I need to check this on a separate machine to see if maybe this always happens and this is just a wild goose or if this is unique to these machines and might be cause of the slowness.

1 Like

I’ve discovered some additional information. After extracting the relevant code from the script so I could run it on its own for testing purposes, I could see that I get the slow down when running the script in a powershell session where debugging is enabled. If I had a powershell session where debugging was not enabled, it runs fast. But I also found that on these servers where the powershell is running slowly, debugging appears to be enabled by default on new powershell sessions. I’m not sure yet what is causing that.

But I’ve found that if I turn it off, then the script runs quickly again.

Here’s I get the value and set it:

$f = $ExecutionContext.GetType().GetField("_context", [System.Reflection.BindingFlags]::NonPublic -bor [Reflection.BindingFlags]::Instance)

$context = $f.GetValue($ExecutionContext)

$dm = $context.GetType().GetField("_debuggingMode",  [System.Reflection.BindingFlags]::NonPublic -bor [Reflection.BindingFlags]::Instance)

$dm.GetValue($context)
1

$dm.SetValue($context, 0)

Here’s what I’ve found out so far. In trying to figure out why this debuggingMode was being set, I discovered the cmdlet Set-PSDebug -Off. When I do this on my local machine, I can see the _debuggingMode being changed to 0, but when I did this on one of these affected machines, it would remain a “1”. Looking at the reflected code, it would only do this if there were breakpoints currently set in the session. If I ran Get-PSBreakPoint, it would return nothing. But then I ran a “Get-Command Get-PSBreakpoint | select *” on affected machines, this was CommandType of Function and on non-affected machines it was CmdLet. The definition on affected machines looked like this:

[CmdletBinding(DefaultParametersetName="Script")]
                      param(
                      [parameter(Mandatory = $True,ValueFromPipeline = $True,ValueFromPipelineByPropertyName =
                      $True,ValueFromRemainingArguments = $True,ParameterSetName = "Variable")]
                      [string[]]
                      $Script,
                      [parameter(Mandatory = $True,Position = 0,ValueFromPipeline = $True,ParameterSetName = "Id")]
                      [int[]]
                      $Id,
                      [parameter(Mandatory = $True,ParameterSetName = "Variable")]
                      [string[]]
                      $Variable,
                      [parameter(Mandatory = $True,ParameterSetName = "Command")]
                      [string[]]
                      $Command,
                      [parameter(Mandatory = $True,Position = 0,ValueFromPipeline = $True,ParameterSetName = "Type")]
                      [Microsoft.PowerShell.Commands.BreakpointType[]]
                      $Type)
                          $local:origGetPsbreakpoint = Get-Command Get-PSBreakpoint -Type cmdlet
                          if ((Test-Path variable:psBoundParameters) -or $psBoundParameters.count) {
                              return ((& $origGetPsbreakpoint @psBoundParameters) | where {!($_.Action -and
                      $_.Action.ToString().toLower().contains('<#sentinelbreakpoints#>'))})
                          } else {
                              return ((& $origGetPsbreakpoint @args) | where {!($_.Action -and
                      $_.Action.ToString().toLower().contains('<#sentinelbreakpoints#>'))})
                          }

In this code I can see “<#sentinelbreakpoints#>” and SentinelOne is our antivirus product. Once I new this, I could call the original cmdlet version of Get-PSBreakpoint and there were 58 Variable and Command breakpoints with Actions on them. It looks like something in SentinelOne is injecting breakpoints into the powershell code so that it can inject itself into certain calls or changes of variables. Because these breakpoints are there, it causes the powershell code to see the debugger active and everytime a variable is set, it is calling ScriptDebugger.CheckVariableWrite which checks the SystemLockdownPolicy which is where I’m seeing the check for the existence of the wldp.dll.

Also, when I decompiled the System.Management.Automation assembly on my machine, I saw this:

But when I grabbed the assembly from one of the affected machines, this is what this method looked like:

I then checked and found that I did indeed have different versions of powershell 5.1 running on my machine vs the server machines.

My next step is going to see if I can get PS 5 updated on the machine and if that doesn’t improve things, I’m going to talk to our AV guys and see what powershell switches they have to potentially turn this off.

1 Like

This topic was automatically closed 31 days after the last reply. New replies are no longer allowed.