Search Profiler

edit

This content applies to: Elasticsearch Observability Security

Elasticsearch has a powerful Profile API for debugging search queries. It provides detailed timing information about the execution of individual components in a search request. This allows users to optimize queries for better performance.

However, Profile API responses can be hard to read, especially for complex queries. Search Profiler helps you visualize these responses in a graphical interface.

Get started
edit

Access Search Profiler under Dev Tools.

Search Profiler displays the names of the indices searched and how long it took for the query to complete. Test it out by replacing the default match_all query with the query you want to profile, and then select Profile.

The following example shows the results of profiling the match_all query. If you take a closer look at the information for the .security_7 sample index, the Cumulative time field shows you that the query took 0.028ms to execute.

Search Profiler match_all example

To see more profiling information, select View details. You’ll find details about query components and the timing breakdown of low-level methods. For more information, refer to Profiling queries in the Elasticsearch documentation.

Filter for an index or type
edit

By default, all queries executed by the Search Profiler are sent to GET /_search. It searches across your entire cluster (all indices, all types).

To query a specific index or type, you can use the Index filter.

In the following example, the query is executed against the indices .security-7 and kibana_sample_data_ecommerce. This is equivalent to making a request to GET /.security-7,kibana_sample_data_ecommerce/_search.

Filtering by index and type
Profile a more complicated query
edit

To understand how the query trees are displayed inside the Search Profiler, take a look at a more complicated query.

  1. Index the following data using Console:

    POST test/_bulk
    {"index":{}}
    {"name":"aaron","age":23,"hair":"brown"}
    {"index":{}}
    {"name":"sue","age":19,"hair":"red"}
    {"index":{}}
    {"name":"sally","age":19,"hair":"blonde"}
    {"index":{}}
    {"name":"george","age":19,"hair":"blonde"}
    {"index":{}}
    {"name":"fred","age":69,"hair":"blonde"}
  2. From the Search Profiler, enter test in the Index field to restrict profiled queries to the test index.
  3. Replace the default match_all query in the query editor with a query that has two sub-query components and includes a simple aggregation:

    {
       "query": {
          "bool": {
             "should": [
                {
                   "match": {
                      "name": "fred"
                   }
                },
                {
                   "terms": {
                      "name": [
                          "sue",
                          "sally"
                      ]
                   }
                }
             ]
          }
       },
       "aggs": {
          "stats": {
             "stats": {
                "field": "price"
             }
          }
       }
    }
  4. Select Profile to profile the query and visualize the results.

    Profiling the more complicated query
    • The top BooleanQuery component corresponds to the bool in the query.
    • The second BooleanQuery corresponds to the terms query, which is internally converted to a Boolean of should clauses. It has two child queries that correspond to "sally" and "sue from the terms query.
    • The TermQuery that’s labeled with "name:fred" corresponds to match: fred in the query.

    In the time columns, the Self time and Total time are no longer identical on all rows:

    • Self time represents how long the query component took to execute.
    • Total time is the time a query component and all its children took to execute.

    Therefore, queries like the Boolean queries often have a larger total time than self time.

  5. Select Aggregation Profile to view aggregation profiling statistics.

    This query includes a stats agg on the "age" field. The Aggregation Profile tab is only enabled when the query being profiled contains an aggregation.

  6. Select View details to view the timing breakdown.

    Drilling into the first shard’s details

    For more information about how the Search Profiler works, how timings are calculated, and how to interpret various results, refer to Profiling queries in the Elasticsearch documentation.

Render pre-captured profiler JSON
edit

Sometimes you might want to investigate performance problems that are temporal in nature. For example, a query might only be slow at certain time of day when many customers are using your system. You can set up a process to automatically profile slow queries when they occur and then save those profile responses for later analysis.

The Search Profiler supports this workflow by allowing you to paste the pre-captured JSON in the query editor. The Search Profiler will detect that you have entered a JSON response (rather than a query) and will render just the visualization, rather than querying the cluster.

To see how this works, copy and paste the following profile response into the query editor and select Profile.

{
   "took": 3,
   "timed_out": false,
   "_shards": {
      "total": 1,
      "successful": 1,
      "failed": 0
   },
   "hits": {
      "total": 1,
      "max_score": 1.3862944,
      "hits": [
         {
            "_index": "test",
            "_type": "test",
            "_id": "AVi3aRDmGKWpaS38wV57",
            "_score": 1.3862944,
            "_source": {
               "name": "fred",
               "age": 69,
               "hair": "blonde"
            }
         }
      ]
   },
   "profile": {
      "shards": [
         {
            "id": "[O-l25nM4QN6Z68UA5rUYqQ][test][0]",
            "searches": [
               {
                  "query": [
                     {
                        "type": "BooleanQuery",
                        "description": "+name:fred #(ConstantScore(*:*))^0.0",
                        "time": "0.5884370000ms",
                        "breakdown": {
                           "score": 7243,
                           "build_scorer_count": 1,
                           "match_count": 0,
                           "create_weight": 196239,
                           "next_doc": 9851,
                           "match": 0,
                           "create_weight_count": 1,
                           "next_doc_count": 2,
                           "score_count": 1,
                           "build_scorer": 375099,
                           "advance": 0,
                           "advance_count": 0
                        },
                        "children": [
                           {
                              "type": "TermQuery",
                              "description": "name:fred",
                              "time": "0.3016880000ms",
                              "breakdown": {
                                 "score": 4218,
                                 "build_scorer_count": 1,
                                 "match_count": 0,
                                 "create_weight": 132425,
                                 "next_doc": 2196,
                                 "match": 0,
                                 "create_weight_count": 1,
                                 "next_doc_count": 2,
                                 "score_count": 1,
                                 "build_scorer": 162844,
                                 "advance": 0,
                                 "advance_count": 0
                              }
                           },
                           {
                              "type": "BoostQuery",
                              "description": "(ConstantScore(*:*))^0.0",
                              "time": "0.1223030000ms",
                              "breakdown": {
                                 "score": 0,
                                 "build_scorer_count": 1,
                                 "match_count": 0,
                                 "create_weight": 17366,
                                 "next_doc": 0,
                                 "match": 0,
                                 "create_weight_count": 1,
                                 "next_doc_count": 0,
                                 "score_count": 0,
                                 "build_scorer": 102329,
                                 "advance": 2604,
                                 "advance_count": 2
                              },
                              "children": [
                                 {
                                    "type": "MatchAllDocsQuery",
                                    "description": "*:*",
                                    "time": "0.03307600000ms",
                                    "breakdown": {
                                       "score": 0,
                                       "build_scorer_count": 1,
                                       "match_count": 0,
                                       "create_weight": 6068,
                                       "next_doc": 0,
                                       "match": 0,
                                       "create_weight_count": 1,
                                       "next_doc_count": 0,
                                       "score_count": 0,
                                       "build_scorer": 25615,
                                       "advance": 1389,
                                       "advance_count": 2
                                    }
                                 }
                              ]
                           }
                        ]
                     }
                  ],
                  "rewrite_time": 168640,
                  "collector": [
                     {
                        "name": "CancellableCollector",
                        "reason": "search_cancelled",
                        "time": "0.02952900000ms",
                        "children": [
                           {
                              "name": "SimpleTopScoreDocCollector",
                              "reason": "search_top_hits",
                              "time": "0.01931700000ms"
                           }
                        ]
                     }
                  ]
               }
            ],
            "aggregations": []
         }
      ]
   }
}

Your output should look similar to this:

Rendering pre-captured profiler JSON