chronometer.psm1

$Script:PSModuleRoot = $PSScriptRoot
# .C:\projects\chronometer\chronometer\Classes\MonitoredScript.ps1
class MonitoredScript
{
    [string]$Path
    [System.Collections.Generic.List[ScriptLine]]$Line

    hidden $lastNode = $null
    hidden $lastRecord = $null

    [timespan]$ExecutionTime = [timespan]::Zero
    [int]$LinesOfCode = 0

    MonitoredScript()
    {
        $this.Line = New-Object 'System.Collections.Generic.List[ScriptLine]'
    }

    [int] SetScript([string]$Path)
    {
        $lineNumber = 0
        foreach ( $command in ( Get-Content -Path $Path ) )
        {
            $this.Line.Add( [ScriptLine]::New($command, $path, $lineNumber) )            
            $lineNumber++
        }
        $this.LinesOfCode = $this.Line.Count
        return $this.LinesOfCode
    }

    [void] AddExecution( [hashtable]$node )
    {
        # Line numbers start at 1 but the array starts at 0
        $lineNumber = $node.Breakpoint.Line - 1
        $record = $this.Line[$lineNumber]

        $record.AddExecution($node)

        # Calclate the delta in time
        if ( $this.lastNode )
        {
            $duration = $node.Elapsed - $this.lastNode.Elapsed
        }
        else
        {
            $duration = $node.Elapsed
        }        
        
        # The delta is how long the last command ran
        if ( $this.lastRecord )
        {
            $this.lastRecord.AddExecutionTime($duration) 
            $this.ExecutionTime += $duration      
        }

        $this.lastRecord = $record
        $this.lastNode = $node
    }

    [void] PostProcessing()
    {
        $this.lastNode = $null
        $this.ExecutionTime = [TimeSpan]::Zero
        foreach ( $node in $this.line )
        {
            $command = $node.text -replace '\s', ''
            
            switch -Regex ( $command )
            {
                '^}$|^}#|^$' 
                {
                    if ( $node.HitCount -eq 0 )
                    {
                        $node.HitCount = $this.lastNode.HitCount
                    }
                    $node.Duration = [TimeSpan]::Zero
                    $node.Average = 0
                    $this.lastNode = $node
                }
                '^{$|^{#}' 
                {
                    $node.Duration = [TimeSpan]::Zero
                    $node.Average = 0
                    $this.lastNode = $node
                }
                default 
                {
                    $this.lastNode = $node
                }
            }
            $this.ExecutionTime += $node.Duration
        }
    }
}
# .C:\projects\chronometer\chronometer\Classes\ScriptProfiler.ps1
class ScriptProfiler {

    static [System.Collections.Queue] $Queue
    static [System.Diagnostics.Stopwatch] $Timer

    static [void] Start()
    {
        [ScriptProfiler]::Queue = New-Object System.Collections.Queue
        [ScriptProfiler]::Timer = [System.Diagnostics.Stopwatch]::StartNew()
    }
   
    static [void] RecordExecution ([System.Management.Automation.LineBreakpoint]$InputObject)
    {
        [ScriptProfiler]::Queue.Enqueue(@{
            Breakpoint = $InputObject
            Elapsed = [ScriptProfiler]::Timer.Elapsed
        })
    }
}

# .C:\projects\chronometer\chronometer\Classes\Chronometer.ps1
class Chronometer
{
    [hashtable]$FileMap = @{}
    $Breakpoint = @()

    [void]AddBreakpoint([string[]]$Path, [int[]]$LineNumber)
    {
        if (-not [string]::IsNullOrEmpty($Path))
        {
            foreach ($file in (Resolve-Path $Path -ea 0))
            {
                $script = [MonitoredScript]@{Path = $file.Path}
                $lines = $script.SetScript($file)
                
                if ( $null -ne $LineNumber )
                {
                    $bpLine = $LineNumber
                }
                else 
                {
                    $bpLine = (1..$lines)
                }

                $this.fileMap[$file.Path] = $script

                $breakpointParam = @{
                    Script = $file
                    Line   = $bpLine
                    Action = { [ScriptProfiler]::RecordExecution( $_) }
                }
                $this.breakPoint += Set-PSBreakpoint @breakpointParam
            }
        }
    }

