Logging and context in distributed systems

Garry Shutler posted about logging at the end of last year; at the same time I was thinking about some structures that my friend Chris Oldwood had put in place to enrich our logging with contextual information. Gary’s intent was to demonstrate that good logging is a vital part of a distributed system; his example mechanism for relating log messages was necessarily simple, and I’d like to expand it.

“Given sufficient detail in your logs,” Garry says, “you no longer have to theorise or piece together how something happened. Your logs will lay it out for you, plain as day.

Anyone with production experience of a distributed system is likely to agree. If you can identify and tie together related log entries over thread and process boundaries then working out what actually happened becomes possible. An important first step is to have process and thread ids in every log message; the alternative is chaos.

Moreover, it’s not just about stack traces; to replicate a problem you often need to understand the path to failure, and that’s where contextual information helps.

Enriching logs with contextual information

Garry’s simplified example has him manually inserting a username into each log entry, allowing him to tag those entries caused by each user’s actions. This is a not so practical in larger-scale system; in such systems we want contextual information to be tagged automatically onto log messages, and we want to be able to arbitrarily extend that contextual information as we see fit. We can do that with a Diagnostic Context, described in Pattern Languages of Program Design Vol. 3.

Diagnostic contexts are essentially maps associated with a logging subsystem. Developers can place whatever they want into the diagnostic context, and the logging subsystem picks it up and tags log messages with it.

At coarsest grain we want a key piece of information carried from one thread to another – like a session id – that allows you to tie related messages together. At finer grain we might want to signal transition through system layers; or the creation of important contextual information like authorisation for a specific user; or the start and end of significant independent workflows.

As crossing boundaries generally implies marshalling this map in some way, especially in service-oriented architectures, then using a single piece of tie information on either side of the boundary is more efficient than simply reconstituting the entire map.

Log4J has both Nested and MappedDiagnosticContexts. Nested contexts are not map-based but instead allow you to push and pop new context strings onto and from a stack. Mapped contexts do not give you this stack-like behaviour – a push of a new value for an already-defined parameter overrides it. In both cases the context can be inherited from a parent thread but you must clone the entire current context and use the clone to create a new context for the new thread.

Log4Net has a GlobalContext which has stack semantics, and allows the attribution of values to named parameters. It similarly makes use of the Dispose pattern and using { } syntax to make management of contexts simpler.

The team I’m currently with has a home-grown Diagnostic context called Causality which bears a deal of similarity to log4net’s GlobalContext.

A simple C# Diagnostic Context

The team I’m currently with has a diagnostic context called Causality. Causality is plumbed into our logging subsystem. If you’re using an off-the-shelf logger that doesn’t support diagnostic contexts you can just decorate your logger invocations with methods that append information from Causality.

Causality is essentially a thread static map. For convenience it's structured as a set of transactions so that attributes can be updated and reverted rather than just overwritten. A single Transaction represents a change to a single Attribute-Value pair, and the Dispose pattern is hijacked to provide some syntactic sugar:

private sealed class Transaction
{
    public Transaction(Attribute attribute, Value @value)
    {
        // instantiate _attributes map if needed and add key-value pair ...
        // if this is an update of an existing Attribute then store the old
    }

    public Dispose()
    {
        // rollback the attribute if it was modified ...
        // or just remove it if it was new
    }

    [ThreadStatic]
    private readonly static Dictionary<string, string> _attributes;
}

As _attributes is private readonly ThreadStatic it’s safe to use without locking in concurrent operations.

A CompoundTransaction extends this, representing a stack of Transactions that is unwound on Dispose. The CompoundTransaction just provides a simple way of updating the context with a set of Attribute-Value pairs.

Labelling the context -- or appending/updating an Attribute -- is then the creation of a Transaction:

public static IDisposable Label(Attribute attribute, Value @value)
{
    // instantiate a transaction ...

    return transaction;
}

which would be used within a using block:

