Skip Navigation LinksHome > View Post

From zero to logging with System.Diagnostics in 15 minutes

Part 1 in a series introducing the Ukadc.Diagnostics project which is currently hosted on codeplex at www.codeplex.com/UkadcDiagnostics.

In this post we'll look at the basics of logging in System.Diagnostics with .NET 2.0 (and above) before looking at how you can use Ukadc.Diagnostics to extend the functionality already available. In the previous post I mentioned a number of other logging frameworks including log4net, nlog and EntLib and it's worth referring to them again, as we look at logging in System.Diagnostics as they all work in much the same way.

This diagram shows the typical 'architecture', if you will, behind these logging components.

logging architecture

Typcially, you have one or more TraceSources (as System.Diagnostics call them) and it is against these instances that the developer logs events to describe the progress and/or state of a program at run-time.

These TraceSources are coupled to zero or more repositories that do something with this logging data. These can be connected programmatically but, more commonly, this occurs at deployment-time with configuration.

As you can see in our diagram above TraceSource A 'writes' log events to TraceListeners 1, 2 and 3. TraceSource B on the other hand only writes to TraceListener 2, as indicated by the orange arrow. Note that we said the TraceSources are coupled to zero or more repositories; the logging information doesn't have to go anywhere until you need it to. This is one of the benefits of configurable diagnostic logging frameworks.

Furthermore, all of the aforementioned logging frameworks support the concept of an event level or priority. This allows you to specify the 'type' of an event and System.Diagnostics does so on a ten point scale (in descending order of importance):

  • Critical
  • Error
  • Warning
  • Information
  • Verbose
  • Start
  • Stop
  • Suspend
  • Resume
  • Transfer
log4net and nlog have a similar set of event types and I've discussed them in a previous post: Logging Levels and how to use them.

These event types can be used to filter certain messages before they reach the listener. For example, maybe we only want events from TraceSource A to reach TraceListener C if it is of event type Warning or higher. I call this 'routing'.

EntLib logging uses many artefacts from System.Diagnostics and shares the same enum for the ten event types. However, EntLib is arguably the most architecturally different logging framework because it only has one 'TraceSource' (Logger) and events are wired to TraceListeners by 'Categories'. I've discussed this at length in a previous post: Log Event to Listener Routing in Enterprise Library. Despite being a fan of EntLib, I do miss the ability to easily route between listeners on EventType. It's common to have one listener writing all events but another (such as an Email based listener) writing only Errors and above. Fortunately, System.Diagnostics (and therefore Ukadc.Diagnostics) does support this.
I'm quickly running out of time if this is only to take 15 minutes, so let's start using System.Diagnostics in an application. The Ukadc.Diagnostics project site has a Quick Reference Example that uses System.Diagnostics to instrument a web site but given we have limited time, we're just going to instrument a Console Application... and here's the code:

public class Program
{
    static void Main(string[] args)
    {
        Console.WriteLine(CalculatePrimes(10000000));
        Console.ReadLine();
    }

    public static int CalculatePrimes(int topNumber)
    {
        BitArray numbers = new BitArray(topNumber, true);

        for (int i = 2; i < topNumber; i++)
        {
            if (numbers[i])
            {
                for (int j = i*2; j < topNumber; j += i)
                {
                    numbers[j] = false;
                }
            }
        }

        int primes = 0;

        for (int i = 1; i < topNumber; i++)
        {
            if (numbers[i])
            {
                primes++;
            }
        }
        
        return primes;
    }
}

Yup, just a simple program to calculate the number of primes below 1,000 (and no comments on the quality of algorithm please, it was lifted directly from the internet). This is far from an ideal application to demonstrate the power of logging, but lets move on anyway and add some instrumentation:

private static TraceSource _source = new TraceSource("primes");

public static int CalculatePrimes(int topNumber)
{
    _source.TraceEvent(TraceEventType.Start, 0, "CalculatePrimes");
    BitArray numbers = new BitArray(topNumber, true);

    for (int i = 2; i < topNumber; i++)
    {
        if (numbers[i])
        {
            for (int j = i*2; j < topNumber; j += i)
            {
                numbers[j] = false;
            }
        }
    }

    int primes = 0;

    for (int i = 1; i < topNumber; i++)
    {
        if (numbers[i])
        {
            primes++;
            _source.TraceEvent(TraceEventType.Information, 0, "Found a prime: {0}", i);
        }
    }
    _source.TraceEvent(TraceEventType.Stop, 0, "CalculatePrimes");
    return primes;
}

