Elegant Inline Debug Tracing

As much fun as it is to step through code with a debugger, I usually prefer to use System.Diagnostics.Debug and Trace with DebugView to see what’s happening in realtime. This is particularly handy to track intermediate results in higher-order functions that you might not be able to step into. However, it’s not always convenient to insert debugging statements amongst the composed expressions of F#, PowerShell or LINQ.

An alternative first came to mind while working in F#:

let dbg x = System.Diagnostics.Debug.WriteLine(x |> sprintf "%A"); x

(Read |> as “as next parameter to”.) We can then use this function anywhere to peek at a value, perhaps an intermediate list in this trivial example:

let data = [1..10]
           |> List.filter (fun i -> i%3 = 0) |> dbg
           |> List.map (fun i -> i*i)

Indeed [3; 6; 9] are traced as multiples of three. Not a particularly convincing example, but it should be pretty easy to imagine a more complex algorithm for which unintrusive tracing would be useful.

This works pretty well with F#’s |> operator to push values forward, but what about C#? Given my posting history, it shouldn’t be hard to guess where I’m going with this…

Extension Methods

So if |> is “as next parameter to”, the . of an extension method call might read “as first parameter to”. So we can implement a roughly equivalent function (sans F#’s nice deep-print formatter "%A") like so:

    public static T Debug<T>(this T value)
        return value;

    public static T Dbg<T>(this T value, string category)
        Debug.WriteLine(value, category);
        return value;

I find the optional label handy to keep different traces separate. Looking again, there’s an overload that accepts a category, so we’ll use that instead. So why might this be useful? Maybe we want to log the value assigned within an object initializer:

var q = new SPQuery() {
  Query = GetMyQuery().Debug("Query")

Rather than store the query string to a temporary variable or retrieve the property after it’s been set, we can just trace the value inline. Or consider a LINQ example:

var items = from SPListItem item in list.GetItems(q)
            let url = new SPFieldUrlValue(item["URL"] as string)
            where url.Url.Debug("URL").StartsWith(baseUrl, StringComparison.OrdinalIgnoreCase)
            select new
                Title = item.Title.Debug("Title"),
                Description = url.Description,

Here we log all URLs that pass through, even the ones excluded from the result by the predicate. This would be much harder to implement efficiently without inline logging.

This technique works great for simple objects with a useful ToString(), but what about more complex objects? As has often been the answer lately, we can use higher-order functions:

    public static T Dbg<T, R>(this T value, Func<T, R> selector)
        return value;

    public static T Dbg<T, R>(this T value, string category, Func<T, R> selector)
        Debug.WriteLine(selector(value), category);
        return value;

Now we can provide a delegate to trace whatever we want without affecting the object itself. For example, we can easily trace a row count for the DataView being returned:

public DataView GetResults()
    var myTable = GetDataTable();
    // Process data...
    return myTable.DefaultView.Dbg("Result Count", v => v.Count);

I could go on, but you get the idea.

PowerShell Filter

Finally, we can implement similar functionality in PowerShell using a filter with an optional scriptblock parameter:

filter Debug([scriptblock] $sb = { $_ })
  [Diagnostics.Debug]::WriteLine((& $sb))

PS > 1..3 | Debug { $_*2 } | %{ $_*$_ }

Which traces 2, 4, 6, as expected.

Update 4/19/2009: Changed functions to use category overloads. And another point to consider: if the value being traced could be null, selector should be designed accordingly to avoid NullReferenceException. There’s nothing worse than bugs introduced by tracing or logging.

About these ads

5 Responses to “Elegant Inline Debug Tracing”

  1. Jeremy Thake Says:

    Very nice mate! Looks good ;-) Only concern is for newbies to the code unless they are aware they are there might not understand them…rather than Debug() maybe DebugWriteAndReturn() or something to make it clearer on what it’s doing…?

  2. Keith Dahlby Says:

    I could go either way on that. The longer method name is more descriptive, but might also distract from the logic being traced. Maybe an XML comment would be sufficient for discovery?

  3. Oskar Austegard Says:

    It breaks naming convention, but then again so many methods do in the era of linq:

    May I suggest “Traced”and “TracedTo” ? as in
    public static T Traced(this T value)
    public static T TracedTo(this T value, string category)

    Then the code could look like this, which reads better IMHO:

    var items = from SPListItem item in list.GetItems(q)
                where url.Url.TracedTo("URL").StartsWith(baseUrl, StringComparison.OrdinalIgnoreCase)
                select new
                    Title = item.Title.TracedTo("Title"),
                    Description = url.Description,
  4. Keith Dahlby Says:

    I don’t think that necessarily breaks naming convention, it just uses a fluent convention which I find perfectly acceptable (even preferred) for extension methods.

    I would probably differentiate between Debug and Trace simply because there’s also System.Diagnostics.Trace which serves a separate (but also useful) purpose. In fact, you might want to define both!

Comments are closed.


Get every new post delivered to your Inbox.

%d bloggers like this: