Sometimes when firing a query, it gets delayed, or the response time is slow. There could be a number of reasons for the sluggishness of the query; ranging from shard issues or from computing certain elements in the query. Elasticsearch, from version 2.2, provides the Profile API for users to inspect the query execution time and other details. In this blog post, we explore how the profile API can be used to look into query timings.

Profile API

The Profile API was introduced with the release of Elasticsearch 2.2 as an experimental feature. The Profile API returns the details of all the shards. For the sake of simplicity, create an index with just 1 shard.

Index creation:

 curl -XPUT http:localhost:9200/myindex -d '{
"settings":{
"number_of_replicas": 0,
"number_of_shards": 1
}
}'

In the above created index, we can populate documents for basic search, and then explain the profile API from the results. Let us index three documents:

 curl -XPOST<a href="http://localhost:9200/myindex/mytype/1"> http://localhost:9200/myindex/mytype/1</a> -d '{
"brand" : "Cotton Plus"
}'
curl -XPOST<a href="http://localhost:9200/myindex/mytype/2"> http://localhost:9200/myindex/mytype/2</a> - d '{
"brand" : "Van Huesen"
}'
curl -XPOST<a href="http://localhost:9200/myindex/mytype/3"> http://localhost:9200/myindex/mytype/3</a> - d '{
"brand" : "Arrow"
}'

The Profile API results can be enabled by giving the "profile: true" above the query part. Let us look how the query, enabled with the profile parameter, would look like on a single query:

 curl XPOST<a href="http://localhost:9200/myindex/mytype/_search"> http://localhost:9200/myindex/mytype/_search</a> -d '{
 "profile": true,
 "query": {
   "match": {
     "brand": "Cotton Plus"
   }
 }
}'

The results for the Profile API are calculated on a per-shard basis. Since there is only one shard in our example, we have only one array element in the shards array of the profile API response, as shown below:

{
 "shards": [
   {
     "id": "[egPYczsCRTqaeJ8jKhFjtw][myindex][0]",
     "searches": [
       {
         "query": [
           {
             "query_type": "BooleanQuery",
             "lucene": "brand:levi brand:goals",
             "time": "1.293761000ms",
             "breakdown": {
               "score": 0,
               "create_weight": 136078,
               "next_doc": 0,
               "match": 0,
               "build_scorer": 1082113,
               "advance": 0
             },
             "children": [
               {
                 "query_type": "TermQuery",
                 "lucene": "brand:levi",
                 "time": "0.04626300000ms",
                 "breakdown": {
                   "score": 0,
                   "create_weight": 30190,
                   "next_doc": 0,
                   "match": 0,
                   "build_scorer": 16073,
                   "advance": 0
                 }
               },
               {
                 "query_type": "TermQuery",
                 "lucene": "brand:goals",
                 "time": "0.02930700000ms",
                 "breakdown": {
                   "score": 0,
                   "create_weight": 16600,
                   "next_doc": 0,
                   "match": 0,
                   "build_scorer": 12707,
                   "advance": 0
                 }
               }
             ]
           }
         ],
         "rewrite_time": 64032,
         "collector": [
           {
             "name": "TotalHitCountCollector",
             "reason": "search_count",
             "time": "0.002931000000ms"
           }
         ]
       }
     ]
   }
 }

Profile API Response Explained

The response above is shown for a single shard. Each shard is assigned a unique id, comprising of the shard number, index name and the number of the shard. Now inside the "shards" array there are another three elements, which are:

  1. query
  2. rewrrite_time
  3. collector

Query

The query section consists of the elements which constitute to the query and also the timing information of them. The basic constituents of the query section in the profile API results are:

  1. query type - As the name indicates, it shows us which type of query was fired. Here it is boolean. This is because the multiple keyword match query is split into two boolean queries.
  2. lucene - This field shows the lucene way of firing the queries. Here you can see that is "brand:levi brand:goals"
  3. time - The time taken for lucene to execute this query. The unit here is in milliseconds.
  4. breakdown - More intricate details about the query, mostly relating to the lucene parameters.
  5. children - The queries with multiple keywords are split into a bool query with corresponding terms, each of which is executed as a separate query. The details for each child query is populated under the children section of the profile API output. In the above section, you can see that the first child element query is "levi" and under it the details like query time and other breakdown parameters are given. Similarly for the second keyword, there is a children element named "goals" with the same information as its sibling. From the children section in the query, we can get information on which search term caused the biggest delay in the overall search.  

Rewrite Time

Since multiple keywords are being broken down to create individual queries, some time will definitely be spent on this process. This time needed to rewrite the query to one or more constituent queries is called "rewrite times."

Collectors

In Lucene, Collectors are the processes which are responsible for gathering raw results, collecting and combining the results, for implementation of sorting in the results, etc. In this query execution, the collector used was the "totalHitCountCollector" , which is used when size:0 is given in the query. This returns only the number of search results (search_count), without the documents. Also, the time taken for the collector is also given with this information.

Conclusion

In this blog post, we have seen how useful the Profile API is, as it gives us a clear idea of the query timings. A clear idea of where the query is slowing, by providing us the details with the children queries, is a very useful feature. Also, details regarding the Lucene implementation in the API results also provides us with a good insight on how Elasticsearch is executing the query.

comments powered by Disqus