Profiler: Analysis

DebugTools provides a number of cmdlets to analyze the data collected in a profiler trace. These cmdlets break down into the following categories:

• Methods
• Frames
• Exceptions

By default, all analysis cmdlets will operate against the implicit profiler session if no session is specified. Sessions can be retrieved using the Get-DbgProfiler cmdlet

Get-DbgProfiler -Id 1001 | Get-DbgProfilerMethod

For more information on the implicit profiler session, please see Session Management.

Unfortunately, as some cmdlet names are long to describe what they do, it can be a bit confusing trying to remember and type out the exact name of a cmdlet. It is recommended to use PowerShell auto-completion when typing out some of the longer cmdlet names in DebugTools. i.e. you can simply do

Show-Db <tab>

to auto-complete Show-DbgProfilerStackTrace

Methods

Once a target process has been launched containing the DebugTools Profiler, regardless of whether or not you are actively recording frame transitions, all methods JITted will be reported back to the profiler controller process. All frames currently known to the profiler controller can be listed using the Get-DbgProfilerMethod

C:\> Get-DbgProfilerMethod

FunctionID     ModuleName                       TypeName                                           MethodName
----------     ----------                       --------                                           ----------
0x7FFCBEFADF60 System.Management.Automation.dll <GetDefaultAvailableModuleFiles>d__2               <>m__Finally2
0x7FFCBEE10530 System.Management.Automation.dll System.Management.Automation.PowerShell            CoreInvoke
...

The Get-DbgProfilerMethod provides a number of parameters that can be used to search for target methods. The simplest way to search using Get-DbgProfilerMethod is to specify a wildcard expression specifying part of the fully qualified method name (including namespace, type and method name).

C:\> Get-DbgProfilerMethod *childitem*

Get-DbgProfilerMethod provides a number of parameters for performing more specific types of filtering: you can filter based on the -ModuleName, -TypeName, -MethodName and even -Exclude certain name patterns that you're not interested in.

By default, Get-DbgProfiler will search all methods that have been invoked since the target process was started. To search only for methods that were invoked in the last trace, specify the -LastTrace parameter.

C:\> Get-DbgProfilerMethod -TypeName *child* -LastTrace

Searching for methods from the last trace can sometimes be a better idea than trying to search for frames, or even drawing a visual stack trace. Once you've identified some potential methods you may be interested, you can jump to cmdlets like Show-DbgProfilerStackTrace which can sometimes take some time to run depending on the number of captured frames that need to be filtered.

To view the parameters available on Get-DbgProfilerMethod do Get-Help Get-DbgProfilerMethod

Frames

When a trace is stopped, the data collected in that trace is cached on the profiler session. The root frames of this trace can be retrieved using the Get-DbgProfilerLastStackTrace cmdlet

C:\> Get-DbgProfilerLastStackTrace

