Measure performance with serilog, elasticsearch and kibana

9. oktober 2015

Measure performance metrics with serilog, elasticsearch and kibana

This guide will cover these topics:

 

When you have implemented this example you will be able to log and measure number of processed elements and how long time it takes to process each element. This is really handy if you have a backend service that does not have a UI. When something goes wrong it's crucial to have sufficient data in order to take informed decisions. Otherwise we will be trying to fix something we think is broken. In the dark. With the wrong tools.

Install elasticsearch on windows

Install Java JDK

Elasticsearch is a java application and needs java JDK in order to run.

Go to the java website and download latest JDK version.

 

Set JAVA_HOME variable

When java installation is done you need to set a system variable which points to where you have installed java.

On windows 8, Right click "This PC" and click properties.

Click "Advanced system settings" on the left.

Image frame

 

Click "Enviroment variables"

Image frame

 

Under system variables, click "New"

Image frame

 

Create a variable called "JAVA_HOME" with a value containing the path to your java installation. In my case it was "C:\Program Files\Java\jdk1.7.0_79"

Image frame

 

Download elasticsearch

Goto elastico's website and download the latest version of elasticsearch.

It has no installer so all you need to do is unpack it in the folder where you want it to be. I love this!

Out of the box, elastic search has no UI. You can start it and the only way to speak to it, is through it's REST api. This is not covered by this post.

Elasticsearch has a plugin structure and there's a plugin called HEAD which gives you a web based user interface. Check out their website here.

In order to install this plugin, open a command prompt and go to the directory where you placed elastic search. Also go into the bin folder.

In my case it's C:\temp\elasticsearch-1.7.2\bin

Image frame

To install head, type "plugin -install mobz/elasticsearch-head"

This will download and install HEAD to your local elasticsearch installation.

Image frame

 

If all goes well, you should see something like this.

Image frame

 

Start elasticsearch

Starting elasticsearch is easy. Simply run "elasticsearch.bat" in the /bin folder. This opens a console window with some output from the elasticsearch process.

If you want to have elasticsearch running as a windows service, run "service.bat install".

 

Open HEAD in a browser

Open a browser and navigate to http://localhost:9200/_plugin/head/

This should give you a window like this:

Image frame

Congratulations! Elasticsearch is now up and running!

 

Install Kibana

Download kibana

Go to elastico's website and download the latest version of Kibana.

It's pretty much the same procedure as elasticsearch. Unpack the file in the folder where you want it to be. There is no installer.

To run it, simple run kibana.bat located in the bin folder.

For reasons unknown there is no service.bat as in lasticsearch.

To install kibana as a service, open a command prompt with administrator rights and use the following command:

sc create "ElasticSearch Kibana 4.0.1" binPath= "{Full path to kibana.bat}"

Open Kibana

Once kibana is running, open a browser and navigate to http://localhost:5601

This should take you to kibanas frontpage:

Image frame

 

Setting up a logger class in C# using serilog

Time to write some code. We'll create a logger class which wraps serilog.

Add packages

In your project you need to add two nuget packages:

PM> Install-Package Serilog

PM> Install-Package Serilog.Sinks.ElasticSearch

 

Create log entry class

Create three classes:

PerformanceDurationEntry.cs

 

using System.Diagnostics;

namespace PerformanceLogging
{
    public class PerformanceDurationEntry : IDisposable
    {
        private readonly PerformanceEntryPersistor entryPersistor;
        private Stopwatch stopwatch { get; set; }
        public string KeyName { get; set; }
        public double Duration { get; set; }
        public int ElementsMeasured { get; set; }

        public PerformanceDurationEntry()
        {
            ElementsMeasured = 0;
        }

        public PerformanceDurationEntry(PerformanceEntryPersistor entryPersistor)
        {
            this.entryPersistor = entryPersistor;
            ElementsMeasured = 0;
            
            stopwatch = new Stopwatch();
            stopwatch.Start();
        }

        public void Dispose()         {             if (stopwatch == null)                 return;
            stopwatch.Stop();             Duration = stopwatch.ElapsedMilliseconds;             entryPersistor.PersistDurationEntry(this);         }     } }

 

