Continuing on from my first play with the Rx framework yesterday, I thought it would be good to come up with a real world example. I thought about rss feeds and stock tickers, but in the end decided on an app with consumes the Twitter REST API.

I will build up an application which can subscribe to a couple of twitter news feeds, polling for new messages on a particular schedule, and merging the results into a single output stream to which we subscribe.

Accessing the Twitter API

I am going to keep this very simple, just access the user_timeline service for a given user, and get the results in XML format, which make it easy for us to project into a Tweet class which we define. I create a class called TwitterAccess with one key static method:

public static Tweet[] GetNewTweets(string username, long lastTweetId)
{
    if(lastTweetId < 1)
        throw new ArgumentOutOfRangeException("lastTweetId", "id must be greater than 0");

    string url = String.Format("http://twitter.com/statuses/user_timeline/{0}.xml?since_id={1}",
                               username.Replace("@", ""), lastTweetId);
    var doc = XDocument.Load(url);

    var items = from s in doc.Descendants("status")
                orderby long.Parse(s.Element("id").Value)
                select new Tweet { Id = long.Parse(s.Element("id").Value),
                                   Time = ParseTwitterDate(s.Element("created_at").Value),
                                   Username = s.Element("user").Element("screen_name").Value,
                                   Status = s.Element("text").Value };
     
    return items.ToArray();
}

This method gets all tweets on the given users timeline whose ID is greater than lastTweetId (although the default limit in twitter is 20 tweets, you will need to specify the count parameter in the rest url if you need more, but this suits our purpose).

The Tweet class just wraps the properties you can see above, and the ParseTwitterDate method just does a DateTime.ParseExact for the specific date format used in twitter.

Wrapping Twitter in an IObservable<T>

Now that we have a means to access twitter, we should create a class which handles the polling of this service and pushes all new tweets out through an IObservable<Tweet> as follows:

public class TweetStream
{
    private long lastTweet = 1;
    private object updateLock = new object();
    private IObservable<Tweet> stream;

    public IObservable<Tweet> Stream
    {
        get { return stream; }
    }

    public TweetStream(string username, int interval)
    {
        var xs = Observable.Interval(TimeSpan.FromSeconds(interval));
        stream = xs.SelectMany(count =>
            {
                Tweet[] items;
                lock (updateLock)
                {
                    items = TwitterAccess.GetNewTweets(username, lastTweet);
                    lastTweet = items.Length > 0 ? items.Last().Id : lastTweet;
                }
                return items.ToObservable();
            });
    }
}

The SelectMany call allows us to define a function which is called each time the interval fires and which itself returns an IObservable. Note that we must use SelectMany instead of Select as SelectMany will automatically flatten all the items in the returned stream into its own stream of Tweets whereas Select would leave you with a stream of IObservables, which will then be difficult to handle.

Getting some output from this stream

I can now update the console app we looked at yesterday in order to create an instance of TweetStream and subscribe to its output, writing this in turn out to the console.

TweetStream bbc = new TweetStream("bbcnews", 120);

var sub = bbc.Stream.Subscribe(i => Console.WriteLine("{0}: {1}: {2}",
                                i.Time.ToString("dd hh:mm"), i.Username, i.Status));

Running this up we get the following output:

07 08:10: bbcnews: A man who was injured during a Premier League football match at Stoke City dies in hospital.  http://
bit.ly/bDjtDM
07 09:00: bbcnews: Worst snow storms to hit eastern US for decades  http://bit.ly/93Jpn9
07 09:00: bbcnews: Iran's leader asks the country's nuclear chief to begin enriching uranium to 20%, in a new challenge
to Western.. http://bit.ly/9AUplq
...
07 02:20: bbcnews: A Scottish pensioner becomes only the seventh person in history to achieve judo's highest rank. http:
//bit.ly/8XRsxv
07 02:40: bbcnews: Scotland take on France at Murrayfield in the third of the opening round of Six Nations fixtures. htt
p://bit.ly/98KHLc

