How to debug UpdateControls.XAML?

Nov 9, 2011 at 6:09 PM

I am having some problems with my WPF UC app and I hope you could offer some debugging tips, or guess what's going wrong here, Micheal.

  • After running my program over the weekend, the program was so slow on Monday morning as to be unusable, taking about 5 seconds between UI updates. I tried to investigate by stopping the program repeatedly in the debugger, and it mostly stopped in UpdateControls.dll or UpdateControls.XAML.dll. It was hard to tell what Dependents were being updated, and I certainly saw no reason why UC sucked up so much time.
  • I have a ListView of key-value pairs, bound to a  whose attributes are updated every second. After a random amount of time has passed (typically less than 10 seconds), all rows of the ListView stop updating. For debugging purposes I introduced a Dependent<List<VM>> called _temp to build the row list, where VM is the row viewmodel (originally I used a plain-old property with no Dependent; the bug occurs either way). I confirmed that _temp.Uses property refers to a Dependent<DateTime> that changes every second, and _temp.UsedBy includes a single (unnamed) Dependent which must have come from UpdateControls.XAML.dll. (To ensure up-to-date information when viewing _temp.Uses and _temp.UsedBy, I put _temp.Value as the first watch in the watch window, which ensures that _temp._status is UP_TO_DATE.)
  • Curiously, investigating the problem in the debugger tends to make it disappear, i.e. when I set a breakpoint in the property that returns _temp.Value, it often (not always) keeps breaking on that line, and even after removing the breakpoint, the list keeps updating. But instead it's replaced by a different bug!!! You see, the ListView I have been talking about shows the attributes of a selected object. Let's call this object "A". So the attributes of "A" keep updating indefinitely (as they should) after stopping in the debugger a couple of times. However, if I now select a different object "B", A.Attributes continues to be called every second! Often B.Attributes also gets called every second, too. If I then remove the breakpoint and select a third object "C", A.Attributes and B.Attributes are called every second, and C.Attributes is called every second until the list randomly decides to stop updating, at which point only A.Attributes and B.Attributes are called every second.

    Apparently the Dependents created by UpdateControls.XAML are getting detached from the ListView, but keep updating. I restarted my program to investigate further and then the phenomenon stopped happening, although I made no code changes! Gah! Then I realized that to make the phenomenon happen, I had to expand _temp.UsedBy in the debugger. Somehow, this is what triggers the consistent updates AND detachment of the Dependent from the ListView.

It occurs to me that my woes with ListView may be related to garbage collection somehow. Maybe updates stopping at random = updates stopping at garbage collections. Expanding UsedBy (DependentVisualizer) causes the Dependents to be extracted in the debugger as strong references, and maybe the debugger holds onto those references for some reason, preventing garbage collection. Any thoughts?

Nov 10, 2011 at 2:13 PM

From your description of the performance bug, it sounds like you have one Dependent that is bound to a very large number of Precedents. It would appear that the list grows over time. You'll remember that we recently optimized that code, but it still uses a linked list to record the list of Precedents. It has to walk them linearly. When you break in the debugger, chances are you will be making that Dependent out-of-date, so that should help you locate which one it is.

I suspect that the second bug (where the attributes stop updating) is related to the recent WeakReference changes. The first time I tried to use WeakReference, I ran into something very similar. I backed out those changes. The second time, I applied some math to the problem. I also tested empirically for that specific scenario. I couldn't find any holes, but it looks like you might have uncovered one.

The third bug I think is caused by the debugger itself. Object A should stop updating, but the debugger keeps checking for the latest value. So UC thinks that it's still bound to something. I would love for Dependent to know when it was in the debugger rather than your own code. That way it could stop updating the Dependent when you watch the variable. If you find a way to detect this, please let me know.

If you can share a repro, we can work on this one together. I wouldn't mind if you added it to the UC project directly, like UpdateControls.XAML.Test. But if you would prefer to keep it out of the code base, then GitHub is a great way to share.

Nov 10, 2011 at 5:29 PM
Edited Nov 10, 2011 at 5:32 PM

Unfortunately, I don't know how to reproduce on a small scale. There is a ListBox of objects, which updates correctly, and when you select an object, its details are shown on a ListView, which stops updating. Could you describe how Dependents in the view "know" that they they need to be updated, or what causes them to stop updating? There must be a strong reference from a WPF binding (in XAML) to the Dependent, to ensure it is not GC'd, right? I have avoided looking at the code of UpdateControls.XAML because I hardly understand WPF in the first place. But maybe that will have to change. Plus, I wrote in my blog about why WPF sucks--I'm only using it due to a marketing-driven need for the app to look "cool". 

It seems possible that the O(N^2) nature of certain operations in UpdateControls might just explain the slow performance over time. My app remembers 24 hours of history about received objects, and I use random test data that occasionally deletes objects and creates new ones. IIRC there were over 32000 objects (over 0x4000 "Apples" and 0x4000 "Bananas", if you recall from my blog) in the Model, although most of them were old, dead objects; the test data ensures that only 1000 objects are live to show on the GUI at once. I'll do some profiling when I get a chance. It seems like I need some way to gather statistics about which precedents are sucking up all the CPU time too, and the profiler can't help (it finds hot call stacks, but cannot tell me which precedents are causing functions in UpdateControls*.dll to be so hot).

