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 to time needed to compute certain elements in the query. Since version 2.2., Elasticsearch 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. For this tutorial, Elasticsearch 5.0 version was used. 

Spin Up a Qbox Elasticsearch Cluster 

 Setting up and configuring Elasticsearch can be quite the undertaking. For this reason, we prefer to spin up a Qbox cluster to handle the Elasticsearch heavy lifting. You can get started with a Qbox Cluster here. For this tutorial we will be using Elasticsearch major version 5.

Profile API

The Profile API was introduced as an experimental feature with the release of Elasticsearch 2.2. The Profile API returns data on all shards. For the sake of simplicity, let's 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
     }
  }'

Next, we can populate documents for basic search, and then explain the profile API based on the search results. Let us index three documents:

 curl -XPOST http://localhost:9200/myindex/mytype/1 
    -H "Content-Type:application/json" 
    -d '{ "brand" : "Cotton Plus"}'
curl -XPOST http://localhost:9200/myindex/mytype/2 
    -H "Content-Type:application/json" 
   - d '{"brand" : "Van Huesen"}'
curl -XPOST http://localhost:9200/myindex/mytype/3 
    -H "Content-Type:application/json" 
   - d '{ "brand" : "Arrow" }'

The Profile API results can be enabled by including the "profile: true" above the query part. That is how the query with a profile parameter enabled should look like:

 curl XPOST http://localhost:9200/myindex/mytype/_search?pretty 
-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  formatted from 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 relate to the query and its timing information. The basic components of the query section in the Profile API results include the following:

  1. query type - As the name suggests, this field shows us which type of query was fired. In our case, it is a Boolean query. 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 it 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 related to the Lucene parameters.
  5. children - The queries with multiple keywords are split into a Boolean query with corresponding terms, each of which is executed as a separate query. The details for each child query are 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 beneath 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,  combining them, filtering, sorting etc. In this query execution, the collector used was the "totalHitCountCollector" , which is applied when size:0 is specified in the query. A query with this type of collector returns only the number of search results (search_count) without the actual documents. Also, the time spent by the collector to collect the results is provided along 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. Understanding why the query is slowing and providing details about children queries that may slow the process are very useful features of the Profile API. Also, details regarding the Lucene implementation in the API results provide us with some useful insights about how Elasticsearch is executing the query.