Elasticsearch provides the ability to log slow search queries that exceed a certain threshold. When enabled, all the search queries that exceed the given threshold are written to /var/log/elasticsearch/${cluster_name}_index_search_slowlog.log. A typical line in the slow log file looks like

[2017-09-10T12:35:53,355][WARN ][index.search.slowlog.fetch] [GOgO9TD]
[testindex-slowlogs][0] took[150.6micros], took_millis[0], types[],
stats[], search_type[QUERY_THEN_FETCH], total_shards[5],
source[{\"query\":{\"match\":{\"name\":{\"query\":\"Nariko\",\"operator\":\"OR\",\"prefix_length\":0,\"max_expansions\":50,\"fuzzy_transpositions\":true,\"lenient\":false,\"zero_terms_query\":\"NONE\",\"boost\":1.0}}},\"sort\":[{\"price\":{\"order\":\"desc\"}}]}]

This information might be enough for simple use cases. But if one operates at scale and if the system is used by multiple teams with wildly different queries, then manually going through every line is not possible.

A simple solution is to parse the text into structured data which can be then ingested into a centralized logging system like Graylog or ELK.

{
                 "node" => "GOgO9TD",
                "shard" => 0,
               "source" => '{"query":{"match":{"name":{"query":"Nariko","operator":"OR","prefix_length":0,"max_expansions":50,"fuzzy_transpositions":true,"lenient":false,"zero_terms_query":"NONE","boost":1.0}}},"sort":[{"price":{"order":"desc"}}]}',
                 "took" => "150.6micros",
                "stats" => "",
                "level" => "WARN",
             "@version" => "1",
                "index" => "testindex-slowlogs",
      "local_timestamp" => "2017-09-10T12:35:53",
           "@timestamp" => 2017-09-10T05:35:53.000Z,
                 "host" => "Ananthas-MacBook-Pro.local",
         "total_shards" => 5,
                "types" => "",
          "search_type" => "QUERY_THEN_FETCH",
          "took_millis" => 0
}

Now we can find queries that took more than 500 ms or group the logs based on a field like level, etc. But there are still some cases where this is not sufficient. Let say we want to see the top 10 slow queries based on the count, we can’t simply group based on the source field. Even though the query structure will be the same, the argument of each query operator might differ for each slow log. What we might find useful is something like parameterized sql query, where all the variables are represented as ?

{
    "source_normalized" => '{"query":{"match":{"name":{"boost":1.0,"fuzzy_transpositions":true,"lenient":false,"max_expansions":50,"operator":"OR","prefix_length":0,"query":"?","zero_terms_query":"NONE"}}},"sort":[{"price":{"order":"desc"}}]}'
    "source_id"         => "289972b28"
}

Once we have that, we could just take the hash of the source_normalized field and group based on it. source_id is just the first 8 characters of md5(source_normalized).

We have written a logstash plugin which does exactly this. All you need to do is install the plugin and add the filter configuration for slow log files.

filter {
  elasticsearchslowlog {
  }

  date {
    match => ["local_timestamp", "ISO8601"]
    timezone => "Asia/Kolkata"
  }
}