Trace sources in WPF

Article
09/14/2006

WPF (Avalon) uses the .Net tracing system to provide some diagnostics about what’s going on inside your WPF application. It’s not at all an exhaustive set of traces, and in fact it’s still pretty rudimentary. But frequently it’s enough to help out when you’re trying to debug a problem.

The short story is that WPF defines a set of TraceSource objects that you can configure and use, with all the normal .Net tracing functionality. The TraceSource names are shown below in a sample .Config file. In addition to the .config file, you need to set a flag in the registry. Or you can skip the .config file and/or registry flag, and do everything with the PresentationTraceSources class, either from code or from the Visual Studio Immediate window.

Now the longer story ...

.Net Tracing Background

First a quick background on .Net tracing … The .Net platform provides some classes to allow you to send trace messages, not only to the debug output window, but to a file, or anyone else that wants to listen. You can send traces using the static System.Diagnostics.Trace class in .Net 1.0, and in .Net 2.0 using TraceSource objects.

The basic model is to instrument your code with calls to Trace or TraceSource of interesting events. You (or the user of your program) can then add some entries to the application's .config file to enable those traces, filter them, and capture them (for example to a file).

For more background on tracing in general, the TraceSource documentation in the SDK provides a nice overview. Also, Mike Rousos has a multi-part overview on .Net tracing ... first a basic overview, and then more details here, here, and here.

Enabling WPF Tracing in a .Config File

