Wednesday, May 19, 2010

Tracing .net WPF

Copy from http://blogs.msdn.com/mikehillberg/archive/2006/09/14/WpfTraceSources.aspx in case that will vanish

Trace sources in WPF

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:






















































type="System.Diagnostics.ConsoleTraceListener"

initializeData="false"/>




type="System.Diagnostics.XmlWriterTraceListener"

traceOutputOptions="None"

initializeData="AvTrace.xml" />




type="System.Diagnostics.TextWriterTraceListener"

initializeData="AvTrace.txt" />













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 tag and the 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", 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:











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

WPF & Silverlight binding trace & debug

A copy from http://bea.stollnitz.com/blog/?p=52 in case that this resource will vanish

Data Binding can be tricky to debug. In this post, I will share the techniques I use to debug WPF bindings, including the new debugging improvements we implemented in the latest 3.5 release. I will discuss the following four techniques:

* Scanning Visual Studio’s Output window for errors.
* Using Trace Sources for maximum control.
* Using the new property introduced in WPF 3.5 PresentationTraceSources.TraceLevel.
* Adding a breakpoint to a Converter.

The DataContext of this app is set to a new instance of Star, which is a class that contains two properties: Picture and Caption. Picture is of type BitmapImage and contains an image of the sun, which I included in the project. Caption is a string property that takes a while to be initialized (more details about this later).


Output Window

In the XAML of this application, I have an Image whose Source is data bound to an incorrect property name. This is a simple scenario that causes a Binding to fail.



Every time a Binding fails, the binding engine prints an informative message in the Output window of Visual Studio. In this case, I get the following message:

System.Windows.Data Error: 35 : BindingExpression path error: ‘PictureWrong’ property not found on ‘object’ ”Star’ (HashCode=49535530)’. BindingExpression:Path=PictureWrong; DataItem=’Star’ (HashCode=49535530); target element is ‘Image’ (Name=”); target property is ‘Source’ (type ‘ImageSource’)

This message should give you enough information to quickly figure out the mistake in the property name.

Advantage of this technique:

* It is very easy to look at the Output window, and in most cases it’s sufficient. It should be the first approach you consider when you have a problem with your bindings.

Disadvantage of this technique:

* Most real world applications print so much information to the Output window that it may be hard to find the error you’re looking for.


Trace Sources

The Trace Sources solution was already around in WPF 3.0. It adds a lot more flexibility to the previous solution by allowing you to control the level of detail you care about, where you want that messages to be printed and the WPF feature you want to debug.

The Trace Sources solution relies on a config file for the configuration of its behavior – the App.config file. Here is a portion of the contents of that file:



















type="System.Diagnostics.TextWriterTraceListener"
initializeData="DebugTrace.txt" />








In this file, I am specifying that:

* I want only messages generated in the Data subarea to be printed. If you’re trying to debug, for example, animations, you would instead add the area System.Windows.Media.Animation.
* I want as much information as possible about data binding. This was done by setting the switch to All. Other possible values are Off, Error, Warning. For a complete list, look up SourceLevels in .NET Reflector.
* I want the messages to be printed to an external file called DebugTrace.txt, instead of the Output Window. This file will be created in the bindebug folder for the application. If you run this application twice, the messages generated the second time will be appended to the existing messages in this file. If you don’t want this behavior, remember to delete the file before running the app.

Other pre-defined listeners allow printing to the Console (ConsoleTraceListener), or to an external file in XML format (XmlWriterTraceListener).

If you run the application with the settings above, you should find a DebugTrace.txt file in the bindebug directory. If you open it, you will see the data binding error we saw previously in the Output Window, plus four “Information” messages. These lower-priority messages are printed because I specified in the switch that I want all the information available about the bindings.

If you want to learn more about this topic, I recommend Mike Hillberg’s blog. He wrote the best article I’ve read about Trace Sources, which I use frequently as a reference.

Advantages of this technique:

* It separates the debug messages you care about from the rest of the information printed in the Output window.
* This solution may help you debug other areas in WPF, not just binding.
* You can get lower-priority messages (such as information or warnings) that are not typically printed to the Output window.

Disadvantages of this technique:

* The text file (or whatever form of output you choose) will contain debug messages about all the bindings in your application. Although this is not as much clutter as the Output window, it may still require some digging for you to find exactly the information you need.
* It won’t help you in scenarios where your Binding actually succeeds, but you still don’t see what you expect in the UI. The first and second techniques I show here only help in scenarios where the Binding fails.

Before you move on, make sure you correct the Path in the Image’s Source so that these errors won’t interfere with the ones I show next.


Trace Level – new in 3.5

In order to understand this feature, let’s start by uncommenting the first TextBlock in the XAML of this application:



This TextBlock attempts to bind to Caption, a property whose value is slow to be initialized. In this case, I am simulating a slow data source by adding a Dispatcher timer to the constructor, but in reality this delay could have many different causes. Notice also that I am *not* raising a property changed notification when Caption changes value.

public string Caption
{
private set
{
this.caption= value;
//OnPropertyChanged("Caption");
}
get
{
return caption;
}
}

public Star()
{
this.Picture = new BitmapImage(new Uri("Images\sun.jpg", UriKind.Relative));
this.Caption = String.Empty;
DispatcherTimer timer = new DispatcherTimer();
timer.Interval = new TimeSpan(0, 0, 3);
timer.Tick += new EventHandler(Timer_Tick);
timer.Start();
}

private void Timer_Tick(object sender, EventArgs e)
{
this.Caption = "Sun";
}

In this scenario, the Binding will succeed (it will bind to the initial value of empty string), but you don’t see what you expect to see in the UI. The unwanted behavior is caused by the fact that the events happen in an order different from what you expect: the Binding will be evaluated before Caption gets its real value. In this case, there are no errors in the Output window or DebugTrace.txt because the Binding succeeds.

You can use the new debugging feature in 3.5 to debug this scenario by adding the attached property PresentationTraceSources.TraceLevel to the Binding, which can be set to None, Low, Medium and High. Since PresentationTraceSource is not in the default namespace mappings for WPF, you will have to write the following XAML:

xmlns:diagnostics="clr-namespace:System.Diagnostics;assembly=WindowsBase"
/>



If you look at the Output window, you will notice that the binding engine generated debug information for every task that may help users find problems with this particular binding:

System.Windows.Data Warning: 47 : Created BindingExpression (hash=25209742) for Binding (hash=3888474)

System.Windows.Data Warning: 91 : BindingExpression (hash=25209742): GetValue at level 0 from Star (hash=31609076) using RuntimePropertyInfo(Caption): ‘ ‘
System.Windows.Data Warning: 71 : BindingExpression (hash=25209742): TransferValue – got raw value ‘ ‘
System.Windows.Data Warning: 78 : BindingExpression (hash=25209742): TransferValue – using final value ‘ ‘

In this case, we can scan the debug messages quickly to see that there were no errors, and look at the last few messages to understand that the value found at the Source was the empty string. This information will help you come to the conclusion that there is some timing issue with the scenario.

Advantages of this technique:

* This feature is particularly useful when you know exactly which binding you want to find out more about, which is the most common scenario.
* It allows you to know more about bindings that succeed, which many times helps you find the mistake in your logic.

Disadvantages of this technique:

* If you forget to remove the property after you found the problem, it adds to the clutter of the Output Window (which adds to the time it takes to start your application in debug mode).


Converter

The last solution is extremely simple: you can simply add a no-op Converter to your binding and put a breakpoint in its Convert method. This is what this solution looks like:



public class DebuggingConverter : IValueConverter
{
public object Convert(object value, Type targetType, object parameter, System.Globalization.CultureInfo culture)
{
return value; // Add the breakpoint here!!
}

public object ConvertBack(object value, Type targetType, object parameter, System.Globalization.CultureInfo culture)
{
throw new NotImplementedException("This method should never be called");
}
}

If you run this code and set a breakpoint inside the Convert method, you can simply hover over the “value” parameter to see what is being passed from the source to the target. In this case, you will see that “value” contains an empty string. This may help you realize that the source of your binding does not have the value you thought it had.

Advantages of this technique:

* It is really easy to implement. It relies on a concept that most data binding users are familiar with.
* It does not depend on the Output window.
* It helps you find out more about scenarios where the binding doesn’t fail.

Disadvantages to this technique:

* It doesn’t provide as much information as the TraceLevel technique.
* If the Binding fails early, the Converter may not be called.