Navcontainerhelper: Creating container w/ reused image and ArtifactUrl is much slower than without ArtifactUrl

[jwikman]

Describe the issue
I've refactored our pipelines to use ArtifactUrl instead of ImageNames with tags. I'm using ArtifactUrl combined with imageName to use cached images.

When not using ArtifactUrl, with images downloaded, it takes about 1.45 minutes to create a container.
When using ArtifactUrl, with artifacts downloaded and image built, it takes about 4 minutes to create a container.

What is causing this difference?
In the logs I see a three minute pause between "Setting EnableTaskScheduler to False" and "Starting Service Tier", so there seems to be something in between there that is causing this. Without ArtifactUrl there is about 40 seconds between those two lines.

To repro below scripts need to be run twice, to cache everything properly.

With ArtifactUrl:

Script

$credential = New-Object pscredential 'super', (ConvertTo-SecureString -String "P@ssword" -AsPlainText -Force)
$parameters = @{
    "accept_eula"              = $true
    "accept_outdated"          = $true
    "containerName"            = 'test'
    "artifactUrl"              = "https://bcartifacts.azureedge.net/sandbox/16.3.14085.14363/se"
    "imageName"                = 'myimage'
    "auth"                     = "NavUserPassword"
    "Credential"               = $credential
    "dns"                      = '8.8.8.8'
    "alwaysPull"               = $true
    "updateHosts"              = $true
    "includeAL"                = $true
    "includeCSide"             = $false
    "doNotExportObjectsToText" = $true
    "shortcuts"                = "none"
    "myScripts"                = @(@{'MainLoop.ps1' = 'while ($true) { start-sleep -seconds 10 }' })
    "doNotCheckHealth"         = $true
    "enableTaskScheduler"      = $false
}

New-NavContainer @parameters

Logs

2020-07-07T16:27:28.9888656Z Creating Self Signed Certificate
2020-07-07T16:27:28.9892738Z Self Signed Certificate Thumbprint B41E763EC611740D02726DE43910660B71D64D94
2020-07-07T16:27:28.9896301Z Modifying Service Tier Config File with Instance Specific Settings
2020-07-07T16:27:28.9900251Z Modifying Service Tier Config File with settings from environment variable
2020-07-07T16:27:28.9903617Z Setting EnableTaskScheduler to False
2020-07-07T16:30:35.2725009Z Starting Service Tier
2020-07-07T16:30:35.2729334Z Registering event sources
2020-07-07T16:30:46.6664919Z Creating DotNetCore Web Server Instance

Full output of scripts

##[section]Starting: Create Container with ArtifactUrl
==============================================================================
Task         : PowerShell
Description  : Run a PowerShell script on Linux, macOS, or Windows
Version      : 2.170.1
Author       : Microsoft Corporation
Help         : https://docs.microsoft.com/azure/devops/pipelines/tasks/utility/powershell
==============================================================================
Generating script.
========================== Starting Command Output ===========================
##[command]"C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe" -NoLogo -NoProfile -NonInteractive -ExecutionPolicy Unrestricted -Command ". 'C:\Agent_AS011_01\_work\_temp\3297dadc-2dc0-442a-9eb7-4f893c8fab24.ps1'"
NavContainerHelper is version 0.7.0.11
NavContainerHelper is running as administrator
Host is Microsoft Windows Server 2019 Standard - ltsc2019
Docker Client Version is 19.03.1
Docker Server Version is 19.03.1
Removing container test
Removing test from host hosts file
Removing C:\ProgramData\NavContainerHelper\Extensions\test
ArtifactUrl and ImageName specified
Image myimage:sandbox-16.3.14085.14363-se already exists
Using image myimage:sandbox-16.3.14085.14363-se
Disabling Health Check (always report healthy)
Creating Container test
Version: 16.3.14085.14363-se
Style: sandbox
Platform: 16.0.14073.14279
Generic Tag: 0.1.0.6
Container OS Version: 10.0.17763.1282 (ltsc2019)
Host OS Version: 10.0.17763.1282 (ltsc2019)
Using locale sv-SE
Using process isolation
Disabling the standard eventlog dump to container log every 2 seconds (use -dumpEventLog to enable)
Additional Parameters:
--env customNavSettings=EnableTaskScheduler=False
Files in C:\ProgramData\NavContainerHelper\Extensions\test\my:
- AdditionalOutput.ps1
- MainLoop.ps1
- SetupVariables.ps1
- updatehosts.ps1
Creating container test from image myimage:sandbox-16.3.14085.14363-se
bc18aad48b94132f2f98f9f99ca67afc95d434443dee3cebde796936ca30a33b
Waiting for container test to be ready
Initializing...
Setting host.containerhelper.internal to 172.18.48.1 in container hosts file
Starting Container
Hostname is test
PublicDnsName is test
Using NavUserPassword Authentication
Starting Local SQL Server
Starting Internet Information Server
Creating Self Signed Certificate
Self Signed Certificate Thumbprint B7B77EDF7C5A83BE76C1F0C43900DD3881FD3054
Modifying Service Tier Config File with Instance Specific Settings
Modifying Service Tier Config File with settings from environment variable
Setting EnableTaskScheduler to False
Starting Service Tier
Registering event sources
Creating DotNetCore Web Server Instance
Enabling Financials User Experience
Creating http download site
Setting SA Password and enabling SA
Creating super as SQL User and add to sysadmin
Creating SUPER user
Container IP Address: 172.18.48.114
Container Hostname  : test
Container Dns Name  : test
Web Client          : http://test/BC/
Dev. Server         : http://test
Dev. ServerInstance : BC
Setting test to 172.18.48.114 in host hosts file