Log.Info("I'm about to do something ...");
using(Causality.Label(Category.System, "User", "timbarrass")
{
    Log.Info("I'm doing something!"); 
}

Log.Info("I've done something.");

Causality also provides a Format or ToString method that flattens the map to a string representation. Assuming that Log.Info or the logging subsystem uses this method, the result of the code above might look like:

2013-01-22 07:34 INFO 3432 1 I'm about to do something ...
2013-01-22 07:34 INFO 3432 1 I'm doing something! [User=timbarrass]
2013-01-22 07:34 INFO 3432 1 I've done something.

The Transaction holds attributes at thread static scope, which means that the attributes won’t be available when you cross a thread or other boundary. On the other side of the boundary you need to reconstitute Causality with a key piece of information that can tie the two threads together. On the first thread:

Causality.IdentifyPrimaryCausality("Request");

using(Causality.Label("User", "timbarrass"))
using(Causality.Label("Request", "31415))
{
    Attributes causality = Causality.AcquirePrimaryCausality();

    Log.Info("Creating worker thread.");

    var worker = new Worker();
    ThreadPool.Start(worker, causality);

    Log.Info("Worker started.");
}

and on the other side of the thread boundary:

public class Worker
{
    public void Start(object state)
    {
        Causality.InjectPrimaryCausality(state as Attributes);

        using(Causality.Label("Component", "Worker")
        {
            Log.Info("Starting work.");
        }
    }
}

The logs here might look like:

2013-01-22 07:34 INFO 3432 1 Creating worker thread. [User=timbarrass;Request=31415]
2013-01-22 07:34 INFO 3432 2 Starting work. [Request=31415]
2013-01-22 07:34 INFO 3432 1 Worker started, [User=timbarrass;Request=31415]

C# performance counters impact performance? No, but it seems that Chart.SaveImage does.

A little thought later and it looks like no, they don’t impact performance. What I was seeing was the effect of prepping and drawing a chart – on about the same timescale that I was querying for information.

Diagnosing the problem was straightforward; I crosschecked the processor usage for the tool with perfmon. After configuring it to avoid saving down a chart the processor usage dropped to zero.

It is a good example of misleading yourself while looking at performance stats. I could see usage spiking on a period that looked suspicious. I used the VS 2010 in-built profiler and saw that PerformanceCounter.NextValue() was by far the biggest contributor to CPU time, and put two and two together to make five.

I ran the app for a few minutes, rather than the one minute I originally tested with, and the stats inverted. Chart.SaveImage() was overwhelmingly responsible for CPU consumption, with the calling method, Agent.Graph(), taking up ~71% of samples.

Schoolboy misinterpretation, but as always a bit of thought and investigation soon shows up the problem.

Now. Why is Chart.SaveImage() so expensive, and is there a cheaper alternative?

C# performance counters impact performance?

I’ve been using System.Diagnostics.PerformanceCounter to get at CPU and memory usage stats – but it looks like whenever I call NextValue it spikes CPU usage. Running my app through the VS profiler points straight at NextValue as the main CPU load.

It looks, then, like querying PerformanceCounter.Next value seriously impacts CPU usage – on my dual core laptop it flipflops between 5 and 10% utilization.

I’m pretty sure that the same thing doesn’t happen when you use ProcessExplorer, or TaskManager, or Perfmon. I’ve been trying to work out a native way of getting at the same data, but it’s been surprisingly difficult. I just found these that look like decent leads:

SO question on logging performance metrics

Logman -- command line perfmon use

Writing performance data to a log file

Creating a chart programmatically in C# using DataVisualization.Charting

Means you have to reference System.Windows.Forms and System.Windows.Forms.DataVisualization, even though you might be doing this in a console application. That said, it also includes a set of data manipulation functions, some of which are even finance-specific:

using System;
using System.Drawing;
using System.Windows.Forms.DataVisualization.Charting;

namespace Sandbox
{
    class Program
    {
        static void Main(string[] args)
        {
            // set up some data
            var xvals = new[]
                {
                    new DateTime(2012, 4, 4), 
                    new DateTime(2012, 4, 5), 
                    new DateTime(2012, 4, 6), 
                    new DateTime(2012, 4, 7)
                };
            var yvals = new[] { 1,3,7,12 };

            // create the chart
            var chart = new Chart();
            chart.Size = new Size(600, 250);

            var chartArea = new ChartArea();
            chartArea.AxisX.LabelStyle.Format = "dd/MMM\nhh:mm";
            chartArea.AxisX.MajorGrid.LineColor = Color.LightGray;
            chartArea.AxisY.MajorGrid.LineColor = Color.LightGray;
            chartArea.AxisX.LabelStyle.Font = new Font("Consolas", 8);
            chartArea.AxisY.LabelStyle.Font = new Font("Consolas", 8);
            chart.ChartAreas.Add(chartArea);

            var series = new Series();
            series.Name = "Series1";
            series.ChartType = SeriesChartType.FastLine;
            series.XValueType = ChartValueType.DateTime;
            chart.Series.Add(series);

            // bind the datapoints
            chart.Series["Series1"].Points.DataBindXY(xvals, yvals);

            // copy the series and manipulate the copy
            chart.DataManipulator.CopySeriesValues("Series1", "Series2");
            chart.DataManipulator.FinancialFormula(
                FinancialFormula.WeightedMovingAverage, 
                "Series2"
            );
            chart.Series["Series2"].ChartType = SeriesChartType.FastLine;

            // draw!
            chart.Invalidate();

            // write out a file
            chart.SaveImage("chart.png", ChartImageFormat.Png);
        }
    }
}

Gives the following result:

RRDTool, and C# .NET bindings

RRDTool is pretty much ubiquitous in Linux/Unix cluster environments – or at least, it is in those I’ve worked with. It provides simple but highly reliable round-robin database services into which you can dump pretty much any metric you like. It’ll keep a running dataset at the granularity and duration you define; enable you to export data in chart and xml form; and even perform some useful analysis.

These days I’m typically working in Windows environment, and typically most clients I work for need some sort of dashboard to aggregate information about their clusters and grids. For a long time RRDTool was a pain to build on Windows, and there was no single .NET wrapper. The front runner – NHawk – actually spawned rrdtool processes rather than wrapping the underlying libs direct.

Now it turns out that someone’s contributed .NET bindings to the trunk of RRDTool. I figured I’d see if I could get it working, on 64bit Win7 (although actually x86 is fine for my app), under Visual Studio 2010.

I checked trunk out from SVN and took a look.

The first thing is to set up the dependencies – I tried to take a short cut and begin with a GTK+ package, but found it’s best to start with the files mentioned explicitly in the WIN32_BUILD_TIPS file.

There were a few apparently non-serious build errors in the rrdlib project. In several places explicit casts from void* were required on malloc, realloc. Also, there was some skipping of variable initialization in switch statements – latter can be fixed just by enclosing in a block.

Running through the tutorial with rrdtutorial raised one problem – an error claiming “No positional legend found”. The error was generated in rrd_graph_helper.c. The log showed that this was a work in progress, so I updated to the preceding version, built and it worked apparently fine.

After that I built the .NET bindings – basically fine, although I wrangled everything to x86 in the end just to get started. But then – nothing was being exported. There’s a .def file in the lib solution, but it doesn’t appear to exist any more. So: I wrapped a copy of the public method declarations in #ifdef WIN32, and prefixed with __declspec(dllexport), then rebuilt the .NET binding solution and: success.

All looks good to go. Next step is to grab metrics from windows performance counters in a C# app and see what I can present through RRDTool.