andyfrench.info

Here's a quick note to remind me how I setup a WSL shell in ConEmu.

I just created a new task with the following command:

set PATH="%ConEmuBaseDirShort%\wsl";%PATH% & wsl

Simple as that.

The problem

I’ve recently been looking at a problem with some software that was written to work in a cluster. This particular software service runs background jobs against a SQL Server database and in order to support fail-over scenarios the software was written to work in a cluster. Only one service instance (the master) was actually doing any work at any given time with the other instances (the slaves) providing redundancy in the case of a failure. In other words, one instance would be nominated as the master and would take responsibility for running the background jobs. If the master crashed or became unavailable one of the other instances in the cluster would take over as master.

From now on I’m going to continue to use the term service instance to describe a software comonent that participates in a cluster. Each service instance is probably a separate process.

The problem was that the mechanism used to elect and monitor the master was based on UDP broadcast, and broadcast is something that can be problematic in cloud-based environments such as AWS. Given there was a need to migrate this service to the cloud this was a significant issue.

At a high level the election algorithm being used by the cluster was for service instances to use UDP broadcast to exchange messages between themselves to agree which instance would be the master. Once the master had been nominated it took over the work of running the background jobs. The other service instances would then periodically poll the master to check that it was still alive. The first instance to find the master to be unavailable would claim the master role, take over the responsibility of running the jobs and broadcast the change in master.

The use of UDP broadcast in this context was useful because it meant that service instances didn’t need to know about each other. To use more direct addressing it would be necessary to store the addresses of all instances in the cluster in some form of registry or configuration. Configuration management across multiple environments is itself a challenge so reducing the amount of configuration can be an advantage.

However, in this case the use of UDP broadcast was an issue that needed to be addressed to facilitate a move to the cloud. This provided a good opportunity to review clustering election patterns and approaches to writing clustered software in general to see what options are available.

Note: There are alternatives to creating writing software that behave as a cluster natively (e.g. ZooKeeper). This article does not deal with these alternative approaches but focuses on the creation of natively clustered software.

Reasons for clustering

There are typically 2 reasons for writing software that supports clustering:

• Failover – to prevent outages it would be advantageous to build in redundancy so that if one service instance crashes there’s another available to take up the slack. Note that in this case it isn’t necessary for all instances to be doing useful work. Some may be on stand-by, available to take over if the primary fails but not doing anything while the primary is active.
• Performance – to facilitate greater application performance running separate software instances (probably on separate servers) may be advantageous. In this case work can be distributed between instances and processed in parallel.

Of course, these two aspects are not mutually exclusive; a cluster may support both high availability and distributed processing.

Characteristics of clustered software

Typically when running software as a cluster one instance will be nominated as the coordinator (leader or master). Note that this instance does not have to perform the work itself, it may choose to delegate the work to one of the other instances in the cluster. Alternatively – such as in our example above – the coordinator may perform the work itself exclusively.

This is somewhat analogous to server clustering which can be either symmetrical or asymmetrical. In the symmetrical case every server in the cluster is performing useful work. To distribute work between the servers in the cluster a load balancer is required. In the case of a software cluster it’s the instance elected as the coordinator that’s probably performing this task.

In the asymmetrical case only one server will be active with the other server instances in the cluster being passive. A passive instance will only be activated in the event of a failure of the primary. In the case of a software cluster the coordinator would be the active instance with other instances being passive.

Whichever basic topology is chosen it will be necessary for the software cluster to elect a coordinator when the cluster starts. It will also be necessary for the cluster to recognise when a coordinator has crashed or become unavailable and for this to trigger the election of a new coordinator.

When designing a system like this care should be taken to avoid the coordinator becoming a bottleneck itself. There are also other considerations. For example, in auto-scaling scenarios what happens if the coordinator is shut down as a result of downsizing the infrastructure?

Election patterns

How do software clusters go about managing the election of a coordinator? Below is a discussion of 3 possible approaches:

• Distributed mutex – use a shared mutex is made available to all service instances and is used to manage which instance is the coordinator. Essentially, all service instances race to grab the mutex. The first to succeed becomes the coordinator.
• Bully algorithm – use messaging between instances in the cluster to elect the coordinator. The election is based on some unique property of each instance (e.g. a process identifier). The process with the highest value ‘wins’. The winning instance bullies the other instances into submission by keeping the mutex and claiming the coordinator role.
• Ring algorithm – use messaging between instances in the cluster to elect the coordinator. Service instances are ordered (either physically or logically) so each instance knows its successors. Ordering in the ring is significant with election messages being passed around the ring to figure out which one is ‘at the top’. That instance is elected the coordinator.

More detailed descriptions of the approaches are provided below. As you’d expect each has its pros and cons.

Distributed mutex

A mutex “ensures that multiple processes that share resources do not attempt to share the same resource at the same time”. In this case the ‘resource’ is really a role – that of coordinator - that one service instance adopts.

Using a distributed mutex has the advantage that it works in situations where there is no natural leader (e.g. no suitable process identifier which would be required for the Bully Algorithm). Under some circumstances (e.g. when the coordinator is the only instance performing any work) the service instances need not know about each other either; the shared mutex is the only thing an instance needs to know about. In cases where the coordinator needs to distribute work amongst the other instances in the cluster then the coordinator must be able to contact – and therefore know about – the other instances.

The algorithm essentially follows this process:

1. Service instances race to get a lease over a distributed mutext (e.g. a database object).
2. The first instance to get the mutex is elected as the coordinator. Other instances are prevented from becoming the coordinator because they are blocked from getting a lease on the mutex.
3. The coordinator performs the task of coordingating the distribution of work (or executing it itself depending on requirements).
4. The lease must be set to expire after a period of time and the coordinator must periodically renew the lease. If the coordinator crashes or becomes unavailable it won’t be able to renew the lease on the mutext which will eventually become available again.
5. All service instances periodically check the mutex to see if the lease has expired. If a service instance finds the lease on the mutex to be available it attempts to secure the lease. If it succeeds the instance becomes the new coordinator.

Note that the mutext becomes a potential single point of failure so consideration should be given to a scenario where unavailability of the mutex can prevent the cluster from electing a coordinator.