This is very cool – without much code we now have a live twitter feed from a single source, which will automatically bring in new tweets (if available) every two minutes. As a final exercise I will attempt to merge two twitter news feeds into one single stream.

Merging Twitter Feeds

It is a simple matter now to update the above code to create two input feeds and then merge them:

TweetStream bbc = new TweetStream("bbcnews", 120);
TweetStream cnn = new TweetStream("cnn", 120);

var news = bbc.Stream.Merge(cnn.Stream);

var sub = news.Subscribe(i => Console.WriteLine("{0}: {1}: {2}",
                                i.Time.ToString("dd hh:mm"), i.Username, i.Status));

Just by calling the Merge method, the output from the two streams gets combined into a single stream. Note that the tweets from a given stream remain in order, but the relative ordering between the two streams depends on how they are scheduled to execute, the merge doesn’t work based on the feed dates or Ids – this is left as an exercise for the reader.

07 12:00: bbcnews: England and Wales are drawn in the same qualifying group for Euro 2012 in Poland and the Ukraine. htt
p://bit.ly/cCEza2
07 12:00: bbcnews: Home Secretary Alan Johnson rejects the idea that MPs facing expenses charges might avoid trial by ci
ting Parli.. http://bit.ly/9tk3X9
...
07 03:20: bbcnews: A court in Libya dismisses a case against a Swiss businessman who was accused of illegal business act
ivities. http://bit.ly/da0kFc
07 03:20: bbcnews: Police have launched an inquiry after a man's body was found on a main road in rural Stirlingshire. h
ttp://bit.ly/9xHMGp
06 01:06: CNN: Toyota: Apology but no new recall. http://on.cnn.com/cxQQrj
06 01:31: CNN: All military health facilities get Plan B pill. http://on.cnn.com/dbrZox
...
06 11:26: CNN: Tonight 9 ET: Watch the Tea Party Convention's keynote address by Sarah Palin live on CNN, CNN.com and CN
N's iPhone App.
07 11:29: CNN: Residents shovel out from heavy snow as blizzard conditions sweep across the eastern U.S.: http://bit.ly/
cFmAiU
07 11:30: CNN: Steps turn into slopes:  http://bit.ly/cyVbMM

I have finally got around to taking a look at this very interesting framework by DevLabs at Microsoft. What it promises to do is amazing, namely to revolutionize certain types of event driven (i.e. asynchronous) applications by allowing to developer to use the familiar LINQ paradigm to manage multiple streams of incoming asynchronous events.

There are already a fair number of videos about Rx available on Channel 9. In my opinion, this Introduction by Erik Meijer is the best starting point, followed by Wes Dyer’s Hello World equivalent. Following these there are a number of In Depth videos, which are indexed on the Team Blog. I cannot hope to describe Rx and its API anywhere near as well as those guys, so for the rest of this post will assume you have at least skimmed through those intros.

Getting Started

For this quick test, I downloaded the .NET Framework 3.5 SP1 variant and installed it. The install goes to Program Files\Microsoft Reactive Extensions\Redist\DesktopV2 and includes four assemblies and matching help files.

I crack open Visual Studio 2008 SP1 and create a new windows console application (oh yeah, we are pushing the boat out with this demonstration). Add references to the Rx framework assemblies:

Hello World

Lets just get straight in there and create a real hello world application using the Rx framework:

static void Main(string[] args)
{
    var xs = Observable.Return("Hello world");
    var sb = xs.Subscribe(msg => Console.WriteLine(msg));

    Console.WriteLine("Press any key to exit");
    Console.ReadKey();

    sb.Dispose();
}

In this trivial snippet, we call Observable.Return which creates an IObservable whose sole purpose is to push out a single string value and then terminate. In itself this would achieve nothing unless we create something which can subscribe to this stream, so we call Subscribe on this IObservable and pass in a lambda which takes the message content (a string) and writes it to the console. So we get:

This is a start, but is not exactly stretching the capabilities of Rx so far. Over the next few demos, hopefully we can start to see some of the real possibilities.

