Monthly Archives: February 2015

ELK System Overview

Overview

There seem to be a lot of old ELK guides on the internet.  It’s time to make a new one that can begin its own eventual decay.

To help minimize the aging process, I’m not going to cover how to install specific packages on specific platforms, but rather discuss the choice of tools and configurations that are available.

Shipper

You have to get your log files off the remote machines and eventually into Elasticsearch.  It’s the shipper’s job to, um, ship the logs to the next step.

There are a few shippers, some of which are outlined here.

tl;dr: use filebeat if you're only moving logs around.

logstash

You can use the full logstash build as your shipper.  There are almost no reasons to do this.  Being JVM-based, it’s big and takes memory.  It also has more features than you’ll typically need for a shipper.

The only excuse to run logstash as a remote shipper is if you have a ton of logs and need to apply some business logic about which ones to ship.  For example, maybe DEBUG logging is enabled in your production environment (?); you could use a full logstash to only ship the more important levels for processing.

logstash-forwarder

NOTE: logstash-forwarder is dead.  See filebeat, below.

This is the right choice.  It’s a light-weight program that does nothing other than read log files and send them to logstash.  Traffic is encrypted with SSL, so certs are required.

logstash-forwarder speaks the “lumberjack” protocol with logstash.

filebeat

Filebeat is the replacement for logstash-forwarder.  It’s also lightweight, gives you the option of not using encryption, and they’re planning to add some nice client-side features (multiline and a basic ‘grep’).

Filebeat requires logstash 1.5+.

beaver

If you need a broker (see below), then beaver is a lightweight tool that, not being encrypted, can talk to redis.

Broker

Many guides describe the use of a broker like redis or rabbitmq between the shipper and logstash.

If you’re using logstash and/or logstash-forwarder as your shipper, you don’t need a broker.  Both of these packages keep track of where they are in the local files, and should recover from a logstash outage.  (If the outage lasts through a file rotation, this may not be true!).

I only like to use brokers when shipping logs from systems that don’t automatically handle logstash failures (e.g. syslog, netflow, etc).  This covers for unplanned outages, and also lets you release changes to logstash without losing data.

Logstash Indexer

Here’s where the magic happens….  Unstructured data is turned into structured information.   See our guide to patterns and best practices.

Elasticsearch

The storage part of the whole equation.

See our best practices.

Better than NewRelic

Application Performance Logging

You can learn a lot about your code by instrumenting it.  You’ll find methods that are called more than you’re expecting, or be able to identify which part of your code is slowing the app down.

There are Saas solutions for this, like New Relic.  From my experience, New Relic “runs” out of the box, and may provide information on common tools (MySQL, etc), but doesn’t provide any real information about your app without adding instrumentation calls to your code.

Also, New Relic works on an aggregated summary of your application.  If it supplies details on a specific request, I never found it.

If you have to instrument your code, and you want to know exactly what your users are doing, then what’s the appeal of New Relic?

Recently, I was involved with a project to instrument some “under performing” python code.  New Relic had been installed, but had provided no value.

Caveat: I was involved on the analysis side.  Another developer wrote the logging framework.

A performance class was created and we added a custom django handler that initialize a performance object for the request.

To instrument a method, you would wrap it in a ‘with’ statement:

with performanceTracking("block name"):
         some block of code

The ‘with’ syntax provides an __enter__ and __exit__ hook, which was used in the performance class to start and stop a timer for that block of code.  On __exit__, logging information for this block was added to a data structure for the entire request.

When the request finished, the handler would write the entire logging block using the standard logging mechanism.  Log these at DEBUG and it was easy to disable it in production.

What you ended up with was a nested set of performance information:

{
    "requestid": "12345",
    "name": "my web page",
    "calls": 1,
    "duration": 200,
    "children": [
        {
           "calls": 2,
           "name": "mysql user lookup",
           "duration": 190
        },
        {
           "calls": 1,
           "name": "something else",
           "duration": 10
        }
    }
}

You could now see that “mysql user lookup” was called twice (!), and was responsible for 95% of time spent (!).  Even better, you knew this information for this individual request.  You can summarize the performance of these blocks across the system (ala New Relic), but you could also zoom in and see the details for this particular user.  Powerful stuff, right?

With your own code, the possibilities are limitless.  In a web app environment, maybe the page is authenticated.  Add the user’s ID to the logging block, and now you can see exactly what happened for Mary on Tuesday at 10AM.  If you run multiple applications or subsystems, add their identifiers to the logs and you can break performance out by component.

Once the information was written to the logs, it was loaded into an Elasticsearch cluster for analysis.

Performance Analysis

With all of this data, the next step is to see what’s going on.  The ELK environment has come a long way since in the year since this project, so it would probably be even easier now!