Another characteristic of using a shared mutex in this way is that election of the leader is non-deterministic. Any service instance in the cluster could take on the role of coordinator.

A good explanation of the shared mutex approach can be found in this article from MSDN.

Bully algorithm

There are some assumptions for the Bully Algorithm:

• Each instance in the cluster has a unique identifier which must be an ordinal. This could be a process number or even a network address but whatever it is we should be able to order instances in the cluster using this identifier.
• Each instance knows the identifiers of the other instances that should be participating in the cluster (some may be dead for whatever reason).
• Service instances don’t know which ones are available and which are not.
• Service instances must be able to send messages to each other.

The basis of the Bully Algorithm is the service instance with the highest identifier will be the coordinator. The algorithm provides a mechanism for service instances to discover which of them has the highest identifier and for that instance to bully the others into submission by claiming the coordinator role. It follows this basic process:

1. A service instance sends an ELECTION message to all instances with identifiers greater than its own and awaits responses.
2. If no service instances respond the originator can conclude it has the highest identifier and is therefore safe to assume the role of coordinator. The instance sends a COORDINATOR message to all other instances announcing the fact. Other instances will then start to periodically check that the coordinator is still available. If it isn’t, the instance that finds the coordinator unavailable will start a new election (back to step 1).
3. Any service instance receiving an ELECTION message and having an identifier greater than the originator will respond with an OK message indicating it’s available.
4. If in response to an ELECTION message the originator receives an OK response back it knows there’s at least one service instance with a higher identifier than itself. The following then happens:
   1. The original service instance abandons the election (because it knows there’s at least one process with a higher identifier than itself).
   2. Any instances that responded to the ELECTION message with OK now issue ELECTION messages themselves (they start at step 1) and the process repeats until the service with the highest identifier has been elected.

A nice description of the process can be found in this article.

Ring algorithm

As with the Bully Algorithm there are some basic assumptions for the Ring Alorithm.

• The service instances are ordered in some way.
• Each service instance uses the ordering to know who its successor is (in fact it needs to know about all the instances in the ring, as we will see below).

The Ring Algorithm basically works like this:

1. All service instances monitor the coordinator.
2. If any service instance finds the coordinator is not available it sends an ELECTION message to its successor. If the successor is not available the message is sent to the next instance in the ring until an active one is found.
3. Each service instance that receives the ELECTION message adds its identifier to the message and passes it on as in step 2.
4. Eventually the message gets back to the originating process instance which recognises the fact because its own identifier is in the list. It examines the list of active instances and finds the one with the highest identifier. The instance then issues a COORDINATOR message informing all the instances in the ring which one is now coordinator (the one with the highest identifier).
5. The service instance with the highest identifier has now been elected as the coordinator and processing resumes.

Note that multiple instances could recognise that the coordinator is unavailable resulting in multiple ELECTION and COORDINATOR messages being sent around the ring. This doesn’t matter, the result is the same.

Other things to look at

A NuGet package is available for a light-weight non-intrusive leader election library for .Net called NanoCluster. Source code is available on GitHub here:

https://github.com/ruslander/NanoCluster

It’s a small project and doesn’t seem to have been used a great deal but might provide some ideas.

References

• Cloud Networking: IP Broadcasting and Multicasting in Amazon EC2 - https://www.ravellosystems.com/blog/cloud-networking-ip-broadcasting-multicasting-amazon-ec2/
• Amazon VPC FAQs - https://aws.amazon.com/vpc/faqs/#R4
• Leader Election Pattern - https://msdn.microsoft.com/en-gb/library/dn568104.aspx
• Apache ZooKeeper - https://zookeeper.apache.org/

This post follows on from 2 previous posts: Running statsd on Windows and Testing Log4Net.Async with statsd and Graphite. In those posts I set up a virtual Linux box which hosted statsd and Graphite before experimenting with log4Net to compare performance when using different appenders. In this post I’m going to look at some .Net statsd clients to see how they compare with regards to performance and usability.

Now, the performance tests I describe below aren’t particularly scientific given my machine is running a lot of applications - including the virtual machine hosting statsd and Graphite. I ran each of the tests a number of times and the elapsed times I provide below are rough averages and should be taken as indicative of performance only. This is ‘finger in the air’ testing and any conclusions should be taken with a pinch of salt.

Statsd C# Client

I created a really simple console application to send a counter to statsd from inside a ‘for’ loop which ran 100,000 iterations. For the first version I used the Statsd C# Client which I used in my previous posts.

namespace StatsD.Client.Test
{
    using System;

    using StatsdClient;

    /// <summary>
    /// The main program class.
    /// </summary>
    class Program
    {
        /// <summary>The stopwatch.</summary>
        private static System.Diagnostics.Stopwatch stopwatch;

        /// <summary>
        /// Defines the entry point of the application.
        /// </summary>
        /// <param name="args">The arguments.</param>
        static void Main(string[] args)
        {
            Configure();
            Start();

            for (int i = 0; i < 100000; i++)
            {
                Metrics.Counter("test-counter");
            }
            
            Stop();
        }

        /// <summary>
        /// Creates and starts the stopwatch.
        /// </summary>
        private static void Start()
        {
            stopwatch = System.Diagnostics.Stopwatch.StartNew();
        }

        /// <summary>
        /// Stops the stopwatch and outputs the elapsed time.
        /// </summary>
        private static void Stop()
        {
            stopwatch.Stop();
            Console.WriteLine("Elapsed time: {0}", stopwatch.ElapsedMilliseconds);
            Console.ReadKey();
        }

        /// <summary>
        /// Configure th <c>statsd</c> client.
        /// </summary>
        private static void Configure()
        {
            var metricsConfig = new MetricsConfig
            {
                StatsdServerName = "localhost",
                StatsdServerPort = 8125
            };

            Metrics.Configure(metricsConfig);   
        }
    }
}

Running this took 591 milliseconds.

From a usability point of view the API is quite nice offering the static Metrics class used above or a more direct Statsd class which you have to instantiate. The nice thing about the static Metrics class is that you can use it from within a ‘using’ block.

using (Metrics.StartTimer("stat-name"))
{
  DoMagic();
}

