Trace-Script.ps1

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
$script:totals = [System.Collections.Queue]::new()

function Write-TimeAndRestart ($sw) { 
    $t = $sw.Elapsed

    if ([timespan]::FromSeconds(1) -gt $t) { 
        Write-Host -ForegroundColor DarkGray " ($([int]$t.TotalMilliseconds)ms)"
    }
    else { 
        Write-Host -ForegroundColor DarkGray " ($([math]::Round($t.TotalSeconds, 2))s)"
    }

    $sw.Restart()
}

function Trace-Script {
    <#
    .DESCRIPTION
    Invoke the provided script or command and profile its execution.
 
    .PARAMETER ScriptBlock
    A ScriptBlock to be profiled.
 
    $trace = Trace-Script -ScriptBlock { Import-Module $PSScriptRoot\Planets.psm1; Get-Planet }
 
    When running a script file use the same syntax, you can specify parameters if you need:
    $trace = Invoke-Script -ScriptBlock { & $PSScriptRoot\MyScript.ps1 }
 
    .PARAMETER Preheat
    Run the provided script or command this many times without tracing it to warm up the session.
    This is good for measuring normal performance excluding startup. Default is 0.
 
    .PARAMETER DisableWarning
    Disable warning about Preheat on PowerShell 7.
 
    .PARAMETER Flag
    A hash table of feature flags to be set to profile code before or after changes. The default is After
    changes. You can toggle the behavior using -Before and also -After (which is the same as using neither).
 
    For this to work your code needs to cooperate:
 
    Each key from the hashtable will be defined as a $global: variable. Use that variable in `if` to wrap
    the new code to test it against the old code.
 
    Use $true, $false as the values. The hashtable represents the after side. Each key will be
    defined with the value for after side. Each key will be defined with $false for the before side.
 
    In this case example is worth 1000 words:
 
    Trace-Script -ScriptBlock { & MyScript.ps1 } -Flag @{ _profiler = $true }
 
    Original code in MyScript.ps1 you are trying to improve:
    $values = 1..1000
    foreach ($v in $Values) {
        $newValues += $v + 10
    }
 
    Modified code with changes that you think are faster wrapped in if using the feature flags:
    if ($_profiler) {
        $values = [System.Linq.Enumerable]::Range(1,1000)
    }
    else {
        $values = 1..1000
    }
 
    if ($_profiler) {
        # after side
        $newValues = foreach ($v in $Values) { $v + 10 }
    }
    else {
        # before side
        foreach ($v in $Values) {
            $newValues += $v + 10
        }
    }
 
    A single feature flag might be good enough for many purposes, but imagine there are multiple improvements
    that migh contradict each other, in that case you are better of adding different flag for each one:
 
    Trace-Script -ScriptBlock { & MyScript.ps1 } -Flag @{ _iteration = $true; _enumerable = $true }
 
    if ($_enumerable) {
        $values = [System.Linq.Enumerable]::Range(1,1000)
    }
    else {
        $values = 1..1000
    }
 
    if ($_iteration) {
        # B side
        $newValues = foreach ($v in $Values) { $v + 10 }
    }
    else {
        # A side
        foreach ($v in $Values) {
            $newValues += $v + 10
        }
    }
 
    Using two or more feature flags you can test them together as shown above, or one without the other:
 
    Trace-Script -ScriptBlock { & MyScript.ps1 } -Flag @{ _iteration = $true; _enumerable = $false }
 
    .PARAMETER Before
    When using -Flag. Force all flags to be set as $false to run the code before changes.
 
    .PARAMETER After
    When using -Flag. Force all flags to be set to the values provided in the -Flag hashtable.
    When both -Before and -After are enabled, -After is used.
    #>


    [CmdletBinding()]
    param(
        [Parameter(Mandatory)]
        [ScriptBlock] $ScriptBlock,
        # [string[]] $FilterPath,
        [uint32] $Preheat = 0,
        [Switch] $DisableWarning,
        [Hashtable] $Flag,
        [Switch] $Before,
        [Switch] $After
        # [Switch] $UseNativePowerShell7Profiler
    )

    if ($Before -and $After) {
        Write-Warning "You should not use -Before and -After together, using -After."
    }

    if ($After) {
        $Before = $false
    }

    $invokedAs = $MyInvocation.Line

    $out = @{ Stopwatch = [TimeSpan]::Zero; ScriptBlocks = $null }
    $trace = Trace-ScriptInternal -ScriptBlock $ScriptBlock -Preheat $Preheat -DisableWarning:$DisableWarning -Flag $Flag -UseNativePowerShell7Profiler:$UseNativePowerShell7Profiler -Before:$Before -Out $out

    $scriptBlocks = $out.ScriptBlocks
    $traceCount = $trace.Count

    Write-Host -ForegroundColor Magenta "Processing $($traceCount) trace events. $(if (1000000 -lt $traceCount) { "This might take a while..."})"

    Write-Host -ForegroundColor Magenta "Figuring out flow." -NoNewline
    $sw = [Diagnostics.Stopwatch]::StartNew()
        $trace = [Profiler.Profiler]::ProcessFlow($trace)
    Write-TimeAndRestart $sw

    Write-Host -ForegroundColor Magenta "Sorting events into lines." -NoNewline
    $fileMap = [Profiler.Profiler]::ProcessLines($trace, $scriptBlocks, $false)
    Write-TimeAndRestart $sw

    # trace starts with event from the measurement script where we enable tracing and ends with event where we disable it
    # events are timestamped at the start so user code duration is from the second event (index 1), till the last real event (index -2) where we disable tracing
    $total = if ($null -ne $trace -and 0 -lt @($trace).Count) { [TimeSpan]::FromTicks($trace[-2].Timestamp - $trace[2].Timestamp) } else { [TimeSpan]::Zero }

    Write-Host -ForegroundColor Magenta "Counting averages and percentages." -NoNewline
    # this is like SelectMany, it lists all the lines in all files into a single array
    $all = foreach ($line in $fileMap.Values.Lines.Values) {
        $line.SelfAverage = if ($line.HitCount -eq 0) { [TimeSpan]::Zero } else { [TimeSpan]::FromTicks($line.SelfDuration.Ticks / $line.HitCount) }
        $line.Average = if ($line.HitCount -eq 0) { [TimeSpan]::Zero } else { [TimeSpan]::FromTicks($line.Duration.Ticks / $line.HitCount) }
        $ticks = if (0 -ne $total.Ticks) { $total.Ticks } else { 1 }
        $line.Percent = [Math]::Round($line.Duration.Ticks / $ticks, 5, [System.MidpointRounding]::AwayFromZero) * 100
        $line
    }
    Write-TimeAndRestart $sw

    Write-Host -ForegroundColor Magenta "Getting Top50 with the longest Duration." -NoNewline
    $top50Duration = $all |
    Where-Object Duration -gt 0 |
    Sort-Object -Property Duration -Descending |
    Select-Object -First 50
    Write-TimeAndRestart $sw

    Write-Host -ForegroundColor Magenta "Getting Top50 with the longest average Duration." -NoNewline
    $top50Average = $all |
    Where-Object Average -gt 0 |
    Sort-Object -Property Average -Descending |
    Select-Object -First 50
    Write-TimeAndRestart $sw

    Write-Host -ForegroundColor Magenta "Getting Top50 with the longest SelfDuration." -NoNewline
    $top50SelfDuration = $all |
    Where-Object SelfDuration -gt 0 |
    Sort-Object -Property SelfDuration -Descending |
    Select-Object -First 50
    Write-TimeAndRestart $sw

    Write-Host -ForegroundColor Magenta "Getting Top50 with the longest average SelfDuration." -NoNewline
    $top50SelfAverage = $all |
    Where-Object SelfAverage -gt 0 |
    Sort-Object -Property SelfAverage -Descending |
    Select-Object -First 50
    Write-TimeAndRestart $sw

    Write-Host -ForegroundColor Magenta "Getting Top50 with the most hits." -NoNewline
    $top50HitCount = $all |
    Where-Object HitCount -gt 0 |
    Sort-Object -Property HitCount -Descending |
    Select-Object -First 50
    Write-TimeAndRestart $sw

    # do not use object initializer syntax here @{}
    # when it fails it will not create any object
    # and won't tell you on which line exactly it failed
    #
    # order properties based on what is least likely to
    # fail on casting
    #
    # this way we can get the partial object out for
    # debugging when this fails on someones system
    $script:processedTrace = [Profiler.Trace]::new()
    $script:processedTrace.TotalDuration = $total
    $script:processedTrace.StopwatchDuration = $out.Stopwatch
    $script:processedTrace.Events = $trace
    $script:processedTrace.AllLines = $all
    $script:processedTrace.Top50Duration = $top50Duration
    $script:processedTrace.Top50Average = $top50Average
    $script:processedTrace.Top50HitCount = $top50HitCount
    $script:processedTrace.Top50SelfDuration = $top50SelfDuration
    $script:processedTrace.Top50SelfAverage = $top50SelfAverage

    $script:processedTrace

    $variable = if ($invokedAs -match "(\$\S*)\s*=\s*Trace-Script") {
        "$($matches[1])"
    }

    if ($null -eq $variable) {
        Write-Host -ForegroundColor Yellow "Looks like you did not assign the output to a variable. Use Get-LatestTrace to retrieve the trace, e.g.: `$trace = Get-LatestTrace"
    }


    $previous = if (0 -lt $totals.Count) {
        $totals.ToArray()[-1]
    }

    $diff = if ($null -eq $previous) {
        0
    }
    else {
        [int] ($total.TotalMilliseconds - $previous.Total.TotalMilliseconds)
    }

    $color = if (0 -eq $diff) {
        "Yellow"
    }
    elseif (0 -gt $diff) {
        "Green"
    }
    else {
        "Red"
    }

    $totals.Enqueue(@{ Color = $color; Diff = $diff ; Total = $total; Before = $Before } )
    while ($totals.Count -gt 5) { $null = $totals.Dequeue() }
    if (1 -lt $totals.Count) {
        Write-Host -ForegroundColor Magenta "Progress: " -NoNewline

        $i = 0
        foreach ($t in $totals) {
            $last = $i -eq ($totals.Count - 1)

            Write-Host -ForegroundColor $t.Color "$(if ($t.Before) { "B:" } else {"A:" }) $($t.Total) ($($t.Diff) ms)$(if (-not $last) {" -> "} else { "`n" })" -NoNewline
            $i++
        }
    }
    else {
        Write-Host -ForegroundColor Magenta "Duration: $(if ($Before) { "B:" } else {"A:" }) " -NoNewline
        Write-Host -ForegroundColor Yellow $total
    }

    Write-Host -ForegroundColor Magenta "Done. Try $(if ($variable) { "$($variable)" } else { '$yourVariable' }).Top50Duration | Format-Table to get the report. There are also Top50Average, Top50SelfDuration, Top50SelfAverage, Top50HitCount, AllLines and Events."
}

function Get-LatestTrace {
    if ($script:processedTrace) {
        $script:processedTrace
    }
    else {
        Write-Warning "There is no trace yet. Run Trace-Script. For example Trace-Script -ScriptBlock { & yourfile.ps1 }."
    }
}


function Show-ScriptExecution {
    # .DESCRIPTION Show how the script executed with margin to show how deep the call was, this is just for fun.
    # You can slow down the excution x times to reflect the mimic the real execution delays.
    [CmdletBinding()]
    param(
        $Trace,
        [switch] $x1,
        [switch] $x10,
        [switch] $x100,
        [switch] $x1000 # ,
        # [switch] $Color
    )

    $trace = if ($Trace) { $Trace } else { Get-LatestTrace }

    $x = if ($x1000) {
        1000
    }
    elseif ($x100) {
        100
    }
    elseif ($x10) {
        10
    }
    elseif ($x1) {
        1
    }
    else {
        0
    }

    $c = [bool] $Color
    if ($c) {
        # https://www.reddit.com/r/PowerShell/comments/b06gtw/til_that_powershell_can_do_colors/
        # ANSI escape character
        $r = 0
        $g = 0
        $b = 0
        $ansi_escape = [char]27
    }

    foreach ($e in $trace.Events) {
        $text = $e.Extent.Text.ToString().Trim()
        $o = "$ansi_escape[48;2;$r;$g;${b}m$text$ansi_escape[0m"
        $margin = ' ' * ($e.Level)
        Write-Host "$margin$o"
        if (0 -lt $x) {
            # this is fun, but hardly accurate, as the resolution is <15ms
            # and many lines take <0.001ms
            [System.Threading.Thread]::Sleep($e.SelfDuration * $x)
        }


        if ($c) {

            $r++

            if (254 -eq $r) {
                $r = 0
                $g++

                if (254 -eq $g) {
                    $g = 0
                    $b++

                    if (254 -eq $b) {
                        $r = 0
                        $g = 0
                        $b = 0
                    }
                }
            }

            "$r $g $b"
        }
    }
}

# don't publish just yet till I get some time using this
function Get-CallStack {

    param (
        [Parameter(Mandatory)]
        [Profiler.Hit] $hit
    )

    $trace = (Get-LatestTrace).Events

    $hit

    if (0 -ne $hit.CallerIndex) {
        do {
            $hit = $trace[$hit.CallerIndex]
            $hit
        } while (1 -lt $hit.CallerIndex)
    }
}