#19133 Added documentation for aggregation profiling
Added documentation for aggregation profiling
This commit is contained in:
Colin Goodheart-Smithe
GitHub
commit
1aa31ec934
|
|
@ -4,25 +4,12 @@
|
|||
experimental[]
|
||||
|
||||
The Profile API provides detailed timing information about the execution of individual components
|
||||
in a query. It gives the user insight into how queries are executed at a low level so that
|
||||
the user can understand why certain queries are slow, and take steps to improve their slow queries.
|
||||
in a search request. It gives the user insight into how search requests are executed at a low level so that
|
||||
the user can understand why certain requests are slow, and take steps to improve them.
|
||||
|
||||
The output from the Profile API is *very* verbose, especially for complicated queries executed across
|
||||
The output from the Profile API is *very* verbose, especially for complicated requests executed across
|
||||
many shards. Pretty-printing the response is recommended to help understand the output
|
||||
|
||||
[NOTE]
|
||||
=======================================
|
||||
The details provided by the Profile API directly expose Lucene class names and concepts, which means
|
||||
that complete interpretation of the results require fairly advanced knowledge of Lucene. This
|
||||
page attempts to give a crash-course in how Lucene executes queries so that you can use the Profile API to successfully
|
||||
diagnose and debug queries, but it is only an overview. For complete understanding, please refer
|
||||
to Lucene's documentation and, in places, the code.
|
||||
|
||||
With that said, a complete understanding is often not required to fix a slow query. It is usually
|
||||
sufficient to see that a particular component of a query is slow, and not necessarily understand why
|
||||
the `advance` phase of that query is the cause, for example.
|
||||
=======================================
|
||||
|
||||
[float]
|
||||
=== Usage
|
||||
|
||||
|
|
@ -35,7 +22,7 @@ curl -XGET 'localhost:9200/_search' -d '{
|
|||
"query" : {
|
||||
"match" : { "message" : "search test" }
|
||||
}
|
||||
}
|
||||
}'
|
||||
--------------------------------------------------
|
||||
<1> Setting the top-level `profile` parameter to `true` will enable profiling
|
||||
for the search
|
||||
|
|
@ -141,7 +128,8 @@ First, the overall structure of the profile response is as follows:
|
|||
"rewrite_time": 185002, <3>
|
||||
"collector": [...] <4>
|
||||
}
|
||||
]
|
||||
],
|
||||
"aggregations": [...] <5>
|
||||
}
|
||||
]
|
||||
}
|
||||
|
|
@ -152,6 +140,7 @@ by a unique ID
|
|||
<2> Each profile contains a section which holds details about the query execution
|
||||
<3> Each profile has a single time representing the cumulative rewrite time
|
||||
<4> Each profile also contains a section about the Lucene Collectors which run the search
|
||||
<5> Each profile contains a section which holds the details about the aggregation execution
|
||||
|
||||
Because a search request may be executed against one or more shards in an index, and a search may cover
|
||||
one or more indices, the top level element in the profile response is an array of `shard` objects.
|
||||
|
|
@ -164,12 +153,26 @@ But occasionally multiple searches will be executed, such as including a global
|
|||
a secondary "match_all" query for the global context).
|
||||
|
||||
Inside each `search` object there will be two arrays of profiled information:
|
||||
a `query` array and a `collector` array. In the future, more sections may be added, such as `suggest`, `highlight`,
|
||||
`aggregations`, etc
|
||||
a `query` array and a `collector` array. Alongside the `search` object is an `aggregations` object that contains the profile information for the aggregations. In the future, more sections may be added, such as `suggest`, `highlight`, etc
|
||||
|
||||
There will also be a `rewrite` metric showing the total time spent rewriting the query (in nanoseconds).
|
||||
|
||||
=== `query` Section
|
||||
=== Profiling Queries
|
||||
|
||||
[NOTE]
|
||||
=======================================
|
||||
The details provided by the Profile API directly expose Lucene class names and concepts, which means
|
||||
that complete interpretation of the results require fairly advanced knowledge of Lucene. This
|
||||
page attempts to give a crash-course in how Lucene executes queries so that you can use the Profile API to successfully
|
||||
diagnose and debug queries, but it is only an overview. For complete understanding, please refer
|
||||
to Lucene's documentation and, in places, the code.
|
||||
|
||||
With that said, a complete understanding is often not required to fix a slow query. It is usually
|
||||
sufficient to see that a particular component of a query is slow, and not necessarily understand why
|
||||
the `advance` phase of that query is the cause, for example.
|
||||
=======================================
|
||||
|
||||
==== `query` Section
|
||||
|
||||
The `query` section contains detailed timing of the query tree executed by Lucene on a particular shard.
|
||||
The overall structure of this query tree will resemble your original Elasticsearch query, but may be slightly
|
||||
|
|
@ -217,9 +220,9 @@ that in a moment. Finally, the `"children"` array lists any sub-queries that ma
|
|||
values ("search test"), our BooleanQuery holds two children TermQueries. They have identical information (type, time,
|
||||
breakdown, etc). Children are allowed to have their own children.
|
||||
|
||||
==== Timing Breakdown
|
||||
===== Timing Breakdown
|
||||
|
||||
The `breakdown` component lists detailed timing statistics about low-level Lucene execution:
|
||||
The `"breakdown"` component lists detailed timing statistics about low-level Lucene execution:
|
||||
|
||||
[source,js]
|
||||
--------------------------------------------------
|
||||
|
|
@ -235,14 +238,14 @@ The `breakdown` component lists detailed timing statistics about low-level Lucen
|
|||
--------------------------------------------------
|
||||
|
||||
Timings are listed in wall-clock nanoseconds and are not normalized at all. All caveats about the overall
|
||||
`time` apply here. The intention of the breakdown is to give you a feel for A) what machinery in Lucene is
|
||||
`"time"` apply here. The intention of the breakdown is to give you a feel for A) what machinery in Lucene is
|
||||
actually eating time, and B) the magnitude of differences in times between the various components. Like the overall time,
|
||||
the breakdown is inclusive of all children times.
|
||||
|
||||
The meaning of the stats are as follows:
|
||||
|
||||
[float]
|
||||
=== All parameters:
|
||||
==== All parameters:
|
||||
|
||||
[horizontal]
|
||||
`create_weight`::
|
||||
|
|
@ -303,7 +306,7 @@ The meaning of the stats are as follows:
|
|||
This records the time taken to score a particular document via it's Scorer
|
||||
|
||||
|
||||
=== `collectors` Section
|
||||
==== `collectors` Section
|
||||
|
||||
The Collectors portion of the response shows high-level execution details. Lucene works by defining a "Collector"
|
||||
which is responsible for coordinating the traversal, scoring and collection of matching documents. Collectors
|
||||
|
|
@ -379,7 +382,7 @@ For reference, the various collector reason's are:
|
|||
|
||||
|
||||
|
||||
=== `rewrite` Section
|
||||
==== `rewrite` Section
|
||||
|
||||
All queries in Lucene undergo a "rewriting" process. A query (and its sub-queries) may be rewritten one or
|
||||
more times, and the process continues until the query stops changing. This process allows Lucene to perform
|
||||
|
|
@ -391,7 +394,7 @@ The rewriting process is complex and difficult to display, since queries can cha
|
|||
showing the intermediate results, the total rewrite time is simply displayed as a value (in nanoseconds). This
|
||||
value is cumulative and contains the total time for all queries being rewritten.
|
||||
|
||||
=== A more complex example
|
||||
==== A more complex example
|
||||
|
||||
To demonstrate a slightly more complex query and the associated results, we can profile the following query:
|
||||
|
||||
|
|
@ -563,28 +566,7 @@ The Collector tree is fairly straightforward, showing how a single MultiCollecto
|
|||
to execute the post_filter (and in turn wraps the normal scoring SimpleCollector), a BucketCollector to run
|
||||
all scoped aggregations. In the MatchAll search, there is a single GlobalAggregator to run the global aggregation.
|
||||
|
||||
=== Performance Notes
|
||||
|
||||
Like any profiler, the Profile API introduce a non-negligible overhead to query execution. The act of instrumenting
|
||||
low-level method calls such as `advance` and `next_doc` can be fairly expensive, since these methods are called
|
||||
in tight loops. Therefore, profiling should not be enabled in production settings by default, and should not
|
||||
be compared against non-profiled query times. Profiling is just a diagnostic tool.
|
||||
|
||||
There are also cases where special Lucene optimizations are disabled, since they are not amenable to profiling. This
|
||||
could cause some queries to report larger relative times than their non-profiled counterparts, but in general should
|
||||
not have a drastic effect compared to other components in the profiled query.
|
||||
|
||||
=== Limitations
|
||||
|
||||
- Profiling statistics are currently not available for suggestions, highlighting, `dfs_query_then_fetch`
|
||||
- Detailed breakdown for aggregations is not currently available past the high-level overview provided
|
||||
from the Collectors
|
||||
- The Profiler is still highly experimental. The Profiler is instrumenting parts of Lucene that were
|
||||
never designed to be exposed in this manner, and so all results should be viewed as a best effort to provide detailed
|
||||
diagnostics. We hope to improve this over time. If you find obviously wrong numbers, strange query structures or
|
||||
other bugs, please report them!
|
||||
|
||||
=== Understanding MultiTermQuery output
|
||||
==== Understanding MultiTermQuery output
|
||||
|
||||
A special note needs to be made about the `MultiTermQuery` class of queries. This includes wildcards, regex and fuzzy
|
||||
queries. These queries emit very verbose responses, and are not overly structured.
|
||||
|
|
@ -602,3 +584,137 @@ just not the physical layout in the response, so it is sufficient to just analyz
|
|||
ignore it's children if you find the details too tricky to interpret.
|
||||
|
||||
Hopefully this will be fixed in future iterations, but it is a tricky problem to solve and still in-progress :)
|
||||
|
||||
=== Profiling Aggregations
|
||||
|
||||
==== `aggregations` Section
|
||||
|
||||
The `aggregations` section contains detailed timing of the aggregation tree executed by a particular shard.
|
||||
The overall structure of this aggregation tree will resemble your original Elasticsearch request. Let's consider
|
||||
the following example aggregations request:
|
||||
|
||||
[source,js]
|
||||
--------------------------------------------------
|
||||
curl -XGET "http://localhost:9200/house-prices/_search" -d'
|
||||
{
|
||||
"profile": true,
|
||||
"size": 0,
|
||||
"aggs": {
|
||||
"property_type": {
|
||||
"terms": {
|
||||
"field": "propertyType"
|
||||
},
|
||||
"aggs": {
|
||||
"avg_price": {
|
||||
"avg": {
|
||||
"field": "price"
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
}'
|
||||
--------------------------------------------------
|
||||
|
||||
Which yields the following aggregation profile output
|
||||
|
||||
[source,js]
|
||||
--------------------------------------------------
|
||||
"aggregations": [
|
||||
{
|
||||
"type": "org.elasticsearch.search.aggregations.bucket.terms.GlobalOrdinalsStringTermsAggregator",
|
||||
"description": "property_type",
|
||||
"time": "4280.456978ms",
|
||||
"breakdown": {
|
||||
"reduce": 0,
|
||||
"build_aggregation": 49765,
|
||||
"initialise": 52785,
|
||||
"collect": 3155490036
|
||||
},
|
||||
"children": [
|
||||
{
|
||||
"type": "org.elasticsearch.search.aggregations.metrics.avg.AvgAggregator",
|
||||
"description": "avg_price",
|
||||
"time": "1124.864392ms",
|
||||
"breakdown": {
|
||||
"reduce": 0,
|
||||
"build_aggregation": 1394,
|
||||
"initialise": 2883,
|
||||
"collect": 1124860115
|
||||
}
|
||||
}
|
||||
]
|
||||
}
|
||||
]
|
||||
--------------------------------------------------
|
||||
|
||||
From the profile structure we can see our `property_type` terms aggregation which is internally represented by the
|
||||
`GlobalOrdinalsStringTermsAggregator` class and the sub aggregator `avg_price` which is internally represented by the `AvgAggregator` class. The `type` field displays the class used internally to represent the aggregation. The `description` field displays the name of the aggregation.
|
||||
|
||||
The `"time"` field shows that it took ~4 seconds for the entire aggregation to execute. The recorded time is inclusive
|
||||
of all children.
|
||||
|
||||
The `"breakdown"` field will give detailed stats about how the time was spent, we'll look at
|
||||
that in a moment. Finally, the `"children"` array lists any sub-aggregations that may be present. Because we have an `avg_price` aggregation as a sub-aggregation to the `property_type` aggregation we see it listed as a child of the `property_type` aggregation. the two aggregation outputs have identical information (type, time,
|
||||
breakdown, etc). Children are allowed to have their own children.
|
||||
|
||||
===== Timing Breakdown
|
||||
|
||||
The `"breakdown"` component lists detailed timing statistics about low-level Lucene execution:
|
||||
|
||||
[source,js]
|
||||
--------------------------------------------------
|
||||
"breakdown": {
|
||||
"reduce": 0,
|
||||
"build_aggregation": 49765,
|
||||
"initialise": 52785,
|
||||
"collect": 3155490036
|
||||
}
|
||||
--------------------------------------------------
|
||||
|
||||
Timings are listed in wall-clock nanoseconds and are not normalized at all. All caveats about the overall
|
||||
`time` apply here. The intention of the breakdown is to give you a feel for A) what machinery in Elasticsearch is
|
||||
actually eating time, and B) the magnitude of differences in times between the various components. Like the overall time,
|
||||
the breakdown is inclusive of all children times.
|
||||
|
||||
The meaning of the stats are as follows:
|
||||
|
||||
[float]
|
||||
==== All parameters:
|
||||
|
||||
[horizontal]
|
||||
`initialise`::
|
||||
|
||||
This times how long it takes to create and initialise the aggregation before starting to collect documents.
|
||||
|
||||
`collect`::
|
||||
|
||||
This represents the cumulative time spent in the collect phase of the aggregation. This is where matching documents are passed to the aggregation and the state of the aggregator is updated based on the information contained in the documents.
|
||||
|
||||
`build_aggregation`::
|
||||
|
||||
This represents the time spent creating the shard level results of the aggregation ready to pass back to the reducing node after the collection of documents is finished.
|
||||
|
||||
`reduce`::
|
||||
|
||||
This is not currently used and will always report `0`. Currently aggregation profiling only times the shard level parts of the aggregation execution. Timing of the reduce phase will be added later.
|
||||
|
||||
=== Performance Notes
|
||||
|
||||
Like any profiler, the Profile API introduces a non-negligible overhead to search execution. The act of instrumenting
|
||||
low-level method calls such as `collect`, `advance` and `next_doc` can be fairly expensive, since these methods are called
|
||||
in tight loops. Therefore, profiling should not be enabled in production settings by default, and should not
|
||||
be compared against non-profiled query times. Profiling is just a diagnostic tool.
|
||||
|
||||
There are also cases where special Lucene optimizations are disabled, since they are not amenable to profiling. This
|
||||
could cause some queries to report larger relative times than their non-profiled counterparts, but in general should
|
||||
not have a drastic effect compared to other components in the profiled query.
|
||||
|
||||
=== Limitations
|
||||
|
||||
- Profiling statistics are currently not available for suggestions, highlighting, `dfs_query_then_fetch`
|
||||
- Profiling of the reduce phase of aggregation is currently not available
|
||||
- The Profiler is still highly experimental. The Profiler is instrumenting parts of Lucene that were
|
||||
never designed to be exposed in this manner, and so all results should be viewed as a best effort to provide detailed
|
||||
diagnostics. We hope to improve this over time. If you find obviously wrong numbers, strange query structures or
|
||||
other bugs, please report them!
|
||||
|
|
|
|||
Loading…
Reference in New Issue