However, I’m rather cautious of using static classes as they tend to lead to code that violates the open/closed principle and can make testing awkward. I’m inclined to wrap frameworks in my own service classed that implement interfaces I can easily mock in unit tests.

NStatsD.Client

For the next test I used the NStatsD.Client by Rob Bihun. There haven’t been any commits to the GitHub repo for 7 months or so. This package adds a bit of configuration to the App.config file so no need for configuration in code.

<?xml version="1.0" encoding="utf-8"?>
<configuration>
  <configSections>
    <section name="statsD" type="NStatsD.StatsDConfigurationSection, NStatsD.Client" />
  </configSections>
  <startup> 
    <supportedRuntime version="v4.0" sku=".NETFramework,Version=v4.5.1" />
  </startup>
  <statsD>
    <server host="localhost" port="8125" />
  </statsD>
</configuration>

Running the NStatsD.Client version took 1031 milliseconds. Interesting.

The API is ‘no frills’ but gets the job done. The API isn’t using static classes but rather employs the singleton pattern.

NStatsD.Client.Current.Increment("increment");
NStatsD.Client.Current.Increment("increment", 0.5); // Optional Sample Rate included on all methods
NStatsD.Client.Current.Decrement("decrement");
NStatsD.Client.Current.Timing("timing", 2345);
NStatsD.Client.Current.Gauge("gauge", 45);

NStatsD.HighPerformance

Next I tried the NStatsD.HighPerformance package. This is actually a fork of the NStatsD.Client and was created by Aaron Stannard, one of the driving forces behind Akka.Net a really interesting framework for creating distributed systems using the Actor model.

Aaron has a very interesting blog post on the Tradeoffs in High Performance Software which talks about his fork of the NStatsD.Client. The big change is in the private SendToStatsD method of the Client class. Originally it looked like this:

private void SendToStatsD(Dictionary<string, string> sampledData, AsyncCallback callback)
{
	var prefix = Config.Prefix;
	var encoding = new System.Text.ASCIIEncoding();

	foreach (var stat in sampledData.Keys)
	{
		var stringToSend = string.Format("{0}{1}:{2}", prefix, stat, sampledData[stat]);
		var sendData = encoding.GetBytes(stringToSend);
		_client.BeginSend(sendData, sendData.Length, callback, null);
	}
}

By simply changing the async BeginSend call to an inline Send he got an improvement in performance of around 40%.

private void SendToStatsD(Dictionary<string, string> sampledData, AsyncCallback callback)
{
	var prefix = Config.Prefix;
	foreach (var stat in sampledData.Keys)
	{
		var stringToSend = string.Format("{0}{1}:{2}", prefix, stat, sampledData[stat]);
		var sendData = Encoding.ASCII.GetBytes(stringToSend);
		UdpClient.Send(sendData, sendData.Length);
	}
}

There hasn’t been any activity on the GitHub repo for over 9 months so I guess this is considered done.

Running the NStatsD.HighPerformance version resulted in an elapsed time of about 691 milliseconds. Not surprisingly the API is identical to NStatsD.Client.

Graphite

The next package I tried was Graphite, a project inspired by MiniProfiler. This project seems to have a larger scope than some of the others I’ve looked at and provides hooks for Elmah and WCF. With this package you can send metrics to statsd or directly to Graphite (the graphing framework). I note that there haven’t been any commits to the GitHub repo for a year or so.

Running the Graphite version resulted in an elapsed time of about 608 milliseconds.

From an API point of view Graphite looks quite nice. Configuration is done through App.config again and the API provides for ‘using’ statements for timers (you can see the MiniProfiler influence here). For timers there’s a special Step method that basically measure the time taken for the Dispose method to be called.

using (MetricsPipe.Current.Step("duration"))
{
    // Do some work here...
}

Wrapping up

As my old Dad used to say, ‘you pays your money and you takes your choice’. That seems to be the case here. There isn’t a massive difference in performance between any of them. One thing you might like to take in to consideration is the user base.

Judging by the number of NuGet downloads and performance the Statsd C# Client comes out on top.

Example code: You can get the example code for this post on BitBucket.

Carrying on from my previous post, Running statsd on Windows, I thought it would be interesting to try to gather some application metrics and send them to statsd. I’ve also been meaning to have a look at the Log4Net.Async library for a while and thought I might be able to combine the two objectives: having a look at Log4Net.Async, and experimenting with statsd metrics to see how the Log4Net.Async appenders compare with standard log4Net ones.

The first question is, how to get metrics out of an application and in to statsd? Not surprisingly someone has beaten me to it – quite a few people have actually – and there are a number of libraries out there. I chose the Statsd C# Client library which seems to have had a good number of downloads on NuGet.

• Statsd C# Client - https://www.nuget.org/packages/StatsdClient/
• Log4Net.Async - https://www.nuget.org/packages/Log4Net.Async/

I have a simple logging library of my own that can use log4Net. So, I decided to use my library to create a simple application to write to a log file in a loop and to time how long it took to do a large number of writes.

Getting the NuGet packages

The first step was to create a console application and to add Log4Net.Async and the Statsd C# Client NuGet packages.

The code

I started by creating a simple interface for a logging service. This allowed me to created separate implementations that could be assigned separate log4Net loggers and subsequently separate appenders.

namespace Logging.StatsD
{
    /// <summary>
    /// Classes implementing this interface will write to the log.
    /// </summary>
    public interface ILoggingService
    {
        /// <summary>Does the logging.</summary>
        /// <param name="numberOfTimes">The number of times to log.</param>
        void DoLogging(int numberOfTimes);
    }
}

I created 3 implementations of the ILoggingService:

• SynchronousLoggingService
  • Logged messages from this class would be handled by a standard log4Net RollingFileAppender
• AsynchronousLoggingService
  • Logged messages from this class would be handled by one of the Log4Net.Async appenders.
• AsyncAwaitLoggingService
  • Just out of interest I used async await – somewhat naively – to wrap calls to the logger in a task.

Here’s an example of one of the logging services, the SynchronousLoggingService:

namespace Logging.StatsD
{
    using Andy.French.Logging;

    using StatsdClient;

    /// <summary>
    /// This class will write to the log synchronously.
    /// </summary>
    public class SynchronousLoggingService : ILoggingService
    {
        /// <summary>The logger.</summary>
        private ILogger logger;

