PowerShell function that times the execution of one or more commands, averaged over a specifiable number of runs.

Time-Command.ps1

<#

  Prerequisites: PowerShell v5.1 and above (verified; may also work in earlier versions)
  License: MIT
  Author:  Michael Klement <mklement0@gmail.com>

  DOWNLOAD and DEFINITION OF THE FUNCTION:

    irm https://gist.github.com/mklement0/9e1f13978620b09ab2d15da5535d1b27/raw/Time-Command.ps1 | iex

  The above directly defines the function below in your session and offers guidance for making it available in future
  sessions too.

  DOWNLOAD ONLY:

    irm https://gist.github.com/mklement0/9e1f13978620b09ab2d15da5535d1b27/raw > Time-Command.ps1

  Thea above downloads to the specified file, which you then need to dot-source to make the function available
  in the current session:

     . ./Time-Command.ps1
   
  To learn what the function does:
    * see the next comment block
    * or, once downloaded and defined, invoke the function with -? or pass its name to Get-Help.

  To define an ALIAS for the function, (also) add something like the following to your $PROFILE:
  
    Set-Alias tcm Time-Command

 #>

function Time-Command {
  <#
  .SYNOPSIS
    Times the execution of one or more commands.

  .DESCRIPTION
    Times the execution of one or more commands, averaging the timings of
    15 runs by default; use -Count to customize.

    The commands' output is suppressed by default.
    -OutputToHost prints it, but only straight to the host (console).

    To see the total execution time and other diagnostic info, pass -Verbose.

    The results are reported from fastest to slowest.

  .PARAMETER ScriptBlock
    The commands to time, passed as an array of script blocks, optionally
    via the pipeline.

  .PARAMETER Count
    How many times to run each command; defaults to 15.
    The average timing will be reported.

    Note: 15 was chosen so as not to trigger JIT compilation of the test
          script blocks by default, which can skew the results.

  .PARAMETER InputObject
    Optional input objects to expose to the script blocks as variable $_.

    $_ refers to the *entire collection* of input objects, whether
    you supply the objects via the pipeline or as an argument.

    Note that this requires that even with pipeline input *all input must
    be collected in memory first*.

  .PARAMETER OutputToHost
    Prints the commands' (success) output, which is suppressed by default,
    directly to the host (console).
    Note:
      * You cannot capture such output.
      * Printing the output clearly affects the duration of the execution.
    The primary purpose of this switch is to verify that the commands work
    as intended.

  .OUTPUTS
  [pscustombject] A custom object with the following properties:
  Factor ... relative performance ratio, with 1.00 representing the fastest
    command. A factor of 2.00, for instance, indicates that the given command
    took twice as long to run as the fastest one.
  Secs (<n>-run avg.) ... a friendly string representation of the execution
    times in seconds; the number of averaged runs in reflected in the property
    name. For programmatic processing, use .TimeSpan instead.
  Command ... the command at hand, i.e., the code inside a script block passed
    to -ScriptBlock.
  TimeSpan ... the execution time of the command at hand, as a [timespan]
    instance.

  .EXAMPLE
  Time-Command { Get-ChildItem -recurse /foo }, { Get-ChildItem -recurse /bar } 50

  Times 50 runs of two Get-ChildItem commands and reports the average execution
  time.

  .EXAMPLE
  'hi', 'there' | Time-Command { $_.Count } -OutputToHost

  Shows how to pass input objects to the script block and how to reference
  them there. Output is 2, because $_ refers to the entire collection of input
  objects.

  .NOTES
  This function is meant to be an enhanced version of the built-in
  Measure-Command cmdlet that improves on the latter in the following ways:
   * Supports multiple commands whose timings can be compared.
   * Supports averaging the timings of multiple runs per command.
   * Supports passing input objects via the pipeline that the commands see
     as the entire collection in variable $_
   * Supports printing command output to the console for diagnostic purposes.
   * Runs the script blocks in a *child* scope (unlike Measure-Object) which
     avoids pollution of the caller's scope and the execution slowdown that
     happens with dot-sourcing
     (see https://github.com/PowerShell/PowerShell/issues/8911).
  * Also published as a Gist: https://gist.github.com/mklement0/9e1f13978620b09ab2d15da5535d1b27
#>

  [CmdletBinding(PositionalBinding = $False)]
  [OutputType([pscustomobject])]
  param(
    [Parameter(Mandatory, Position = 0)]
    [scriptblock[]] $ScriptBlock
    ,
    [Parameter(Position = 1)]
    [int] $Count = 15
    ,
    [Parameter(ValueFromPipeline, Position = 2)]
    [object[]] $InputObject
    ,
    [switch] $OutputToHost
  )

    begin {
      # IMPORTANT:
      # Declare all variables used in this cmdlet with $private:...
      # so as to prevent them from shadowing the *caller's* variables that
      # the script blocks may rely upon.
      # !! See below re manual "unshadowing" of the *parameter* variables.
      $private:dtStart = [datetime]::UtcNow
      $private:havePipelineInput = $MyInvocation.ExpectingInput
      [System.Collections.ArrayList] $private:inputObjects = @()
      # To prevent parameter presets from affecting test results,
      # create a local, empty $PSDefaultParameterValues instance.
      $PSDefaultParameterValues = @{ }
    }

    process {
      # Collect all pipeline input.
      if ($havePipelineInput) { $inputObjects.AddRange($InputObject) }
    }

    end {

      if (-not $havePipelineInput) { $inputObjects = $InputObject }

      # !! The parameter variables too may accidentally shadow *caller* variables
      # !! that the script blocks passed may rely upon.
      # !! We don't bother trying to *manually* "unshadow" ALL parameter variables,
      # !! but we do it for -Count / $Count, because it is such a common variable name.
      # !! Note that this unshadowing will NOT work if the caller is in a different
      # !! scope domain.
      $__tcm_runCount = $Count # !! Cannot use $private, because it is used in child scopes of calculated properties.
      $Count = Get-Variable -Scope 1 Count -ValueOnly -ErrorAction Ignore

      # Time the commands and sort them by execution time (fastest first):
      [ref] $__tcm_fastestTicks = 0 # !! Cannot use $private, because it is used in child scopes of calculated properties.
      $ScriptBlock | ForEach-Object {
        $__tcm_block = $private:blockToRun = $_  # !! Cannot use $private, because it is used in child scopes of calculated properties.
        if ($OutputToHost) {
          # Note: We use ... | Out-Host, which prints to the console, but faster
          #       and more faithfully than ... | Out-String -Stream | Write-Verbose would.
          #       Enclosing the original block content in `. { ... }` is necessary to ensure that
          #       Out-Default applies to *all* statements in the block, if there are multiple.
          $blockToRun = [scriptblock]::Create('. {{ {0} }} | Out-Host' -f $__tcm_block.ToString())
        }
        Write-Verbose "Starting $__tcm_runCount run(s) of: $__tcm_block..."
        1..$__tcm_runCount | ForEach-Object {
          # Force garbage collection before every run, so as to minimize the risk of collection kicking 
          # in during execution due to preexisting memory pressure or from previous runs.
          [GC]::Collect(); [GC]::WaitForPendingFinalizers()        
          # Note how we pass all input objects as an *argument* to -InputObject
          # so that the script blocks can refer to *all* input objects as $_
          # !! Run the script block via a wrapper that executes it in a *child scope*
          # !! to as to eliminate the effects of variable lookups that occur in
          # !! (implicitly) dot-sourced code.
          # !! (Measure-Command runs its script-block argument dot-sourced).
          # !! See https://github.com/PowerShell/PowerShell/issues/8911
          Measure-Command { & $blockToRun } -InputObject $inputObjects
        } | Measure-Object -Property Ticks -Average |
          Select-Object @{ n = 'Command'; e = { $__tcm_block.ToString().Trim() } },
          @{ n = 'Ticks'; e = { $_.Average } }
  } | Sort-Object Ticks |
    # Note: Choose the property order so that the most important information comes first:
    #       Factor, (friendly seconds, followed by the potentially truncated Command (which is not a problem - it just needs to be recognizable).
    #       The TimeSpan column will often not be visible, but its primary importance is for *programmatic* processing only.
    #       A proper solution would require defining formats via a *.format.ps1xml file.
    Select-Object @{ n = 'Factor'; e = { if ($__tcm_fastestTicks.Value -eq 0) { $__tcm_fastestTicks.Value = $_.Ticks }; '{0:N2}' -f ($_.Ticks / $__tcm_fastestTicks.Value) } },
    @{ n = "Secs ($__tcm_runCount-run avg.)"; e = { '{0:N3}' -f ($_.Ticks / 1e7) } },
    Command,
    @{ n = 'TimeSpan'; e = { [timespan] [long] $_.Ticks } }

  Write-Verbose "Overall time elapsed: $([datetime]::UtcNow - $dtStart)"

  }

}



# --------------------------------
# GENERIC INSTALLATION HELPER CODE
# --------------------------------
#    Provides guidance for making the function persistently available when
#    this script is either directly invoked from the originating Gist or
#    dot-sourced after download.
#    IMPORTANT: 
#       * DO NOT USE `exit` in the code below, because it would exit
#         the calling shell when Invoke-Expression is used to directly
#         execute this script's content from GitHub.
#       * Because the typical invocation is DOT-SOURCED (via Invoke-Expression), 
#         do not define variables or alter the session state via Set-StrictMode, ...
#         *except in child scopes*, via & { ... }
if ($MyInvocation.Line -eq '') {
  # Most likely, this code is being executed via Invoke-Expression directly 
  # from gist.github.com

  # To simulate for testing with a local script, use the following:
  # Note: Be sure to use a path and to use "/" as the separator.
  #  iex (Get-Content -Raw ./script.ps1)

  # Derive the function name from the invocation command, via the enclosing
  # script name presumed to be contained in the URL.
  # NOTE: Unfortunately, when invoked via Invoke-Expression, $MyInvocation.MyCommand.ScriptBlock
  #       with the actual script content is NOT available, so we cannot extract
  #       the function name this way.
  & {
    
    param($invocationCmdLine)
    
    # Try to extract the function name from the URL.
    $funcName = $invocationCmdLine -replace '^.+/(.+?)(?:\.ps1).*$', '$1'
    if ($funcName -eq $invocationCmdLine) {
      # Function name could not be extracted, just provide a generic message.
      # Note: Hypothetically, we could try to extract the Gist ID from the URL
      #       and use the REST API to determine the first filename.
      Write-Verbose -Verbose "Function is now defined in this session."
    } 
    else {

      # Indicate that the function is now defined and also show how to
      # add it to the $PROFILE or convert it to a script file.
      Write-Verbose -Verbose @"
Function `"$funcName`" is now defined in this session.

* If you want to add this function to your `$PROFILE, run the following:

   "``nfunction $funcName {``n`${function:$funcName}``n}" | Add-Content `$PROFILE

* If you want to convert this function into a script file that you can invoke
  directly, run:

   "`${function:$funcName}" | Set-Content $funcName.ps1 -Encoding $('utf8' + ('', 'bom')[[bool] (Get-Variable -ErrorAction Ignore IsCoreCLR -ValueOnly)])

"@
    }

  } $MyInvocation.MyCommand.Definition # Pass the original invocation command line to the script block.

}
else {
  # Invocation presumably as a local file after manual download, 
  # either dot-sourced (as it should be) or mistakenly directly.  

  & {
    param($originalInvocation)

    # Parse this file to reliably extract the name of the embedded function, 
    # irrespective of the name of the script file.
    $ast = $originalInvocation.MyCommand.ScriptBlock.Ast
    $funcName = $ast.Find( { $args[0] -is [System.Management.Automation.Language.FunctionDefinitionAst] }, $false).Name

    if ($originalInvocation.InvocationName -eq '.') {
      # Being dot-sourced as a file.
      
      # Provide a hint that the function is now loaded and provide
      # guidance for how to add it to the $PROFILE.
      Write-Verbose -Verbose @"
Function `"$funcName`" is now defined in this session.

If you want to add this function to your `$PROFILE, run the following:

    "``nfunction $funcName {``n`${function:$funcName}``n}" | Add-Content `$PROFILE

"@

    }
    else {
      # Mistakenly directly invoked.

      # Issue a warning that the function definition didn't effect and
      # provide guidance for reinvocation and adding to the $PROFILE.
      Write-Warning @"
This script contains a definition for function "$funcName", but this definition
only takes effect if you dot-source this script.

To define this function for the current session, run:
  
  . "$($originalInvocation.MyCommand.Path)"
  
"@
    } 

  }  $MyInvocation # Pass the original invocation info to the helper script block.

}