In general, you configure .Net tracing by configuring the TraceSource objects. The easiest way to configure the traces is with a .config file for the application, or machine-wide (if you're an administrator) by adding entries to the machine.config file.

For WPF, however, you also need to get the trace sources enabled first. Otherwise we don’t even read the .config file to look for settings. The WPF traces can be enabled by setting a flag in registry, or by calling PresentationTraceSources.Refresh from code. I’ll talk more about PresentationTraceSources later in "Enabling and Configuring WPF Trace Sources Programmatically". To enable WPF tracing in the registry, create the key

"hkey_current_user\software\microsoft\tracing\wpf", add a "ManagedTracing" DWORD value, and set it to one.

Additionally, some WPF tracing is enabled automatically when you launch your app from within the debugger. Specifically, this is the case for databinding warnings and errors.

Once you've got the registry set for the WPF trace sources, you still won't get much tracing until you turn it on with the .Config file. The easiest way to explain the rest of this is to show a sample .config file:

<system.diagnostics>

<!--

</listeners>

</source>

-->

<!--

</listeners>

</source>

-->

<!--

</listeners>

</source>

-->

<!--

</listeners>

</source>

-->

<!--

</listeners>

</source>

-->

<!--

</listeners>

</source>

-->

<!--

</listeners>

</source>

-->

<!--

</listeners>

</source>

-->

<!--

</listeners>

</source>

-->

</sources>

</switches>

<add name="console"

type="System.Diagnostics.ConsoleTraceListener"

initializeData="false"/>

<add name="xmlListener"

type="System.Diagnostics.XmlWriterTraceListener"

traceOutputOptions="None"

initializeData="AvTrace.xml" />

<add name="textListener"

type="System.Diagnostics.TextWriterTraceListener"

initializeData="AvTrace.txt" />

</sharedListeners>

</system.diagnostics>

</configuration>

You can put this Xml into a .config file and use it as is. For example, to get tracing for XamlPad.exe, put this in a file named XamlPad.exe.config and put it in the same directory as XamlPad.exe. (If you’re on Windows Vista it might not like you putting a file in to XamlPad’s directory under Program Files, but you can just copy XamlPad.exe out to another directory first.) Note that this Xml includes the <configuration> tag and the <system.diagnostics> tag, etc. So if you're adding these settings to an existing .config file or to the machine.config file, and it already has those tags, just copy in the content without the tags.

Notice in this Xml that it lists all of the trace sources that WPF creates. Also note that everything is commented out. So you need to un-comment the trace sources that you want to be used. Once you've uncommented a section, you can configure all the settings available from the basic .Net tracing; WPF just uses that and doesn't do anything special.

By default, the above settings write output to a file named "avtrace.txt", in the same directory as the .config and .exe files. But you can choose other trace listeners, including custom trace listeners that you write. You can also filter traces away from listeners by writing custom filters and adding them to the .config file.

Examining the raw output

So let's try an example. Put the above Xml into a XamlPad.exe.config file, put it in the same directly as XamlPad.exe, and remove the comments around the System.Windows.RoutedEvent and System.Windows.NameScope sections. Run XamlPad with the following markup, click on the Button, then close XamlPad:

<Button Name="Button1">Clack</Button>

</Page>

Now look at the output in avtrace.txt, and the first thing you’ll notice is that there’s a lot of it. The basic format of the output is several fields with:

· The trace source name

· “Start” or “Stop”

· Trace ID (each different type of trace from a trace source has its own ID number)

· Brief description of the event

· A list of parameters for the event.

(As you look at the output, also remember that XamlPad is itself a WPF application, so most of the traces you see are from XamlPad, not your Page and Button.)

As I said earlier, this is all pretty rudimentary. But by building it on the standard .Net tracing system, you can create your own tools to process or filter it, or load it into Excel, create pivot tables, etc.

So here’s an interesting trace from the output, this shows a System.Windows.NameScope trace where the “Button1” name from your markup got registered for the Button:

System.Windows.NameScope Start: 1 : Name has been registered on INameScope; NameScope='System.Windows.NameScope'; NameScope.HashCode='42483779'; NameScope.Type='System.Windows.NameScope'; Name='Button1'; Object='System.Windows.Controls.Button'; Object.HashCode='46809697'; Object.Type='System.Windows.Controls.Button'

Notice the parameters there are defined by the trace. In the case of this trace, it shows the name, and the object getting named. If you write a custom trace filter, you can actually look at the instance of the button. For the standard trace listeners/filters, an object is simply written out by calling ToString, GetHashCode, and GetType. For example, the button was represented in the above trace with:

Object='System.Windows.Controls.Button'; Object.HashCode='46809697'; Object.Type='System.Windows.Controls.Button'

Most of the WPF traces include the relevant object, so a quick-and-dirty way to filter the output is to grep for that object’s hash code in the name registration. That will now show you most everything in the output related to that button, and for example filter out all the traces relating to XamlPad itself.

Now looking through this filtered output, you can more easily see traces such as the MouseEnter event when I first moved the mouse over the button:

System.Windows.RoutedEvent Start: 1 : Raise RoutedEvent; RoutedEvent='Mouse.MouseEnter'; RoutedEvent.HashCode='117163'; RoutedEvent.Type='System.Windows.RoutedEvent'; Element='System.Windows.Controls.Button: Clack'; Element.HashCode='46809697'; Element.Type='System.Windows.Controls.Button'; RoutedEventArgs='System.Windows.Input.MouseEventArgs'; RoutedEventArgs.HashCode='9490272'; RoutedEventArgs.Type='System.Windows.Input.MouseEventArgs'; Handled='False'

And you can see the button click event itself. Here’s the traces for the click event, as well as the MouseUp event that triggered it, along with the other events that are triggered from a MouseUp (the MouseUp and Click events are highlighted):

System.Windows.RoutedEvent Start: 1 : Raise RoutedEvent; RoutedEvent='Mouse.MouseUp'; RoutedEvent.HashCode='7092232'; RoutedEvent.Type='System.Windows.RoutedEvent'; Element='System.Windows.Controls.Button: Clack'; Element.HashCode='46809697'; Element.Type='System.Windows.Controls.Button'; RoutedEventArgs='System.Windows.Input.MouseButtonEventArgs'; RoutedEventArgs.HashCode='63830089'; RoutedEventArgs.Type='System.Windows.Input.MouseButtonEventArgs'; Handled='False'

System.Windows.RoutedEvent Start: 2 : Raise RoutedEvent; RoutedEvent='UIElement.MouseLeftButtonUp'; RoutedEvent.HashCode='37599894'; RoutedEvent.Type='System.Windows.RoutedEvent'; Element='System.Windows.Controls.Button: Clack'; Element.HashCode='46809697'; Element.Type='System.Windows.Controls.Button'; RoutedEventArgs='System.Windows.Input.MouseButtonEventArgs'; RoutedEventArgs.HashCode='63830089'; RoutedEventArgs.Type='System.Windows.Input.MouseButtonEventArgs'; Handled='False'

System.Windows.RoutedEvent Start: 1 : Raise RoutedEvent; RoutedEvent='Mouse.LostMouseCapture'; RoutedEvent.HashCode='2854726'; RoutedEvent.Type='System.Windows.RoutedEvent'; Element='System.Windows.Controls.Button: Clack'; Element.HashCode='46809697'; Element.Type='System.Windows.Controls.Button'; RoutedEventArgs='System.Windows.Input.MouseEventArgs'; RoutedEventArgs.HashCode='25692540'; RoutedEventArgs.Type='System.Windows.Input.MouseEventArgs'; Handled='False'

System.Windows.RoutedEvent Stop: 1 : Raise RoutedEvent; RoutedEvent='Mouse.LostMouseCapture'; RoutedEvent.HashCode='2854726'; RoutedEvent.Type='System.Windows.RoutedEvent'; Element='System.Windows.Controls.Button: Clack'; Element.HashCode='46809697'; Element.Type='System.Windows.Controls.Button'; RoutedEventArgs='System.Windows.Input.MouseEventArgs'; RoutedEventArgs.HashCode='25692540'; RoutedEventArgs.Type='System.Windows.Input.MouseEventArgs'; Handled='False'

System.Windows.RoutedEvent Start: 1 : Raise RoutedEvent; RoutedEvent='ButtonBase.Click'; RoutedEvent.HashCode='42526340'; RoutedEvent.Type='System.Windows.RoutedEvent'; Element='System.Windows.Controls.Button: Clack'; Element.HashCode='46809697'; Element.Type='System.Windows.Controls.Button'; RoutedEventArgs='System.Windows.RoutedEventArgs'; RoutedEventArgs.HashCode='47192740'; RoutedEventArgs.Type='System.Windows.RoutedEventArgs'; Handled='False'

System.Windows.RoutedEvent Stop: 1 : Raise RoutedEvent; RoutedEvent='ButtonBase.Click'; RoutedEvent.HashCode='42526340'; RoutedEvent.Type='System.Windows.RoutedEvent'; Element='System.Windows.Controls.Button: Clack'; Element.HashCode='46809697'; Element.Type='System.Windows.Controls.Button'; RoutedEventArgs='System.Windows.RoutedEventArgs'; RoutedEventArgs.HashCode='47192740'; RoutedEventArgs.Type='System.Windows.RoutedEventArgs'; Handled='False'

System.Windows.RoutedEvent Stop: 2 : Raise RoutedEvent; RoutedEvent='Mouse.MouseUp'; RoutedEvent.HashCode='7092232'; RoutedEvent.Type='System.Windows.RoutedEvent'; Element='System.Windows.Controls.Button: Clack'; Element.HashCode='46809697'; Element.Type='System.Windows.Controls.Button'; RoutedEventArgs='System.Windows.Input.MouseButtonEventArgs'; RoutedEventArgs.HashCode='63830089'; RoutedEventArgs.Type='System.Windows.Input.MouseButtonEventArgs'; Handled='True'

WPF Trace Sources

As you can see from the sample config file above, there are several trace sources created by WPF. They’re all named after the type or namespace that implements them. Here’s a description of all the sources:

· System.Windows.Data
This is probably the most useful trace source, and provides all kinds of information about WPF databinding, including warnings when it wasn’t possible to resolve a binding. This trace source does one thing that the other WPF trace sources do not, it enables itself automatically when you start your app in the debugger.

· System.Windows.DependencyProperty
This is probably the least useful trace source, and just provides information about registration of DPs. Unfortunately it doesn’t provide information such as property values being set and calculated.

· System.Windows.Freezable
This provides tracing about Freezable problems that don’t cause an exception. For example, if you call the CanFreeze method on a Freezable and it returns false, this tracing might be able to help you determine what exactly couldn’t be frozen.

· System.Windows.RoutedEvent
Provides tracing information on the routing of RoutedEvents, including a trace indicating what event listener handled the event.

· System.Windows.Media.Animation
Sends traces when storyboards are started, stopped, paused, resumed, etc.

· System.Windows.NameScope
Sends a trace when a name is registered, providing the name and the object.

· System.Windows.ResourceDictionary
Sends traces when a resource is set, removed, looked up, etc. Since there could be multiple resource dictionaries that define the same resource, this can be a useful way to determine where the resource is actually coming from.

· System.Windows.Markup
This sends traces when Xaml (or Baml) is loaded, with information such as the objects being created, the properties being set, and the type converters being used.

· System.Windows.Documents
Traces information about page formatting errors for paginated documents.

Enabling and Configuring WPF Trace Sources Programmatically

Instead of, or in addition to, the .config file, you can configure the WPF traces from code in your app. The PresentationTraceSources class holds all of the TraceSource objects described above. As a result, you can simply configure the sources with the TraceSource API.

Of special note is the PresentationTraceSources.Refresh method. One thing that this does is call Trace.Refresh, which causes all TraceSource objects in the application (including WPF’s) to re-read the .Config file. But in addition this causes the WPF traces to be enabled first, as if the registry flag described earlier had been set. That is, calling Refresh is a way to turn on WPF debugging without actually modifying the registry.

And you can equivalently call the Refresh method from the Immediate window in Visual Studio for any app; you don’t have to actually call it from code in the app. If you have a .config file, it will be read and trace sources will be configured appropriately. If you don’t have a .config file set, you can still set up the trace sources manually in the Immediate window. For example, running these commands enables the WPF trace sources, and sets up for all RoutedEvent traces to go to the debug output window:

PresentationTraceSources.Refresh()

PresentationTraceSources.RoutedEventSource.Listeners.Add(new DefaultTraceListener() )

PresentationTraceSources.RoutedEventSource.Switch.Level = SourceLevels.All

Trace Switch Levels

As described in the .Net tracing documentation, a TraceSource has a Switch property that can be used to indicate what level of traces should be sent by the source. These switch levels can be set in the .config file, or programmatically via the PresentationTraceSources.

The interesting levels for WPF traces are Warning, ActivityTracing, and All. Not all of the trace sources in WPF provide warnings, but the Freezable and ResourceDictionary provide a few, and Data provides a lot of useful Warning traces as well as Error traces. The ActivityTracing level tends to get a lot more verbose, and of course the simplest thing to do is use All.

The WPF trace sources do one additional thing on top of what TraceSource does automatically. If you’re running under the debugger, and the trace source is enabled in the .config file but set with a level of “Off”. The side-effect of this is that if you set the level to “Off” in the .config file, it will still get promoted to “Warning”, and you’ll see all Warning/Error/Critical traces. To work around this, rather than setting the level to “Off”, set it to “Critical”, as none of the WPF traces are at this high level. If you enable WPF traces by calling PresentationTraceSources.Refresh() from code or from the Immediate Window in Visual Studio, this promotion doesn’t occur.

That’s It

That’s all the gory details … TraceSource objects for WPF features, you can configure them with a .Config file (the big gray block of Xml back at the beginning), you need to enable them with a registry setting, and/or you can configure and enable them with the PresentationTraceSources class, and sometimes a level of “Off” gets promoted to “Warning”.

Finally, for the registry setting, you can do it from the command prompt by putting the following into a file and running it with regini:

hkey_current_user\software\microsoft\tracing\wpf

ManagedTracing = REG_DWORD 1

Trace sources in WPF

Additional resources