        /// <summary>
        /// Initialises a new instance of the <see cref="SynchronousLoggingService"/> class.
        /// </summary>
        /// <param name="loggerFactory">The logger factory.</param>
        public SynchronousLoggingService(ILoggerFactory loggerFactory)
        {
            this.logger = loggerFactory.CreateInstance(typeof(SynchronousLoggingService));
        }

        /// <summary>
        /// Does the logging.
        /// </summary>
        /// <param name="numberOfTimes">The number of times to log.</param>
        public void DoLogging(int numberOfTimes)
        {
            using (Metrics.StartTimer("time-to-log-sync"))
            {
                for (int i = 0; i < numberOfTimes; i++)
                {
                    this.logger.Debug("This is test message {0} from the SynchronousLoggingService.", i);
                }
            }
        }
    }
}

You can see that the DoLogging method simply writes a Debug message to the log in a ‘for’ loop. The most interesting line is line 30. This is a call to the Statsd C# Client library and creates a timer around the code enclosed by the using statement. Note the name of the metric (time-to-log-sync). Similar code was added to the other logging services but with each one using a unique metric name.

So far we only have half of the story. What remains is the need to configure the Statsd C# Client library before it can successfully send messages to statsd. That was done in the main program.

namespace Logging.StatsD
{
    using System;

    using Andy.French.Configuration.Service;
    
    using Ninject;

    using StatsdClient;

    /// <summary>
    /// The main program.
    /// </summary>
    public class Program
    {
        /// <summary>The configuration service.</summary>
        private static IConfigurationService configurationService;

        /// <summary>The synchronous logging service.</summary>
        private static ILoggingService synchronousLoggingService;

        /// <summary>The asynchronous logging service.</summary>
        private static ILoggingService asynchronousLoggingService;

        /// <summary>The async await logging service.</summary>
        private static ILoggingService asyncAwaitLoggingService;

        /// <summary>
        /// Defines the entry point of the application.
        /// </summary>
        /// <param name="args">The arguments.</param>
        public static void Main(string[] args)
        {
            try
            {
                ConfigureMetrics();
                ResolveDependencies();

                var numberOfTimes = configurationService.GetInt("Number.Of.Times");

                asynchronousLoggingService.DoLogging(numberOfTimes);
                synchronousLoggingService.DoLogging(numberOfTimes);
                asyncAwaitLoggingService.DoLogging(numberOfTimes);
            }
            catch (Exception ex)
            {
                Console.WriteLine("An error occurred: {0}", ex.Message);
            }
        }

        /// <summary>
        /// Configures the <c>statsd</c> client.
        /// </summary>
        private static void ConfigureMetrics()
        {
            var metricsConfig = new MetricsConfig
            {
                StatsdServerName = "localhost",
                StatsdServerPort = 8125
            };

            Metrics.Configure(metricsConfig);
        }

        /// <summary>
        /// Resolves the dependencies.
        /// </summary>
        private static void ResolveDependencies()
        {
            var kernel = new StandardKernel(new ProgramModule());
            configurationService = kernel.Get<IConfigurationService>();
            synchronousLoggingService = kernel.Get<ILoggingService>("Synchronous");
            asynchronousLoggingService = kernel.Get<ILoggingService>("Asynchronous");
            asyncAwaitLoggingService = kernel.Get<ILoggingService>("AsyncAwait");
        }
    }
}

The Statsd C# Client library is configured in the call to the ConfigureMetrics method. Here we specify the statsd server name and port by creating a new instance of MetricsConfig and passing it to the static Metrics.Configure method.

Note – To find the statsd port I went back into the Chef cookbooks created when I set up the virtual machine. In <statsd-graphite-vm repository directory>\cookbooks\statsd\attributes there’s a default.rb file. The default.rb file contains the settings used to setup statsd in the virtual machine, including the port number.

default["statsd"]["dir"]                          = "/usr/share/statsd"
default["statsd"]["conf_dir"]                     = "/etc/statsd"
default["statsd"]["repository"]                   = "https://github.com/etsy/statsd.git"
default["statsd"]["reference"]                    = "master"
default["statsd"]["flush_interval"]               = 10000
default["statsd"]["percent_threshold"]            = 90
default["statsd"]["address"]                      = "0.0.0.0"
default["statsd"]["port"]                         = 8125
default["statsd"]["mgmt_address"]                 = "0.0.0.0"
default["statsd"]["mgmt_port"]                    = 8126
default["statsd"]["graphite_host"]                = "127.0.0.1"
default["statsd"]["graphite_port"]                = 2003
default["statsd"]["graphite_role"]                = "graphite_server"
default["statsd"]["graphite_query"]               = "roles:#{node['statsd']['graphite_role']} AND chef_environment:#{node.chef_environment}"
default["statsd"]["delete_idle_stats"]            = false
default["statsd"]["delete_timers"]                = false
default["statsd"]["delete_gauges"]                = false
default["statsd"]["delete_sets"]                  = false
default["statsd"]["delete_counters"]              = false
default["statsd"]["username"]                     = "statsd"
default["statsd"]["debug"]                        = false
default["statsd"]["dump_messages"]                = false

# Graphite storage config
default["statsd"]["graphite"]["legacy_namespace"] = true
default["statsd"]["graphite"]["global_prefix"]    = "stats"
default["statsd"]["graphite"]["global_suffix"]    = ""
default["statsd"]["graphite"]["prefix_counter"]   = "counters"
default["statsd"]["graphite"]["prefix_timer"]     = "timers"
default["statsd"]["graphite"]["prefix_gauge"]     = "gauges"
default["statsd"]["graphite"]["prefix_set"]       = "sets"

# nodejs
default["statsd"]["nodejs_bin"] = "#{node["nodejs"]["dir"]}/bin/node"

Configuring log4Net

