The Profiler module was mentioned in the episode on January 15th of the PowerShell Podcast from PDQ (My favorite!), and it did not cross my path earlier. In this blog post, I will show you how it works and why it’s a great tool to optimize your script performance!
What does the Profiler module do?
“Script, ScriptBlock and module performance profiler for PowerShell 5, and PowerShell 7 that works in Windows, Linux and MacOS.” by Jakub Jareš.
Source: https://github.com/nohwnd/Profiler
Podcast in which it was mentioned: https://powershellpodcast.podbean.com/e/from-listener-to-speaker-daniel-schroeder-s-powershell-summit-success/
How to install
The Module is available from the PowerShell gallery and can be installed by running:
Install-Module Profiler
After installation, these Cmdlets are available:
C:\Users\HarmVeenstra> get-command -Module Profiler | Select-Object Name | Sort-Object Name ---- Get-CallStack Get-LatestTrace Invoke-Script Show-ScriptExecution Trace-Script
Using Profiler
Trace-Script
If you have a script that you want to check for performance (To determine which part takes the longest), then you can use the Trace-Script cmdlet. In the example below, I use it to check my PowerShell profile:
C:\Users\HarmVeenstra> $trace=Trace-Script -ScriptBlock {& $profile}
Running in PowerShell 7.4.1 64-bit.
Starting trace.
Stopwatch is high resolution, max resolution of timestamps is 100ns.
Run finished after 00:00:00.5250598.
Tracing done. Got 58 trace events.
Processing 58 trace events.
Figuring out flow. (0ms)
Sorting events into lines. (3ms)
Counting averages and percentages for lines. (2ms)
Sorting events into functions. (1ms)
Counting averages and percentages for functions. (2ms)
Getting Top50 lines with the longest Duration. (2ms)
Getting Top50 lines with the longest SelfDuration. (1ms)
Getting Top50 lines with the most hits. (2ms)
Getting Top50 functions with the longest Duration. (1ms)
Getting Top50 functions with the longest SelfDuration. (1ms)
Getting Top50 functions with the most hits. (1ms)
Progress: A: 00:00:00.7160076 (0 ms) -> A: 00:00:00.6621001 (-54 ms) -> A: 00:00:00.5224182 (-140 ms)
Done. Try $trace.Top50SelfDuration to get the report. There are also Top50Duration, Top50HitCount, Top50FunctionSelfDuration, Top50FunctionDuration, Top50FunctionHitCount AllLines and Events.
I stored the results in the $trace variable. This variable allows you to retrieve the following:
Top50Duration : List top 50 lines based on duration Top50HitCount : List top 50 lines based on hit count Top50SelfDuration : List top 50 lines based on time consumed directly by the line Top50FunctionDuration : List top 50 functions based on duration Top50FunctionHitCount : List top 50 functions based on hit count Top50FunctionSelfDuration : List top 50 functions based on time consumed directly by the function AllLines : Show all lines processed by profiler trace Events : Show raw trace-events returned from the profiler engine TotalDuration : 00:00:00.5224182 StopwatchDuration : 00:00:00.5250598
For example, this is the output for all lines:
As you can see, I load multiple things in my PowerShell profile, which lists those with the File that was read and what command (Text) was executed. In my case, the 365healthstatus.ps1 script took about 93% of the total execution time of my PowerShell profile. From within that script, line 22 ($issues=Get-MgServiceAnnouncementIssue | Where-Object IsResolved…) takes 88 % of the time from that script. And I can imagine why: it connects to 365 using an App Registration, retrieves events, and shows any open event like this:
Ok, but I do retrieve them all and use Where-Object afterward. Should I be using a Filter, perhaps? There is a -Filter parameter, and yes, that works a lot faster 🙂 So, I updated the script with that (And the blog post about that script), and these are the results:
It’s down from 5.2 seconds to 3.7 seconds 🙂 A simple check using Profiler with a simple Where-Object to a -Filter parameter change was all it took… (It did test this a few times, and sometimes it even saves about 4 seconds in total!)
You can also visualize the results using the –ExportPath parameter, which will save the results to a JSON file. For example:
C:\Users\HarmVeenstra> Trace-Script -ScriptBlock {& $profile} -ExportPath c:\temp\visual
Running in PowerShell 7.4.1 64-bit.
Starting trace.
Stopwatch is high resolution, max resolution of timestamps is 100ns.
Run finished after 00:00:00.3149503.
Tracing done. Got 58 trace events.
Processing 58 trace events.
Figuring out flow. (0ms)
Sorting events into lines. (5ms)
Counting averages and percentages for lines. (2ms)
Sorting events into functions. (1ms)
Counting averages and percentages for functions. (1ms)
Getting Top50 lines with the longest Duration. (2ms)
Getting Top50 lines with the longest SelfDuration. (2ms)
Getting Top50 lines with the most hits. (2ms)
Getting Top50 functions with the longest Duration. (1ms)
Getting Top50 functions with the longest SelfDuration. (1ms)
Getting Top50 functions with the most hits. (1ms)
Top50Duration : List top 50 lines based on duration
Top50HitCount : List top 50 lines based on hit count
Top50SelfDuration : List top 50 lines based on time consumed directly by the line
Top50FunctionDuration : List top 50 functions based on duration
Top50FunctionHitCount : List top 50 functions based on hit count
Top50FunctionSelfDuration : List top 50 functions based on time consumed directly by the function
AllLines : Show all lines processed by profiler trace
Events : Show raw trace-events returned from the profiler engine
TotalDuration : 00:00:00.3125971
StopwatchDuration : 00:00:00.3149503
Looks like you did not assign the output to a variable. Use Get-LatestTrace to retrieve the trace, e.g.: $trace = Get-LatestTrace
Progress: A: 00:00:00.4605239 (73 ms) -> A: 00:00:00.3440766 (-116 ms) -> A: 00:00:00.4875477 (143 ms) -> A: 00:00:00.4907421 (3 ms) -> A: 00:00:00.3125971 (-178 ms)
Exporting report into speedscope format. (2ms)
Exported for https://speedscope.app/, to: C:\temp\visual.speedscope.json
Done. Try $yourVariable.Top50SelfDuration to get the report. There are also Top50Duration, Top50HitCount, Top50FunctionSelfDuration, Top50FunctionDuration, Top50FunctionHitCount AllLines and Events.
This will output the results to c:\temp\visual.speedscope.json (It automatically appends speedscope.json to your filename). When opening the website https://speedscope.app/, select Browse and open the c:\temp\visual.speedscope.json file.
You can select items from the script by clicking on it, and in the bottom left, it will show you details:
Get-LatestTrace
As the cmdlet name suggests, Get-LatestTrace retrieves the last results if you didn’t assign the output to a variable.
Invoke-Script
As mentioned above, you must test it a few times to see the difference after making adjustments. You can do that using the Invoke-Script cmdlet. In the example below, I used the 365healthstatus.ps1 again, stored that in the $scriptblock variable, and let it run three times. Before running the test, you must run $flag = @{ _profiler = $true }.
This was the script using Where-Object :
Running in PowerShell 7.4.1 64-bit.
Flags for After runs:
_profiler = True
Run 1 - Before
Run 1 - Before finished after 00:00:00.4506141
Run 1 - After
Run 1 - After finished after 00:00:00.4454036
Run 2 - Before
Run 2 - Before finished after 00:00:00.4757822
Run 2 - After
Run 2 - After finished after 00:00:00.4184053
Run 3 - Before
Run 3 - Before finished after 00:00:00.3726470
Run 3 - After
Run 3 - After finished after 00:00:00.3688039
Done.
Run 0: 00:00:00.4506141 -> 00:00:00.4454036 (-5 ms)
Run 1: 00:00:00.4757822 -> 00:00:00.4184053 (-57 ms)
Run 2: 00:00:00.3726470 -> 00:00:00.3688039 (-4 ms)
This is the script after changing it to use the -Filter parameter:
Running in PowerShell 7.4.1 64-bit.
Flags for After runs:
_profiler = True
Run 1 - Before
Run 1 - Before finished after 00:00:00.2899766
Run 1 - After
Run 1 - After finished after 00:00:00.2267792
Run 2 - Before
Run 2 - Before finished after 00:00:00.2500021
Run 2 - After
Run 2 - After finished after 00:00:00.2276385
Run 3 - Before
Run 3 - Before finished after 00:00:00.2523482
Run 3 - After
Run 3 - After finished after 00:00:00.2279400
Done.
Run 0: 00:00:00.2899766 -> 00:00:00.2267792 (-63 ms)
Run 1: 00:00:00.2500021 -> 00:00:00.2276385 (-22 ms)
Run 2: 00:00:00.2523482 -> 00:00:00.2279400 (-24 ms)
Show-ScriptExecution
This cmdlet will show you the script’s contents and how long it took to run. In the examples below, I use the same 365healthstatus.ps1 script with Where-Object and with the -Filter parameter.
With where-object:
C:\Users\HarmVeenstra> Trace-Script -ScriptBlock {& C:\scripts\365healthstatus.ps1}
Running in PowerShell 7.4.1 64-bit.
Starting trace.
Stopwatch is high resolution, max resolution of timestamps is 100ns.
Run finished after 00:00:00.4621402.
Tracing done. Got 31 trace events.
Processing 31 trace events.
Figuring out flow. (0ms)
Sorting events into lines. (1ms)
Counting averages and percentages for lines. (4ms)
Sorting events into functions. (1ms)
Counting averages and percentages for functions. (1ms)
Getting Top50 lines with the longest Duration. (2ms)
Getting Top50 lines with the longest SelfDuration. (2ms)
Getting Top50 lines with the most hits. (1ms)
Getting Top50 functions with the longest Duration. (2ms)
Getting Top50 functions with the longest SelfDuration. (5ms)
Getting Top50 functions with the most hits. (1ms)
Top50Duration : List top 50 lines based on duration
Top50HitCount : List top 50 lines based on hit count
Top50SelfDuration : List top 50 lines based on time consumed directly by the line
Top50FunctionDuration : List top 50 functions based on duration
Top50FunctionHitCount : List top 50 functions based on hit count
Top50FunctionSelfDuration : List top 50 functions based on time consumed directly by the function
AllLines : Show all lines processed by profiler trace
Events : Show raw trace-events returned from the profiler engine
TotalDuration : 00:00:00.4605239
StopwatchDuration : 00:00:00.4621402
Looks like you did not assign the output to a variable. Use Get-LatestTrace to retrieve the trace, e.g.: $trace = Get-LatestTrace
Progress: A: 00:00:00.3721849 (-159 ms) -> A: 00:00:00.6295020 (257 ms) -> A: 00:00:00.4615247 (-168 ms) -> A: 00:00:00.3879327 (-74 ms) -> A: 00:00:00.4605239 (73 ms)
Done. Try $yourVariable.Top50SelfDuration to get the report. There are also Top50Duration, Top50HitCount, Top50FunctionSelfDuration, Top50FunctionDuration, Top50FunctionHitCount AllLines and Events.
C:\Users\HarmVeenstra> Show-ScriptExecution
$null = [Profiler.Tracer]::Patch($PSVersionTable.PSVersion.Major, $ExecutionContext, $host.UI, $tracer) (0ms, 0%)
$null = & $ScriptBlock (1.5ms, 0%)
{ (0ms, 0%)
& C:\scripts\365healthstatus.ps1 (4.7ms, 1%)
Connect-MgGraph -ClientId xxxxx-xxx-xxx-xxx-xxxxx-TenantId xxx-xxxx-xxx-xxxx-xxx -CertificateThumbprint xxxxx -ContextScope CurrentUser -Environment Global | Out-Null (30ms, 7%)
Import-Module Microsoft.Graph.Devices.ServiceAnnouncement -ErrorAction Stop (2.4ms, 1%)
@{
....
$issues=Get-MgServiceAnnouncementIssue | where-object isresolved -ne true | Select-Object StartDateTime, Id, ImpactDescription, Feature, Classification, Status | Sort-Object StartDateTime | Format-Table -Autosize (0.5ms, 0%)
With the -Filter parameter:
C:\Users\HarmVeenstra> Trace-Script -ScriptBlock {& C:\scripts\365healthstatus.ps1}
Running in PowerShell 7.4.1 64-bit.
Starting trace.
Stopwatch is high resolution, max resolution of timestamps is 100ns.
Run finished after 00:00:00.3458216.
Tracing done. Got 31 trace events.
Processing 31 trace events.
Figuring out flow. (0ms)
Sorting events into lines. (1ms)
Counting averages and percentages for lines. (1ms)
Sorting events into functions. (1ms)
Counting averages and percentages for functions. (1ms)
Getting Top50 lines with the longest Duration. (1ms)
Getting Top50 lines with the longest SelfDuration. (1ms)
Getting Top50 lines with the most hits. (1ms)
Getting Top50 functions with the longest Duration. (1ms)
Getting Top50 functions with the longest SelfDuration. (1ms)
Getting Top50 functions with the most hits. (1ms)
Top50Duration : List top 50 lines based on duration
Top50HitCount : List top 50 lines based on hit count
Top50SelfDuration : List top 50 lines based on time consumed directly by the line
Top50FunctionDuration : List top 50 functions based on duration
Top50FunctionHitCount : List top 50 functions based on hit count
Top50FunctionSelfDuration : List top 50 functions based on time consumed directly by the function
AllLines : Show all lines processed by profiler trace
Events : Show raw trace-events returned from the profiler engine
TotalDuration : 00:00:00.3440766
StopwatchDuration : 00:00:00.3458216
Looks like you did not assign the output to a variable. Use Get-LatestTrace to retrieve the trace, e.g.: $trace = Get-LatestTrace
Progress: A: 00:00:00.6295020 (257 ms) -> A: 00:00:00.4615247 (-168 ms) -> A: 00:00:00.3879327 (-74 ms) -> A: 00:00:00.4605239 (73 ms) -> A: 00:00:00.3440766 (-116 ms)
Done. Try $yourVariable.Top50SelfDuration to get the report. There are also Top50Duration, Top50HitCount, Top50FunctionSelfDuration, Top50FunctionDuration, Top50FunctionHitCount AllLines and Events.
C:\Users\HarmVeenstra> Show-ScriptExecution
$null = [Profiler.Tracer]::Patch($PSVersionTable.PSVersion.Major, $ExecutionContext, $host.UI, $tracer) (0.1ms, 0%)
$null = & $ScriptBlock (1.6ms, 0%)
{ (0ms, 0%)
& C:\scripts\365healthstatus.ps1 (6.4ms, 2%)
Connect-MgGraph -ClientId xxxxx-xxx-xxx-xxx-xxxxx-TenantId xxx-xxxx-xxx-xxxx-xxx -ContextScope CurrentUser -Environment Global | Out-Null (35ms, 10%)
Import-Module Microsoft.Graph.Devices.ServiceAnnouncement -ErrorAction Stop (2.3ms, 1%)
@{
.....
$issues=Get-MgServiceAnnouncementIssue -Filter 'isresolved ne true' | Select-Object StartDateTime, Id, ImpactDescription, Feature, Classification, Status | Sort-Object StartDateTime | Format-Table -Autosize (0.4ms, 0%)
And yes, you have to retest multiple times because sometimes, one thing is faster, and one thing is slower suddenly, and Invoke-Script can help you with that to get a good average.
Wrapping up
I haven’t played around with the Profiler module that much yet, but it already helped me optimize my PowerShell profile while writing this blog post 🙂 Check out the GitHub page for it, fiddle around a bit, and optimize your scripts!