Octopus 2.6.5.1010 API is very slow

James_Baker · May 19, 2015, 3:55am

Hi, we have noticed in 2.6.5.1010 that the API is very slow and as a result makes Octopus grind to a halt
We have a process where an AWS enviroment is torn down which results in a powershell script to clean up the tentacles from Octopus. This used to take 60-120 seconds to run on 2.6.4 however it now takes in the order of 10-20x longer

For example

2015-05-19 10:48:04 Getting Octopus environments to find MyEnvironmentName
Invoke-RestMethod : The operation has timed out.
At cleanup-octopus.ps1:45 char:8
+     $ms = Invoke-RestMethod $environmenturi -Headers $h -Method Get
+           ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : InvalidOperation: (System.Net.HttpWebRequest:HttpWebRequest) [Invoke-RestMethod], WebExc
   eption
    + FullyQualifiedErrorId : WebCmdletWebResponseException,Microsoft.PowerShell.Commands.InvokeRestMethodCommand

2015-05-19 10:52:23 Removing Environment from Developers Group
Invoke-RestMethod : The operation has timed out.
At cleanup-octopus.ps1:58 char:12
+ $prejson = Invoke-RestMethod -Uri $teamuri -Headers $h -Method get
+            ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : InvalidOperation: (System.Net.HttpWebRequest:HttpWebRequest) [Invoke-RestMethod], WebExc
   eption
    + FullyQualifiedErrorId : WebCmdletWebResponseException,Microsoft.PowerShell.Commands.InvokeRestMethodCommand

