Helper classes for performance instrumentation in PowerShell scripts. This is not the start and end of performance analysis of scripts, I'm not even saying it's good, it is as consistent and low overhead as I have the energy to make it right now and has helped troubleshoot a real problem at work.

TimeKeeper.ps1

#!/usr/bin/pwsh
#Requires -Version 5

#region TimeKeeper
################################################################################
##                                 TimeKeeper                                 ##
################################################################################
<#
    This a set of helper functions for logging overlapping timeslices in regions
    of your code. BeginFunctionTick, EndFunctionTick, New-TimeKeeper and
    Get-TimeKeepingEvents are the primary functions needed to utilize this.
    Efforts have been made to reduce runtime overhead so runtime performance tracing
    in production is a possibility. Timeslices are captured in a preallocated
    List<[Tuple]>, where being and end events are logged. Begin and end events
    are aggregated into spans with the Get-TimeKeepingEvents function to be
    exported for later analysis.

    See examples in the GitHub Gist here:
    https://gist.github.com/sean-m/09467f261e0038dfec0c9e8792248690
#>
class TimeEvent {
    <#
        Used to compute durations out of sample log list.
    #>
    [int]    $id
    [string] $caller

    [long]   $startTick
    [long]   $endTick

    [string] $comment

    [TimeSpan] GetDuration() {
        if ($this.startTick -and $this.endTick) {
            [long]$tickSpan = $this.endTick - $this.startTick
            return [System.TimeSpan]::new($tickSpan)
        }
        return $null
    }

    [bool] Completed() {
        return ($this.startTick -and $this.endTick)
    }

    [string] ToString() {

        $duration = $this.GetDuration()
        if ($duration) { $duration = "$(($duration.TotalMilliseconds)) ms"}
        if (-not $duration) { $duration = "INCOMPLETE" }

        $result =  "ID: {0}  Caller: {1}  Duration: {2}" -f $this.id, $this.caller, $duration

        return $result
    }

    [PSCustomObject] ToTableFriendly() {
        $duration = $(($this.GetDuration().TotalMilliseconds))
        if (-not $duration) { $duration = "NaN" }

        return [PSCustomObject]@{
            Id = $this.id
            Caller = $this.caller
            StartTick = $this.startTick
            EndTick = $this.endTick
            'Duration(ms)' = $duration
        }
    }
}

class TimeKeeper {
    <#
        This class does the book keeping elements of the performance measurements.
        All calls to Started and Ended add a log entry to a generic list of strings.
        Data is computed from those log entries.
    #>
    #[System.Collections.Generic.List[Tuple[long,int,int,string]]]
    [System.Collections.Generic.List[object]]
    $timeEvents
    hidden $calls=0
    hidden $initialSize = 100  # If you know how many events are in your script, this preallocates the list of them.
                               # On the whole doing this has a negligable impact, but testing showed that tracing
                               # overhead was more consistent this way.
    hidden static $default = {}
    TimeKeeper() {
        $this.timeEvents = [System.Linq.Enumerable]::ToList([Linq.Enumerable]::Repeat({}, $this.initialSize))
    }
    TimeKeeper($initialSize=100) {
        $this.initialSize = $initialSize
        $this.timeEvents = [System.Linq.Enumerable]::ToList([Linq.Enumerable]::Repeat({}, $initialSize))
    }

    [int] Started ([string] $Caller) {
        $id = $this.calls
        $entry = [Tuple]::Create($([DateTime]::Now.Ticks),${id},1,${Caller})
        if ($this.calls -lt $this.timeEvents.Capacity) {
            $this.timeEvents[$id] = $entry
        } else {
            $this.timeEvents.Add($entry)
        }
        $this.calls++
        return $id
    }

    [void] Ended ([int] $id, [string] $comment=[string]::Empty) {
        $this.timeEvents.Add([Tuple]::Create($([DateTime]::Now.Ticks),${id},0,$comment))
    }