Counting

The above demo did one thing and then stopped. For real excitement, lets now create an IObservable which just keeps pushing out events forever:

var xs = Observable.Interval(TimeSpan.FromSeconds(1));
var sb = xs.Subscribe(i => Console.WriteLine("{0}: {1}", 
                               DateTime.Now.ToString("mm:ss"), i));

The call to Observable.Interval gives us an IObservable which will sit there pushing events continuously. It starts with an integer value of 0, and after each of the defined intervals it increments this and pushes it out again.

By itself this appears to be a relatively useless feature, but we will see later that in conjunction with some of the more advanced facilities offered by Rx, this can be quite powerful as a means to quantize some other stream of events.

Advanced Counting

For this section, lets first start by creating two separate streams of events with Observable.Interval.

var xs = Observable.Interval(TimeSpan.FromSeconds(1));
var ys = Observable.Interval(TimeSpan.FromMilliseconds(200));

var sb1 = xs.Subscribe(i => Console.WriteLine("{0}: {1} (xs)",
                                DateTime.Now.ToString("mm:ss"), i));
var sb2 = ys.Subscribe(i => Console.WriteLine("{0}: {1} (ys)",
                                DateTime.Now.ToString("mm:ss"), i));

As expected, we have two streams outputting results, one ticking five times faster than the other. If we want to synchronize these, we have two options, either throttle each stream so that we output a single event only when both streams have a new event available, or alternatively each time one of the streams pushes a new event we combine that with the most recent event of the other stream. These features are provided by the Zip and the CombineLatest methods respectively.

Zipping Up

One of the nice touches in the videos linked above is the concept of marble diagrams. These do a very good job of visualizing some potentially mind-melting concurrency scenarios, and also do a good job in showing what each of the Rx operators achieve. The simple (no failures) scenario for Zip is as follows:

Each blob represents some event occurring with xs and ys being the input streams in this case. Stream zs is created by zipping xs with ys and combining the two events using the function ‘f’.

var xs = Observable.Interval(TimeSpan.FromSeconds(1));
var ys = Observable.Interval(TimeSpan.FromMilliseconds(200));
var zs = xs.Zip(ys, (x, y) => String.Format("({0},{1})", x, y));

var sb = zs.Subscribe(i => Console.WriteLine("{0}: {1} (zs)",
                               DateTime.Now.ToString("mm:ss"), i));

In this method we introduce the call to Zip, which combines events from the input streams, and created new events using the lambda. In this case we simply return a string representation of the tuple.

As we can see here, the 200ms stream is effectively throttled back to the speed of the slowest stream. In many cases this may be the desired result, but consider if the two streams were different types of financial market data, one remains up to date whilst the other gets more and more stale, after one hour of this, one of the streams would be feeding data 48 minutes old.

CombineLatest

So to solve this problem, another operator, CombineLatest, steps in. The marble diagram below shows that the same type of function is performed to pair the events, but the means for achieving this is quite different:

In this case, whenever we get an event on either stream, we combine that with the most recent event (or wait until there is one) on the other stream. So once we have data on both streams, the combined event stream pushes events as fast as the fastest of the input streams.

var xs = Observable.Interval(TimeSpan.FromSeconds(1));
var ys = Observable.Interval(TimeSpan.FromMilliseconds(200));
var zs = xs.CombineLatest(ys, (x, y) => String.Format("({0},{1})", x, y));

var sb = zs.Subscribe(i => Console.WriteLine("{0}: {1} (zs)",
                               DateTime.Now.ToString("mm:ss"), i));

Summary

What I have briefly looked at is just the tip of the iceberg in terms of functionality. There are numerous other methods in the framework for dealing with events, and many ways in which they can be composed to achieve some very powerful results. Also, I have only looked at success scenarios so far, and Rx has much to give in terms of dealing with exceptions and retry policies on particular event streams.

One of the key changes in Visual Studio 2010 is the start of a move to a fully managed code implementation. Several aspects of the product are implemented in managed code using the Managed Extensibility Framework (MEF) - see Visual Studio 2010 New Features, Extensibility Points and Partner Opportunities for the full detail, and watch this video by Paramesh Vaidyanathan and Rico Mariani for an overview of the direction Microsoft is taking here.

I want to see how easy it is to create a simple extension for Visual Studio 2010, in terms of development and deployment, and so I start by downloading the SDK. This SDK includes all the bits needed for developing extensions to Visual Studio, along with a number of project templates to get you started.

Notice the description of the selected template - this isn't just a blank project, it actually implements an editor adornment, which in this case highlights every character 'a' within the editor document by putting it within a box.

What I would like to do as a first project is to implement a similar editor adornment, but in this case look for block comments which contain the text "TODO:" as the first non-whitespace text in the comment, and highlight the entire comment in a graduated red box (similar to the blue selection box we have in VS 2010). This highlight will extend to the first line which isn't a comment (or which is a comment, but only has whitespace characters). So something like this:

So I create a new Editor Text Adornment project, and take a look at what comes out

We get two C# files and a .vsixmanifest file - which I guess we should take a look at first. Double clicking on this opens up a property editor

I'm not going to dig into this in detail for the moment, but looks like this gives us the ability to define what we want packaged up with our extension in terms of additional files and referenced packages and assemblies. We can also name our extension and define some icons which appear in the Extension Manager. Finally we can restrict supported versions of Visual Studio and the framework if we so desire.

OK, now lets look at the classes. AdornmentFactory.cs is responsible for two things - firstly it defines a new layer onto which our class will draw its adornments.

And secondly the class itself implements IWpfTextViewCreationListener which allows it to hook into IWpfTextView events in the TextViewCreated method.

I don't like the way this is implemented - ie having the contructor "do stuff" with a class which is never used, a very non-intuitive bit of code in my opinion, it would look better with a static method which itself calls the constructor, eg ScarletCharacter.RegisterView(textView).

The constructor of our adornment class itself simply caches the view, and the adornment layer which we registered for this view, along with some graphics objects (Brush, Pen etc not shown above) and registers a LayoutChanged handler for this view.

This event handler gets details of each change made in the editor, and is called when the editor is first opened also. The CreateVisuals implementation by default deals with highlighting all 'a' characters in the file, but we want a different implementation. So lets rename this adornment class to TodoHighlighter and we should get away with changing CreateVisuals to achieve our purpose.

This is similar to the original implementation, except here we go through all lines in the editor, looking for those which start a TODO block, and for each of these determine the extent of the block and then create the highlight based on a SnapshotSpan. TODO blocks are detected with these methods:

Finally we can add some sparkle to the default brush used to draw the highlight - we wanted a gradient red, similar to the blue used for normal highlight in the WPF based text editor. Lets modify the constructor code as follows:

We should be ready to rock. Lets F5 this bad boy and see what comes out. Well, as is so happens, F5 spins up a new visual studio instance running under the debugger and by default took ages. I stopped the debugger, changed Options to disable Historical Debug, and tried again - much better.

So in this debug Visual Studio, I create a console app, and modify Program.cs with a TODO comment, and tada:

Great stuff, maybe needs some tweeking but the concept is proven. Now what do we do about installing this into Visual Studio? Lets examine what has actually been generated for us.

This is the contents of bin |> debug for this project. We have what we would expect, but also this TodoCustomHighlighter.vsix file. This is actually the zipped package file which Visual Studio now recognises for extensions. If we go into the Extension Manager, we should be able to select this and install it.

Hmm, no options there for installing from a local drive. Lets just double click on the vsix file. This seems to work fine:

So I click install, then restart Visual Studio as suggested. Nothing, no sign of my extension in the Extension Manager, and no highlighting of my TODO comments.

Perhaps it didn't hear me. I try installing from the vsix again. This time it fails with the following error in the log:

Install Error : Microsoft.VisualStudio.ExtensionManager.AlreadyInstalledException: TodoCustomHighlighter is already installed.