    [void]ClearBreakpoint()
    {
        if ( $null -ne $this.Breakpoint -and $this.Breakpoint.count -gt 0 )
        {
            Remove-PSBreakpoint -Breakpoint $this.Breakpoint
        }
        
    }

    [void] AddExecution([hashtable]$Execution)
    {
        $script = $Execution.Breakpoint.Script
        if ( $this.FileMap.ContainsKey($script) )
        {
            # Each script tracks it's own execution times
            $this.FileMap[$script].AddExecution($Execution)
        }
    }

    [MonitoredScript[]] GetResults()
    {
        foreach ( $node in $this.FileMap.Values )
        {
            $node.PostProcessing()
        }
        return $this.FileMap.Values
    }
}


# .C:\projects\chronometer\chronometer\Classes\ScriptLine.ps1

class ScriptLine
{
    [TimeSpan] $Duration = 0
    [float] $HitCount = 0
    [TimeSpan] $Min = [TimeSpan]::MaxValue
    [TimeSpan] $Max = [TimeSpan]::MinValue
    [float] $Average = 0
    [int] $LineNumber
    [string] $Path
    [string] $Text
    [System.Collections.ArrayList]$Executions
    hidden [hashtable]$LastNode = @{}

    ScriptLine()
    {
        $this.Executions = New-Object 'System.Collections.ArrayList'
    }

    ScriptLine($Command, $Path, $LineNumber) 
    {
        $this.Executions = New-Object 'System.Collections.ArrayList'
        $this.Text = $Command
        $this.Path = $Path
        $this.LineNumber = $LineNumber
    }


    [void]AddExecutionTime([timespan]$Duration)
    {
        $this.LastNode.Duration = $Duration
        $this.Duration += $Duration
        $this.HitCount += 1
        $this.Average = $this.Duration.TotalMilliseconds / $this.HitCount
        
        if ( $Duration -lt $this.Min )
        {
            $this.Min = $Duration
        }

        if ( $Duration -gt $this.Max )
        {
            $this.Max = $Duration
        }
    }

    [void] AddExecution([hashtable]$node)
    {
        $this.Executions.Add($node)
        $this.LastNode = $node
    }

    [void] Clear()
    {
        $this.Duration = [timespan]::Zero
        $this.HitCount = 0
        $this.Average = 0
        $this.LastNode = $null
        $this.Executions.Clear()
    }