EntryPersistor.cs

using System;
using Serilog;
using Serilog.Sinks.Elasticsearch;

namespace PerformanceLogging
{
    public class PerformanceEntryPersistor
    {
        private ILogger performanceLogger { get; set; }
        private bool isSetup { get; set; }

        public void Setup(string elasticSearchUrl, string indexName)
        {
            performanceLogger = new LoggerConfiguration()
                .WriteTo.Sink(new ElasticsearchSink(new ElasticsearchSinkOptions(new Uri(elasticSearchUrl))
                {
                    AutoRegisterTemplate = true,
                    IndexDecider = (e, o) =>
                    {
                        return indexName.ToLower();
                    }
                }))
                .MinimumLevel.Verbose()
                .CreateLogger();

            isSetup = true;
        }

        public void PersistDurationEntry(PerformanceDurationEntry durationEntry)
        {
            if (!isSetup)
                throw new InvalidOperationException("PerformanceEntryPersistor is not setup. Run Setup(...) before logging.");
            try
            {
                performanceLogger.Information("DurationEntry {@Data}", durationEntry);
            }
            catch (Exception ex)
            {

            }
        }
    }
}

 

PerformanceLogger.cs

 

namespace PerformanceLogging
{
    public class PerformanceLogger
    {
        private readonly PerformanceEntryPersistor performanceEntryPersistor;

        public PerformanceLogger(PerformanceEntryPersistor performanceEntryPersistor)
        {
            this.performanceEntryPersistor = performanceEntryPersistor;
        }

        public PerformanceDurationEntry NewDurationLog(string keyName)
        {
            var toReturn = new PerformanceDurationEntry(performanceEntryPersistor);
            toReturn.KeyName = keyName;
            return toReturn;
        }
    }
}

 

Log some items

Lets get some data into elasticsearch through our logger.

Find a way to execute this code.

            var randomizer = new Random();
            var persistor = new PerformanceEntryPersistor();
            persistor.Setup("http://localhost:9200/", "PerformanceLog");
            var logger = new PerformanceLogger(persistor);
            
            for (int i = 0; i < 500; i++)
            {
                using (var logEntry = logger.NewDurationLog("DemoMetric"))
                {
                    logEntry.ElementsMeasured = 1;
                    Thread.Sleep(randomizer.Next(10,200));
                }
            }

This will log 500 items with a random duration.

Notice "PerformanceLog" in the persistor constructor. This is the name of the index which the logger will put data into. It will be lower cased in elasticsearch.

Open http://localhost:9200 and click "Browser" tap in the top menu. Here you can browse all data in elasticsearch. Click any item and you can see the content. Should look something like this.

Image frame

 

Setup a nice performance chart in kibana

Configure an index pattern

Open kibana in your browser: http://http://localhost:5601/

By default it should ask you to configure a index pattern, of not go to Settings -> Indicies.

Enter the name of our target index.

IMPORTANT: You must enter it in all lowercase otherwise nothing will come up.

Image frame

Click "Create". This will create the index pattern. Kibana now knows what the performancelog index looks like.

Click "Visualize" and choose "Vertical bar chart".

Choose "From a new search".

Now we have to configure how our bar chart should be constructed.

Click "X-Axis". In "Aggregation" dropdown, choose "Date Histogram". As interval, choose second.

Image frame

 

Click "Y-axis" on top.

As Aggregation, choose average. Field must be set to "fields.Data.Duration".

 

Image frame

 

This configuration will give us the average duration for each second. looking something like this.

Image frame

If no data is visible, it's probably because kibana is looking at a timeframe where your data is not present.

Click "Last 15 minutes" in the top-right corner and adjust it to where your data is.

Or simply run your data insert program again.

Notes about logging in high performance enviroments

It's worth a mention that this type of logging is not suitable for high-performance loops. Each log opens a TCP connection to elasticsearch which will ruin performance. A workaround could be to sum up all metrics in local variables inside your loop, and flush these to elasticsearch in a fixed time interval. It will still impact performance but not nearly as much as logging each item.