At this point I had the code to write to a log but I still needed to configure log4Net. The log4Net configuration was all in  App.config.

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" />
  </configSections>
  
  <log4net>
    <appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender">
      <file value="log.txt" />
      <immediateFlush value="true" />
      <appendToFile value="true" />
      <maximumFileSize value="100MB" />
      <maxSizeRollBackups value="2" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date [%thread] %-5level %logger - %message%newline" />
      </layout>
      <lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
    </appender>

    <appender name="AsyncForwarder" type="Log4Net.Async.AsyncForwardingAppender,Log4Net.Async">
      <appender-ref ref="RollingFileAppender" />
    </appender>

    <logger name="Logging.StatsD.AsynchronousLoggingService">
      <level value="DEBUG" />
      <appender-ref ref="AsyncForwarder" />
      <!--<appender-ref ref="AsyncRollingFileAppender" />-->
    </logger>

    <logger name="Logging.StatsD.SynchronousLoggingService">
      <level value="DEBUG" />
      <appender-ref ref="RollingFileAppender" />
    </logger>

    <logger name="Logging.StatsD.AsyncAwaitLoggingService">
      <level value="DEBUG" />
      <appender-ref ref="RollingFileAppender" />
    </logger>
    
  </log4net>

  <appSettings>
    <add key="Number.Of.Times" value="10000" />
  </appSettings>
  
  <startup> 
    <supportedRuntime version="v4.0" sku=".NETFramework,Version=v4.5.1" />
  </startup>
</configuration>

Starting on line 24 there are 3 loggers, one for each of the logging service classes I created. Each logger was configured to use one of the appenders defined on lines 8 and 20:

• RollingFileAppender – a standard log4Net rolling file appender
• AsyncForwarder – A Log4Net.Async appender. This appender uses a ring buffer and it is possible for message loss to take place. More on that later.

A note about Log4Net.Async appenders

It pays to read documentation and that’s certainly true of the Log4Net.Async library. In my test application the logger created for the AsynchronousLoggingService is set to use the AsyncForwarder appender. This appender – one of the Log4Net.Async appenders - provides high performance at the expense of potential lost messages.

And lost messages is what I got. When running the example I saw occasional log entries like this:

2015-04-05 10:15:13,886 [AsyncForwarder Forwarding Appender Thread] ERROR AsyncForwardingAppender - Buffer overflow. 13 logging events have been lost in the last 30 seconds. [BufferSize: 1000]

This isn’t an error; it’s by design.

“This appender utilizes a ring buffer with a a default limit of 1000 messages. If the head of the buffer overtakes the tail, message loss occurs. This behavior prioritizes application performance over logging fidelity. The current implementation uses a 10ms polling (sleep) period on the background thread.” - https://github.com/cjbhaines/Log4Net.Async

If you need lossless messaging another option is to use the ParallelForwardingAppender.

“This appender utilizes System.Collections.Concurrent.BlockingCollection(T) and other facets of the Task Parallel Library (TPL) to implement a lossless message queue. This implementation does not use polling but rather waits until new messages are available to append. This results in less CPU overhead for queue polling and appending starts without having to wait on sleep expiration.” - https://github.com/cjbhaines/Log4Net.Async

Trying things out

