Elasticsearch 2.2: Profile API (benchmarking queries revisited)

Send to Kindle

speedSome time ago, we described the benchmark API, that was meant to provide us with functionality of checking our queries performance. That API was initially planned for Elasticsearch 1.5, but somehow it was removed and it never showed up – until recently. In Elasticsearch 2.2, we will have a new, experimental profile API introduced that will allow us to get detailed timing informations regarding our queries. Let’s see what we can expect from that API.

Using the Profile API

Using the new Profile API is very simple comparing to the abandoned Benchmark API. When it comes to Benchmark API we had to run Elasticsearch in a certain way to be able to use that API. With Profile API it is just a matter of adding the top level profile property to our query and setting it to true. For example, let’s assume that our query looks as follows:

curl -XGET 'localhost:9200/wiki/_search?pretty' -d '{
 "query" : {
  "match_all" : {}
 },
 "aggs" : {
  "categories" : {
   "terms" : {
    "field" : "category"
   }
  },
  "specials" : {
   "terms" : {
    "field" : "special"
   }
  }
 }
}'

The same query, but with profiling turned on, looks as follows:

curl -XGET 'localhost:9200/wiki/_search?pretty' -d '{
 "profile" : true,
 "query" : {
  "match_all" : {}
 },
 "aggs" : {
  "categories" : {
   "terms" : {
    "field" : "category"
   }
  },
  "specials" : {
   "terms" : {
    "field" : "special"
   }
  }
 }
}'

You can see that the only difference between those two queries is the profile property set to true in the root of the query object.

The Response

There is one problem when it comes to profile API – it requires knowledge about internal structures of Elasticsearch and Apache Lucene. Elasticsearch includes various sections in the response, depending on the used query (full reference can be found in the official documentation). For our above query, the response would look as follows:

{
  "took" : 156,
  "timed_out" : false,
  "_shards" : {
    "total" : 2,
    "successful" : 2,
    "failed" : 0
  },
  "hits" : {
    "total" : 244203,
    "max_score" : 0.0,
    "hits" : [ ]
  },
  "aggregations" : {
    "specials" : {
      "doc_count_error_upper_bound" : 0,
      "sum_other_doc_count" : 0,
      "buckets" : [ {
        "key" : 0,
        "key_as_string" : "false",
        "doc_count" : 241331
      }, {
        "key" : 1,
        "key_as_string" : "true",
        "doc_count" : 2872
      } ]
    },
    "categories" : {
      "doc_count_error_upper_bound" : 10490,
      "sum_other_doc_count" : 1935939,
      "buckets" : [ {
        "key" : "in",
        "doc_count" : 83873
      }, {
        "key" : "of",
        "doc_count" : 59477
      }, {
        "key" : "the",
        "doc_count" : 41619
      }, {
        "key" : "county",
        "doc_count" : 40069
      }, {
        "key" : "births",
        "doc_count" : 24746
      }, {
        "key" : "people",
        "doc_count" : 23980
      }, {
        "key" : "from",
        "doc_count" : 22099
      }, {
        "key" : "places",
        "doc_count" : 21814
      }, {
        "key" : "established",
        "doc_count" : 21397
      }, {
        "key" : "and",
        "doc_count" : 19523
      } ]
    }
  },
  "profile" : {
    "shards" : [ {
      "id" : "[CEENg4mKTBGMQ5cSmTHJ2g][wiki][0]",
      "searches" : [ {
        "query" : [ {
          "query_type" : "MatchAllDocsQuery",
          "lucene" : "*:*",
          "time" : "7.737684000ms",
          "breakdown" : {
            "score" : 0,
            "create_weight" : 353489,
            "next_doc" : 6553735,
            "match" : 0,
            "build_scorer" : 830460,
            "advance" : 0
          }
        } ],
        "rewrite_time" : 3086,
        "collector" : [ {
          "name" : "MultiCollector",
          "reason" : "search_multi",
          "time" : "76.03410900ms",
          "children" : [ {
            "name" : "TotalHitCountCollector",
            "reason" : "search_count",
            "time" : "6.874080000ms"
          }, {
            "name" : "BucketCollector: [[categories, specials]]",
            "reason" : "aggregation",
            "time" : "46.22560400ms"
          } ]
        } ]
      } ]
    }, {
      "id" : "[CEENg4mKTBGMQ5cSmTHJ2g][wiki][1]",
      "searches" : [ {
        "query" : [ {
          "query_type" : "MatchAllDocsQuery",
          "lucene" : "*:*",
          "time" : "7.025982000ms",
          "breakdown" : {
            "score" : 0,
            "create_weight" : 5533,
            "next_doc" : 6671452,
            "match" : 0,
            "build_scorer" : 348997,
            "advance" : 0
          }
        } ],
        "rewrite_time" : 3077,
        "collector" : [ {
          "name" : "MultiCollector",
          "reason" : "search_multi",
          "time" : "77.93884100ms",
          "children" : [ {
            "name" : "TotalHitCountCollector",
            "reason" : "search_count",
            "time" : "6.934513000ms"
          }, {
            "name" : "BucketCollector: [[categories, specials]]",
            "reason" : "aggregation",
            "time" : "48.25236800ms"
          } ]
        } ]
      } ]
    } ]
  }
}

As you can see, apart from the main section of the response that contains our aggregation results we also got a new section called profile. This is where the profiling information is returned by Elasticsearch.

Profiling information

As you can see, Elasticsearch returns profiling information for each shard. For each of them we have the information about the shard identifier and the searches done on that shard with all the needed profiling information.

Let’s look at the search section a bit closer:

[ {
 "query" : [ {
 "query_type" : "MatchAllDocsQuery",
 "lucene" : "*:*",
 "time" : "7.025982000ms",
 "breakdown" : {
  "score" : 0,
  "create_weight" : 5533,
  "next_doc" : 6671452,
  "match" : 0,
  "build_scorer" : 348997,
  "advance" : 0
 }
} ]

We can see it that it contains information about our simple match_all query. It shows us the type, what Lucene query it corresponds to and of course the timing – the time property that shows us the execution time of the query.

Of course this is not everything. We also see the time taken by the query rewrite mechanism and of course the time of collectors execution time in the collector section of the profile response:

"collector" : [ {
 "name" : "MultiCollector",
 "reason" : "search_multi",
 "time" : "77.93884100ms",
 "children" : [ {
  "name" : "TotalHitCountCollector",
  "reason" : "search_count",
  "time" : "6.934513000ms"
 }, {
  "name" : "BucketCollector: [[categories, specials]]",
  "reason" : "aggregation",
  "time" : "48.25236800ms"
 } ]
} ]

We can see total collection time in the top level collector timing. In addition we have the search count collector timing (calculating number of documents) and the aggregation calculation time.

Summary

As you can see the profile API can be a great source of information regarding your queries execution and performance. Hopefully it will allow you to narrow down query performance issues and make your queries faster 🙂

Tagged , , , , ,

Leave a Reply