Event Tracing in Windows Presentation Foundation

Introduction

When you try to understand the performance characteristics of a Windows Presentation Foundation (WPF) application, one useful feature to take advantage of is Event Tracing for Windows (ETW). By default, WPF emits an array of interesting events that can be used to track the execution of an application at the framework level.

This document will provide insight into some of WPF’s ETW events to help clarify what is happening inside an application and what can be done to achieve better performance.

What is Event Tracing for Windows?

Event Tracing for Windows (ETW) provides application programmers the ability to start and stop event tracing sessions, instrument an application to provide trace events, and consume trace events. Trace events contain an event header and provider-defined data that describes the current state of an application or operation. You can use the events to debug an application and perform capacity and performance analysis.

Visualizing Event Traces

Event traces contain large amounts of information and they are difficult to analyze effectively without the aid of good tools. The WPF team recommends two specific tools for viewing ETW data. The tools are XPerf (http://go.microsoft.com/fwlink/?LinkId=128544) and the WPF Performance Suite (http://go.microsoft.com/fwlink/?LinkId=128544).

Event Definitions

There are several ETW events that can potentially be emitted during the execution of a WPF application. This section lists the available event definitions.

Each event definition has a table that lists the GUID associated with that event, the event types that you can listen for (Info, Start, or End), as well as any additional event specific data contained in the event. For events with start and end variations, all additional event data is assumed to be available only for the start variation, unless explicitly stated. In a text based ETW log Info events will be displayed as the listed event name, Start events will have a ‘+’ suffix, and End events will have a ‘-‘ suffix.

Events that are particularly interesting are marked in the table of contents with an asterisk (*).

Dispatcher Events

WClientUIContextDispatch

Raised when processing a DispatcherOperation from the Dispatcher queue.

Use this event to watch for start and end events from DispatcherOperations that are posted to the queue. If the elapsed time for processing of DispatcherOperations is large, you should make sure that overly complex, high priority operations are not starving the Dispatcher queue.

GUID	2481a374-999f-4ad2-9f22-6b7c8e2a5db0
Priority [UInt32]	DispatcherPriority of the DispatcherOperation.
Operation [String]	Name of the DispatcherOperation.
Event Types	Start, End

WClientUIContextPost

Raised when a DispatcherOperation is successfully posted to the Dispatcher queue.

GUID	76287aef-f674-4061-a60a-76f95550efeb
Priority [UInt32]	DispatcherPriority of the DispatcherOperation.
Operation [String]	Name of the DispatcherOperation.
Event Types	Info

WClientUIContextAbort

Raised when a DispatcherOperation is aborted and removed from the Dispatcher queue.

GUID	39404da9-413f-4581-a0a1-4715168b5ad8
Priority [UInt32]	DispatcherPriority of the DispatcherOperation.
Operation [String]	Name of the DispatcherOperation.
Event Types	Info

WClientUIContextPromote

Raised when the priority of a queued DispatcherOperation is changed via Dispatcher.SetPriority method.

GUID	632d4e9e-b988-4b32-ab2a-b37aa34927ee
Priority [UInt32]	DispatcherPriority of the DispatcherOperation.
Operation [String]	Name of the DispatcherOperation.
Event Types	Info

WClientUIContextIdle

Raised if during processing the next DispatcherOperation from the Dispatcher queue, all queued operations are at or below the “idle” priorities.

GUID	c626ebef-0780-487f-81d7-38d3f0a6f05e
Event Types	Info

Layout Events

*WClientLayout

Raised at the start and end of a layout pass. In between WClientLayout begin and end events you can expect to see begin and end events first for WClientMeasure and next for WClientArrange. It is also possible to see multiple Measure and Arrange pairs within a single WClientLayout.

If the layout pass is taking a long time, the measure and/or arrange pass is the cause. Check to see whether measure and/or arrange can be further optimized. Also, keep in mind that scrolling within virtualized panels such as the VirtualizingStackPanel will be expensive in layout because of the frequent expansion of templates during the Measure pass. In ItemsControls, avoid repeated ItemTemplates that are overly complex, and avoid expensive Measure and Arrange code. Consider virtualizing ItemsControls with a large number of items to improve scrolling performance.

GUID	A3edb710-21fc-4f91-97f4-ac2b0df1c20f
Id [Int32]	Identifier of the Dispatcher performing the current layout pass.
Event Types	Start, End

*WClientMeasure

Raised at the start and end of a measure pass.

If the measure pass is taking a long time consider the following. Excessive use of templates, complex templates, or frequent changes to the visual tree will cause WPF to spend a lot of time in Measure. Avoid animating properties with FrameworkPropertyMetadata.AffectsMeasure set to true.

GUID	3005e67b-129c-4ced-bcaa-91d7d73b1544
Id [Int32]	Identifier of the Dispatcher performing the current layout pass.
Event Types	Start, End

*WClientArrange

Raised at the start and end of an arrange pass.

If the arrange pass is taking a long time, consider the following. Excessive use of templates, complex templates, or frequent changes to the visual tree will cause WPF to spend a lot of time in Measure. Avoid animating properties with FrameworkPropertyMetadata.AffectsArrage set to true.

GUID	4b0ef3d1-0cbb-4847-b98f-16408e7e83f3
Id [Int32]	Identifier of the Dispatcher performing the current layout pass.
Event Types	Start, End

Interop Events

WClientCreateVisual

Raised each time a new HwndTarget is created.

GUID	2dbecf62-51ea-493a-8dd0-4bee1ccbe8aa
Id [Int32]	Identifier of the Dispatcher performing the current layout pass.
HWND [Int64]	64-bit pointer to the HWND.
Event Types	Info

WClientInputMessage

Raised whenever an input windows message is handled on the keyboard, mouse, or stylus.

GUID	4ac79bac-7dfb-4402-a910-fdafe16f29b2
Id [Int32]	Identifier of the Dispatcher handling the input event.
HWND [Int64]	64-bit pointer to the HWND.
Msg [Int32]	ID of the message.
WParam [Int32]	WParam of the message.
LParam [Int32]	LParam of the message.
Event Types	Info

Rendering Events

*WClientRenderHandler

Raised before and after calls to the standard RenderMessageHandler callback, which handles construction of a render batch. This gets called in response to property changes with FrameworkPropertyMetadata.AffectsRender.

During the standard RenderMesageHandler callback, the TimeManager is incremented by one clock cycle to update animations. If the scene contains a large number of animations, the duration of the TimeManager’s tick will be large. After the TimeManager is incremented, CompositionTarget.Rendering is run if it has been hooked, followed by a walk of the visual tree to construct the render batch. A large time span between ticking of the TimeManager (WClientTimeManagerTick) and construction of the render batch (WClientMediaRender) indicates that CompositionTarget. Rendering is doing a lot of work. More than one tick can occur during this callback if new animations have been added in CompositionTarget.Rendering. CompositionTarget.Rendering is only called after the first tick.

GUID	7723d8b7-488b-4f80-b089-46a4c6aca1c4
Id [Int32]	Identifier of the Dispatcher handling the input event.
Event Types	Start, End

*WClientAnimRenderHandler

Raised before and after updating of the timing, animation, and construction of a render batch. This gets called in response to active animations or the CompositionTarget.Rendering event. Remarks for the WClientRenderHandler event also applies for this event.

GUID	521c1c8d-faaa-435b-ad8c-1d64442bfd70
Id [Int32]	Identifier of the Dispatcher handling the input event.
Event Types	Start, End

*WClientMediaRender

Raised at the start and end of construction of the render batch.

If you use legacy BitmapEffects or make complex changes to the visual tree, construction of the render batch will take longer.

GUID	6827e447-0e0e-4b5e-ae81-b79a00ec8349
Id [Int32]	Render ID of the current render pass.
QPCExpectedPresentTime [Int64]	Next estimated presentation time as a QPC count.
Event Types	Start, End

WClientPostRender

Raised each time the MediaContext.PostRender method is called. This occurs whenever WPF needs to force construction of a render batch right away. Changing a dependency property with ‘FrameworkPropertyMetadata.AffectsRender’ set to true will force the MediaContext.PostRender method to invoke the standard RenderMessageHandler callback as a DispatcherOperation at ‘Render’ priority. If the WClientPostRender event is followed by a long pause before the next RenderHandler event, this could indicate starvation of the Dispatcher queue at Render priority.

GUID	fb69cd45-c00d-4c23-9765-69c00344b2c5
Event Types	Info

Composition Events

WClientQPCFrequency

Raised when the MediaContext class’ static constructor is called. This event provides the frequency and current time of the high-resolution performance counter, if one exists.

GUID	30EE0097-084C-408b-9038-73BED0479873
QPCFrequency [Int64]	Frequency of the high-resolution performance counter.
QPCCurrentTime [Int64]	Current Time of the high-resolution performance counter.
Event Types	Info

WClientPrecomputeScene

Raised at the start and end of the pre-compute pass of the root visual.

The pre-compute pass computes bounds for the dirty part of the visual tree.

GUID	3331420f-7a3b-42b6-8dfe-aabf472801da
Id [Int32]	ID of the CompositionTarget pre-computing the scene.
Event Types	Start, End

WClientCompileScene

Raised at the start and end of the scene compile step where visual changes are prepared for the render thread.

If the compile step takes a long time, it is likely that a large number of updates are being made to the scene. Consider simplifying changes to the scene to minimize the number of updates being made.

GUID	af36fcb5-58e5-48d0-88d0-d8f4dcb56a12
Id [Int32]	ID of the CompositionTarget performing the scene compile.
Event Types	Start, End

*WClientUpdateRealizations

Raised at the start and end of updating realizations.

If the update realizations step takes a long time, check for the presence of legacy BitmapEffects. These are known to perform poorly and the WPF team discourages their use. If you are running on a version of WPF prior to the .NET Framework 3.5 SP1, excessive text updates, such as animation of text, will also cause a performance hit when updating realizations.

GUID	ab29585b-4794-4465-91e6-9df5861c88c5
ContextID [Int32]	ID of the MediaContext constructing the render batch.
ResponseID [Int32]	ID of the current render pass.
Event Types	Info

WClientUIResponse

Raised at the end of construction of a render batch.

GUID	ab29585b-4794-4465-91e6-9df5861c88c5
ContextID [Int32]	ID of the MediaContext constructing the render batch.
ResponseID [Int32]	ID of the current render pass.
Event Types	Info

WClientUICommitChannel

Raised each time the visual changes are sent to the render thread.

GUID	f9c0372e-60bd-46c9-bc64-94fe5fd31fe4
Id [Int32]	ID of the current render pass.
Event Types	Info

*WClientUceNotifyPresent

Raised each time the render thread updates the screen.

Since this event is raised each time WPF presents to the screen, the number of occurrences of this event per second can be used to compute the frame rate of an application. The MIL_PRESENTATION_RESULTS parameter is defined as follows:


internal enum MIL_PRESENTATION_RESULTS
{
    MIL_PRESENTATION_VSYNC,
    MIL_PRESENTATION_NOPRESENT,
    MIL_PRESENTATION_VSYNC_UNSUPPORTED,
    MIL_PRESENTATION_DWM,
    MIL_PRESENTATION_FORCE_DWORD = unchecked((int)0xffffffff)
};

GUID	24cd1476-e145-4e5a-8bfc-50c36bbdf9cc
QPCLastPresentationTime [Int64]	The last presentation time as a QPC count.
PresentationResults [Int64]	The MIL_PRESENTATION_RESULTS for this present.
Event Types	Info

WClientScheduleRender

Raised each time a new render pass is scheduled.

GUID	6d5aeaf3-a433-4daa-8b31-d8ae49cf6bd1
RenderDelay [Int32]	Delay before the next render in milliseconds.
Event Types	Info

XAML/BAML Parsing Events

WClientParseBaml

Raised at the start and end of Binary Application Markup Language (BAML) parsing. The time in this event includes time spent in WClientParseFefCrInst, WClientParseInstVisTree, WClientParseRdrCrInst, and WClientParseRdrCrInFType.

GUID	8a1e3af5-3a6d-4582-86d1-5901471ebbde
Event Types	Start, End

WClientParseXml

Raised at the start and end of XML parsing. Time here will include time spent in WClientParseFefCrInst, WClientParseInstVisTree, WClientParseRdrCrInst, and WClientParseRdrCrInFType.

GUID	bf86e5bf-3fb4-442f-a34a-b207a3b19c3b
Event Types	Start, End

WClientParseXmlInitialized

Raised after initialization of the XAML parser.

GUID	80484707-838b-4328-9f31-5ecbaf25a531
Event Types	Info

WClientParseFefCrInst

Raised at the start and end of application of a ControlTemplate to an element.

GUID	f7555161-6c1a-4a12-828d-8492a7699a49
Event Types	Start, End

WClientParseInstVisTree

Raised at the start and end of application of a ControlTemplate to an element from XAML. The ‘message’ field is only available in the ‘end’ variation of this event.

GUID	a8c3b9c0-562b-4509-becb-a08e481a7273
Message [String]	A message describing why the instance was created.
Event Types	Start, End

WClientParseRdrCrInst

Raised each time the BamlRecordReader creates a new instance of an object.

GUID	8ba8f51c-0775-4adf-9eed-b1654ca088f5
Event Types	Start, End

WClientParseRdrCrInFTyp

Raised each time the BamlRecordReader creates a new instance of an object from a Type. The ‘type’ field is only available in the ‘end’ variation of this event.

GUID	0da15d58-c3a7-40de-9113-72db0c4a9351
Type [String]	The name of the type being created.
Event Types	Start, End

Other Events

WClientAppCtor

Raised when the Application class is constructed.

See WClientAppRun.

GUID	f9f048c6-2011-4d0a-812a-23a4a4d801f5
Event Types	Info

WClientAppRun

Raised when the Application.Run method is called.

Since this event is raised in the Application.Run method, all prior events can be attributed to application startup time.

GUID	08a719d6-ea79-4abc-9799-38eded602133
Event Types	Info

*WClientTimeManagerTick

Raised each time the TimeManager ticks. The ‘ticktime’ field is only available in the ‘start’ variation of this event.

GUID	ea3b4b66-b25f-4e5d-8bd4-ec62bb44583e
TickTime [Int64]	Absolute time to which we are ticking in milliseconds.
Event Types	Start, End

WClientString

Raised for custom ‘string’ events. Some places where WPF raises these custom events are in the ContentPresenter.BuildVisualTree, DrawingContext.DrawText, ItemsContainerGenerator.SetStatus, ScrollContentPresenter.Measure/ArrangeOverride, ScrollViewer.MeasureOverride, Stack.Measure/ArrangeOverride, TextFormatterImpl.FormatLineInternal, and VirtualizingStackPanel.Measure/ArrangeOverride methods.

GUID	6b3c0258-9ddb-4579-8660-41c3ada25c34
Info [String]	A custom per-event string.
Event Types	Start, End, Info

WClientFontCache

Raised when the font cache overflows.

GUID	f3362106-b861-4980-9aac-b1ef0bab75aa
Event Types	Info