Nice, function. I haven't used it in my answers yet because I do have an issue with the timespan column.
Unfortunately, I can't get a grip on it when this happens.

• it looks like is is related to prior runs and results
• it happens in both Windows PowerShell and PowerShell Core
• I am dot-sourcing the script

Sometimes, the timespan column doesn't appear at all, this happens for me with the test below:

$fillerArray = 1..1000
[string[]] $ItemArray =  $fillerArray + 'a' + $fillerArray + 'b' + $fillerArray + 'c' + $fillerArray + 'd'
[string[]] $exclusionArray = $fillerArray +  'b' + $fillerArray + 'c'

Time-Command {
	# LINQ
	[string[]] [Linq.Enumerable]::Except($ItemArray, $exclusionArray)
}, { 
	# LINQ GetEnumerator
	([string[]] [Linq.Enumerable]::Except($ItemArray, $exclusionArray)).GetEnumerator()
}

and sometimes it is completely squeezed to the right:

Factor Secs (1-run avg.) Command                                                                                      T
                                                                                                                      i
                                                                                                                      m
                                                                                                                      e
                                                                                                                      S
                                                                                                                      p
                                                                                                                      a
                                                                                                                      n
------ ----------------- -------                                                                                      -
1,00   0,026             # LINQ…                                                                                      0
16,52  0,436             # Where-Object -notContains…                                                                 0
1,00   0,005             # LINQ…                                                                                      0
91,38  0,430             # Where-Object -notContains…                                                                 0
1,00   0,004             # LINQ…                                                                                      0
100,87 0,425             # Where-Object -notContains…                                                                 0
1,00   0,005             # LINQ…                                                                                      0
91,48  0,414             # Where-Object -notContains…                                                                 0