Files:
http://test:8080/ALLanguage.vsix

Initialization took 207 seconds
Ready for connections!
Reading CustomSettings.config from test
Creating .net Assembly Reference Folder for VS Code
Copying DLLs from C:\Windows\assembly to assemblyProbingPath
Copying DLLs from C:\Program Files\Microsoft Dynamics NAV\160\Service to assemblyProbingPath
Copying DLLs from C:\Program Files (x86)\Microsoft Dynamics NAV\160\RoleTailored Client to assemblyProbingPath
Copying DLLs from C:\Test Assemblies\Mock Assemblies to assemblyProbingPath
Copying DLLs from C:\Program Files (x86)\Open XML SDK to assemblyProbingPath
Container test successfully created
It took 240.3655495 seconds to create the container
##[section]Finishing: Create Container with ArtifactUrl

Without ArtifactUrl:

Script

$credential = New-Object pscredential 'super', (ConvertTo-SecureString -String "P@ssword" -AsPlainText -Force)
$parameters = @{
    "accept_eula"              = $true
    "accept_outdated"          = $true
    "containerName"            = 'test'
    "imageName"                = "mcr.microsoft.com/businesscentral/sandbox:se" 
    "auth"                     = "NavUserPassword"
    "Credential"               = $credential
    "dns"                      = '8.8.8.8'
    "alwaysPull"               = $true
    "updateHosts"              = $true
    "includeAL"                = $true
    "includeCSide"             = $false
    "doNotExportObjectsToText" = $true
    "shortcuts"                = "none"
    "myScripts"                = @(@{'MainLoop.ps1' = 'while ($true) { start-sleep -seconds 10 }' })
    "doNotCheckHealth"         = $true
    "enableTaskScheduler"      = $false
}
New-NavContainer @parameters

Logs

2020-07-07T16:31:39.8205193Z Creating Self Signed Certificate
2020-07-07T16:31:39.8209661Z Self Signed Certificate Thumbprint 9388FC85A98B153DB2AF9529EAEB7B07CB9EECC1
2020-07-07T16:31:39.8212831Z Modifying Service Tier Config File with Instance Specific Settings
2020-07-07T16:31:39.8214770Z Modifying Service Tier Config File with settings from environment variable
2020-07-07T16:31:39.8219301Z Setting EnableTaskScheduler to False
2020-07-07T16:32:20.9931251Z Starting Service Tier
2020-07-07T16:32:20.9932286Z Registering event sources
2020-07-07T16:32:29.7140945Z Creating DotNetCore Web Server Instance

Full output of scripts