    [object] GetCallTimes() {
        $events = [TimeEvent[]]::new($this.calls)

        foreach ($e in $this.timeEvents) {
            if ($this::default -eq $e) { continue }
            if ($e.GetType().Name -notlike "Tuple*") { continue }
            switch ($e.Item3) {
                1 {
                    $ev = [TimeEvent]::new()
                    $ev.startTick = $e.Item1
                    $ev.id        = $e.Item2
                    $ev.caller    = $e.Item4
                    $events[$ev.id] = $ev
                }
                0 {
                    $events[$e.Item2].endTick = $e.Item1
                    if ($e.Item4) {
                        $events[$e.Item2].comment = $e.Item4
                    }
                }
            }
        }

        return $events.Where({ $_ })
    }

    [string] GetCallTimeTable () {
        return $this.GetCallTimes() | foreach { $_.ToTableFriendly() }  | FT | Out-String
    }

    [string[]] GetCallTimeLog() {
        return $this.GetCallTimes() | foreach { $_.ToString() }
    }
}

class TimeKeeperNoop : TimeKeeper{
    TimeKeeperNoop () { }
    [int] Started ([string] $Caller) { return 0 }
    [void] Ended ([int] $id) { }
    [object] GetCallTimes() { return $null }
    [string] GetCallTimeTable () { return [string]::Empty }
    [string[]] GetCallTimeLog() { return [string]::Empty }
}

function New-TimeKeeper {
    param ($initialSize=100)
    if ((Get-Variable '_TimeKeeper' -Scope 'Script' -ErrorAction SilentlyContinue) -and $Script:_TimeKeeper -isnot [TimeKeeperNoop]) {
        Write-Warning "Overwriting existing timekeeper!"
    }
    New-Variable -Name _TimeKeeper -Scope Script -Value ([TimeKeeper]::new($initialSize)) -Force
}

function Get-TimeKeepingLog {
    $Script:_TimeKeeper.GetCallTimeLog()
}
function Get-TimeKeepingTable {
    $Script:_TimeKeeper.GetCallTimeTable()
}
function Get-TimeKeepingEvents {
    param (
        [switch]
        $IncludeHostInfo
    )
    $result = $null
    $events = $Script:_TimeKeeper.GetCallTimes()

    if ($IncludeHostInfo) {
        $result = @{}
        $result.Add("Host", $(hostname))
        $result.Add("HostType", $env:HOSTTYPE)
        $result.Add("PSVersion", $PSVersionTable.PSVersion)
        $result.Add("PSEdition", $PSVersionTable.PSEdition)
        $result.Add("PSOS", $PSVersionTable.OS)
        $result.Add("PSPlatform", $PSVersionTable.Platform)
        $result.Add("Events", $events)
    } else {
        $result = $events
    }

    $result
}

function BeginFunctionTick {
    # Log start event for a span with the given name. Returns span id.
    param (
        [Parameter(Mandatory=$true)]
        [string]$Name
        )
    if (-not $Script:_TimeKeeper) { return }
    $id = ($Script:_TimeKeeper.Started($Name))
    #Write-Debug "${id}`tStarted: $Name"
    return $id
}

function EndFunctionTick {
    # Log end event for a span with the given id.
    param ([int] $id, [string]$comment=[string]::Empty)
    #Write-Debug "${id}`tEnded"
    $Script:_TimeKeeper.Ended($id, $comment)
}

function ProfileScriptBlock {
    # Execute a scriptblock with the given argument list and log a timeslice.
    # Note: no errors are handled here, they must be handled by the caller 
    # (the try{} doesn't have a catch{}).
    param ([scriptblock]$Function, $Arguments, [string]$Name, [string]$EndComment)
    $tsName=$Name
    if (-not $tsName) { $tsName = "AnonymousFunctionCall" }
    $tsFuncCall = BeginFunctionTick $tsName
    try {
        if ($Arguments) { return $Function.Invoke($Arguments) }
        else { return $Function.Invoke() }
    }
    finally {
        if ($EndComment) { EndFunctionTick -id $tsFuncCall -comment $EndComment }
        else { EndFunctionTick -id $tsFuncCall }
    }
}

