xPSDesiredStateConfiguration: Continuous Integration Runs Are Approaching the AppVeyor Time Limit of 60 Minutes

[mhendric]

Details of the scenario you tried and the problem that is occurring

Some Continuous Integration runs for this module are taking close to 60 minutes. Once they reach 60 minutes, the run will start failing on AppVeyor, as 60 minutes is the max build time for AppVeyor. We should come up with a plan to address this before it becomes a problem.

Verbose logs showing the problem

Here's a couple recent examples:

From #475, took 52 min 20 sec:
https://ci.appveyor.com/project/PowerShell/xpsdesiredstateconfiguration/builds/21752318

From #448, took 56 min 41 sec:
https://ci.appveyor.com/project/PowerShell/xpsdesiredstateconfiguration/builds/21836214

Suggested solution to the issue

I think there's at least a couple ways to address this. One would be to analyze all the existing tests and see if any are overlapping and can be refactored. Another would be to switch over to a CI platform that doesn't have a time limit (like Azure Pipelines).

[johlju]

In SqlServerDsc I first split the tests into containers to run the in parallel which almost cut the testing time in half. But due to excessive memory (when running two containers and a SQL Server instance) I had to revert that approach an split the Unit tests and Integration tests into separate jobs so they could run sequentially (or in parallel in paid account). But that double the initial time it took to run the test, mostly because the test framework runs the meta tests in both jobs (we can resolve that in the test framework).
So currently the Unit tests and Integration tests into separate jobs (build workers) in SqlServerDsc. One way of quickly solving the soon to be problem, but is not a long term solution.

I would be happy to use Azure Pipelines instead of AppVeyor to not to have to worry about the length the tests run, and potentially have a much bigger control of the build workers - and hopefully even be able to integration tests more complex things that need several VM's.
If DscResource.Tests could be changed to use the Azure Pipelines that would be awesome, but that is a discussion for an issue in that repo. 🙂

[PlagueHO]

IHMO it is worth reducing the run time of the tests to be well under the 60 minute limit. We want contributors to be able to run these tests in their own forks using free AppVeyor accounts. So we can't rely on the parallelism of the paid account.

I am definitely keen to look into the use of Azure DevOps (and had actually been planning to investigate what it would take to make DscResource.Tests work over there).

But IMHO, I think we need to first look at refactoring and optimizing the tests. From doing my first review/refactoring on xArchive I found many tests that could be optimized.

Also, perhaps this also indicates that the resources themselves could be optimized? As these are the core DSC resources and used so much we'd want them to perform well.

Do we know what tests/resources take the longest in the run? I wonder if we could adjust DSCResource.Tests to automatically measure and summarize all test runs for us automatically at the end of the run. That might help us identify targets for optimization.

[mhendric]

I agree that regardless of what we do with the CI platform, it's probably good to refactor both tests and the resources themselves. I've noticed there's a lot of duplicated code in the tests that could be refactored to at least make the code cleaner.