##[section]Starting: Create Container with ImageTag
==============================================================================
Task         : PowerShell
Description  : Run a PowerShell script on Linux, macOS, or Windows
Version      : 2.170.1
Author       : Microsoft Corporation
Help         : https://docs.microsoft.com/azure/devops/pipelines/tasks/utility/powershell
==============================================================================
Generating script.
========================== Starting Command Output ===========================
##[command]"C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe" -NoLogo -NoProfile -NonInteractive -ExecutionPolicy Unrestricted -Command ". 'C:\Agent_AS011_01\_work\_temp\f6aa5066-90b7-4744-a5bd-6842ef40cf47.ps1'"
NavContainerHelper is version 0.7.0.11
NavContainerHelper is running as administrator
Host is Microsoft Windows Server 2019 Standard - ltsc2019
Docker Client Version is 19.03.1
Docker Server Version is 19.03.1
Removing container test
Removing test from host hosts file
Removing C:\ProgramData\NavContainerHelper\Extensions\test
WARNING: You are running specific Docker images Microsoft container registries. These images will no longer be updated, you should switch to user Docker artifacts. See https://freddysblog.com/2020/07/05/july-updates-are-out-they-are-the-last-on-premises-docker-images/
Pulling image mcr.microsoft.com/businesscentral/sandbox:se-ltsc2019
se-ltsc2019: Pulling from businesscentral/sandbox
Using image mcr.microsoft.com/businesscentral/sandbox:se-ltsc2019
Disabling Health Check (always report healthy)
Creating Container test
Version: 16.3.14085.14363-se
Style: sandbox
Platform: 16.0.14073.14279
Generic Tag: 0.0.9.99
Container OS Version: 10.0.17763.973 (ltsc2019)
Host OS Version: 10.0.17763.1282 (ltsc2019)
WARNING: The container operating system matches the host operating system, but the revision is different.
If you encounter issues, you might want to specify -isolation hyperv
Using locale sv-SE
Using process isolation
Disabling the standard eventlog dump to container log every 2 seconds (use -dumpEventLog to enable)
Additional Parameters:
--env customNavSettings=EnableTaskScheduler=False
Files in C:\ProgramData\NavContainerHelper\Extensions\test\my:
- AdditionalOutput.ps1
- MainLoop.ps1
- SetupVariables.ps1
- updatehosts.ps1
Creating container test from image mcr.microsoft.com/businesscentral/sandbox:se-ltsc2019
35f89a7f7f87b2c4d4a1e15c3edcdc4203d44a075841fcf3730cc2759c0f16c8
Waiting for container test to be ready
Initializing...
Setting host.containerhelper.internal to 172.18.48.1 in container hosts file
Starting Container
Hostname is test
PublicDnsName is test
Using NavUserPassword Authentication
Starting Local SQL Server
Starting Internet Information Server
Creating Self Signed Certificate
Self Signed Certificate Thumbprint 0B29F764C2C105E6EAF50FE2DEEB09BA62746F54
Modifying Service Tier Config File with Instance Specific Settings
Modifying Service Tier Config File with settings from environment variable
Setting EnableTaskScheduler to False
Starting Service Tier
Registering event sources
Creating DotNetCore Web Server Instance
Enabling Financials User Experience
Creating http download site
Setting SA Password and enabling SA
Creating super as SQL User and add to sysadmin
Creating SUPER user
Container IP Address: 172.18.54.18
Container Hostname  : test
Container Dns Name  : test
Web Client          : http://test/BC/
Dev. Server         : http://test
Dev. ServerInstance : BC
Setting test to 172.18.54.18 in host hosts file

Files:
http://test:8080/ALLanguage.vsix

WARNING: You are running a container which is 144 days old.
Microsoft recommends that you always run the latest version of our containers.

Initialization took 65 seconds
Ready for connections!
Reading CustomSettings.config from test
Creating .net Assembly Reference Folder for VS Code
Copying DLLs from C:\Windows\assembly to assemblyProbingPath
Copying DLLs from C:\Program Files\Microsoft Dynamics NAV\160\Service to assemblyProbingPath
Copying DLLs from C:\Program Files (x86)\Microsoft Dynamics NAV\160\RoleTailored Client to assemblyProbingPath
Copying DLLs from C:\Test Assemblies\Mock Assemblies to assemblyProbingPath
Copying DLLs from C:\Program Files (x86)\Open XML SDK to assemblyProbingPath
Container test successfully created
It took 96.7644316 seconds to create the container
##[section]Finishing: Create Container with ImageTag

[freddydk]

There is one thing that cannot be correct.
The step that takes time is starting the service tier.
In your output - starting the service tier is instant - that cannot be.
the 40 seconds vs. something must be or starting the service tier.

I can also see that I never start the service tier while the image is build.
That should happen - and should dramatically reduce the time for starting it the second time.

Will investigate,

[freddydk]

I know why this happens.
The reason is, that some of the artifacts doesn't have a license file (the license file is already in the database)
The installer only starts the service tier during image build if a license file needs to be applied.
This will be fixed in two ways:

1. Our build team is going to be building the artifacts and then the flf is always included.
2. I will fix the installer to always start and stop the service tier during build process

[jwikman]

Great, thanks!

Blitzing fast, as always.

[freddydk]

Just tried the fix - goes from 158 seconds to 46 seconds (the initialization) on my laptop

[freddydk]

@jwikman - you should just keep the code with artifacts - when a new generic is shipped, it will automatically detect that and build a new image, which is faster...
Will run some more tests on this and publish tomorrow probably.

[freddydk]

BTW - thanks for the very detailed bug report - this is really a case of you helping me to help you!
THANKS!

[jwikman]

Yes, of course I'll go ahead with the artifacts approach in our pipeline framework. This is the way it should have been before.
But now I can stop cursing about it being slower than before, even though it shouldn't be! :D

Thanks!

[freddydk]

new generic shipped - should be fixed with that,

[jwikman]

Hmmm... is that why all my pipelines started to fail with a few different errors?

Do we get concurrency issues when several parallell pipelines are downloading artifacts and building images at almost the same time? Docker deamon seemed to handle things quite nicely when several pipelines requests the same image.

I'm updating all pipelines with the Artifact changes and are therefore running a lot of pipelines i parallell today. All issues I've seen seems to have to do with concurrency...

Should I create a new issue with those logs?

[freddydk]

No - I messed up in containerhelper
0.7.0.13 is out now - should fix that.

[jwikman]

hehe, ok.

And several of my strange errors came from the fact that I ran out of disk on the build server.
A lot of images was cached:

• old images with image tags
• new images built on generic from yesterday
• new images built on the new generic -> out of disk!

Reclaiming 200gb right now...