Delay importing custom module in server 2012 R2

Legacy Uncategorised
1

Hi,

I am trialling Octopus for a client.
We are finding a large deployment time difference between 2008R2 and 2012R2.
Looking at the logs, this happens when the ps1 script called on the server via the tentacle imports some custom PS modules.

I have created a simple scenario to isolate just this behaviour.
The test project does not apply any changes, it simply loads the modules and stops.
I have created 2 VMs running 2008 R2 and 2 VMs running 2012 R2 (they are all brand new, created by script and identical apart from the OS, and running on the same Hyper-V host).

I have installed the latest 3.3.17 Octopus (likewise all tentacles)
2 logs attached

  • one for ‘Test’ env (2x 2008 R2) - this takes 1 minute
  • one for ‘Live’ env (2x 2012 R2) - this takes 6 minutes

Logging onto the 2012 servers and invoking the exact same PS script manually completes in under a minute, so this is not just a 2012 thing.
The custom modules are hosted on the servers, and are used as part of other routine activities.
The script code within Octopus is simply to call the ps1 on each server.

Are you aware of any issues when importing custom modules via a tentacle in this way?
For example, does the tentacle wrap anything in a funky way that might account for this difference in behaviour?

Thanks in advance,
Allan

test_-_2008_R2_environment.log (8 KB)

live_-_2012_R2_environment.log (8 KB)

2

Hi Allan,

Thanks for getting in touch. As a general rule we haven’t had issues with importing modules.

When you log into the server to run the scripts, are you logging in as the same user the Tentacle is running as?

