Ideas to improve performance for dbachecks with Pester v5 compared to v4? Getting a single Tag from a file with 100 +Tags

[SQLDBAWithABeard]

Terminology - a check when stated below can be thought of as a Pester Describe block with a unique Tag name which contains a single Context and 1 or more It blocks.

We are currently rewriting dbachecks to use Pester v5 (using this project in case anyone fancies helping out! )

So that we can ensure that when we rewrite we are testing the same, passing for the same and failing for the same because these are databases we are talking about and we are (ex) DBAs and cautious folk, @jpomfret and I wrote a dev container configuration with 3 sql instances and also a function that is loaded into the session that will run the same check against the 3 instances in the dev container and compare the output to see if they are the same. (This has caught some coding misconceptions :-) ) We also use Sampler to build and deploy the module so that we are developing in clean sessions ( if you want to follow along instructions are here)

We also want to improve the performance of the checks as we had scenarios where you could run 5 different checks against the same instance and actually return to the instance 5 times to get the same information !! So we added to the above function to use Jakubs profier module to work out what is happening.

Now we want to gather the information from a single trip to the instance so we identify the unique checks that we are running, work out which files they are in and add that to the $Configuration.Run.Path property.

So that is the background. Now the issue.

If we look at a number of checks like this

$Checks = 'ErrorLogCount', 'XESessionRunning', 'XESessionRunningAllowed', 'XESessionExists', 'XESessionStopped', 'XpCmdShellDisabled', 'WhoIsActiveInstalled', 'CLREnabled', 'TwoDigitYearCutoff', 'MaxDopInstance', 'ErrorLogCount', 'ModelDbGrowth', 'DefaultBackupCompression', 'SaExist', 'SaDisabled', 'SaRenamed', 'DefaultFilePath', 'AdHocDistributedQueriesEnabled', 'AdHocWorkload', 'DefaultTrace', 'OleAutomationProceduresDisabled', 'CrossDBOwnershipChaining', 'ScanForStartupProceduresDisabled', 'RemoteAccessDisabled', 'SQLMailXPsDisabled', 'DAC', 'OLEAutomation', 'ServerNameMatch', 'OrphanedFile', 'MaxMemory', 'NetworkLatency'
# and run the validation
Invoke-PerfAndValidateCheck -Checks $Checks

then it runs for a minute and outputs

We are amazing, running the same tests against the same instances on the same hardware gives the same results and runs in 50% of the time with our new code. AWESOME.

However, and the reason for this question. If we change that to run only a single check

 $Checks = 'OrphanedFile'
# and run the validation
Invoke-PerfAndValidateCheck -Checks $Checks

We get

Yes with different single checks, yes the hardware is the same, we are in a dev container, the test run straight after each other, it doesnt matter the host that you use, you can even get the same resutls in the codespace. So we can look at the perf detail. We normally use this to try and improve our code.

Running a single check takes between 150% and 300% longer

 $Checks = 'OrphanedFile'
# and run the validation
Invoke-PerfAndValidateCheck -Checks $Checks -PerfDetail

So we have something using 40+% of our duration, lets find out what

$SQLInstances = $dbachecks1, $dbachecks2, $dbachecks3 = 'dbachecks1', 'dbachecks2', 'dbachecks3'
$password = ConvertTo-SecureString "dbatools.IO" -AsPlainText -Force
$cred = New-Object -TypeName System.Management.Automation.PSCredential -ArgumentList "sqladmin", $password
$show = 'All'

$traci = Trace-Script -ScriptBlock {
    $v5code = Invoke-DbcCheck -SqlInstance $Sqlinstances -SqlCredential $cred -Check $Checks -legacy $false -Show $show -PassThru
}
$traci.Top50SelfDuration 

$traci.Top50SelfDuration[0] |fl

Percent      : 37.878Duration     : 00:00:04.6019035                                                                          
SelfPercent  : 37.878
SelfDuration : 00:00:04.6019035
HitCount     : 38
File         : Pester.psm1
Line         : 12058
Function     : 
Module       : dbachecks
Text         : foreach ($bootstrapFunction in (& $Get_Command -Name "PesterMock_*")) {
Path         : /workspace/output/RequiredModules/Pester/5.3.3/Pester.psm1
Hits         : {00000000-0000-0000-0000-000000000000, 00000000-0000-0000-0000-000000000000, 00000000-0000-0000-0000-000000000000, 00000000-0000-0000-0000-000000000000…}
CommandHits  : {[40, Profiler.CommandHit: Line=12058; Column=40; HitCount=19; SelfDuration=00:00:04.6015251; Text='(& $Get_Command -Name "PesterMock_*")'], [18, Profiler.CommandHit: 
               Line=12058; Column=18; HitCount=19; SelfDuration=00:00:00.0003784; Text='$bootstrapFunction']}

So it appears that it is this code that is causing the slowup, which I don't claim to understand the reasoning for.

        foreach ($bootstrapFunction in (& $Get_Command -Name "PesterMock_*")) {
            & $Remove_Item "function:/$($bootstrapFunction.Name)"
        }

The question is - how do we fix this?
How do we get teh same performance improvements for 1 check (Tag) as we do for many?

Answers on a post card please.

Thank you
Rob - @SQLDBAWithABeard
Jess - @jpomfret
Cláudio - @ClaudioESSilva
Shane - @shaneis

[nohwnd]

@SQLDBAWithABeard that code is cleaning up orphaned mock hook functions that might be in place when you cancel a run. In non-interactive session this code should be rarely needed (so maybe we can skip it). It runs once per run (once per Invoke-Pester), how many times are you calling Invoke-Pester? It shows 38 hits above. The time impact is probably constant ~5s for both multiple filters and single filter.

[SQLDBAWithABeard]

Yes, that has made a difference. Brought a single check up to near parity which is ok

[SQLDBAWithABeard]

Without commenting it out I can also improve by doing this

$Modules = 'dbatools', 'dbachecks', 'PsFramework','Pester','JessAndBeard'
Get-Module | Where Name -notin $modules | Remove-Module -Force

Not sure that that is a viable option for production though !!!!

[nohwnd]

Not removing the functions should be totally fine for production. What is the difference now? How much time do you need to shave off of those top 3 commands?

[SQLDBAWithABeard]

Now we are at about a second. But as each check uses different dbatools or SMO code (we have optimised our SMO usage) we can approach those during our conversion for each check. We can do more of that now that I am not chasing around wondering what was going on!!

Makes more sense too as it has got more noticeable since we moved to using Sampler which has increased the number of modules that we have loaded

[nohwnd]

PR here: #2332

[nohwnd]

Could you also run (Measure-Command { 1..38 | % { Get-Command -Name "PesterMock_*" }}).TotalSeconds on the server? Shows 1 second for me locally, and you probably have way more cmdlets imported.

[SQLDBAWithABeard]

In the container on my main machine we get 6.4

[SQLDBAWithABeard]

and then I find another one !! - #2335