Regarding shortening runtimes, is anyone aware of a tool that can analyze PowerShell based test runs and look for overlapping tests? Alternately we can find something that will provide a breakdown of how much time is spent in various code paths (I know Visual Studio can do this but I've only run it against C# projects, not PowerShell). That could at least help us hone in on tests that should be prioritized for inspection and possible refactoring.

[PlagueHO]

I like the pattern you used to start to reduce the code duplication. I'll try and aim to "refactor" and reduce duplication for each resource I touch. I'll try and adopt the boy scout rule.

Would be good to investigate if there was such an analysis tool if available - if not might make a good project 😁 . I might do some tweaks on a local copy of DscResource.Tests and use a bit of Measure-* to try and figure out a heat map of what is taking the most time and focus on optimizing those areas.

From memory, some of the PSSA checks do really run slowly - so possibly our custom PSSA rules might be slowing things down and could be optimized (or even converted to C#)?

[johlju]

Would be cool with a tool that @mhendric mention. Would be cool if Pester could count the number of hits on each row. Then we could see if there are excessive hits on rows, which could mean that the block of code could be refactored into smaller helper functions maybe (to mock them instead).

But at least I think we could add the measure in the test framework. Each test script runs (should run) Initialize-TestEnvironment and Restore-TestEnvironment. So one way could be to add

Initialize-TestEnvironment

$script:timer = [System.Diagnostics.Stopwatch]::StartNew()

Restore-TestEnvironment

    Write-Verbose -Message ('Test {1} run for {0} minutes' -f ([timespan]::FromMilliseconds($timer.ElapsedMilliseconds)).ToString("mm\:ss"), 'MyResourceName') -Verbose
    $timer.Stop()

We might be able to use our test framework helper function Write-Info instead of Write-Verbose.

[johlju]

I wouldn't mind if the meta tests run in a separate job (it's own build worker), then the meta tests could run for 60 minutes on it own (today it runs for ~13 minutes), and then unit test and integration tests could get the full 60 minutes in it's own job (this would work for free account to, it would just run sequentially).

[johlju]

The branch multiple-jobs contains an example of running several jobs (appveyor.yml) over multiple images, and split the unit and integration tests.

This is run on a AppVeyor free account. Total run time is 1 hour and 59 minutes (119 minutes), but each job runs quicker (23-39 minutes) than running everything in one build worker (which takes ~40 min).
If we could run the meta tests as a separate job too, then the run time for each job will be cut substantially
See the test run here: https://ci.appveyor.com/project/johlju/xpsdesiredstateconfiguration

It could be possible to divide the integration tests between more jobs too.

Note that the matrix configuration does not handle Codecov correctly, only one of the runs of the unit test should send in the Codecov result. I think that can be handled by the matrix directly without any code changes in the test framework.

[mhendric]

While I hunt for a better tool, here's a quick and dirty breakdown of how much time was spent in each script of build (https://ci.appveyor.com/project/PowerShell/xpsdesiredstateconfiguration/builds/21902981)

PS C:\Users\Mike\Desktop> .\GetScriptExecutionTimes.ps1 -Path 'buildlog.txt'

ScriptName                                                                                                         ScriptMinutes
----------                                                                                                         -------------
C:\projects\xpsdesiredstateconfiguration\DscResource.Tests\Meta.Tests.ps1                                       7.73333333333333
C:\projects\xpsdesiredstateconfiguration\Tests\Integration\xGroupSet.Integration.Tests.ps1                                     7
C:\projects\xpsdesiredstateconfiguration\Tests\Integration\MSFT_xGroupResource.Integration.Tests.ps1            3.93333333333333
C:\projects\xpsdesiredstateconfiguration\Tests\Unit\MSFT_xPackageResource.Tests.ps1                             3.78333333333333
C:\projects\xpsdesiredstateconfiguration\Tests\Unit\MSFT_xArchive.Tests.ps1                                     2.58333333333333
C:\projects\xpsdesiredstateconfiguration\Tests\Unit\MSFT_xUserResource.Tests.ps1                                1.61666666666667
C:\projects\xpsdesiredstateconfiguration\Tests\Integration\MSFT_xWindowsFeature.Integration.Tests.ps1                       1.25
C:\projects\xpsdesiredstateconfiguration\Tests\Unit\MSFT_xRegistryResource.Tests.ps1                                        1.05
C:\projects\xpsdesiredstateconfiguration\Tests\Integration\MSFT_xUserResource.Integration.Tests.ps1            0.966666666666667
C:\projects\xpsdesiredstateconfiguration\Tests\Integration\xWindowsFeatureSet.Integration.Tests.ps1            0.916666666666667
C:\projects\xpsdesiredstateconfiguration\Tests\Unit\MSFT_xGroupResource.Tests.ps1                                            0.9
C:\projects\xpsdesiredstateconfiguration\Tests\Unit\MSFT_xEnvironmentResource.Tests.ps1                        0.866666666666667
C:\projects\xpsdesiredstateconfiguration\Tests\Unit\MSFT_xServiceResource.Tests.ps1                                         0.75
C:\projects\xpsdesiredstateconfiguration\Tests\Unit\MSFT_xMsiPackage.Tests.ps1                                 0.616666666666667
C:\projects\xpsdesiredstateconfiguration\Tests\Integration\MSFT_xWindowsProcess.Integration.Tests.ps1          0.616666666666667
C:\projects\xpsdesiredstateconfiguration\Tests\Integration\MSFT_xArchive.Integration.Tests.ps1                              0.55
C:\projects\xpsdesiredstateconfiguration\Tests\Unit\MSFT_xDSCWebService.Tests.ps1                              0.516666666666667
C:\projects\xpsdesiredstateconfiguration\Tests\Integration\MSFT_xArchive.EndToEnd.Tests.ps1                    0.433333333333333
C:\projects\xpsdesiredstateconfiguration\Tests\Integration\xWindowsOptionalFeatureSet.Integration.Tests.ps1    0.433333333333333
C:\projects\xpsdesiredstateconfiguration\Tests\Integration\MSFT_xMsiPackage.EndToEnd.Tests.ps1                 0.366666666666667
C:\projects\xpsdesiredstateconfiguration\Tests\Integration\MSFT_xEnvironmentResource.EndToEnd.Tests.ps1        0.366666666666667
C:\projects\xpsdesiredstateconfiguration\Tests\Integration\MSFT_xWindowsOptionalFeature.Integration.Tests.ps1  0.316666666666667
C:\projects\xpsdesiredstateconfiguration\Tests\Integration\MSFT_xMsiPackage.Integration.Tests.ps1                            0.3
C:\projects\xpsdesiredstateconfiguration\Tests\Integration\MSFT_xPackageResource.Integration.Tests.ps1                      0.25
C:\projects\xpsdesiredstateconfiguration\Tests\Integration\MSFT_xServiceResource.Integration.Tests.ps1         0.233333333333333
C:\projects\xpsdesiredstateconfiguration\Tests\Integration\MSFT_xRegistryResource.EndToEnd.Tests.ps1                         0.2
C:\projects\xpsdesiredstateconfiguration\Tests\Unit\MSFT_xWindowsFeature.Tests.ps1                                          0.15
C:\projects\xpsdesiredstateconfiguration\Tests\Unit\MSFT_xWindowsProcess.Tests.ps1                             0.116666666666667
C:\projects\xpsdesiredstateconfiguration\Tests\Integration\xServiceSet.Integration.Tests.ps1                   0.116666666666667
C:\projects\xpsdesiredstateconfiguration\Tests\Integration\MSFT_xScriptResource.Integration.Tests.ps1         0.0833333333333333
C:\projects\xpsdesiredstateconfiguration\Tests\Unit\MSFT_xScriptResource.Tests.ps1                            0.0833333333333333
C:\projects\xpsdesiredstateconfiguration\Tests\Integration\MSFT_xRegistryResource.Integration.Tests.ps1       0.0833333333333333
C:\projects\xpsdesiredstateconfiguration\Tests\Unit\MSFT_xRemoteFile.Tests.ps1                                0.0666666666666667
C:\projects\xpsdesiredstateconfiguration\Tests\Unit\MSFT_xWindowsOptionalFeature.Tests.ps1                    0.0666666666666667
C:\projects\xpsdesiredstateconfiguration\Tests\Integration\MSFT_xWindowsPackageCab.Integration.Tests.ps1                    0.05
C:\projects\xpsdesiredstateconfiguration\Tests\Integration\MSFT_xEnvironmentResource.Integration.Tests.ps1                  0.05
C:\projects\xpsdesiredstateconfiguration\Tests\Unit\CommonResourceHelper.Tests.ps1                                          0.05
C:\projects\xpsdesiredstateconfiguration\Tests\Integration\xProcessSet.Integration.Tests.ps1                                0.05
C:\projects\xpsdesiredstateconfiguration\Tests\Unit\MSFT_xWindowsPackageCab.Tests.ps1                         0.0333333333333333
C:\projects\xpsdesiredstateconfiguration\Tests\Integration\MSFT_xRemoteFile.Tests.ps1                         0.0166666666666667

Here's the quick and dirty script I wrote for this. To use just download the build log to file and then run this against it.

[CmdletBinding()]
param
(
    [System.String]
    $Path
)

function Get-TimeFromLine
{
    param
    (
        [System.String]
        $Line
    )

    $timeParts = $Line.Substring(1, $Line.IndexOf(']') - 1).Split(':')
    $now = [DateTime]::Now
    $time = [DateTime]::new($now.Year, $now.Month, $now.Day, $timeParts[0], $timeParts[1], $timeParts[2])

    return $time
}

function Get-ScriptNameFromLine
{
    param
    (
        [System.String]
        $Line
    )

    return $Line.SubString($Line.IndexOf('Executing script ') + 'Executing script '.Length)
}

[System.String[]]$logContents = Get-Content -Path $Path | Where-Object {$_.Contains('] Executing script')}
[System.Collections.Generic.List[PSObject]]$scriptTimes = New-Object System.Collections.Generic.List[PSObject]

for ($i = 1; $i -lt $logContents.Length; $i++)
{
    $previous = $logContents[$i - 1]
    $previousTime = Get-TimeFromLine -Line $previous
    $previousScript = Get-ScriptNameFromLine -Line $previous
    $current  = $logContents[$i]
    $currentTime = Get-TimeFromLine -Line $current
    $timeDiff = $currentTime - $previousTime

    $scriptTimes.Add((New-Object -Type PSObject -Property @{ScriptName=$previousScript; ScriptMinutes=[Decimal]::Parse($timeDiff.TotalMinutes)}))
}

return ($scriptTimes | Sort-Object -Property ScriptMinutes -Descending)

[PlagueHO]

That is awesome @mhendric !

I have another option we could consider:

As we output the NUnitXML from Pester, we actually get the exact time for each test available to us - broken down by TestFixture and TestCase:

So what we need is a way to visualize this. Azure DevOps does this for us in Azure Pipelines, but unfortunately AppVeyor doesn't (not that I know of):

FWIW, Azure DevOps display isn't perfect though because it doesn't pick up the test file even though it is there.

In theory we could add a simple function to DSCResource.Tests that takes an NUnitXML and displays a table of statistics at the end of the test run (e.g. broken down by file and perhaps top level fixture in each file). Somewhere around this point: https://github.com/PowerShell/DscResource.Tests/blob/dev/AppVeyor.psm1#L817

I did look to see if we could use the Test Results object Invoke-Pester can return, but it doesn't look like it contains the level of info we need.

Perhaps we should add this idea as an issue over in DscResource.Tests to track it?

[PlagueHO]

Added a new issue to DscResource.Tests to discus issue further (otherwise these PR ideas tend to get lost): PowerShell/DscResource.Tests#309

[johlju]

AppVeyor shows the time spent in each It block in the test pane, it does not have the ability to group/summarize per file; https://ci.appveyor.com/project/johlju/xpsdesiredstateconfiguration/builds/21909185/job/rqm6kvg2rqrh8u4o/tests

[johlju]

For fun I did another run at improving my sequential testing above. I separated the meta tests into a separate job in the build matrix (appveyor.yml), and remove the meta tests from the other runs. It cut the total time with 21 minutes, to a total of 1 hour and 38 minutes, and each individual job saved 4 minutes. 🙂

https://ci.appveyor.com/project/johlju/xpsdesiredstateconfiguration/builds/21917432

[johlju]

Very interesting that the integration tests take double the time on the Visual Studio 2017 build worker than the Visual Studio 2015 one.

[mhendric]

Sweet! I definitely like the idea of separating the Meta, Unit, and Integration tests. It seems like that's something we could do even before we add more images as is being discussed in #403. It won't help those with free accounts, but it should definitely improve build times for the paid account.

I wonder if the double time for the 2017 integration tests was just a coincidence, or if that's always the case. It seems like the job times on AppVeyor can vary quite a bit. The entire build process sometimes completes in as little as 40 minutes, but sometimes takes near 60.

[stale]

This issue has been automatically marked as stale because it has not had activity from the community in the last 30 days. It will be closed if no further activity occurs within 10 days. If the issue is labelled with any of the work labels (e.g bug, enhancement, documentation, or tests) then the issue will not auto-close.

[PlagueHO]

Closing this because it no longer applies since we've moved to Azure DevOps.