Are you able to provide any excerpts from the script? Also, are you familiar with the Script Console (http://docs.octopusdeploy.com/display/OD/Script+Console)? This may be useful for isolating and executing smaller sections of the script, to see if the same behavior is observed.

Is the time taken for ‘Start-vScript’ the primary concern? The Resolve-DNSName and Get-SQLInstanceData steps can also contribute a considerable percentage of the time, is this expected?

Hopefully this will help us troubleshoot what is happening.

Shannon

3

Hi,

Yes, we are using the same service user to compare the run times when logging on to the servers and running the script manually.

The test script is not doing anything other than importing modules and then exiting, so there is little benefit sharing the code.

As stated, this test scenario was specifically setup so we could isolate the delay seemingly caused by the call through the tentacle on 2012 R2 servers.

I have attached 2 more logs to further display the discrepancy.

The 2 other functions you mentioned are red-herrings, I’ve added more debug logging to show that the real cause is the act of simply importing the custom modules.

For example, just using the import time of the core module as an example, the differences are:

2008R2

Manually – 12 Seconds

Tentacle – 35 Seconds

2012R2

Manually – 10 Seconds

Tentacle – 180 Seconds

There is nothing special in these modules, they are module manifests (.psd1) with child .psm1 modules.

Even the hit of 35 seconds (Tentacle on 2008R2) is ok.

However, the 180 seconds delay is going to cause problems for the client to commit to this as a release process.

Thanks,

Allan

ServerTasks-1747-TestEnv(2008R2).log (6 KB)

ServerTasks-1748-LiveEnv(2012R2).log (6 KB)

4

Hi Allan,

I have run up a clean Windows Server 2012 installation and tested executing a variety of scripts, both interactively and via a Tentacle deployed to the server, but haven’t been able to replicate the delay you are experiencing.

One thing that might be worth trying is using the -Verbose switch on the Module import, to see if it yields any better detail on which part of the import is being delayed.

Shannon

5

Hi,

Ok, thanks for your time on this.

The problem is not with running scripts per se but when importing a module manifest.

I have setup a dummy module manifest to help you replicate this issue.

Repro steps:

  1.   Unzip the attached file to the 2012 server (I used D:\DelayTest as the target)

  2.   Create a test project with 1 script step containing this single line of code: “D:\DelayTest\Test-ModuleStartTime.ps1”

  3.   Obviously, update the step details and the .ps1 script to match the new path if you’ve changed it

  4.   Jump on the server and run the script manually

  5.   Run a release from octopus

  6.   Check for differences J

Octopus raw logs also attached.

Btw, there is nothing at all out of the ordinary with this setup.

Everything is referenced via full paths, there is no reliance on the PSModulePath environment variable for example.

It could not be simpler, however I am again seeing a very large difference in the time taken through the tentacle and when run manually.

In fact 2012 (manually) is marginally quicker than 2008 (manually).

I appreciate your help with this.

Thanks

Allan

FYI my test results are:

=== 2008 Manually ===

Importing Module

Days : 0

Hours : 0

Minutes : 0

Seconds : 3

Milliseconds : 859

Ticks : 38598510

TotalDays : 4.46742013888889E-05

TotalHours : 0.00107218083333333

TotalMinutes : 0.06433085

TotalSeconds : 3.859851

TotalMilliseconds : 3859.851

=== 2008 Tentacle ===

09:51:29 Info | Importing Module

09:51:40 Info | Days : 0

09:51:40 Info | Hours : 0

09:51:40 Info | Minutes : 0

09:51:40 Info | Seconds : 10

09:51:40 Info | Milliseconds : 738

09:51:40 Info | Ticks : 107386048

09:51:40 Info | TotalDays : 0.000124289407407407

09:51:40 Info | TotalHours : 0.00298294577777778

09:51:40 Info | TotalMinutes : 0.178976746666667

09:51:40 Info | TotalSeconds : 10.7386048

09:51:40 Info | TotalMilliseconds : 10738.6048

=== 2012 manually ===

Importing Module

Days : 0

Hours : 0

Minutes : 0

Seconds : 3

Milliseconds : 146

Ticks : 31464204

TotalDays : 3.64169027777778E-05

TotalHours : 0.000874005666666667

TotalMinutes : 0.05244034

TotalSeconds : 3.1464204

TotalMilliseconds : 3146.4204

=== 2012 Tentacle ===

09:52:04 Info | Importing Module

09:53:07 Info | Days : 0

09:53:07 Info | Hours : 0

09:53:07 Info | Minutes : 1

09:53:07 Info | Seconds : 0

09:53:07 Info | Milliseconds : 888

09:53:07 Info | Ticks : 608882985

09:53:07 Info | TotalDays : 0.000704725677083333

09:53:07 Info | TotalHours : 0.01691341625

09:53:07 Info | TotalMinutes : 1.014804975

09:53:07 Info | TotalSeconds : 60.8882985

09:53:07 Info | TotalMilliseconds : 60888.2985

ServerTasks-1804-TestEnv2008.log (3 KB)

DelayTest.zip (122 KB)

ServerTasks-1805-LiveEnv2012.log (3 KB)

6

Hi Allan,

I’ve configured a test project per the steps provided and it’s taking about 2s to execute. I added the -Verbose flag to the Import-Module in Test-ModuleStartTime.ps1, and can see about 500-600 lines of detail about the import and it all runs smoothly. I’d suggest giving that a go on your server to see if there is a single load that is slow or if they are all slow.

I’ve also tried deploying to a single Tentacle and to multiple Tentacles at once. Could you try deploying to a single server to see if you get the same behaviour?

Shannon

7

Hi,

I’ve created 2 new 2012 VMs on the same host to test this further.

We are now seeing different behaviour between these boxes when run through the Tentacle.

It seems the faster box has managed to cache the temp module in some way, therefore it shows a much faster import time when the script loads it (as you would expect with a module PS already has loaded).

But, this was after a clean reboot so there is no way the Tentacle (or Calamari) could have known about it.

I also added a line to the all users profile to list the loaded modules as session startup.

            Get-Module | Select Name

The .ps1 script has been updated to display the process tree currently in use from the PowerShell $PID upwards.

2 logs attached Slow-Server & Fast-Server

The ‘Slow’ server actually takes longer to complete the whole task than the Fast one (overall), but the module import is much faster.

Line 14 of both logs shows a Calamari version verbose entry, this takes 2 seconds on the slow server and over a minute on the fast server (I have to ask what it’s doing during this minute?)

Both logs show that no modules (apart from ‘Microsoft.PowerShell.Utility’) were loaded at session start.

I initially wondered why this appears twice but this is explained looking at the process tree.

Wininit.exe > Services.exe > Tentacle.exe > powershell.exe > Calamari.exe > powershell.exe

So both tentacle and calamari invoke their own PowerShell and hence start their own profile (this btw could have serious time implications if we were to use this profile for common loading of modules).

But, the main difference was that the fast server lists the temp module as already loaded, before actually loading it??

How is this so? Since the startup loaded module list does not show this entry, it must be the Tentacle/Calamari invoked session that loaded it – but when?

Predictably, the server having to load from scratch then takes over a minute whereas the server reporting it as pre-loaded only takes <1 second.

My questions are:

  1.   Does tentacle/calamari do anything not output into the logs (I am thinking of the extra minute taken in the fast server log)?

  2.   Regardless, why does this all run (from scratch) manually on both servers in <3 seconds?

  3.   Why does one server seem to be able to ghost import this module while the other logs the full output?

Can you compare your output logs made during the <2 second run time and see if the module was already loaded (look for the VERBOSE: Loading module from path '…’ entries), as this might explain why you experience no delay.

Also, does the task run time match running this directly on the server, and not just the reported module load time.

Thanks

Allan

Slow-Server.log (44 KB)

Fast-Server.log (10 KB)

8

Hi Allan,

In short, I think the issue might be profile related. My reasoning and the answers to your last questions are as follows.

I’ve checked through the Tentacle and Calamari code and can’t see anything of signifance that isn’t being output to the logs. I’ve also had someone else on the team run the scripts in their environment and got similar results to mine.

Your depiction of the process tree is correct, the Tentacle uses PowerShell to invoke Calamari and it in turns uses PowerShell to invoke the script from the build Step.

The outputs of my Tentacle logs are as per your Slow-Server’s log, i.e. I see all of the Exporting function and Importing function lines. I am running my VM in Hyper-V on my laptop, which has an SSD that could account for a large part of the time difference in importing all of the module files.

If I run the script directly on the server the output looks the same and takes 0.9s (TotalSeconds). Interestingly, if I run it a second time in the same session, the output looks like your Fast-Server’s log (I only see Importing function lines) and it executes in 0.076s.

In your latest logs I noted the same things you had. I’ll add a “PowerShell is far from my strong suit” disclaimer at this point, but I also noticed that the time the Slow-Server takes to complete (after Importing Module …) seems to coincide with how long PowerShell takes to initialise on the Fast-Server. In the latter scenario though, as you’d noted, the TempModule is then “installed”. So it looks like it’s importing for every PowerShell session (in a non-Verbose manner) on that server, which would be a double hit through the Tentacle and Calamari combination.

So I added the following (with path adjusted to suit my server) to the Tentacle user’s profile

Import-Module D:\DelayTest\TempModule\TempModule.psd1 -Verbose

The results were then almost identical to your Fast-Server’s log, except I could see all of the Exporting function and Importing function lines twice over as PowerShell was starting. A Get-Module added to the top of my script step, prior to calling Test-ModuleStartTime.ps1, also confirmed that TempModule was “installed” in the session. The execution time was still fast enough on my VM (again, presumably a side-effect of the SSD) that I wouldn’t have known it was happening without the Verbose logging.

So based on that, I believe that somehow the profile on the Fast-Server is causing it to import the module on session start. This would also explain the fast times when running directly on that server too, because the module is already imported.

The import taking over a minute is probably still the more pressing issue. Given the number of module files this could possibly be I/O related. Packaging into few files for deployment could help resolve this, but you’ll be better positioned to know what options are practical for your scenario.

Shannon

9

Hi Shannon,

I’ve spent a while longer and can answer your points as follows:

  •      I cannot say if the difference was  profile related, I re-commissioned those boxes and then had identical (but still slow) run times on 2012. But it does seem likely to be as you suggest.

  •      The disks on the host are all SSDs sat behind a hardware RAID card (as R0), so very fast indeed.

However, we eventually found that if all the code contained in the nested modules is placed into one .psm1 file (per module manifest), the import time is faster.

But, this is a work-around and does not really provide an explanation for the extra time for import through the Tentacle.

When configured like this, the manual load time (for the real modules) goes from 3 seconds to .07 seconds and the Tentacle load time goes from 3 minutes to 15 seconds (all for initial load).

15 seconds is within a workable range, but is still a massive factor difference to running manually.

I have tried different targets (physical and virtual), and they all show the same lag when run through the tentacle.

Anyway.

  1.   It is not practical for us to hold the full code of each module manifest in a single file, nor is it a good source control practice.

  2.   We cannot host all the shared code within Octopus script modules because it is used in other tasks.

Therefore, we have updated the routines used to install the shared code so as to concatenate into a single file at deploy time (this then being pushed via Octopus).

This is not ideal but not a big deal either.

It is a shame we could not identify the root cause (not least because others might have benefitted), but I am grateful for your time spent on this.

Regards

Allan

10

Hi Allan,

It’s interesting that the load times are that long using an SSD.

I agree that having a single file isn’t a good idea from a development and source control perspective, but packaging into a single file for deployment isn’t really a bad idea.

It would indeed be nice to be sure of the root cause, but I’m glad you’ve been able to get to a workable option.

Regards
Shannon