ThreadId ThreadName                Parent Children
-------- ----------                ------ --------
19516    Pipeline Execution Thread        {System.Management.Automation.Runspaces.Pipeline...
...

The data contained returned from this cmdlet can then potentially be cached and then passed to other cmdlets that analyze frames. If no frame is specified to a frame analysis cmdlet, an analysis will automatically be performed starting from the root frame of each thread in the last recorded trace. Due to the amount of memory a trace can potentially consume, if you wish to hold onto the output of a previous trace for potentially comparing two traces, you should keep an eye on your process/system memory, as this data will not be garbage collected as long as you are holding a reference to it.

Frames can be searched for using the Get-DbgProfilerStackFrame cmdlet. The Get-DbgProfilerStackFrame cmdlet supports specifying a wide array of parameters for narrowing down its search results.

# List all frames whose fully qualified name includes "childitem"
C:\> Get-DbgProfilerStackFrame *childitem*

Display                                               MethodInfo
-------                                               ----------
GetChildItemCommand.get_Force                         Microsoft.PowerShell.Commands.GetChildItemCommand.get_Force
GetChildItemCommand.get_Include                       Microsoft.PowerShell.Commands.GetChildItemCommand.get_Include
GetChildItemCommand.get_Exclude                       Microsoft.PowerShell.Commands.GetChildItemCommand.get_Exclude
...

To get a more visual feel for a stack trace, the Show-DbgProfilerStackTrace can be used. Show-DbgProfilerStackTrace supports all of the same parameters that Get-DbgProfilerStackFrame supports.

For a full list of parameters supported by all cmdlets, do Get-Help <cmdlet> within PowerShell

Get-Help Show-DbgProfilerStackTrace

Unique

Cmdlets capable of filtering frames (including Get-DbgProfilerStackFrame, Watch-DbgProfilerStack Show-DbgProfilerStackTrace) allow specifying that only -Unique frames should be displayed. However, "uniqueness" can mean different things depending on your perspective.

To illustrate this, consider the following stack trace, with sequence numbers listed in brackets after each frame

first (1)
├─second (2)
│ └─third (3)
│   ├─second (4)
│   │ └─fourth (5)
│   └─second (6)
│     └─fourth (7)
└─second (8)

In this trace, the method second occurs in four different frames

• Twice, being called from first
• Twice, being called from third which itself called from a separate invocation of second

There are several different strategies that can potentially be used for determining "uniqueness" of a frame

Strategy	Pro	Con	Example
Include the first occurrence of a method executed globally	Exactly one occurrence of second will occur in the trace	Methods such as fourth which only occur on a subsequent, or inner invocation, will be lost	first(1) └─second(2)
Analyze the entire hierarchy a frame and all its children for determining uniqueness
Only compare frames at the same level under the same parent
Make child frames that would have been lost children of the first unique parent we are including	All frames are included in the output	Frames will be listed under a parent frame that isn't actually their parent

Currently, DebugTools uses Strategy 1, taking the first occurrence of a method executed globally. Depending on how DebugTools' filter cmdlets are invoked, different behavior can be exhibited.

There are two phases of analysis that occur when DebugTools attempts to filter a stack trace

• Frame Analysis
• Tree Reconstruction

When only the -Unique parameter is specified,

Show-DbgProfilerStackTrace -Unique

DebugTools skips the entire Frame Analysis stage entirely, and proceeds straight to the Tree Reconstruction Phase, where the first frame encountered that uses each method will be included in the new stack trace that is built.

If any additional parameters are specified, DebugTools will search for all frames that match the specified predicate, and then construct a new tree with all matched frames as leaf nodes.

Show-DbgProfilerStackTrace -Unique *childitem*

Wwhen determining uniqueness, the uniqueness engine will prefer the parents of any matches frames over standalone frames to ensure a given frame is not listed twice. For example, consider the following scenario filtering for unique methods that are like *movenext*

30600
└─System.Diagnostics.Tracing.EventListener.DisposeOnShutdown (1)
  ├─Enumerator.MoveNext (4)
  └─Enumerator.MoveNext (36)
    └─Enumerator.MoveNextRare (37)

Methods Enumerator.MoveNext and Enumerator.MoveNextRare are found to match the predicate. The first invocation of each is selected. But since a separate invocation of Enumerator.MoveNext calls Enumerator.MoveNextRare, we could inadvertently list Enumerator.MoveNext twice, which is not what we want! As such, DebugTools will analyze the parents of MoveNext (4) and MoveNextRare (37), see that MoveNext (36) will be included, and use that instead of MoveNext (4) giving us the final output of

30600
└─System.Diagnostics.Tracing.EventListener.DisposeOnShutdown (1)
  └─Enumerator.MoveNext (36)
    └─Enumerator.MoveNextRare (37)

If two unique methods B and C are each executed from a different invocation of function A however, function A will be listed twice in the output

# Even though -Unique methods were listed, A is listed twice due to B and C being called from
# separate invocation of A

1000
├─A
│ └─B
└─A
  └─C

Exceptions

A list of all exceptions captured in the last trace can be displayed via the Get-DbgProfilerException cmdlet

C:\> Get-DbgProfilerException

ThreadId Type                             Sequence Status ThrownFrame                    HandledFrame
-------- ----                             -------- ------ -----------                    ------------
3640     System.IO.FileNotFoundException  1        Caught ExecutionContext.LoadAssembly  ExecutionContext.LoadAssembly
...

Exceptions output can be limited to those that occurred on a specific -ThreadId or those that match a specific -Type

C:\> Get-DbgProfilerException *invalidoperation*