Is there any merit in 'Aspect Based Tracing'?

Question

Just to be clear, my meaning of 'aspect' is a horizontal factor of the application's functions, not intercepting all method calls as in Aspect Oriented Programming.

I have just discovered the beauty of the .NET Trace infrastructure, and in particular, the TraceSource object. Like the noob at this I am, I gave each class it's own TraceSource, to trace method begins and ends, errors, etc.

Now, however, I think one TraceSource per aspect is better. E.g. I have an app that imports records of vehicle movements within parkades, to calculate a charge for parking, and then post messages to a billing system (WHMCS).

I'm thinking I should rather have a class with a bunch of static TraceSource properties, like this:

public static class Traces
{
    static Traces()
    {
        VehicleMovements = new TraceSource("VehicleMovements", SourceLevels.All);
        Pricing = new TraceSource("Pricing", SourceLevels.All);
        Calculation = new TraceSource("Calculation", SourceLevels.All);
        Billing = new TraceSource("Billing", SourceLevels.All);
    }
    public static TraceSource VehicleMovements { get; set; }
    public static TraceSource Pricing { get; set; }
    public static TraceSource Calculation { get; set; }
    public static TraceSource Billing  { get; set; }
}

This way, I can do, e.g. a Traces.Pricing.VehicleMovements ("Terminal Id not configured"); in any class I find that scenario, and have a better grouped and more cohesive log or other output.

Is this a good idea? For a bonus, some pointers to resources on tracing strategies and patterns would be great, thanks.

Answer 1

Sorry, this is going to be more of a programmers SE sort of answer. The specific code you show is a fine example of theme based tracing, as opposed to class based tracing. If it is good or bad depends on what sort of story you are trying to generate and if that story is providing the information you need to understand the problem and find the bug.

I got the trace "obsession" and began tracing everything after I read a book where the author interviewed a bunch of famous developers and asked them how they debug-- almost all said they fall back to some sort of writing messages to the screen at strategic points. So there could/should be a way to formalize this practice, right?

So I started using System.Diagnostics-- it's main advantage is that it is always available. It is a flawed API, nLogger and log4net are more elegant APIs. But System.Diagnostics is extensible and that fixes a lot of the flaws-- I always use the Essential.Diagnostics and Ukadc libraries together with System.Diagnostics and some of my own custom listeners.

Aspect Oriented Trace This implies adding trace statements just before and after each method call. This is extremely chatty and at the point of error, it provides the same information, mostly, as the stack trace. Most performance tracing using this strategy to find out which methods are called too many times or which methods are consuming too much time either in a single call or collectively.

Class Based Trace Trace gets chatty very fast. At Microsoft, they call the pages of trace "Spew" and if no particular thought goes into what get's traced, it can be informative as vomit. This is the motivation for one TraceSource per class, so that you can turn on trace just for the one or two classes you care about.

Theme base Trace I tried to use the TraceSource per class, but I found that my app (db-centric a web app) really needed theme based trace. So I have a trace source for "perf", "http", "data", "sql", and "app". Perf is anything related to time to execute, http is info about requests and responses, data dumps the data to the screen as I get it, sql dumps the sql + parameters to the screen as I get it. In my work flow, I have theme base trace turned on about all the time, and class base trace normally turned off, unless there is a specific problem.

Production/Testing Team Trace There is a lot of overlap with trace and error logging. Trace tells the story, error logging says what went wrong. Trace can be expensive to gather, but if I have the trace up to the time an error happened, sometimes that is useful. At the moment, in production I write trace to memory and then include that trace with emailed error reports. Production trace and error logging has to be more finely tuned that development trace because of the more dramatic consequences to excessive spew, such as bad perf or the dev-ops team ignoring important errors in the error log because of logging unimportant issues.

Here is a blog post I wrote about Trace when I was trying to work out some normative guidelines for trace http://suburbandestiny.com/Tech/?p=640 because the common advice for API's like trace (This API is so powerful you can use it for anything you want to!) isn't actually all that empowering.

Answer 2

In the documentation for the Essential.Diagnostics project, which contains a bunch of listeners that extend System.Diagnostics (TraceSource), I have a few pages on guidance. (I am involved in the Essential.Diagnostics project)

I won't reproduce the entire document here, but will try to give a summary so that the answer can be stand alone.

(1) Trace levels -- Messages rated Critical, Error, and Warning probably always want to be traced, possibly even written to something like the Windows Event Log, and it may not make sense to be able to turn off.

At Information level there are some global events, e.g. service started, that you always want to log, as well as per-transaction events, which may have their own custom (highly structured) application log file (e.g. IIS logs). Your code should make sure there is consistency between error reporting, application logs, and lower level tracing (otherwise it gets confusing).

Below this is all the Verbose stuff -- at this point it can be a lot and a single on/off switch is not very useful; you really need some way to turn on/off individual sections. Hierarchical based logging such as log4net, or the new Microsoft.Extensions.Logging, are good for this, but having a half dozen separate TraceSource for different assemblies/namespaces/themes is generally okay manually. (If you go down to class level, explicit support for hierarchy is useful.)

The key point is that you need to be able to turn on/off individual parts of Verbose logging, or some other way to filter, for it to be useful. (The other option is to write everything to something like Seq, e.g. using Essential.Diagnostics.SeqTraceListener, and then filter what you are interested in.)

More detail: https://essentialdiagnostics.codeplex.com/wikipage?title=Logging%20Levels&referringTitle=Guidance

(2) Theory of event IDs -- The other main piece of guidance is based on the early Internet RFCs "Theory of Reply Codes"; if you have worked with Web/HTTP, then you usually work out 400 and 500 messages are errors. I think having managed event IDs, particular for Information level & above (but not for Verbose) is a good feature. System.Diagnostics support this, and the fluent interfaces I have in Essential.Diagnostics make it a bit easier. The new Microsoft.Extensions.Logging also includes good support for event IDs, but other frameworks (log4net, NLog, etc) can be a bit clunky.

More details: https://essentialdiagnostics.codeplex.com/wikipage?title=Event%20Ids&referringTitle=Guidance