Moving the (fixed width) TimeSpan column in front of the Command might better format the table in general and possibly resolve the issue without knowing the cause.

I do have a feature request thou:
Is it possible to add a measurement of how long it takes before the first (streamed) item arrives?
For commands that do not use the pipeline, this will likely be same as the Secs column, but for PowerShell cmdlets (that do nicely stream the output), it might better show advantage of the PowerShell pipeline...
I guess, a good example to highlight this purposed feature would be:

Time-Command { Get-Content .\Test.txt }, { Get-Content -Raw .\Test.txt }

Thanks, @iRon7.

The formatting problem is probably not specific to the function, as it relies on default output formatting.

The column disappearing is to be expected, if the window is too narrow; you can always use Format-List instead, or omit the Secs ... column, for instance - see https://stackoverflow.com/a/38576389/45375

As for the "squeezed" column:
I have seen the symptom before, but I cannot recreate it. Is remoting involved? An older PowerShell version? It would be good to have a reproducible case, so we can file a bug report.

As for the feature request: That sounds tricky, because Time-Command would have to inject code into the script blocks passed as arguments.

However, if it's just about measuring how long it takes for the first object to be received via the pipeline, add | Select-Object -First 1 to your script blocks; e.g.:

Time-Command { Get-Content .\Test.txt | Select-Object -First 1 }, { Get-Content -Raw .\Test.txt  | Select-Object -First 1 }

For the "squeezed" column issue, there is no remoting involved, it is a local system. I will keep an eye on it, if I am able to further narrow it down, I will let you know.

For capturing the start time of the pipeline;
The point that I am trying to make is similar to the one in in the stack overflow question: a well designed PowerShell command/function/cmdlet, should be designed to Implement for the Middle of a Pipeline, therefore I think it is not correct to just measure the total execution time...
Technically, I don't think it is required to inject code, I had something like this in mind (quickly coded):

Function Measure-PSCommand ([scriptblock[]] $ScriptBlock) {
	$ScriptBlock | ForEach-Object {
		$Start = $Null
		$Stopwatch = [system.diagnostics.stopwatch]::StartNew()
		&$_ | ForEach-Object {If ($Null -eq $Start) {$Start = $Stopwatch.Elapsed}}
		# $Null = &$_ # Comparison to understand the time lost for the overhead capturing the start time
		$Stopwatch.Stop()
		[PSCustomObject]@{'Command' = "$_".Trim(); 'Start time' = $Start; 'Total Time' = $Stopwatch.Elapsed}
	}
}

Measure-PSCommand { Get-Content .\Test.txt }, { Get-Content -Raw .\Test.txt }

Result example:

Command                     Start time       Total Time
-------                     ----------       ----------
Get-Content .\Test.txt      00:00:00.0063824 00:00:01.3021951
Get-Content -Raw .\Test.txt 00:00:00.0418468 00:00:00.0420012