This is weird - looks like Visual Studio recognises that the extension has been installed, but for some reason is not running it, or even acknowledging its existence. Looking at the options dialog, there are some extension manager options.

This has the option Load extensions from my local application data folder, but this is unchecked and also disabled. I am running the Windows 7 RTM, so this may be a UAC issue. I shut down VS and restart in escalated mode by holding down Ctrl-Shift whilst clicking the Visual Studio taskbar icon. This allows me to check the Load extensions... option - great.

Except that even now, before or after restarting Visual Studio, I still don't get my "installed" extension. Something strange is going on here. Time to check the event log and the registry to see if we can find out what is happening.

OK I find the extension in HKCU\Software\Microsoft\VisualStudio\10.0Exp\ExtensionManager\EnabledExtensions containing:

Name: TodoCustomHighlighter..fbe86c05-ea59-4bb6-b982-b1478430e535,1.0
Value: C:\Users\Chris\AppData\Local\Microsoft\VisualStudio\10.0Exp\Extensions\TodoCustomHighlighter\1.0\

Looking for that specified directory, all I have is C:\Users\Chris\AppData\Local\Microsoft\VisualStudio\10.0Exp\Extensions - which is empty. Possible that something went wrong because I didn't have Load extensions from my local application data folder enabled when I first installed the extension. I will delete this registry value, and see if that allows me to install again.

Nope, same problem. Although I notice the TodoCustomHighlighter\1.0 folder has appeared in the root of the C drive for some reason. Moved this to the path specified above, but still doesn't load.

It's annoying, but I am going to have to leave it there for now. I will monitor some of the VSX blogs for any solutions or workarounds to this problem and update this post when I have more info, but for now it looks like I have a working extension which just can't be installed.

EDIT: I found a workaround by re-reading Scott Hanselman's post on the Demo Dashboard extension - if you just drop the DLL into C:\Program Files\Microsoft Visual Studio 10.0\Common7\IDE\Components and restart Visual Studio, the extension is installed, although still isn't listed in the Extension Manager. Perhaps this area isn't quite there in this beta 1 release for home grown extensions?

ADDITIONAL: Finally worked it out - I noticed that I could download and install .vsix from the Visual Studio Gallery but that these had an additional part to the filename beneath the Extensions area in AppData. I also noted that I left the Author field blank in the .vsixmanifest file - so I fill this in with "roundthecampfire", and replace the name GUID with a new one so that this looks like a new component.

Now if I rebuild all and reinstall from the .vsix file, it shows success (as it did previously), but if I start Visual Studio it's a different story:

Finally - I have what I wanted all along, a standalone installer file for my extension, and a good user experience for installing it, enabling/disabling it, and for uninstall. The process was tougher than it needed to be for me, but this is beta software, and I guess I should have taken more notice of the little red exclaimation mark next to Author in the .vsixmanifest editor. Hopefully come the RTM this will cause a compilation failure, or an install failure rather than feining success.

A number of enhancements have been made to the intellisense and refactoring features build into Visual Studio 2010 which should greatly enhance support for real test driven development. This post documents my investigation into how well this works in reality.

First I need to recap what I mean by "real" test driven development. This is where each test is written before the code itself, which assists the developer in focussing on the requirements, and essentially defining these requirements through the test alone. Once the test is written, classes and method stubs are added in order to allow the project to compile, the test is executed (and fails), then the classes & methods are updated with the required functionality, and the test re-run to ensure that it passes. See Test Driven Development on wikipedia and the book Test Driven Development by Kent Beck for further reading.

So to use an example that has never been done before (not) lets implement a calculator class, and create a class library (CalcLib) and related test assembly (CalcLib.Test) in a new solution. Add a reference from CalcLib.Test back to CalcLib.

Lets start by adding a test for the constructor - we (arbitrarily) decide that the constructor should initialise the running total to whatever we ask for, so add a new test class CalculatorTests.cs to the test project, and add the first test ConstructorInitialisesTotal to this class.