Notice that we've added a TraceSource (_source) called "primes" and we log a 'Start' event at the beginning of the method and a 'Stop' at the end. We've also added an 'Information' level event whenever a prime is found (and formats a string to display the value of the prime). If you run the program you'll see that nothing happens - it doesn't even run measurably slower. That's because we haven't turned the TraceSource on so it isn't logging anywhere.

We can turn the TraceSource on without a rebuild by adding the appropriate source to the exe's configuration file and we can have the logging output write to the Console window by specifying the ConsoleTraceListener:

<configuration>
    <system.diagnostics>
        <sources>
            <source name="primes" switchValue="All">
                <listeners>
                    <add name="console" type="System.Diagnostics.ConsoleTraceListener" />
                </listeners>
            </source>
        </sources>
    </system.diagnostics>
</configuration>

This turns on the primes TraceSource and logs All events. Easy peasy...

Console window with logging turned on

You can also take limited control of the output by selecting a number of 'traceOutputOptions' from ProcessId, LogicalOperationStack, ThreadId, DateTime, Timestamp, and Callstack: v

<listeners>
    <add
        name="console"
        type="System.Diagnostics.ConsoleTraceListener"
        traceOutputOptions="ThreadId,ProcessId,Timestamp" />
</listeners>

Which looks like this:

Console window with additional output options turned on

Even in this (very) contrived example this is useful. It means that we can embed diagnostic code inside our application that doesn't do anything until we need it and doesn't adversely impact performance when not in use.

Next, we'll look at how Ukadc.Diagnostics can give you more control over the output with added token goodness.

If you want to know more and don't want to wait for more posts, why not head off and check the Quick Reference Example on the project site.

 
Josh Post By Josh Twist
12:37 PM
27 Apr 2008

» Next Post: Using tokens in Ukadc.Diagnostics to control output
« Previous Post: Introducing Ukadc.Diagnostics

Comments are closed for this post.

Posted by Ron Grabowski @ 29 Apr 2008 6:01 PM
FYI, log4net has had 15 levels of logging for quite some time:

Emergency
Fatal
Alert
Critical
Severe
Error
Warn
Notice
Info
Debug
Fine
Trace
Finer
Verbose
Finest

Its easy to add additional levels.

This is how you log a message using one of those built-in levels:

log.Logger.Log(
GetType(),
Level.Emergency,
"Check this out!",
null);

Posted by Josh @ 29 Apr 2008 11:57 PM
Hey Ron,

Thanks for dropping by and your correction - I've updated the post. I'd managed to overlook this addition in my recent use of log4net.

Josh

Posted by Brian @ 10 Jul 2008 8:43 PM
You know, maybe I'm over thinking it, but 15 levels seems beyond the level of usefulness.

It's like colors; but whose eye sight out there is good enough to determine the difference in RGB of (220, 15, 12) vs. (221, 16, 12)?

My point being is Fatal? Emergency? Critical? Severe? Aren't these all the same in reality...I mean common...'we'll send an send an email if it's fatal, but just log it if it's an emergency?'...how to justify this when writing code...deciding 'this is an emergency' but this is 'critical'.

I think it's like unit testing...there's a reason there's just green, yellow, and red...I mean a failure is a failure, a 'crimson' test result vs. a 'red' test result...what would that be?

Do you guys follow? Please keep this in mind with you library...10 is sufficient, because in these 10, some are 'level' (Critical, Error, Warning, Information, Verbose) and some are 'notificiation' (Start, Stop, Resume, Suspend, Transfer), and please mention something on this logic in a future post if you agree. Or chastise me here if you don't. :)

Posted by Josh @ 15 Jul 2008 2:13 AM
Hi Brian,

I kind of agree. Fortunately (I think) I won't be able to change the number in the Ukadc.Diagnostics library because the enumeration is provided by System.Diagnostics (that's not to say the .NET team won't add more levels though!).

If you find there are too many levels then this might be one reason to wrap the your logging library of choice - providing a different enumeration with fewer options :)

http://www.thejoyofcode.com/Unit_testing_a_logging_wrapper.aspx#comment6e94f047-c595-4df4-b324-a243e418ba38

Posted by Grd @ 08 Sep 2008 1:08 PM
Hi Josh,
How can we make ukadc.diagnostics to pick up the trace written by "System.Diagnostics.Trace.Writeline".

Thanks

Posted by Josh @ 09 Sep 2008 7:25 AM
Good question - more here:

http://www.thejoyofcode.com/How_to_use_Ukadc_Diagnostics_with_Trace_and_Debug.aspx

© 2005 - 2014 Josh Twist - All Rights Reserved.