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                                 ##
################################################################################

class TimeEvent {
    <#
        Used to compute durations out of event 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 measurement.
        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=1
    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.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.initialSize) {
            $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 }
            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 ($Script:_TimeKeeper -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)
}

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)
    [long] $rangeMin = [Linq.Enumerable]::Min($starts)
    [long] $rangeMax = [Math]::Max([Linq.Enumerable]::Max($starts), [Linq.Enumerable]::Max($ends))
    $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.
    #>

    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)"
}
"@ | 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]::TicksPerMicrosecond
        $tickSpan =  $end - $start
        $timespan = [timespan]::new($tickSpan)
        $dur = $timespan.TotalMicroseconds

        $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

#region Testing

class TimeKeeperTracer {
    <#
        This class does the book keeping elements of the performance measurement.
        All calls to Started and Ended add a log entry to a generic list of strings.
        Data is computed from those log entries.
    #>
    hidden $calls=1
    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 $pid = [System.Diagnostics.Process]::GetCurrentProcess().Id

    TimeKeeper() {
        [System.Diagnostics.Trace]::AutoFlush = $false
    }

    [int] Started ([string] $Caller) {
        $id = $this.calls
        [System.Diagnostics.Trace]::WriteLine("TK:$($this.pid):$([DateTime]::Now.Ticks):${id}:$Caller:start")
        return $id
    }

    [void] Ended ([int] $id) {
        [System.Diagnostics.Trace]::WriteLine("TK:$($this.pid):$([DateTime]::Now.Ticks):${id}:end")
    }
    
    [object] GetCallTimes() {
        $events = [TimeEvent[]]::new($this.calls)

        <#
        foreach ($e in $this.timeEvents) {
            if ($this::default -eq $e) { 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
                }
            }
        }
        #>

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

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

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


function TimeMeasuredScope {
    param (
        [Parameter(Mandatory=$true)]
        [string]$Name,
        [Parameter(Mandatory=$true)]
        [scriptblock]$Command,
        [object[]]
        $ArgumentList
    )
    begin {
        $local:_rounds=0
        $local:_totalId = BeginFunctionTick "$Name-Total"
    }
    process {
        $local:rounds++
        $local:_id = BeginFunctionTick "$Name-${local:_rounds}"
        Invoke-Command -NoNewScope -ScriptBlock $Command -ArgumentList $ArgumentList
        EndFunctionTick $local:_id
    }
    end {
        EndFunctionTick $local:_totalId
    }
}
#endregion Testing

################################################################################
##                         Instrumented Test Functions                        ##
################################################################################

function DoThis {
    begin {
        $beginId = BeginFunctionTick $($MyInvocation.MyCommand)
    }
    process {
        $st = 222  # statically set to measure overhead of my tracing though Start-Sleep seems to have the most variability
        $st = (Get-Random -Minimum 0 -Maximum 1000)
        #Write-Host -ForegroundColor Cyan "$(($MyInvocation.MyCommand)) Sleeping for $st ms"
        Start-Sleep -Milliseconds $st
    }
    end {
        EndFunctionTick $beginId
    }
}


function DoThat {
    begin {
        $beginId = BeginFunctionTick ($MyInvocation.MyCommand)
    }
    process {
        $st = 222  # statically set to measure overhead of my tracing though Start-Sleep seems to have the most variability
        $st = (Get-Random -Minimum 0 -Maximum 1000)
        #Write-Host -ForegroundColor Cyan "$(($MyInvocation.MyCommand)) Sleeping for $st ms"
        Start-Sleep -Milliseconds $st
    }
    end {
        EndFunctionTick $beginId
    }
}

function DoThisOtherThing {
    begin {
        $beginId = BeginFunctionTick ($MyInvocation.MyCommand)
    }
    process {
        $st = 222  # statically set to measure overhead of my tracing though Start-Sleep seems to have the most variability
        $st = (Get-Random -Minimum 0 -Maximum 1000)
        #Write-Host -ForegroundColor Cyan "$(($MyInvocation.MyCommand)) Sleeping for $st ms"
        Start-Sleep -Milliseconds $st
    }
    end {
        EndFunctionTick $beginId
    }
}

function ThenDoThis {
    begin {
        $beginId = BeginFunctionTick ($MyInvocation.MyCommand)
    }
    process {
        $st = 222  # statically set to measure overhead of my tracing though Start-Sleep seems to have the most variability
        $st = (Get-Random -Minimum 0 -Maximum 1000)
        #Write-Host -ForegroundColor Cyan "$(($MyInvocation.MyCommand)) Sleeping for $st ms"
        Start-Sleep -Milliseconds $st
    }
    end {
        EndFunctionTick $beginId
    }
}

function OrThat {
    process {
        TimeMeasuredScope -Name ($MyInvocation.MyCommand) -Command {
            $st = 222  # statically set to measure overhead of my tracing though Start-Sleep seems to have the most variability
            $st = (Get-Random -Minimum 0 -Maximum 1000)
            #Write-Host -ForegroundColor Cyan "$(($MyInvocation.MyCommand)) Sleeping for $st ms"
            Start-Sleep -Milliseconds $st
        }
    }
}


################################################################################
##                           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.