Nov 11, 2011 at 11:51 PM

I just did some profiling on my app after it became ultra-slow. A lot of time was being spent in Precedent.Delete and Precedent.RecordDependent (mostly Insert()), and a couple of things jumped out.

  • 30.4% of all CPU time was spent in Precedent.Delete, of which 25.6% (5/6 of that time) was spent in string.Format(). Er, what? This is because I was using a debug build of UC and the Debug.Assert line in that method calls string.Format "just in case" the assert fails. I'd suggest changing this to drastically improve debug build performance:
    /*-*/ Debug.Assert(count == 1, String.Format(
               "Expected 1 dependent, found {0}.", count));
    /*+*/ if (count != 1) Debug.Fail(String.Format(
               "Expected 1 dependent, found {0}.", count));
     Hopefully it will be optimized out of Release builds in either case.
  • 31.5% of all CPU time was spent in Precedent.RecordDependent, with 5.1% in Precedent.AddPrecedent() and 18% in Precedent.Insert(). Why is Insert() so expensive? Well, 12.3% is mysteriously attributed to mscorwks.dll and 4.8% to WeakReference's constructor. I'm not sure what mscorwks.dll is doing, but the cost of "new WeakReference" can be eliminated by only creating a single WeakReference for any given dependent, instead of creating one for every Precedent that is used by that Dependent (as I've suggested earlier).

Shall I make these changes?

Of course, such optimizations are still not enough. The biggest problem is the large fan-out of independents: around 30,000 objects (containing over 100,000 independents) are being scanned by a very small number of Dependents. 50 to 100 of those objects are updated every second; the key question is, how is it possible to avoid scanning the rest of the objects that are unmodified? But I still lack inspiration for a solution.

Nov 12, 2011 at 1:44 AM

Yes, please. While you have a good test case go ahead and optimize.

As much as I would prefer to favor a more sane number of dependencies, go ahead and try replacing the linked list with a dictionary and see what impact it has on memory and CPU consumption. I believe that you will find that memory usage spikes, and CPU usage decreases but is still bad. But if you find that it really makes a difference in the insane case, then we can measure the negative impact on the sane case. Maybe we can even do that adaptive algorithm that you recommended.

The solution that I expect you will eventually go to is to not use dependency tracking on that large data set. Dependency can always be inverted and managed manually. This data set is just beyond the size that UC was designed to accommodate. But please, see if you can stretch it.

Nov 15, 2011 at 4:17 PM
Edited Nov 15, 2011 at 6:27 PM

I am entirely convinced that I don't need to deactivate UC on the large data set -- I just need to figure out how to coax UC into managing it more efficiently. I think UC needs some kind of "map-reduce" system for these kinds of situations (i.e. large data set is projected onto a much smaller data set with incremental changes being made to the large data set -- large-to-large is also worth considering). I'll be thinking about it. Plus, I don't know how to write a "mixed-mode" program that uses UC in the ViewModel but not in the Model.

Sorry, I forgot to add a comment on my last checkin. I tried to click Cancel during the checkin but it was too late! I just checked in the two changes I mentioned, and fixed the test suite to match:

// Started at 336.
// Making Precedent a base class: 312.
// Removing Gain/LoseDependent events: 288.
// Making IsUpToDate no longer a precident: 248.
// Custom linked list implementation for dependents: 200.
// Custom linked list implementation for precedents: 160.
// Other optimizations: 144.
// Added WeakReferenceToSelf: 148.
Assert.AreEqual(148 + IndependentPlatformOffset, end - start);

It's curious that there is no mention in these comments about the (original) addition of WeakReferences; I thought the change to WRs was made after the memory optimizations, and of course WRs occupy some memory.

A Dictionary wouldn't help that much. It might speed up Precedent.Delete and Precedent.Contains, but now that String.Format is not called, the profiler tells me now that Delete() uses 6.9% and Contains() uses 7.1%. Dependent.AddPrecedent still takes 12% even though it is an O(1) operation (11% in mscorwks.dll, 1% in AddPrecedent itself). Similarly, Precedent.Insert() takes 12.3% with 10.9% in mscorwks.dll. So trying to optimize the low-level operations further will enjoy diminishing returns. (Besides, you'd need a special dictionary that supports WeakReference keys properly.)

Update: I just remembered that only Dependents tend to have large lists of Independents, while Independents (and other Precedents) tend to have short lists of Dependents. So it's no wonder that Precedent.Delete() and Precedent.Contains() aren't super costly. As for a Dependent's list of Precedents, only three operations are done on the list represented by Dependent._firstPrecedent: iterate over all items; add an item; clear the list. Thus, a linked list, List<T> and a dictionary would all be roughly the same speed.

I've noticed that my app has "bimodal" behavior. If it processes network messages in a timely fashion, then it is usable, if a bit sluggish. However, if the messages get backed up then the app becomes almost completely unresponsive. I think the problem is the priority of UC updates; perhaps UC updates give themselves higher priority than UI updates and user input. I'll look into that today.

Update: The code in UpdateControls.XAML/Wrapper is not documented. I think it would help me a lot to hear a description of how all of these classes work and fit together. Could you write something about UC.XAML internals? In particular, I would like to understand how list updating works in UC when a list's ItemsSource is set to a LINQ query wrapped by ForView.Wrap, as compared to a ObservableCollection.