The property 'EnvironmentIds' cannot be found on this object. Verify that the property exists and can be set.
At cleanup-octopus.ps1:60 char:1
+ $prejson.EnvironmentIds = [string[]]($prejson.EnvironmentIds | Where-Object {$_  ...
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : InvalidOperation: (:) [], RuntimeException
    + FullyQualifiedErrorId : PropertyNotFound

Invoke-RestMethod : The remote server returned an error: (500) Internal Server Error.
At cleanup-octopus.ps1:64 char:1
+ Invoke-RestMethod -Uri $teamuri -Headers $h -Method Put -Body $json
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : InvalidOperation: (System.Net.HttpWebRequest:HttpWebRequest) [Invoke-RestMethod], WebExc
   eption
    + FullyQualifiedErrorId : WebCmdletWebResponseException,Microsoft.PowerShell.Commands.InvokeRestMethodCommand

2015-05-19 10:54:57 Getting Octopus tentacles (machines)
2015-05-19 10:56:15 Removing tentacle /api/machines/machines-5240
2015-05-19 10:56:15 @{Id=ServerTasks-10428; Name=Delete; Description=Delete: MyEnvironmentName-XXX
al (machines-5240); Arguments=; State=Queued; Completed=Queued...; QueueTime=2015-05-19T00:56:15.603+00:00; StartTime=;
LastUpdatedTime=2015-05-19T00:56:15.603+00:00; CompletedTime=; Duration=less than a second; ErrorMessage=; HasBeenPicked
UpByProcessor=False; IsCompleted=False; FinishedSuccessfully=False; HasPendingInterruptions=False; CanRerun=True; HasWar
ningsOrErrors=False; Links=}
2015-05-19 10:56:15 Removing tentacle /api/machines/machines-5250
2015-05-19 10:56:24 @{Id=ServerTasks-10429; Name=Delete; Description=Delete: MyEnvironmentName-XXX
al (machines-5250); Arguments=; State=Queued; Completed=Queued...; QueueTime=2015-05-19T00:56:24.432+00:00; StartTime=;
LastUpdatedTime=2015-05-19T00:56:24.432+00:00; CompletedTime=; Duration=less than a second; ErrorMessage=; HasBeenPicked
UpByProcessor=False; IsCompleted=False; FinishedSuccessfully=False; HasPendingInterruptions=False; CanRerun=True; HasWar
ningsOrErrors=False; Links=}
2015-05-19 10:56:24 Removing tentacle /api/machines/machines-5246
2015-05-19 10:57:02 @{Id=ServerTasks-10430; Name=Delete; Description=Delete: MyEnvironmentName-XXX
al (machines-5246); Arguments=; State=Queued; Completed=Queued...; QueueTime=2015-05-19T00:57:02.463+00:00; StartTime=;
LastUpdatedTime=2015-05-19T00:57:02.463+00:00; CompletedTime=; Duration=less than a second; ErrorMessage=; HasBeenPicked
UpByProcessor=False; IsCompleted=False; FinishedSuccessfully=False; HasPendingInterruptions=False; CanRerun=True; HasWar
ningsOrErrors=False; Links=}
2015-05-19 10:57:02 Removing tentacle /api/machines/machines-5247
2015-05-19 10:58:11 @{Id=ServerTasks-10431; Name=Delete; Description=Delete: MyEnvironmentName-XXX
(machines-5247); Arguments=; State=Queued; Completed=Queued...; QueueTime=2015-05-19T00:58:11.541+00:00; StartTime=; Las
tUpdatedTime=2015-05-19T00:58:11.541+00:00; CompletedTime=; Duration=less than a second; ErrorMessage=; HasBeenPickedUpB
yProcessor=False; IsCompleted=False; FinishedSuccessfully=False; HasPendingInterruptions=False; CanRerun=True; HasWarnin
gsOrErrors=False; Links=}
2015-05-19 10:58:11 Removing tentacle /api/machines/machines-5244
2015-05-19 10:59:38 @{Id=ServerTasks-10432; Name=Delete; Description=Delete: MyEnvironmentName-XXX
l (machines-5244); Arguments=; State=Queued; Completed=Queued...; QueueTime=2015-05-19T00:59:38.338+00:00; StartTime=; L
astUpdatedTime=2015-05-19T00:59:38.338+00:00; CompletedTime=; Duration=less than a second; ErrorMessage=; HasBeenPickedU
pByProcessor=False; IsCompleted=False; FinishedSuccessfully=False; HasPendingInterruptions=False; CanRerun=True; HasWarn
ingsOrErrors=False; Links=}
2015-05-19 10:59:38 Removing tentacle /api/machines/machines-5242
2015-05-19 11:00:32 @{Id=ServerTasks-10433; Name=Delete; Description=Delete: MyEnvironmentName-XXX
 (machines-5242); Arguments=; State=Queued; Completed=Queued...; QueueTime=2015-05-19T01:00:32.713+00:00; StartTime=; La
stUpdatedTime=2015-05-19T01:00:32.713+00:00; CompletedTime=; Duration=less than a second; ErrorMessage=; HasBeenPickedUp
ByProcessor=False; IsCompleted=False; FinishedSuccessfully=False; HasPendingInterruptions=False; CanRerun=True; HasWarni
ngsOrErrors=False; Links=}
2015-05-19 11:00:32 Removing tentacle /api/machines/machines-5245
Invoke-RestMethod : The operation has timed out.
At cleanup-octopus.ps1:78 char:9
+             $t = Invoke-RestMethod "$($OctopusServer)$($m)" -Headers $h -Method Delete
+                  ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : InvalidOperation: (System.Net.HttpWebRequest:HttpWebRequest) [Invoke-RestMethod], WebExc
   eption
    + FullyQualifiedErrorId : WebCmdletWebResponseException,Microsoft.PowerShell.Commands.InvokeRestMethodCommand

2015-05-19 11:02:12 @{Id=ServerTasks-10433; Name=Delete; Description=Delete: MyEnvironmentName-XXX
 (machines-5242); Arguments=; State=Queued; Completed=Queued...; QueueTime=2015-05-19T01:00:32.713+00:00; StartTime=; La
stUpdatedTime=2015-05-19T01:00:32.713+00:00; CompletedTime=; Duration=less than a second; ErrorMessage=; HasBeenPickedUp
ByProcessor=False; IsCompleted=False; FinishedSuccessfully=False; HasPendingInterruptions=False; CanRerun=True; HasWarni
ngsOrErrors=False; Links=}
2015-05-19 11:02:12 Removing tentacle /api/machines/machines-5248
Invoke-RestMethod : The operation has timed out.
At cleanup-octopus.ps1:78 char:9
+             $t = Invoke-RestMethod "$($OctopusServer)$($m)" -Headers $h -Method Delete
+                  ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : InvalidOperation: (System.Net.HttpWebRequest:HttpWebRequest) [Invoke-RestMethod], WebExc
   eption
    + FullyQualifiedErrorId : WebCmdletWebResponseException,Microsoft.PowerShell.Commands.InvokeRestMethodCommand

2015-05-19 11:03:52 @{Id=ServerTasks-10433; Name=Delete; Description=Delete: MyEnvironmentName-XXX
 (machines-5242); Arguments=; State=Queued; Completed=Queued...; QueueTime=2015-05-19T01:00:32.713+00:00; StartTime=; La
stUpdatedTime=2015-05-19T01:00:32.713+00:00; CompletedTime=; Duration=less than a second; ErrorMessage=; HasBeenPickedUp
ByProcessor=False; IsCompleted=False; FinishedSuccessfully=False; HasPendingInterruptions=False; CanRerun=True; HasWarni
ngsOrErrors=False; Links=}
2015-05-19 11:03:52 Waiting for 8 tentacles to fall off
2015-05-19 11:05:25 @{Id=ServerTasks-10428; Name=Delete; Description=Delete: MyEnvironmentName-XXX
al (machines-5240); Arguments=; State=Success; Completed=Tuesday, May 19, 2015 10:56 AM; QueueTime=2015-05-19T00:56:15.6
03+00:00; StartTime=2015-05-19T00:56:15.822+00:00; LastUpdatedTime=2015-05-19T00:56:16.025+00:00; CompletedTime=2015-05-
19T00:56:16.025+00:00; Duration=less than a second; ErrorMessage=; HasBeenPickedUpByProcessor=True; IsCompleted=True; Fi
nishedSuccessfully=True; HasPendingInterruptions=False; CanRerun=True; HasWarningsOrErrors=False; Links=}
2015-05-19 11:06:59 @{Id=ServerTasks-10429; Name=Delete; Description=Delete: MyEnvironmentName-XXX
al (machines-5250); Arguments=; State=Success; Completed=Tuesday, May 19, 2015 10:56 AM; QueueTime=2015-05-19T00:56:24.4
32+00:00; StartTime=2015-05-19T00:56:24.603+00:00; LastUpdatedTime=2015-05-19T00:56:24.932+00:00; CompletedTime=2015-05-
19T00:56:24.932+00:00; Duration=less than a second; ErrorMessage=; HasBeenPickedUpByProcessor=True; IsCompleted=True; Fi
nishedSuccessfully=True; HasPendingInterruptions=False; CanRerun=True; HasWarningsOrErrors=False; Links=}
2015-05-19 11:08:16 @{Id=ServerTasks-10430; Name=Delete; Description=Delete: MyEnvironmentName-XXX
al (machines-5246); Arguments=; State=Success; Completed=Tuesday, May 19, 2015 10:57 AM; QueueTime=2015-05-19T00:57:02.4
63+00:00; StartTime=2015-05-19T00:57:24.963+00:00; LastUpdatedTime=2015-05-19T00:57:25.182+00:00; CompletedTime=2015-05-
19T00:57:25.182+00:00; Duration=less than a second; ErrorMessage=; HasBeenPickedUpByProcessor=True; IsCompleted=True; Fi
nishedSuccessfully=True; HasPendingInterruptions=False; CanRerun=True; HasWarningsOrErrors=False; Links=}
2015-05-19 11:09:41 @{Id=ServerTasks-10431; Name=Delete; Description=Delete: MyEnvironmentName-XXX
(machines-5247); Arguments=; State=Success; Completed=Tuesday, May 19, 2015 10:58 AM; QueueTime=2015-05-19T00:58:11.541+
00:00; StartTime=2015-05-19T00:58:25.197+00:00; LastUpdatedTime=2015-05-19T00:58:25.525+00:00; CompletedTime=2015-05-19T
00:58:25.525+00:00; Duration=less than a second; ErrorMessage=; HasBeenPickedUpByProcessor=True; IsCompleted=True; Finis
hedSuccessfully=True; HasPendingInterruptions=False; CanRerun=True; HasWarningsOrErrors=False; Links=}
2015-05-19 11:10:57 @{Id=ServerTasks-10432; Name=Delete; Description=Delete: MyEnvironmentName-XXX
l (machines-5244); Arguments=; State=Success; Completed=Tuesday, May 19, 2015 11:00 AM; QueueTime=2015-05-19T00:59:38.33
8+00:00; StartTime=2015-05-19T01:00:01.307+00:00; LastUpdatedTime=2015-05-19T01:00:01.525+00:00; CompletedTime=2015-05-1
9T01:00:01.525+00:00; Duration=less than a second; ErrorMessage=; HasBeenPickedUpByProcessor=True; IsCompleted=True; Fin
ishedSuccessfully=True; HasPendingInterruptions=False; CanRerun=True; HasWarningsOrErrors=False; Links=}
2015-05-19 11:12:10 @{Id=ServerTasks-10433; Name=Delete; Description=Delete: MyEnvironmentName-XXX
 (machines-5242); Arguments=; State=Success; Completed=Tuesday, May 19, 2015 11:01 AM; QueueTime=2015-05-19T01:00:32.713
+00:00; StartTime=2015-05-19T01:01:01.541+00:00; LastUpdatedTime=2015-05-19T01:01:01.807+00:00; CompletedTime=2015-05-19
T01:01:01.807+00:00; Duration=less than a second; ErrorMessage=; HasBeenPickedUpByProcessor=True; IsCompleted=True; Fini
shedSuccessfully=True; HasPendingInterruptions=False; CanRerun=True; HasWarningsOrErrors=False; Links=}
2015-05-19 11:13:38 @{Id=ServerTasks-10433; Name=Delete; Description=Delete: MyEnvironmentName-XXX
 (machines-5242); Arguments=; State=Success; Completed=Tuesday, May 19, 2015 11:01 AM; QueueTime=2015-05-19T01:00:32.713
+00:00; StartTime=2015-05-19T01:01:01.541+00:00; LastUpdatedTime=2015-05-19T01:01:01.807+00:00; CompletedTime=2015-05-19
T01:01:01.807+00:00; Duration=less than a second; ErrorMessage=; HasBeenPickedUpByProcessor=True; IsCompleted=True; Fini
shedSuccessfully=True; HasPendingInterruptions=False; CanRerun=True; HasWarningsOrErrors=False; Links=}
2015-05-19 11:15:04 @{Id=ServerTasks-10433; Name=Delete; Description=Delete: MyEnvironmentName-XXX
 (machines-5242); Arguments=; State=Success; Completed=Tuesday, May 19, 2015 11:01 AM; QueueTime=2015-05-19T01:00:32.713
+00:00; StartTime=2015-05-19T01:01:01.541+00:00; LastUpdatedTime=2015-05-19T01:01:01.807+00:00; CompletedTime=2015-05-19
T01:01:01.807+00:00; Duration=less than a second; ErrorMessage=; HasBeenPickedUpByProcessor=True; IsCompleted=True; Fini
shedSuccessfully=True; HasPendingInterruptions=False; CanRerun=True; HasWarningsOrErrors=False; Links=}
2015-05-19 11:16:39 Waiting for 0 tentacles to fall off
2015-05-19 11:16:39 Removing environment /api/environments/Environments-825
2015-05-19 11:18:08 @{Id=ServerTasks-10438; Name=Delete; Description=Delete: MyEnvironmentName (Environments-825); A
rguments=; State=Queued; Completed=Queued...; QueueTime=2015-05-19T01:18:08.370+00:00; StartTime=; LastUpdatedTime=2015-
05-19T01:18:08.370+00:00; CompletedTime=; Duration=less than a second; ErrorMessage=; HasBeenPickedUpByProcessor=False;
IsCompleted=False; FinishedSuccessfully=False; HasPendingInterruptions=False; CanRerun=True; HasWarningsOrErrors=False;
Links=}
2015-05-19 11:18:08 Done, 1803.9800247s.

As you can see that took 1800 sec to run and caused Octopus to grind to a halt

Here is the script we are running if you want to test it

# ====================================================================================
# Cleanup all artefacts (tentacles / machines and environment) for an environment in OctopusDeploy
#
# ====================================================================================
Param(
	[Parameter(Mandatory=$true)][string]$Environment,
	[string]$OctopusServerApiKey,
	[string]$OctopusServer 
	)

	
function WriteHostAndLog{
    param(
        [string]$Text,
        [string]$Color = "White"
    )

    $now = Get-Date -Format "yyyy-MM-dd HH:mm:ss"
    $output = "$now $Text"

    Write-Host -NoNewLine -ForegroundColor Gray "$now"
    Write-Host -ForegroundColor $Color " $Text"
    Add-Content -Path $GlobalLogFile -Value $output
}

$sw = [Diagnostics.Stopwatch]::StartNew()
$scriptName = ([io.fileinfo]($MyInvocation.MyCommand.Name)).basename

$suf = Get-Date -f "yyyyMMdd"
$dataroot = "c:\temp\customresources\$($suf)"
if(!(Test-Path -Path $dataroot )){
	New-Item -ItemType directory -Path $dataroot
}

$GlobalLogFile = Join-Path $dataroot "$scriptName.log"
$DebugPreference = "Continue"

$h = @{"X-Octopus-ApiKey" = $OctopusServerApiKey}

WriteHostAndLog "Getting Octopus environments to find $Environment"

$es = @()
$environmenturi = "$($OctopusServer)/api/environments"
do {
	$ms = Invoke-RestMethod $environmenturi -Headers $h -Method Get
	$es += $ms.Items
	$environmenturi = "$($OctopusServer)$($ms.Links.'Page.Next')"
} while ($ms.Links.'Page.Next')

$myenv = $es | Where-Object {$_.Name -eq "$Environment"}

WriteHostAndLog "Removing Environment from Developers Group"

$teamuri = "$($OctopusServer)/api/teams/teams-67"

$1 = $myenv.Id

$prejson = Invoke-RestMethod -Uri $teamuri -Headers $h -Method get

$prejson.EnvironmentIds = [string[]]($prejson.EnvironmentIds | Where-Object {$_ -ne $1})

$json = $prejson | ConvertTo-Json

Invoke-RestMethod -Uri $teamuri -Headers $h -Method Put -Body $json

if ($myenv) {
	
	WriteHostAndLog "Getting Octopus tentacles (machines)"
	$nomoretentacles = $false
	do {
		$nomoretentacles = $true
		$mymachines = Invoke-RestMethod "$($OctopusServer)$($myenv.Links.Machines)" -Headers $h -Method Get

		$tasks = @()
		foreach ($m in $mymachines.Items.Links.Self) {
			$nomoretentacles = $false
			WriteHostAndLog "Removing tentacle $m"
			$t = Invoke-RestMethod "$($OctopusServer)$($m)" -Headers $h -Method Delete
			WriteHostAndLog $t
			$tasks += $t
		}

		WriteHostAndLog "Waiting for $($tasks.Count) tentacles to fall off"
		$tasksdone = $false
		do {
			$tasksdone = $true
			foreach ($t in $tasks.Links.Self) {
				if ($tasksdone) {
					$nowtask = Invoke-RestMethod "$($OctopusServer)$($t)" -Headers $h -Method Get
					WriteHostAndLog $nowtask
					if ($nowtask.IsCompleted) { continue }
					else {
						$tasksdone = $false;
						WriteHostAndLog "Still waiting for tentacles to fall off";
						Start-Sleep 10;
					}
				}
			}
			} until ($tasksdone)
		} until ($nomoretentacles)
	
	WriteHostAndLog "Removing environment $($myenv.Links.Self)"
	$t = Invoke-RestMethod "$($OctopusServer)$($myenv.Links.Self)" -Headers $h -Method Delete
	WriteHostAndLog $t
}
else {
	WriteHostAndLog "Could not find environment $Environment"
}

$sw.Stop()
WriteHostAndLog "Done, $($sw.Elapsed.TotalSeconds)s."

Any ideas?

thanks

Vanessa_Love · May 22, 2015, 2:19am

Hi James,

Due to recent support tickets that have been brought up, I am going to ask some questions that might track this down a little better.
I am assuming that you are heavy users and that you are doing more and more automation.
I also would be leaning towards your API timing issues being more of a reaching Raven limits than anything else, again 2.6.5 had no changes to account for API slowness.

So how large is your Raven database and how many documents are in it?
Do you run any form of retention policy at all?

I would also like you to consider running these scripts outside of busy times such as when Octopus is not in heavy use and see if there is any time differences. I have to assume 11am is a high use time.

Raven and thus how Octopus is built has to prioritize tasks, and a deployment would come first above all, including deleting data.

Vanessa

James_Baker · May 22, 2015, 3:25am

Hi Vanessa

Current document size is 22k, we are not using any retention at this stage.

I have re-factored how our AWS environments drop off but this still causes blips where Octopus is slow. We are also thinking about how we can queue these tasks for later work

Internally we also feel this is a Raven issue.

Thanks