Now if we start typing the test, by created a new instance of the Calculator class, something annoying happens with intellisense - the test class itself is the default choice, so even if we type Calculator in full and type the first parenthesis, it autocompletes as CalculatorTest instead, and we have to Ctrl-Z to get what we wanted. Grrrr.

Notice that intellisense now has an initial item which says <Ctrl-Alt-Space> - type that - I dare you! This switches intellisense into Consume First Completion Mode, which is what we have been missing all along. Now if I type = new Calculator(); I am allowed to type this without interference, and I see the blue smart tag underline beneath Calculator. A swift Ctrl-. gives me the Generate... menu:

So click on Generate class for Calculator - right? I must admit I already had misgivings before I clicked on this, and this proves to be correct - click on this option and you get a nice fat Calculator class in a Calculator.cs source file and, sadly, inside your CalcLib.Test project, not inside the CalcLib project. This is unfortunate, being as this functionality is in support of TDD, it would have been good to see some intelligence here, ie noting that the current proj is a test project, and has a single reference to another project in the same solution, and at least give us a third option in the menu such as Generate class for Calculator in CalcLib project.

OK, not as good as it should have been. Click on Generate other... instead - this is more long winded, but gives us the flexibility that we are after:

A quick flip of the project menu, press OK, and presto - we now have Calculator.cs in our CalcLib project - is nice. The solution should now build correctly.

Still not much use, because we have an empty test testing an empty class, so lets expand the test firstly by adding a double parameter to the call to the Calculator constructor, thus:

Clicking this gives us a constructor taking a double value as a parameter (albeit it generates a spurious backing property for this parameter, which we don't want in this case - however if it had prompted for a name, we could have added the Total property in one hit, never mind).

Now lets add an assertion that the contructor sets the Total property, and in so doing generate this property in the Calculator class.

If we take the Generate property stub... option and complete the assertion, we now have our test complete and the Calculator class in a compileable state - so lets compile and run the tests. Oops, it doesn't build - the property it generated for us is the wrong type, it can't really infer the type from that overload of Assert.AreEqual, so it has a guess.

Lets try that again, but this time use the generic version of AreEqual so that we know the concrete types for the parameters to this method - hopefully that will allow Generate property stub to correctly guess the type?

Which generates the property as follows:

Much better, so now we CAN compile and run the tests with a Ctrl-R, A and lets see what we get...

Well that sucks - it failed, why? Oh, maybe because we haven't actually implemented the constructor yet - lets do that now.

Now we can build and run the tests one last time -

Great, so we have implemented a test which defines our requirements, observed that the test fails befored the requirement is implemented, and finally observed that once implemented the test passes.

Visual Studio 2010 goes some way towards supporting this method of development, although we have seen a few shortcomings in this beta 1 version. Hopefully at least the issue with generating code within the referenced assembly rather than the test assembly itself can be addressed prior to RTM.

Addendum

Got a great response from Karen Liu, Lead Program Manager on the C# and VB IDE team regarding my questions above, and a quick search revealed some great channel 9 videos she has produced in this same area, especially this one which has the exact same topic as this blog post, and I am embarrased that I didn't spot this beforehand...

Regarding the first issue - the fact that Generate class only generates within the current assembly: the thinking here is that to iterate over referenced assemblies might slow the presentation of the Generate menu, hence the decision was made to only generate within the same class, and refactor later, or to use the Generate other function, as I suggested above.

Regarding the spuriously named property generated with the constructor - Karen had a great suggestion - use a named parameter (C# 4.0 feature), which the Generate constructor function picks up on as expected, so:

Gives us a Calculator class which is already exactly what we need - we don't need to create the Total property in a later step as we did before.

Thanks for the suggestions Karen - looking forward to seeing what we get in the next release!

One of the major new features in VS2010 is Historical Debugging. This feature automatically instruments applications running under the debugger, causing key events to be logged into trace log files. These trace logs are integrated with the VS2010 debugger, and enable the developer to step back through these events when looking for clues. It is no longer necessary to set a breakpoint before the point at which the bug occurs.

There are two levels of logging supported by Historical Debugging, the first designed to capture events at the OS / Framework level - such as registry access, file access, exceptions etc. The second level supports instrumentation of methods and parameters within your own code (and obviously has a significant impact on performance, although we will dig into that a little later in this exercise). This is all set up within Options |> Historical Debugging |> General:

Historical Debugger Operation

In order to test this feature, I have cobbled together a little console app which does some file writes and reads as well as writing to the console. I have also introduced a bug which should give us a FileNotFoundException somewhere in the code, but which is immediately caught and swallowed - something which would previously have hindered debugging. The main program is simply:

This makes use of two utility classes, one for creating a temporary file containing the given text, and one for writing the contents of a specified file to the console:

          
            
              
                
                
              
            
          
So
now I can F5 this into the debugger, and immediately see something new:

The Debug History window gives us the ability to suspend a running application at any time, and then look through the historical data captured so far. We can see some failures occuring in that console output, so let's do that now. A list of eventds is presented in this historical view, and scrolling up a little we can see some interesting events prior to the console "Failed" output (note that Console output is not treated as an event by default - I have enabled this in Options |> Historical Debugging |> Diagnostic Events):

We can see now that an exception has been thrown and caught, and the detail of this exception actually gives us the reason - the filename has a spurious $ on the end. We can also see this in the File: Access event above. However, assuming we didn't get the detail we needed as this point, we can switch to Debug Tree view, at which point we can take a look at our own call hierarchy - eg select the File: Access event, then click on Show Tree View:

Here we can see a lot of useful information - we can see the actual call to FileOutputter.WriteFile and the parameter value supplied. Also, if we double click on this, we can see the relevant line in the source file, and can even set watches for values which have been logged (eg the filePath method parameter) - although anything which has not been logged (such as local variables) will show "[Historical Data Has Not Been Collected]". 

This is all clearly an invaluable resource for if not finding a big immediately based on the historical data, then at least giving us a good idea as to where we should set our initial breakpoint prior to a traditional debugging session.

Clearly we don't get any of this for free, so lets now dig into some of the performance aspects.

Historical Debug Performance

In order to get some useful performance stats, I have modified the outputter class to instead just keep a running total of the string lengths, and modified the main routine as follows:

So we repeat the main loop 5,000 times, which should be enough to get some reasonable numbers for overall execution time, and enough to get some relatively significant trace log files. The test is repeated several times (results are averaged) for three setups, all running under the debugger, but once with Historical Debug disabled, then enabled in Events only mode, and finally in Full mode.

As expected, when running with Historical Debug enabled, the performance impact is very significant (two orders of magnitude slower) albeit this is an extreme test with logged events occuring continuously in a tight loop, so this should be nowhere near as significant in typical client (eg WinForms) applications. However, this does signify that in many cases this technology would not be appropriate for debugging server apps.

One slight anomaly is that the full historical mode actually runs quicker than the events only mode. It would be interesting to find out why this is, possibly due to the full mode doing some sort of IL weaving which actually proves to be more efficient in a simplistic piece of code like this.

Anyway, performance issues asside, this looks like a very interesting bit of technology which will prove highly useful in debugging intermittent or deeply buried issues in client applications. Don't forget to disable it when debugging your server code though.

For more detail check out this video on channel 9 which shows it all in action.

Following my usual technique of learning a new technology by blogging about it, I have decided to start a series covering new features in Visual Studio 2010 and .NET Framework 4.0 / C# 4.0 (these posts will be based on Visual Studio 2010 Team System Edition, Beta 1, which is available at that link for public download).

I will start by looking at some of the basic new VS2010 features, and then go in depth into some of the more extensive new features, such as the Architecture Browser, Data Modelling and Code Metrics. Following this I will look into what's new in .NET 4.0 and C# 4.0, with a little help from my trusty Reflector.

Posts to follow soon, and will be indexed from this entry.