Tracing WPF in Visual Studio 2010

Pete Brown - 09 March 2010

Yesterday I blogged about using the special "Item[]" property name in the PropertyChanged event for a custom ObservableDictionary class.

What I didn't know was whether or not the Item[] property name was effectively a change notification for every single binding target, or just the current one. I suspected it did it for every binding (I even tried specifying a key inside the brackets, but the string truly is just a magic string). While I was curious about it, I didn't have time to test it at the time. Trust my friend and former coworker Tom McKearney to call me out on it :)

So I thought for a bit about how I'd debug this problem. It turns out the easiest way is something new in Visual Studio 2010: the new Trace Information settings. I found this only after monkeying around for a bit with the older style WPF trace settings, and not finding any that would work in VS2010. I'm actually happy that happened, as I would have not thought to check out the new debugging settings in VS2010 otherwise.

Configuring Trace

Under Tools > Options, select Debugging and then the Output Window. You'll get a dialog that has settings for standard trace and a separate group for WPF tracing. By default, Data Binding is set to show errors. I changed it to All just for the duration of this session.

Viewing the Trace Information

Once I did that, and ran my little test, the output window was filled with useful debugging information. I cleared out the window, changed the value of one field and tabbed off. What came through was this:

System.Windows.Data Warning: 93 : BindingExpression (hash=14185124): Got LostFocus event from TextBox (hash=58400548)
System.Windows.Data Warning: 88 : BindingExpression (hash=14185124): Update - got raw value '105'
System.Windows.Data Warning: 91 : BindingExpression (hash=14185124): Update - implicit converter produced '105'
System.Windows.Data Warning: 92 : BindingExpression (hash=14185124): Update - using final value '105'
System.Windows.Data Warning: 100 : BindingExpression (hash=14185124): SetValue at level 0 to ObservableDictionary`2 (hash=57274684 Count=3) using RuntimePropertyInfo(Item): '105'
System.Windows.Data Warning: 93 : BindingExpression (hash=14185124): Got PropertyChanged event from ObservableDictionary`2 (hash=57274684 Count=3)
System.Windows.Data Warning: 93 : BindingExpression (hash=58939632): Got PropertyChanged event from ObservableDictionary`2 (hash=57274684 Count=3)
System.Windows.Data Warning: 99 : BindingExpression (hash=58939632): GetValue at level 0 from ObservableDictionary`2 (hash=57274684 Count=3) using RuntimePropertyInfo(Item): 'Pete Brown'
System.Windows.Data Warning: 78 : BindingExpression (hash=58939632): TransferValue - got raw value 'Pete Brown'
System.Windows.Data Warning: 82 : BindingExpression (hash=58939632): TransferValue - implicit converter produced 'Pete Brown'
System.Windows.Data Warning: 87 : BindingExpression (hash=58939632): TransferValue - using final value 'Pete Brown'
System.Windows.Data Warning: 93 : BindingExpression (hash=29677729): Got PropertyChanged event from ObservableDictionary`2 (hash=57274684 Count=3)
System.Windows.Data Warning: 99 : BindingExpression (hash=29677729): GetValue at level 0 from ObservableDictionary`2 (hash=57274684 Count=3) using RuntimePropertyInfo(Item): DateTime (hash=1726221417)
System.Windows.Data Warning: 78 : BindingExpression (hash=29677729): TransferValue - got raw value DateTime (hash=1726221417)
System.Windows.Data Warning: 82 : BindingExpression (hash=29677729): TransferValue - implicit converter produced 'Monday, March 08, 2010'
System.Windows.Data Warning: 87 : BindingExpression (hash=29677729): TransferValue - using final value 'Monday, March 08, 2010'
System.Windows.Data Warning: 93 : BindingExpression (hash=30116333): Got PropertyChanged event from ObservableDictionary`2 (hash=57274684 Count=3)
System.Windows.Data Warning: 99 : BindingExpression (hash=30116333): GetValue at level 0 from ObservableDictionary`2 (hash=57274684 Count=3) using RuntimePropertyInfo(Item): '105'
System.Windows.Data Warning: 78 : BindingExpression (hash=30116333): TransferValue - got raw value '105'
System.Windows.Data Warning: 82 : BindingExpression (hash=30116333): TransferValue - implicit converter produced '105'
System.Windows.Data Warning: 87 : BindingExpression (hash=30116333): TransferValue - using final value '105'
System.Windows.Data Warning: 93 : BindingExpression (hash=1032856): Got PropertyChanged event from ObservableDictionary`2 (hash=57274684 Count=3)
System.Windows.Data Warning: 99 : BindingExpression (hash=1032856): GetValue at level 0 from ObservableDictionary`2 (hash=57274684 Count=3) using RuntimePropertyInfo(Item): 'Pete Brown'
System.Windows.Data Warning: 78 : BindingExpression (hash=1032856): TransferValue - got raw value 'Pete Brown'
System.Windows.Data Warning: 82 : BindingExpression (hash=1032856): TransferValue - implicit converter produced 'Pete Brown'
System.Windows.Data Warning: 87 : BindingExpression (hash=1032856): TransferValue - using final value 'Pete Brown'
System.Windows.Data Warning: 93 : BindingExpression (hash=32429809): Got PropertyChanged event from ObservableDictionary`2 (hash=57274684 Count=3)
System.Windows.Data Warning: 99 : BindingExpression (hash=32429809): GetValue at level 0 from ObservableDictionary`2 (hash=57274684 Count=3) using RuntimePropertyInfo(Item): DateTime (hash=1726221417)
System.Windows.Data Warning: 78 : BindingExpression (hash=32429809): TransferValue - got raw value DateTime (hash=1726221417)
System.Windows.Data Warning: 82 : BindingExpression (hash=32429809): TransferValue - implicit converter produced '3/8/2010 12:00:00 AM'
System.Windows.Data Warning: 87 : BindingExpression (hash=32429809): TransferValue - using final value '3/8/2010 12:00:00 AM'
System.Windows.Data Warning: 99 : BindingExpression (hash=14185124): GetValue at level 0 from ObservableDictionary`2 (hash=57274684 Count=3) using RuntimePropertyInfo(Item): '105'
System.Windows.Data Warning: 78 : BindingExpression (hash=14185124): TransferValue - got raw value '105'
System.Windows.Data Warning: 82 : BindingExpression (hash=14185124): TransferValue - implicit converter produced '105'
System.Windows.Data Warning: 87 : BindingExpression (hash=14185124): TransferValue - using final value '105'

Conclusion: Yes Everything is Re-Evaluated

Yes, that confirms that binding is re-evaluating every field bound to the ObservableDictionary. On a small form, that's not a big deal, but if you have lots of fields or complex value converters, that could be a problem. It looks like there are duplicate bindings in there, but remember the form has textboxes and then textblocks both bound to the same values.