nohandle

This user hasn't shared any biographical information

Homepage: http://www.jakubjares.com/


Posts by nohandle

Compare-command and time measuring in Powershell

I am playing with PowerShell exceptions a lot lately and since I’ve read that exceptions are expensive I was looking for a measurement tool that would enable me to measure commands precisely. Reading tons of articles resulted to realizing there are so many ways to measure time on Windows, but not one lead me to stable sub-millisecond precision.

Without the required accuracy but still useful, there is Compare-Command I wrote today:

function Compare-Command
{
	<#
	.SYNOPSIS
	Compare timing of two commands.
	.DESCRIPTION
	The function takes two scriptblocks as mandatory parameters and number of iterations
        as an optional parameter. The scriptblocks' executions are interlaced to make sure
        the running conditions for the scripts are similar as possible. But still the results are rough.
        Don't use this to microoptimize.
	.EXAMPLE
	Compare-Command -ReferenceScript {Start-Sleep -Milliseconds 10} -DifferenceScript {Get-Process} -Iterations 10
	.EXAMPLE
	Compare-Command -ReferenceScript {get-process > $null} -DifferenceScript {Get-Process | Out-Null}
	.PARAMETER ReferenceScript
	Script block that is taken as reference script.
    .PARAMETER DifferenceScript
    Script block that is taken as difference script.
    .PARAMETER Iterations
    Number of iterations to perform on the script, defaults to 10. Setting this parameter to high value
    will result in very long waiting time.
	#>

	[cmdletbinding(SupportsShouldProcess=$True,ConfirmImpact='Low')]
	param (
		[Parameter(
			Mandatory = $True,
			Position=1,
			ValueFromPipeline=$False,
			ValueFromPipelineByPropertyName=$True
		)]
		[ValidateNotNullOrEmpty()]
		[scriptblock]$ReferenceScript,
		[Parameter(
			Mandatory = $True,
			Position=2,
			ValueFromPipeline=$False,
			ValueFromPipelineByPropertyName=$True
		)]
    	[ValidateNotNullOrEmpty()]
		[scriptBlock]$DifferenceScript,
		[Parameter(Position=3)]
		[int]$Iterations=10
	)
	begin
	{
		$RefTime = $DiffTime = 0
		$stopWatch = New-Object System.Diagnostics.Stopwatch
	}
	process
	{
		for ($Index=0 ; $Index -lt $Iterations ; ++$Index)
		{
			$stopWatch.reset()
			$stopWatch.start()
			& $ReferenceScript > $null
			$stopWatch.stop()
			$refTime += $stopWatch.ElapsedMilliseconds
			$stopWatch.reset()
			$stopWatch.start()
			& $DifferenceScript > $null
			$stopWatch.Stop()
			$DiffTime+=$stopWatch.ElapsedMilliseconds
			}
	}
	end
	{
		#the rounding is introduced because the measure command is not as precise
        $resultRef= [math]::round($RefTime/$Iterations,0)
        $resultDif= [math]::round($DiffTime/$Iterations,0)

        if ($ResultRef -lt $resultDif)
        {
            $compare="<="
        }
        elseif ($ResultRef -gt $resultDif)
        {
            $compare="=>"
        }
        else
        {
            $compare="="
        }
        #order the proerties correctly even in powershell 2
        "" |Select-Object @{n="ReferenceScript";e={$ResultRef}},@{n="DifferenceScript";e={$ResultDif}},@{n="Compare";e={$Compare}}
	}
}

The code itself is not anything revolutionary. In fact you would be better off using Measure-Command instead of the StopWatch class, which Measure-Command uses internally anyway. But Measure-Command seemed a bit boring after re-implementing the StopWatch class using Pinvoke calls in embedded C# code in PowerShell earlier today; in the hunt for accurate measurement tool.
The rounding (line 69, 70) is there for a reason, the accuracy of the measurement on computer with more than one CPU core (without setting the process affinity to one core), without setting process priority to high, classing all other applications etc. is very volatile, hence presenting the measurements with more digits introduced incorrect incoherent results.

Testing the function:

1..3 | %{Compare-Command {get-process *idle*} {Get-Process | where {$_.name -like "idle"}}}
ReferenceScript DifferenceScript Compare
--------------- ---------------- -------
              1                7 <=
              1               10 <=
              1               10 <=     

As you can see in the output I tried to mimick the SideIndicator property on Compare-Object command, even if I don’t like using it.

1..3 | %{Compare-Command {Get-Process} {Get-Process} -Iterations 100} | ft -AutoSize

Here you can see that even if the same commands are used the results may still differ a bit.

ReferenceScript DifferenceScript Compare
--------------- ---------------- -------
              2                1 =>
              2                1 =>
              1                1 =      
Note: Never test your measurement tool's accuracy by Start-Sleep -Milliseconds 1. It won't work properly you will get strange timings close to 15.6 milliseconds (or 10 ms on one core). The Windows kernel raises the IRQ Level to the Clock just every 15.6 milliseconds by default and schedules the sleep timers to the nearest window not to the exact 1ms.