The only downside, I see is that you will lose some time capturing the start time (and checking whether it is already capture), but maybe this could be smarter/faster:

I see - yes, there are tradeoffs between streaming, pipeline-based processing and collect-everything-up-front, expression/method-based processing, based on whether speed is paramount, how much memory is available, and whether it's important for results to start showing as they're being produced.

However, by design the Time-Command function is solely focused on overall execution time - whatever code is being executed.

As least for my purposes, including | Select-Object -First 1 in order to measure how long it takes for the first result to show up is sufficient, but I encourage you to create your own variant if the described feature is important to you.

Michael, any plans on turning it into a Module for the PS Gallery? I would much rather use this one instead of BenchPress, the author is quite unresponsive and the Module as of today is unusable in PS Core. I do like the usage of hash tables for Key = Test Name and Value = Expression to run from that Module, I could help adding that parameter to Time-Command :P

Good idea, Santiago. If this were to become a module, I'd have to change the name to switch to an approved verb, and I guess Measure is the obvious candidate, but it seems too abstract, though perhaps the timing aspect can be put into the noun, as with Measure-Benchmark (whose name I don't want to duplicate). Another option would be to go with Compare, along the lines of Compare-Runtime. Any thoughts?

Sorry for the delay, Compare-Runtime seems good to me. Nice call using $private: scope btw !

Thanks - it's a bit clumsy, but, fortunately, in a module the need for $private would go away.

This is great! Exactly what I needed, as I was writing my own Measure-Command wrapper, so thanks for pointing me to this. I do have a few questions though.

1. What is this JIT compiler thing about? Can you say something more about why, when and how this is done?

2. I noticed that most commands are being "cached" upon 1st run, somehow. So that means that they get executed much faster on subsequent runs. I suggest to take this into account in your averaging, and remove the 1st 1-3 runs, for getting an improved measure.

3. What about processor affinity? Is this using multi-threads? Maybe add a designated processor for only this task?

Glad to hear it, @eabase:

Re 1, JITting: Please see https://learn.microsoft.com/en-us/powershell/scripting/dev-cross-plat/performance/script-authoring-considerations?view=powershell-7.4#jit-compilation

Re 2.: There is definitely on-demand caching, especially with respect to .NET method calls, but my main focus was on avoiding the distortion that comes from JIT compilation kicking in by default. If anything, the 1st run deserves not to be eliminated, given that in real-world situations there may only be one run.

Re 3: The code makes no attempts to create separate threads or utilize processor affinity. I'm not even sure that would provide any benefit without interfering with the measurements.

At the end of the day, performance measurements in PowerShell are an inexact science, and all that Time-Command aspires to is to provide a general sense of fundamental performance differences.

#1 Wow, very cool. I had no idea. This explains a lot!

• Loops that have fewer than 300 instructions are eligible for JIT-compilation.
• Loops larger than that are too costly to compile.
• When the loop has executed 16 times, the script is JIT-compiled in the background. When the JIT-compilation completes, execution is transferred to the compiled code.

But what is an instruction in this context?

Yes, regarding #2, indeed a very good point. Do we want to measure user experience, or do we want to measure code efficiency? So, for getting an idea for how some function or code snippet run on your machine, then we should not optimize the time. For determining what algo or function is the fastest or most efficient, then we should optimizes as much as possible, and then if we're testing binaries, then of course we shouldn't be in posh at all. And use bare metal timers. (As I did some time ago, by using in-code C within a python script...

Regarding #3, I suppose processor and thread load balancing really does a lot of weird things there. The idea would be to allocate a separate CPU/core only for the $SBE, and excluse all others.

I tried to get an idea how to get the $PID for whatever is started from & ($SBC). For some reason I just get the same PID for every iteration, which cannot be correct. I guess I'm getting PID in the worng way, or it's using some thread. E.g. using tce { Sleep 4; Write-Host "$PID"; } -Count 3. (Assuming it's an automatic variable for [System.Diagnostics.Process]::GetCurrentProcess().ID.)

Also not sure what instruction means; I'm guessing it's the same as statement.

I don't know what $SBC and $SBE refer to (and I assume that tce refers to Time-Command), but note that there are no child processes (or threads) involved, so the $PID value is expected to be the caller's in all iterations.

Ah, sorry, I should have said: $SBC = "Script Block Code". The blob you try to test.