With the data properly loaded parsed in logstash and fed into elasticsearch, you can make dashboards in kibana to show things like:

  • total application performance over time (graph the top-level “duration” field).
  • the performance of each code block over time
  • the most-frequently called code blocks
  • the worst-performing code blocks
  • does performance degrade with load?

We found it to be very useful to wrap every third-party API call with this framework.  If the vendor was slow, we’d be slow, but now we had our own data to isolate the cause and work with the vendor.

Combine this information with other sources of data and you can determine neat stuff like:

  • the overhead added by your web server (difference between total time and the applications total time).

Doing a basic code review on the worst-performing block would usually make it very clear why the performance was suffering.  I was the largest creator of tickets for the dev group in the company.

Using this information, we focused on two goals:

  • making the lines flat, i.e. creating consistent, scalable performance.
  • making the lines lower, i.e. increasing overall performance.

We were very successful in both of these goals.

We had several interesting “deep dives” into this data, but one of them stands out:

The whole system was monitored with Gomez, which one of the executives liked.  Gomez started to report performance problems, but they weren’t seen in the summary data that we graphed.

Since we had the details, I was able to find the exact request that Gomez had made (user name and time), and see the block of code that was slow.

It turned out that the system was writing a row into a table every time a user logged in.  The Gomez test account logged in a lot, so there were a lot of rows for this user.  The application pulled these rows, looking for some recent information (last search string, etc).  Unfortunately, the app pulled in all the rows, not the just recent ones that it needed.

It was easy to find and easy to fix.  Management was happy.

Elasticsearch best practices

Don’t forget to check out the Logstash best practices, too.

Memory

Give elasticsearch half of your system’s RAM, up to 32GB.

Make sure the allocated memory doesn’t get swapped out by using mlockall.  In your config/elasticsearch.yml, add:

bootstrap.mlockall: true

You may need to allow this as part of the startup by running

ulimit -l unlimited

On (at least) centos6, you can have this run for you in the init.d script by adding this line to /etc/sysconfig/elasticsearch:

MAX_LOCKED_MEMORY=unlimited

For centos7, edit /usr/lib/systemd/system/elasticsearch.service:

LimitMEMLOCK=infinity

After restarting, confirm the setting is correct in elasticsearch:

curl http://localhost:9200/_nodes/process?pretty

Index Names

Use an index for each day.  There are only two ways to delete data in elasticsearch, and using curator against daily indexes is the right one.

Note that this is the default from logstash.

Run an odd number of nodes

This will prevent the split-brain problem.

Run at least three nodes

With one replica (two copies), using three nodes will give you an I/O boost.

Adjust the Mapping

Elasticsearch supports many different field types, and you should use the appropriate one for each field.

By using ‘int’, you can use comparisons (“http_status:>500”) or ranges (“http_status:[400 TO 499]”).  Other field types give similar benefits of just using strings.

Logstash best practices

Don’t forget to check out the Elasticsearch best practices, too.

Set @timestamp

If your log entry contains the time at which the event occurred, use the date{} filter to replace @timestamp with this value.  See “Save the Date”, too.

If you’ve already grok{}’ed out a field called ‘apache_timestamp’, your date{} stanza might look like this:

filter {
  if [type] == "access" {
    date {
      match => [ 'apache_timestamp', "dd/MMM/yyyy:HH:mm:ss Z" ]
      remove_field => [ 'apache_timestamp' ]
    }
  }
}

Save the Date

By overwriting @timestamp (as suggested, above), you won’t know when logstash processed the event.  Being able to manage this lag is important.  Cover this by copying @timestamp to another field (using mutate->add_field) before applying the date{} filter.

Use Smart Patterns

You can cast the field to integer or float in the pattern, e.g.:

%{INT:my_field:int}

Use grok’s tag_on_failure

When the grok{} filter fails, it adds a tag called “_grokparsefailure”.  This is helpful, unless you have multiple grok{} filters.  In this case, add a unique tag_on_failure attribute to each grok{}.

grok {
    match => [
        "message", "%{PATTERN_1}"
    ]
    tag_on_failure => [ "failedPattern1" ]
}

Note that the syslog{} input uses grok{} internally, so it can also throw _grokparsefailure messages.  In logstash 1.5, this tag is _grokparsefailure_sysloginput.

Increase the Output Workers

Many outputs (include elasticsearch{}) support using multiple output workers.  Each will maintain their own cache (of flush_size events).  Specifying multiple output workers can increase throughput.

Increase the Filter Workers

If you’re not using the multiline{} filter, you can increase the number of logstash worker threads.  This will better utilize the CPU of your logstash machine.  In your startup script, use the “-w” flag with a value that slightly less than the number of CPUs on the machine, e.g.:

-w 18

 Increase the Open File Descriptors

On centos the init script will run ‘ulimit -n’ if you update /etc/sysconfig/logstash, e.g.:

LS_OPEN_FILES=65535