Skip to content

Commit

Permalink
Add tools for PowerShell perf analysis (PowerShell#7595)
Browse files Browse the repository at this point in the history
  • Loading branch information
lzybkr authored and TravisEz13 committed Aug 31, 2018
1 parent 087de5b commit eae6d50
Show file tree
Hide file tree
Showing 9 changed files with 1,040 additions and 0 deletions.
17 changes: 17 additions & 0 deletions .spelling
Original file line number Diff line number Diff line change
Expand Up @@ -1096,3 +1096,20 @@ interactivetesting
allowprerelease
prereleases
url
- tools/performance/README.md
analyze
wpa
wpaProfile
PerfView
etl
perfview
wpr
wprui.exe
perfview.exe
GC.Regions.xml
JIT.Regions.xml
PowerShell.Regions.xml
PowerShell.stacktags
PowerShell.wpaProfile
PowerShell.wprp
Invoke-PerfviewPS
106 changes: 106 additions & 0 deletions tools/performance/GC.Regions.xml
Original file line number Diff line number Diff line change
@@ -0,0 +1,106 @@
<?xml version='1.0' encoding='utf-8' standalone='yes'?>
<!-- See definitions in C:\Windows\Microsoft.NET\Framework\v4.0.30319\CLR-ETW.man for .NET events -->
<!--
Unlike JIT GC is largely single threaded and the times correlate very well with PerfView where we can drill down into each GC
generation in the region graph in WPA.
We use bascially the GC Start/Stop events where the GC Start event has also the generation traced which enables us to create
regions for each GC type.
GC suspensions work a bit different were I use the GCSuspendEE_V1 as start and GCRestartEEEnd as end event. This allows us
to capture in principle also the time where the suspension or resumption itself takes an abnormally long time whic would indicate
a GC bug or a thread priority problem.
-->
<InstrumentationManifest>
<Instrumentation>
<Regions>
<RegionRoot Guid="{d8d639a0-cf4c-45fb-976a-0000DEADBEEF}" Name="GC" FriendlyName="GC Activity">
<Region Guid="{d8d639a1-cf4c-45fb-976a-100000000101}" Name="Gen 0" FriendlyName="GCs">
<Region Guid="{d8d639a1-cf4c-45fb-976a-000000000001}" Name="Gen 0" FriendlyName="Gen 0">
<Start>
<Event Provider="{e13c0d23-ccbc-4e12-931b-d9cc2eee27e4}" Id="1" Version="1"/>
<PayloadIdentifier FieldName="Depth" FieldValue="0"/>
<!-- Depth is the Generation number -->
</Start>
<Start>
<Event Provider="{e13c0d23-ccbc-4e12-931b-d9cc2eee27e4}" Id="1" Version="2"/>
<!-- .NET 4.6 has a new GC Start event -->
<PayloadIdentifier FieldName="Depth" FieldValue="0"/>
</Start>

<Stop>
<Event Provider="{e13c0d23-ccbc-4e12-931b-d9cc2eee27e4}" Id="2" Version="1"/>
</Stop>
<Match>
<Event PID="true"/>
</Match>
<Naming>
<PayloadBased NameField="Depth"/>
</Naming>
</Region>
</Region>

<Region Guid="{d8d639a1-cf4c-45fb-976b-100000000101}" Name="Gen 1" FriendlyName="GCs">
<Region Guid="{d8d639a1-cf4c-45fb-976a-000000000005}" Name="Gen 1" FriendlyName="Gen 1">
<Start>
<Event Provider="{e13c0d23-ccbc-4e12-931b-d9cc2eee27e4}" Id="1" Version="1"/>
<PayloadIdentifier FieldName="Depth" FieldValue="1"/>
</Start>
<Start>
<Event Provider="{e13c0d23-ccbc-4e12-931b-d9cc2eee27e4}" Id="1" Version="2"/>
<!-- .NET 4.6 has a new GC Start event -->
<PayloadIdentifier FieldName="Depth" FieldValue="1"/>
</Start>

<Stop>
<Event Provider="{e13c0d23-ccbc-4e12-931b-d9cc2eee27e4}" Id="2" Version="1"/>
</Stop>
<Match>
<Event PID="true"/>
</Match>
<Naming>
<PayloadBased NameField="Depth"/>
</Naming>
</Region>
</Region>

<Region Guid="{d8d639a1-cf4c-45fb-976c-100000000101}" Name="Gen 2" FriendlyName="GCs">
<Region Guid="{d8d639a1-cf4c-45fb-976a-000000000006}" Name="Gen 2" FriendlyName="Gen 2">
<Start>
<Event Provider="{e13c0d23-ccbc-4e12-931b-d9cc2eee27e4}" Id="1" Version="1"/>
<PayloadIdentifier FieldName="Depth" FieldValue="2"/>
</Start>
<Start>
<Event Provider="{e13c0d23-ccbc-4e12-931b-d9cc2eee27e4}" Id="1" Version="2"/>
<!-- .NET 4.6 has a new GC Start event -->
<PayloadIdentifier FieldName="Depth" FieldValue="2"/>
</Start>

<Stop>
<Event Provider="{e13c0d23-ccbc-4e12-931b-d9cc2eee27e4}" Id="2" Version="1"/>
</Stop>
<Match>
<Event PID="true"/>
</Match>
<Naming>
<PayloadBased NameField="Depth"/>
</Naming>
</Region>
</Region>

<Region Guid="{d8d639a2-cf4c-45fb-976a-000000000003}" Name="GCSuspends" FriendlyName="GC Suspensions">
<Region Guid="{d8d639a2-cf4c-45fb-976a-000000000002}" Name="GCSuspend" FriendlyName="GC Suspension">
<Start>
<Event Provider="{e13c0d23-ccbc-4e12-931b-d9cc2eee27e4}" Id="9" Version="1"/>
</Start>
<Stop>
<Event Provider="{e13c0d23-ccbc-4e12-931b-d9cc2eee27e4}" Id="3" Version="1"/>
</Stop>
<Match>
<Event PID="true"/>
</Match>
</Region>
</Region>

</RegionRoot>
</Regions>
</Instrumentation>
</InstrumentationManifest>
55 changes: 55 additions & 0 deletions tools/performance/Invoke-PerfviewPS.ps1
Original file line number Diff line number Diff line change
@@ -0,0 +1,55 @@
#requires -RunAsAdministrator

param(
$ETLFileName = '.\PerfViewData.etl',

[Parameter(Mandatory)]
[scriptblock]
$ScriptBlock,

$LogFileName = '.\perfview.log',

$PowerShellPath = $(Get-Command pwsh.exe).Source)

$EncodedScriptBlock = [System.Convert]::ToBase64String([System.Text.Encoding]::UNICODE.GetBytes($ScriptBlock.ToString()))
$perfViewArgs = @(
'/AcceptEula'
'/ThreadTime'
"/LogFile=$LogFileName"
"/DataFile:$ETLFileName"
'/noRundown'
'/Merge'
'/Zip:False'
# GCSampledObjectAllocationHigh is sometimes useful, but quite expensive so not included by default
# '/ClrEvents=default+GCSampledObjectAllocationHigh'
'/Providers:*Microsoft-PowerShell-Runspaces,*Microsoft-PowerShell-CommandDiscovery,*Microsoft-PowerShell-Parser,*Microsoft.Windows.PowerShell'
'run'
"""$PowerShellPath"""
'-NoProfile'
'-EncodedCommand'
$EncodedScriptBlock
)

$process = Start-Process -FilePath (Get-Command PerfView.exe).Source -ArgumentList $perfViewArgs -PassThru

$rs = [runspacefactory]::CreateRunspace($host)
$rs.Open()
$ps = [powershell]::Create()
$ps.Runspace = $rs

$null = $ps.AddCommand("Get-Content").
AddArgument($LogFileName).
AddParameter("Wait").
AddParameter("Tail", 0)
$null = $ps.AddCommand("Out-Host")

# If log file doesn't exist yet, wait a little bit so Get-Content doesn't fail
while (!(Test-Path $LogFileName))
{
Start-Sleep -Seconds 1
}

$null = $ps.BeginInvoke()
$process.WaitForExit()
$ps.Stop()

34 changes: 34 additions & 0 deletions tools/performance/JIT.Regions.xml
Original file line number Diff line number Diff line change
@@ -0,0 +1,34 @@
<?xml version='1.0' encoding='utf-8' standalone='yes'?>
<!-- See definitions in C:\Windows\Microsoft.NET\Framework\v4.0.30319\CLR-ETW.man for .NET events -->
<!-- Created by Alois Kraus. Free for public use.
The JIT time is determined by the MethodJitStart event and the directly on this thread following MethodLoadUnload event which signals when the JIT compilation for this
method is complete.
Unfortunately the Region sums as it is currently in WPA it will sum not the JIT times of all threads but if e.g. 2 threads JIT for one second each then the WPA sum accross all threads will be only 1s.
WPA seems to sum on a timeline only the active time accross all threads and uses this as sum which is not a good measure to compare results. This should be changed although this logic might
be well suited for regions where each region signals a bottleneck on which others have to wait e.g. during boot.
-->
<InstrumentationManifest>
<Instrumentation>
<Regions>
<RegionRoot Guid="{d8d639a0-1f4c-45fb-976a-0000DEADBEEF}" Name="JIT" FriendlyName="JIT Activity">
<Region Guid="{d8d639a1-2f4c-45fb-976a-100000000101}" Name="JITs" FriendlyName="JITs">
<Region Guid="{d8d639a1-3f4c-45fb-976a-000000000001}" Name="Method" FriendlyName="Method">
<Start>
<Event Provider="{e13c0d23-ccbc-4e12-931b-d9cc2eee27e4}" Id="145" Version="1"/> <!-- MethodJittingStarted_V1 -->
</Start>
<Stop>
<Event Provider="{e13c0d23-ccbc-4e12-931b-d9cc2eee27e4}" Id="143" Version="1"/> <!-- MethodLoadUnloadVerbose_V1 -->
</Stop>
<Match>
<Event TID="true"/>
</Match>
<Naming>
<PayloadBased NameField="MethodNamespace" />
</Naming>
</Region>
</Region>
</RegionRoot>
</Regions>
</Instrumentation>
</InstrumentationManifest>

Loading

0 comments on commit eae6d50

Please sign in to comment.