    [string] ToString()
    {
        $values = @(
            $this.Duration.TotalMilliseconds
            $this.HitCount
            $this.Average
            $this.LineNumber
            $this.Text
        )
        return ("[{0:0000}ms,{1:000},{2:000}ms] {3,4}:{4}" -f $values)
    }
}
# Importing from [C:\projects\chronometer\chronometer\Private]
# .\chronometer\Private\Write-ScriptLine.ps1
function Write-ScriptLine
{
    [Diagnostics.CodeAnalysis.SuppressMessageAttribute("PSAvoidUsingWriteHost", "")]
    [cmdletbinding()]
    param(
        [scriptline]
        $line,
        $WarningAt = [int]::MaxValue,
        $ErrorAt = [int]::MaxValue
    )

    if ( $line )
    {         
        $Color = 'Green'
        if ( $line.HitCount -eq 0 )
        {
            $Color = 'Gray'
        }
        elseif ( $line.Average -ge $ErrorAt )
        {
            $Color = 'Red'
        }
        elseif ( $line.Average -ge $WarningAt )
        {
            $Color = 'Yellow'
        }
        
        Write-Host $line.toString() -ForegroundColor $Color
    }
}
# Importing from [C:\projects\chronometer\chronometer\Public]
# .\chronometer\Public\Format-Chronometer.ps1
function Format-Chronometer
{
    <#
        .Description
        Generates a report from a Chronometer

        .Example
        $script = ls C:\workspace\PSGraph\PSGraph -Recurse -Filter *.ps1
        $resultes = Get-Chronometer -Path $script.fullname -ScriptBlock {Invoke-Pester C:\workspace\PSGraph}
        $results | Format-Chronometer -WarnAt 20 -ErrorAt 200
    #>

    [Diagnostics.CodeAnalysis.SuppressMessageAttribute("PSAvoidUsingWriteHost", "")]
    [cmdletbinding(DefaultParameterSetName = 'Script')]
    param(
        # This is a MonitoredScript object from Get-Chronometer
        [Parameter(
            ValueFromPipeline = $true,
            ParameterSetName = 'Script'
        )]
        [MonitoredScript[]]
        $InputObject,

        # This is a ScriptLine object from a MonitoredScript object
        [Parameter(
            ValueFromPipeline = $true,
            ParameterSetName = 'Line'
        )]
        [ScriptLine[]]
        $Line,

        # If the average time of a command is more than this, the output is yellow
        [int]
        $WarningAt = 20,

        #If the average time of a comamand is more than this, the output is red
        [int]
        $ErrorAt = 200,

        # Forces the report to show scripts with no execution time
        [switch]
        $ShowAll
    )

    process
    {
        try
        {
            foreach ( $script in $InputObject )
            {            
                if ( $script.ExecutionTime -ne [TimeSpan]::Zero -or $ShowAll )
                {
                    Write-Host ''
                    Write-Host "Script: $($script.Path)" -ForegroundColor Green
                    Write-Host "Execution Time: $($script.ExecutionTime)" -ForegroundColor Green

                    $script.line | Format-Chronometer -WarningAt $WarningAt -ErrorAt $ErrorAt
                }
            }

            foreach ( $command in $Line )
            {
                Write-ScriptLine $command -WarningAt $WarningAt -ErrorAt $ErrorAt
            }            
        }
        catch
        {
            $PSCmdlet.ThrowTerminatingError($PSItem)
        }
    }
}

# .\chronometer\Public\Get-Chronometer.ps1
function Get-Chronometer
{
    <#
        .Description
        Loads a script and then tracks the line by line execution times

        .Example
        Get-Chronometer -Path .\example.ps1 -Script {
            .\example.ps1
        }
    #>

    [CmdletBinding()]
    param(
        # Script file to measure execution times on
        [Parameter(
            ValueFromPipeline = $true
        )]
        [Object[]]
        $Path,

        # Line numbers within the script file to measure
        [int[]]
        $LineNumber = $null,

        # The script to start the scrupt or execute other commands
        [Parameter(Position = 0)]
        [alias('Script', 'CommandScript')]
        [scriptblock]
        $ScriptBlock             
    )

    process 
    {
        try
        {
            if ( $null -eq $Path )
            {
                $Path = Get-ChildItem -Recurse -Include *.psm1, *.ps1 -File
            }

            if ( $Path.FullName )
            {
                $Path = $Path.FullName
            }

            $Chronometer = [Chronometer]::New()

            Write-Verbose "Setting breakpoints"
            $Chronometer.AddBreakpoint($Path, $LineNumber)

            if ( $null -ne $Chronometer.breakPoint -and $null -ne $ScriptBlock )
            {
                Write-Verbose "Executing Script"
                [ScriptProfiler]::Start()
                [void] $ScriptBlock.Invoke($Path)

                Write-Verbose "Clearing Breapoints"
                $Chronometer.ClearBreakpoint()

                Write-Verbose "Processing data"
                foreach ( $node in [ScriptProfiler]::Queue.GetEnumerator() )
                {
                    $Chronometer.AddExecution($node)
                }

                Write-Output $Chronometer.GetResults()
            }
            else
            {
                Write-Warning "Parsing files did not result in any breakpoints"
            }
        }
        catch
        {
            $PSCmdlet.ThrowTerminatingError($PSItem)
        }
    }
}