I ran the application a number of times over the course of a few minutes and then viewed the Graphite UI in my browser (to get to the Graphite I went to http://localhost:8888 as described in my previous post). By expanding the Graphite > stats > timers folder on the Graphite page I was able to see the 3 metrics I added to the application. That confirmed that the metrics were in fact being forwarded to statsd. Cool!

By expanding each of the timers I could see various values which I could select and add to the graph. I chose the ‘upper’ value for each of the 3 timers.

Once the values had been chosen for each of the metrics the results appeared in the graph. I ran the test application approximately once a minute over a 10 minute period so to make things clearer I configured the graph to only show data for the last 10 minutes. I also changed the line type to be a connected line.

Now I have to say I was blown away by what I saw. The version of the logging service that was using the Log4Net.Async forwarding appender was blisteringly fast. Check out the graph for yourself.

I’m a bit suspicious so I did some additional tests using a StopWatch in the code but the results were confirmed. The down-side was lost messages (roughly between 8 and 20 per run).

My naive async await implementation certainly wasn’t any faster – it was actually slower - although I could see that logging work was being assigned to different threads.

As an experiment I switched to a different Log4Net.Async appender, the ParallelForwardingAppender, which guarantees message delivery and tried again.

Not as fast as the AsyncForwardingAppender but still much faster than the standard log4Net appender.

Wrapping up

So there we have it. We’ve managed to get metrics from an application into statsd using the Statsd C# Client library and we’ve seen that the Log4Net.Async appenders offer performance gains over the standard log4Net equivalents. We’ve also managed to view the metrics in Graphite.

Result! Glass of wine anybody?

We are going to be using statsd (or possibly Heka) to consume and analyse performance metrics for our applications. Being a curious soul I wanted to start playing with statsd on a Windows 8.1 machine at home but quickly discovered that the best approach is to go with Linux.

There are quite a few projects knocking around on GitHub to help build virtual machines with statsd and Graphite – a graphing solution that allows time series data to be visualised – but I chose José Padilla’s statsd-graphite-vm as a starting point although I had to customise things a little because I didn’t have all the necessary infrastructure in place.

José’s solution makes use of several technologies:

• VirtualBox - a x86 and AMD64/Intel64 virtualization product
• Vagrant – orchestrates the provisioning of the virtual environment
• Chef – an automation platform for building virtualised environments

At the end of the process I ended up with a virtual Linux box running 32-bit Ubuntu complete with statsd and Graphite.

Cloning the statsd-graphite-vm project

The first step was to clone the statsd-graphite-vm project from GitHub. I chose to use SourceTree because it’s nice.

Installing VirtualBox

OK, I love Chocolatey. I was late to the game here but I have to say if you’re not using it already you really should. There’s no messing around finding the latest version of something or worrying about 32 or 64-bit distributions. You just ask Chocolatey to install a package by name and away it goes.

So, the next thing to do here is to install VirtualBox. Time to fire up Chocolatey.

That’s it. VitualBox is installed. VirtualBox is described in the following terms:

“VirtualBox is a powerful x86 and AMD64/Intel64 virtualization product for enterprise as well as home use. Not only is VirtualBox an extremely feature rich, high performance product for enterprise customers, it is also the only professional solution that is freely available as Open Source Software under the terms of the GNU General Public License (GPL) version 2.” - https://www.virtualbox.org/

Basically, VirtualBox gives us a virtual machine into which we can load an operating system etc. a process which is greatly simplified by using Vagrant. 

Installing Vagrant

The next piece of the puzzle is Vagrant. Chocolatey to the rescue again.

So what part is Vagrant playing? Vagrant is described thus:

“Vagrant provides easy to configure, reproducible, and portable work environments built on top of industry-standard technology and controlled by a single consistent workflow to help maximize the productivity and flexibility of you and your team.

To achieve its magic, Vagrant stands on the shoulders of giants. Machines are provisioned on top of VirtualBox, VMware, AWS, or any other provider. Then, industry-standard provisioning tools such as shell scripts, Chef, or Puppet, can be used to automatically install and configure software on the machine.” - https://docs.vagrantup.com/v2/why-vagrant/

And:

“If you're a developer, Vagrant will isolate dependencies and their configuration within a single disposable, consistent environment, without sacrificing any of the tools you're used to working with (editors, browsers, debuggers, etc.). Once you or someone else creates a single Vagrantfile, you just need to vagrant up and everything is installed and configured for you to work.” - https://docs.vagrantup.com/v2/why-vagrant/

If you look inside the statsd-graphite-vm folder you’ll find a Vagrantfile. This file is read by Vagrant and is used to define the type of virtual machine we want including instructions to run Chef to setup software etc. Chef is being used to create a ‘recipe’ of all the ingredients we need included in the new virtual machine.

My customisation - Getting the Chef cookbooks

Now, the statsd-graphite-vm solution uses Chef to configure all the bits and pieces that go in to building the virtual machine. In fact, the statsd-graphite-vm project suggests you use librarian-chef to automatically download all the Chef cookbooks required to build the VM by running ‘librarian-chef install’ as the first step in the process of provisioning the new virtual machine. This really simplifies things – or at least it should - but after a lot of time spent installing Ruby and getting librarian-chef up-and-running I was still having problems (e.g. SSL certificate issues).

Life’s too short so I abandoned that approach and elected to download the cookbooks manually. To do that I created a ‘cookbooks’ folder under statsd-graphite-vm, hit the interweb and Googled with Bing to find the necessary cookbooks and put them in the cookbooks folder myself. A bit of a pain but it worked.

If you choose to do the same the full set of cookbooks looks like this:

If you’re looking for Chef cookbooks a great place to start is the Chef Supermarket. An alternative for some of the cookbooks used here is Hector Castro’s contributions on GitHub. I used a variety of locations which I’ve listed here:

• apt: https://supermarket.chef.io/cookbooks/apt
• ark: https://github.com/burtlo/ark
• apache2 from here: https://supermarket.chef.io/cookbooks/apache2
• build-essential: https://supermarket.chef.io/cookbooks/build-essential
• chef_handler: https://github.com/opscode-cookbooks/chef_handler
• dmg: https://supermarket.chef.io/cookbooks/dmg
• git: https://supermarket.chef.io/cookbooks/git
• graphite: https://github.com/hectcastro/chef-graphite
• iptables from here: https://supermarket.chef.io/cookbooks/iptables
• logrotate: https://supermarket.chef.io/cookbooks/logrotate
• memcached: https://github.com/opscode-cookbooks/memcached
• nodejs: https://github.com/hectcastro/chef-nodejs
• python: https://supermarket.chef.io/cookbooks/python
• runit: https://supermarket.chef.io/cookbooks/runit
• statsd: https://github.com/hectcastro/chef-statsd
• yum: https://supermarket.chef.io/cookbooks/yum
• yum-epel: https://supermarket.chef.io/cookbooks/yum-epel
• windows: https://supermarket.chef.io/cookbooks/windows

Firing up the VM

At this point things are just about ready to go but I found that I needed to change a port number in the Vagrantfile to avoid a conflict. I changed the forward_port for port 80 to be 8888 from the default 8080.

# -*- mode: ruby -*-
# vi: set ft=ruby :
#^syntax detection

VAGRANTFILE_API_VERSION = "2"

Vagrant.configure(VAGRANTFILE_API_VERSION) do |config|

  # Every Vagrant virtual environment requires a box to build off of.
  config.vm.box = 'precise32'
  config.vm.box_url = 'http://files.vagrantup.com/precise32.box'

  # Forward a port from the guest to the host, which allows for outside
  # computers to access the VM, whereas host only networking does not.
  config.vm.network 'forwarded_port', guest: 80, host: 8888
  config.vm.network 'forwarded_port', guest: 8125, host: 8125, protocol: 'udp'
  config.vm.network 'forwarded_port', guest: 8126, host: 8126

  config.vm.provision 'chef_solo' do |chef|
    chef.add_recipe 'apt'
    chef.add_recipe 'graphite'
    chef.add_recipe 'nodejs'
    chef.add_recipe 'statsd'
  end

end

You can also see in the Vagrantfile that the build is based on a ‘box’ called precise32 (in this case a 32-bit Ubuntu 12.04 build). What is a box?

“Instead of building a virtual machine from scratch, which would be a slow and tedious process, Vagrant uses a base image to quickly clone a virtual machine. These base images are known as boxes in Vagrant, and specifying the box to use for your Vagrant environment is always the first step after creating a new Vagrantfile.” - http://docs.vagrantup.com/v2/getting-started/boxes.html

Precise32 is a standard Ubuntu 12.04 LTS 32-bit box from HashiCorp's Atlas box catalog.

Once all the above had been done I was able to start the VM by issuing a simple Vagrant command. I opened a command prompt and changed to the statsd-graphite-vm folder before running the following:

vagrant up
vagrant ssh

And we are in!

So, let’s see what we get if we browse http://localhost:8888 in a web browser.

Boom shakalaka, rude boy!

More revision, a few musings and another aide-mémoire.

Idempotence is a subject of much debate and seems to mean different things to different people when used in different contexts. This post is just a quick mile-high overview by way of a bit of revision.

Idempotence defined

Lets pop over to Wikipedia and get a definition of idempotence:

“Idempotence (/ˌaɪdɨmˈpoʊtəns/ EYE-dəm-POH-təns) is the property of certain operations in mathematics and computer science, that can be applied multiple times without changing the result beyond the initial application.” [1]

“In computer science, the term idempotent is used more comprehensively to describe an operation that will produce the same results if executed once or multiple times. This may have a different meaning depending on the context in which it is applied. In the case of methods or subroutine calls with side effects, for instance, it means that the modified state remains the same after the first call…

This is a very useful property in many situations, as it means that an operation can be repeated or retried as often as necessary without causing unintended effects. With non-idempotent operations, the algorithm may have to keep track of whether the operation was already performed or not.” [2]

So for our purposes idempotence is the property of an operation that means if it is executed once or multiple times the result will always be the same. Now it’s the result that seems to be cause of the debate.

There are often side effects – sometimes quite subtle - that could be considered part of the result. For example, if you were to create an audit record every time an apparently idempotent operation is executed is that still idempotent? The answer is ‘probably not’ but will depend on the expected behaviour of the application. Logging, auditing and monitoring may be considered side effects of message handling:

“These side effects are not relevant to the semantics of the application behavior, so the processing of an idempotent request is still considered idempotent even if side effects exist.” [6]

Idempotence in HTTP

In HTTP there are some methods that are considered idempotent.

“Methods can also have the property of "idempotence" in that (aside from error or expiration issues) the side-effects of N > 0 identical requests is the same as for a single request. The methods GET, HEAD, PUT and DELETE share this property. Also, the methods OPTIONS and TRACE should not have side effects, and so are inherently idempotent.” [3]

Actually in practice there are some potential pitfalls with methods like DELETE. Although the result of a delete operation on the server may be idempotent – deleting the same resource multiple times has the same effect - it is possible for repeated DELETE operations on the same resource to return different HTTP status codes. An initial call to DELETE may return a status code of 200 but subsequent calls could return 404. From the client side the operation may not appear to be idempotent.  

Idempotency is a concept that features in REST quite a bit and is regarded as an important characteristic of fault-tolerant APIs. In REST the result may well be the resource representation so issues about audit records etc. may not be a concern. To illustrate here’s a quote from http://restcookbook.com:

“An idempotent HTTP method is a HTTP method that can be called many times without different outcomes. It would not matter if the method is called only once, or ten times over. The result should be the same. Again, this only applies to the result, not the resource itself. This still can be manipulated (like an update-timestamp, provided this information is not shared in the (current) resource representation.” [4]

So the author is drawing a distinction here between the actual resource and it’s representation. As long as the representation doesn’t change then the operation is regarded as idempotent.

Idempotence in messaging

Idempotence in message-based systems is very useful because it helps avoid the necessity of using strategies such as two-phase commit (2PC) to manage distributed transactions. Essentially 2PC in a message-based system means that a message must be processed exactly once by the cohorts participating in the distributed transaction. As we know there are potential drawbacks to using 2PC because it is a blocking protocol that potentially ties up resources.

With a 2PC strategy in place the coordinating process has to determine if a failure condition has occurred and abort the distributed transaction. This causes all participating cohorts to abort their part of the distributed transaction. In a message-based system this effectively means that the messages sent to the cohorts are regarded as not having been processed. Recovering from the failure requires the coordinator to replay the whole distributed transaction by republishing the messages.

An alternative approach is to use a strategy where a message is processed at least once. With this strategy if a failure occurs the original message may be published again by the coordinating process but recipients that have already processed the message are expected to ignore it. This can be achieved 2 ways: have a mechanism in place to remove duplicate messages from being processed by participating cohorts, or messages have to be idempotent. [5]

A typical pattern for handling messages is for a message to be read from a queue, processed, and then removed from the queue.[6] In this scenario if a failure occurs after the message has been processed but before the message has been removed from the queue (e.g. there’s a power failure) the message will be processed twice. If the messages are idempotent this is no longer a concern.

Strategies for implementing idempotent messages include:

• Natural idempotency – some messages are naturally idempotent (processing them multiple times has the same effect). In much the same way as an HTTP DELETE can be idempotent so could a message to delete a resource.
• Use a correlation identifier – add a unique identifier to each message and use it to see if the message has been processed before.

Idempotence and SOA

Just a quick note here that idempotence has a place to play in a service oriented architecture because it facilities fault-tolerance:

“Idempotency guarantees that repeated invocations of a service capability are safe and will have no negative effect.

Idempotent capabilities are generally limited to read-only data retrieval and queries. For capabilities that do request changes to service state, their logic is generally based on "set", "put" or "delete" actions that have a post-condition that does not depend on the original state of the service.

The design of an idempotent capability can include the use of a unique identifier with each request so that repeated requests (with the same identifier value) that have already been processed will be discarded or ignored by the service capability, rather than being processed again.” [7]

References

[1] Idempotence (Wikipedia)

[2] Idempotence – Computer science meaning (Wikipedia)

[3] RFC 2616 Part 9

[4] The RESTful CookBook – Idempotency

[5] (Un) Reliability in messaging: idempotency and de-duplication (Jimmy Bogard, Los Techies)

[6] Idempotence Is Not a Medical Condition (Pat Helland, acm.org)

[7] Idempotent Capability

Time for a bit of revision. What is Two-phase Commit (2PC)?

Firstly, there’s lots of in formation out there on 2PC including Wkikpedia and MSDN. Those articles will go into much more detail about 2PC than I will here. This post is really just an aide-mémoire.

In a nutshell:

“It is a distributed algorithm that coordinates all the processes that participate in a distributed atomic transaction on whether to commit or abort (roll back) the transaction (it is a specialized type of consensus protocol). The protocol achieves its goal even in many cases of temporary system failure (involving either process, network node, communication, etc. failures), and is thus widely utilized.” [1]

Essentially 2PC provides a mechanism for tasks to be executed across separate systems as a single atomic distributed transaction. For example you might want to make updates to separate databases on different servers - with each update running in its own transaction - and have the whole process run as a single distributed transaction. If an error occurs during any of the component transactions then all of the transactions should be aborted (rolled back).

Note that 2PC does not have to apply to database transactions. A step in the process could mean executing a program.

“The term transaction (or any of its derivatives, such as transactional), might be misleading. In many cases, the term transaction describes a single program executing on a mainframe computer that does not use the 2PC protocol. In other cases, however, it is used to denote an operation that is carried out by multiple programs on multiple computers that are using the 2PC protocol.” [2]

There will be 2 basic actors to 2PC: a coordinating process that manages the distributed transaction, and participating processes (participants, cohorts, or workers).

The 2PC protocol calls for 2 phases (see reference [1] for full details):

• Commit-request phase (or Voting phase)
• The coordinator sends an instruction to all cohorts to undertake their part of the distributed transaction and waits until it has received a reply from all cohorts.
• The cohorts execute the transaction up to the point where they will be asked to commit. They each write an entry to their undo log and an entry to their redo log.
• Each cohort replies with an agreement message (cohort votes Yes to commit), if the cohort's actions succeeded, or an abort message (cohort votes No, not to commit), if the cohort experiences a failure that will make it impossible to commit.
• Commit phase (or Completion phase)
• Success
• If the coordinator received an agreement message from all cohorts during the commit-request phase:
• The coordinator sends a commit message to all the cohorts.
• Each cohort completes the operation, and releases all the locks and resources held during the transaction.
• Each cohort sends an acknowledgment to the coordinator.
• The coordinator completes the transaction when all acknowledgments have been received.
• Failure
• If any cohort votes No during the commit-request phase (or the coordinator's timeout expires):
• The coordinator sends a rollback message to all the cohorts.
• Each cohort undoes the transaction using the undo log, and releases the resources and locks held during the transaction.
• Each cohort sends an acknowledgement to the coordinator.
• The coordinator undoes the transaction when all acknowledgements have been received.

The key point is that the cohorts do their work up to the point that they need to commit their transactions. They then vote on whether or not to commit. If all cohorts vote “Yes” then the coordinator tells all cohorts to commit. If any cohort votes “No” then the coordinator tells all cohorts to abort (rollback).

An interesting scenario to be considered is what happens if a cohort crashes having already voted but before it receives or processes the coordinator’s instruction to commit. The trick here is that the distributed transaction is not committed until all cohorts have acknowledged that they have committed. The coordinator will instruct the crashed cohort to commit when it becomes available again. To make this kind of scenario work the cohorts need to use logging to keep track of what steps they have taken (e.g. the database transaction log):

“To accommodate recovery from failure (automatic in most cases) the protocol's participants use logging of the protocol's states. Log records, which are typically slow to generate but survive failures, are used by the protocol's recovery procedures.” [1]

Disadvantages

The two-phase commit protocol is a blocking protocol. So,

• Resources may be locked by cohorts while waiting for an instruction from the coordinator to commit or abort
• If the coordinator fails permanently, some cohorts will never resolve their transactions

References

[1] Two-phase commit protocol (Wikipedia)

[2] Two-Phase Commit (MSDN)

The Problem

We use CruiseControl.Net (CCNet) for continuous integration and also for automated deployment of applications. The deployment processes usually include compiling an application, configuring it appropriately for a target environment (e.g. test, production, etc.), creating a deployment package such as a Zip archive, and then copying the package to the appropriate server(s) where it is installed.

However, we suddenly started getting failures when running these deployment builds. After checking the CCNet build logs we could see errors such as “Could not find a part of the path \\servername\deploymentfolder”.

Initial checks on the build server showed that the Universal Naming Convention (UNC) paths were actually valid. So what was going on?

The Solution

To find out what was going on I used Process Monitor to see if there were issues accessing the UNC paths.

Firstly, I grabbed the latest version of Process Monitor from Microsoft SysInternals. It’s free and does not need installation – it runs as a single executable. Then I copied Process Monitor (procmon.exe) to the machine in question and ran it. Once it has opened I did the following:

1. Disabled event capture by clicking the magnifying glass icon so it has the red ‘X’ overlay.
2. Clicked the eraser icon to clear all existing captured events.
3. Made sure Process Monitor was only going to capture file system activity by only selecting the filing cabinet icon.

Then I needed to add a filter so I only saw events relating to the file/folder I was interested in:

1. Clicked the filter icon (the Filter > Filter… menu option does the same thing).
2. Once the Process Monitor Filter dialog opened, clicked the Reset button.
3. Using the drop-down menus etc. created a filter that said “Path begins with \\servername\deploymentfolder then include”.
4. Clicked the Add button to add the new filter.

Finally I clicked the magnifying glass icon again to start event capture and forced one of the failing builds to run. Once the build completed I stopped capturing events again. This was the result:

So I could see that NAnt had been unable to copy the deployment file to the server because of a login failure. By double-clicking on an entry in the event list I could see more details about the issue including which account was being used.

Further digging identified the cause of the issue being related to the account being used to run the CCNet service and was easy to correct.

• Single Responsibility Principle
• A class should have one, and only one, reason to change.
• If a class assumes more than one responsibility, then there will be more than one reason for it to
  change.
• If a class has more then one responsibility, then the responsibilities become coupled.
• Open-Closed Principle
• Software entities should be open for extension but closed for modification.
• You should be able to extend a classes behaviour, without modifying it.
• The primary mechanisms behind the Open-Closed principle are abstraction (inheritance) and polymorphism.
• Liskov Substitution Principle
• Derived classes must be substitutable for their base classes.
• Functions that use pointers or references to base classes must be able to use objects of derived classes without knowing it.
• A.K.A. Design By Contract.
• Derived types are completely substitutable for their base types.
• Interface Segregation Principle
• Make fine grained interfaces that are client specific.*
• Clients should not be forced to depend upon interfaces that they do not use.
• Dependency Inversion Principle
• Depend on abstractions, not on concretions.
• Modules that encapsulate high level policy should not depend upon
  modules that implement details.
• High level modules should not depend upon low level modules. Both should depend upon abstractions.
• Abstractions should not depend upon details. Details should depend upon abstractions.

* “This principle deals with the disadvantages of “fat” interfaces. Classes that have “fat” interfaces are classes whose interfaces are not cohesive. In other words, the interfaces of the class can be broken up into groups of member functions. Each group serves a different set of clients. Thus some clients use one group of member functions, and other clients use the other groups.”

"We’ve heard from lots of developers that times are tough. You’re doing more with less, applying your skills more broadly, and maybe even learning new tools. That’s why we created Thrive – a one-stop community hub that offers job postings, technical content, and community resources."