May 15th, 2023
heart5 reactions

Measuring script execution time

Francisco Nabas
System/Cloud Administrator

Most of the time while developing PowerShell scripts we don’t need to worry about performance, or execution time. After all, scripts were made to run automation in the background. However, as your scripts become more sophisticated, and you need to work with complex data or big data sizes, performance becomes something to keep in mind. Measuring a script execution time is the first step towards script optimization.

Measure-Command

PowerShell has a built-in cmdlet calledMeasure-Command, which measures the execution time of other cmdlets, or script blocks. It has two parameters:

  • Expression: The script block to be measured.
  • InputObject: Optional input to be passed to the script block. You can use$_ or$PSItem to access them.

Besides the two parameters, objects in the pipeline are also passed to the script block.Measure-Command returns an object of typeSystem.TimeSpan, giving us more flexibility on how to work with the result.

Measure-Command { foreach ($number in 1..1000) { <# Do work #> } }
Days              : 0Hours             : 0Minutes           : 0Seconds           : 0Milliseconds      : 8Ticks             : 85034TotalDays         : 9.84189814814815E-08TotalHours        : 2.36205555555556E-06TotalMinutes      : 0.000141723333333333TotalSeconds      : 0.0085034TotalMilliseconds : 8.5034

Using the pipeline or theInputObject parameter.

1..1000 |    Measure-Command -Expression { foreach ($number in $_) { <# Do work #> } } |    Select-Object TotalMilliseconds
TotalMilliseconds-----------------            10.60
Measure-Command -InputObject (1..1000) -Expression { $_ | % { <# Do work #> } } |    Select-Object TotalMilliseconds
TotalMilliseconds-----------------            19.98

Scope and Object Modification

Measure-Command runs the script block in the current scope, meaning variables in the current scope gets modified if referenced in the script block.

$studyVariable = 0Measure-Command { 1..10 | % { $studyVariable += 1 } }Write-Host "Current variable value: $studyVariable."
Days              : 0Hours             : 0Minutes           : 0Seconds           : 0Milliseconds      : 15Ticks             : 155838TotalDays         : 1.80368055555556E-07TotalHours        : 4.32883333333333E-06TotalMinutes      : 0.00025973TotalSeconds      : 0.0155838TotalMilliseconds : 15.5838Current variable value: 10.

To overcome this, you can use the invocation operator& and enclose the script block in{}, to execute in a separate context.

$studyVariable = 0Measure-Command { & { 1..10 | % { $studyVariable += 1 } } }Write-Host "Current variable value: $studyVariable."
Days              : 0Hours             : 0Minutes           : 0Seconds           : 0Milliseconds      : 8Ticks             : 86542TotalDays         : 1.00164351851852E-07TotalHours        : 2.40394444444444E-06TotalMinutes      : 0.000144236666666667TotalSeconds      : 0.0086542TotalMilliseconds : 8.6542Current variable value: 0.

It’s also worth remember that if your script block modifies system resources, files, databases or any other static data, the object gets modified.

$scriptBlock = {    if (!(Test-Path -Path C:\SuperCoolFolder)) {        New-Item -Path C:\ -Name SuperCoolFolder -ItemType Directory    }}Measure-Command -Expression { & $scriptBlock }Get-ChildItem C:\ -Filter SuperCoolFolder | Select-Object FullName
Days              : 0Hours             : 0Minutes           : 0Seconds           : 0Milliseconds      : 11Ticks             : 118978TotalDays         : 1.37706018518519E-07TotalHours        : 3.30494444444444E-06TotalMinutes      : 0.000198296666666667TotalSeconds      : 0.0118978TotalMilliseconds : 11.8978FullName : C:\SuperCoolFolder

As a cool exercise, try figuring out why the output fromNew-Item didn’t show up.

Output and Alternatives

Measure-Command returns aSystem.TimeSpan object, but not the result from the script. If your study also includes the result, there are two ways you can go about it.

Saving the output in a variable

We know that scripts executed withMeasure-Object runs in the current scope. So we could assign the result to a variable, and work with it.

$range = 1..100$evenCount = 0$scriptBlock = {    foreach ($number in $range) {        if ($number % 2 -eq 0) {            $evenCount++        }    }}Measure-Command -InputObject (1..100) -Expression $scriptBlock |    Format-List TotalMillisecondsWrite-Host "The count of even numbers in 1..100 is $evenCount."
TotalMilliseconds : 1.3838The count of even numbers in 1..100 is 50.

Custom Function

If you are serious about the performance variable, and want to keep the script block as clean as possible, we could elaborate our own function, and shape the output as we want.

TheMeasure-Command Cmdlet uses an object calledSystem.Diagnostics.Stopwatch. It works like a real stopwatch, and we control it using its methods, likeStart(),Stop(), etc. All we need to do is start it before executing our script block, stop it after execution finishes, and collect the result from theElapsed property.

function Measure-CommandEx {    [CmdletBinding()]    param (        [Parameter(Mandatory, Position = 0)]        [scriptblock]$Expression,        [Parameter(ValueFromPipeline)]        [psobject[]]$InputObject    )    Begin {        $stopWatch = New-Object -TypeName 'System.Diagnostics.Stopwatch'        <#            We need to define result as a list because the way objects            are passed to the pipeline. If you pass a collection of objects,            the pipeline sends them one by one, and the result            is always overridden by the last item.        #>        [System.Collections.Generic.List[PSObject]]$result = @()    }    Process {        if ($InputObject) {            # Starting the stopwatch.            $stopWatch.Start()            # Creating the '$_' variable.            $dollarUn = New-Object -TypeName psvariable -ArgumentList @('_', $InputObject)            <#                Overload is:                    InvokeWithContext(                        Dictionary<string, scriptblock> functionsToDefine,                        List<psvariable> variablesToDefine,                        object[] args                    )            #>            $result.AddRange($Expression.InvokeWithContext($null, $dollarUn, $null))            $stopWatch.Stop()        }        else {            $stopWatch.Start()            $result.AddRange($Expression.InvokeReturnAsIs())            $stopWatch.Stop()        }    }    End {        return [PSCustomObject]@{            ElapsedTimespan = $stopWatch.Elapsed            Result = $result        }    }}

Note that there is overhead when using theInputObject parameter, meaning there is a difference in the overall execution time.

Conclusion

I hope you, like me, learned something new today, and had fun along the way.

Until a next time, happy scripting!

Links

Author

Francisco Nabas
System/Cloud Administrator

0 comments

Discussion is closed.

    Stay informed

    Get notified when new posts are published.
    Follow this blog
    facebook