#New-Variable -Name _TimeKeeper -Scope Script -Value ([TimeKeeperNoop]::new()) -Force

#endregion TimeKeeper

#region TimeKeeperAnalysis

function Get-WaterfallChartFromEventTimes {
    <#
        This returns a ascii string representation of a waterfall chart to show
        overlapping timeslices from profile data.

        It expects an array of objects that look like the TimeEvent class but there's
        no typesafety enforcing it so capturing output from where and select statements
        to filter your profile is fine.

        The member properties that must be present are: StartTick, EndTick and Caller.
    #>
    param (
        $Times,
        # Sets resolution width for the chart
        $Width = 120
    )

    $events = $null
    if ($Times -is [array]) {
        $events = $Times
    } elseif ($Times -is [hashtable] -or $Times -is [PSCustomObject]) {
        $events = $Times.Events
    }

    [long[]] $starts = ($events.StartTick)
    [long[]] $ends   = ($events.EndTick)
    $startMeasure = $starts | measure -Minimum -Maximum
    [long] $rangeMin = $startMeasure.Minimum
    [long] $rangeMax = [Math]::Max($startMeasure.Maximum, ($ends | measure).Maximum)
    $range = $rangeMax - $rangeMin

    $sb = [System.Text.StringBuilder]::new()

    $events | Sort-Object StartTick | ForEach-Object {

        [long]$start = $_.StartTick
        [long]$end = $_.EndTick

        $tickOffsetFromBeginning = $start - $rangeMin
        $tickSpan =  $end - $start

        $startPadding = [Math]::Round($tickOffsetFromBeginning / $range * $Width)
        $charWidth = [Math]::Abs([Math]::Round(($tickSpan / $range * $Width))) - 1
        $sb.Append(''.PadLeft([Math]::Max($startPadding-1,0),' ')) | Out-Null
        $sb.AppendFormat("* {0} {1} ms`n", $_.Caller, ([timespan]::new($tickSpan).TotalMilliseconds)) | Out-Null
        $sb.Append('['.PadLeft($startPadding,' ')) | Out-Null
        if ($charWidth -gt 0) { $sb.Append(('=' * $charWidth)) | Out-Null }
        $sb.AppendLine("]") | Out-Null
    }
    $sb.AppendLine() | Out-Null
    $totalTime = [timespan]::new($range)
    $sb.AppendLine("Begin: " + [DateTime]::new($rangeMin).ToString("o")) | Out-Null
    $sb.AppendLine("End:   " + [DateTime]::new($rangeMax).ToString("o")) | Out-Null
    $sb.AppendLine("Elapsed (ticks): $range") | Out-Null
    $sb.AppendLine("Elapsed (ms): " + $totalTime.TotalMilliseconds) | Out-Null

    $chart = $sb.ToString()


    [int[]]$lengths = @(($chart -split "`n").Where({$_.TrimEnd().EndsWith(']')}).ForEach({ $_.TrimEnd().Length }))
    $chartWidth = [System.Linq.Enumerable]::Max($lengths) - 2

    [string]::Concat("* Total Time $($totalTime.TotalMilliseconds) ms`n", "[$('=' * ($chartWidth))]`n", $chart)
}

function Get-ChromeProfileFromEventTimes {
    <#
        Returns a JSON payload that can be read by the performance profiler in
        Chrome dev tools. As of August 2023, it works in Chromium based broswers from
        Chromium 55+. Ultimately it's the same representation of info from the waterfall
        chart but is more interactive and can lead to a richer debugging experience
        when analysing a large sample set.

        It expects an array of objects that look like the TimeEvent class but there's
        no typesafety enforcing it so capturing output from where and select statements
        to filter your profile is fine.

        The member properties that must be present are: StartTick, EndTick and Caller.

        Holy smokes -- the format is actually documented now!
        https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview?tab=t.0
    #>

    param (
        $Times,
        $Width # not used, just makes it easier to switch between waterfall chart and this
    )

    $profile = @"
{
    "traceEvents": [],
    "meta_datetime": "$((Get-Date).ToString())",
    "meta_user": "$($env:currentuser)",
    "metadata": {"source":"TimeKeeper"}
}
"@ | ConvertFrom-Json
    # '{ "pid":1, "tid":1, "ts":0, "dur":0, "ph":"X", "name":"", "args":{ "ms":0 } }'
    class ChrmTraceEvent { $pid=1; $tid=1; $ts=0; $dur=0; $ph="X"; $name=""; $args=[pscustomobject]@{'ms'=0}; TraceEvent() {}}

    $events = $null
    if ($Times -is [array]) {
        $events = $Times
    } elseif ($Times -is [hashtable]) {
        $events = $Times.Events
        foreach ($k in $Times.Keys) {
            if ($k -like 'Events') { continue }
            $memberName = "meta_$k"
            $profile | Add-Member -MemberType NoteProperty -Name $memberName -Value ($Times[$k])
        }
    } elseif ($Times -is [PSCustomObject]) {
        $events = $Times.Events
    }


    [long[]] $starts = ($events.StartTick)
    [long[]] $ends   = ($events.EndTick)
    [long] $rangeMin = [Linq.Enumerable]::Min($starts)
    [long] $rangeMax = [Math]::Max([Linq.Enumerable]::Max($starts), [Linq.Enumerable]::Max($ends))

    $events | ForEach-Object {
        [long]$start = $_.StartTick
        [long]$end = $_.EndTick

        $tickOffsetFromBeginning = $start - $rangeMin
        $ts = $tickOffsetFromBeginning / ([timespan]::TicksPerMillisecond / 1000)  # TicksPerMicrosecond isn't defined in .net framework so isn't in PowerShell 5.
        [long]$tickSpan =  $end - $start
        $timespan = [timespan]::new($tickSpan)
        $dur = $timespan.TotalMilliseconds * 1000

        $te = [ChrmTraceEvent]::new()
        $te.name = $_.Caller
        $te.ts = $ts
        $te.dur = $dur
        $te.args.ms = $timespan.TotalMilliseconds
        if ($_.comment) {
            $comment = $_.comment
            $te.args | Add-Member -MemberType NoteProperty -Name 'comment' -Value $comment -Force
        }

        $profile.traceEvents += $te
    }

    $profile | ConvertTo-Json -Compress -Depth 5
}

#endregion TimeKeeperAnalysis


################################################################################
##                           Execute Test Functions                           ##
################################################################################

$debugPref = $DebugPreference
try {
    #$DebugPreference = 'Continue'

    New-TimeKeeper

    ## Set some tracing around the functions themselves. Makes the resulting charts more interesting
    $at = BeginFunctionTick 'AllTests'
    $t = BeginFunctionTick 'ThisAndThat'
    DoThis
    DoThat
    EndFunctionTick -id $t

    $t = BeginFunctionTick 'TheseOtherThings'
    DoThisOtherThing
    ThenDoThis
    OrThat
    EndFunctionTick $t
    EndFunctionTick $at

    Write-Host "**  Simple time log"
    Get-TimeKeepingLog

    Write-Host "**  Log as a table"
    Get-TimeKeepingTable

    Write-Host "**  Time keeping events as waterfall chart`n"
    $events = Get-TimeKeepingEvents
    Get-WaterfallChartFromEventTimes -Times $events -Width 100

    Write-Host "** Write out json file that can be loaded with Chrome profiler"
    Get-ChromeProfileFromEventTimes $events -Width 100 | Out-File ./timekeeper.json -Encoding ascii

    $events = Get-TimeKeepingEvents -IncludeHostInfo
    Get-ChromeProfileFromEventTimes $events -Width 100 | Out-File ./timekeeper_full.json -Encoding ascii
} 
finally {
    $DebugPreference = $debugPref
}

Saw your post on Reddit. Running your code throws div by zero error on line 314.

Yes sorry about that. There were some perfectly reasonable cases where the math wasn't lining up. Most of those bugs have been fixed, hopefully.