Profiling a more complicated query

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

  1. Index the following data:

    POST test/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. Enter "test" in the Index filter above the query editor (the input box with a grayed-out _all). This restricts profiled queries to the test index.

    Using the index filter
  3. Replace the default match_all query with a query that has two sub-query components and includes a simple aggregation. For example, copy and paste the following query into the query editor.

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

    Profiling the more complicated query

    As before, you’ll see a list of shards appear in the center panel. You’ll notice that the query was slightly slower (15ms vs 0.13ms) because it actually had to do a bit of work this time, unlike the match_all query.

  5. Click the first shard’s Expand button to view the query details.

    Drilling into the first shard's details

You’ll notice several interesting things in the results. The shard details contain a row for each query component:

  • The top-level 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 "sue" and "sally" from the terms query.
  • The TermQuery that’s labeled with "name:fred" corresponds to match: fred in the query.

If you look at the timings, you can see that "Self Time" and "Total Time" are no longer identical on all the 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 larger Total than Self.

In particular, you can see that the BooleanQuery for "name:sue name:sally" took 3.8ms total, but 2.8ms of that was "self" time. That means 2.8ms was spent by the BooleanQuery itself, processing the should clauses

Aggregations

This particular query also includes a aggregation (a stats agg on the "age" field). To view Aggregation profiling statistics, click the Aggregation Profile tab. This tab is only enabled if the query being profiled contains an aggregation.

Drilling into the first shard's details

Click a shard’s Expand button to view the aggregation details. Hover over an aggregation row to view the timing breakdown.

For more information about how the Search Profiler works, how timings are calculated, and how to interpret various results, see the Profile Reference Documentation