elasticsearch/elasticsearch — pull request #6699 by polyfractal (2014-07-03 01:02:25+00:00)
Title: Feature: Add ability to profile queries

This PR adds the ability to profile queries and determine which portions of the query are the slowest. All timings are relative and displayed in microseconds.

Timings are not guaranteed to match the `took` time of the query...in fact, they will likely be larger. This is because timings are aggregated from all shards, often executing in parallel, so the profiled time is more akin to CPU time than wallclock time.

It is also important to understand that Profile times represetn relative costs, rather than absolute times. The act of profiling adds considerable overhead to the querying process since all components in the query must be wrapped and timed.

### Enabling Profiling

Profling can be enabled with a query param, URI param or dedicated endpoint:

```bash
# Query param
curl -XGET localhost:9200/my_index/my_type/_search -d '{
"profile": true,
"query" : { ... }
}'

# URI param
curl -XGET localhost:9200/my_index/my_type/_search?profile=true

# Endpoint
curl -XGET localhost:9200/my_index/my_type/_profile -d '{
"query" : { ... }
}'
```

### Response output

When enabled, the response will contain an additional `profile` element. This will contain a tree of "profile components", where each component represents a portion of the query. Often, this tree of components will be larger than you expect - Elasticsearch and Lucene will expand and rewrite portions of the query, which introduces more pieces than you might expect.

Each component contains the following:

- **type** - The name of the Elasticsearch/Lucene class for this part of the query, e.g. `TermQuery`
- **time** - The total aggregated time at this level in the tree, which includes all children and all shards. Displayed as microseconds
- **relative** - Relative contribution of this level in the tree. This metric is `time / total_time`. Displayed as a percentage
- **lucene** - A rough approximation of the Lucene syntax for the component, which is often helpful in differentiating many similar components (e.g. differentiating `term: { "field1": "fred" }` from `term: { "field1": "bob" }`, since both are `TermQuery`s)
- **components** - Zero or more additional components which are children to this level. For example, a Bool will have children components representing the various clauses.

```json
{
"took": 99,
"timed_out": false,
"_shards": { ... },
"hits": { ... },
"profile": [
{
"type": "XFilteredQuery",
"time": 153996,
"relative": "100.00%",
"lucene": "filtered(filtered(my_field:the my_field:quick my_field:fox)->cache(input1:[1 TO 1]))->cache(_type:test)",
"components": [
{
"type": "XFilteredQuery",
"time": 108036,
"relative": "70.155%",
"lucene": "filtered(my_field:the my_field:quick my_field:fox)->cache(input1:[1 TO 1])",
"components": [
{
"type": "BooleanQuery",
"time": 62053,
"relative": "40.295%",
"lucene": "my_field:the my_field:quick my_field:fox",
"components": [
{
"type": "TermQuery",
"time": 20366,
"relative": "13.225%",
"lucene": "my_field:the"
},
{
"type": "TermQuery",
"time": 1117,
"relative": "0.72534%",
"lucene": "my_field:quick"
},
{
"type": "TermQuery",
"time": 391,
"relative": "0.25390%",
"lucene": "my_field:fox"
}
]
},
{
"type": "FilterCacheFilterWrapper",
"time": 3983,
"relative": "2.5864%",
"lucene": "cache(input1:[1 TO 1])"
}
]
},
{
"type": "FilterCacheFilterWrapper",
"time": 3835,
"relative": "2.4903%",
"lucene": "cache(_type:test)"
}
]
}
]
}
```

### Todo / Known Issues

- More tests! The current tests check for basic validity and overt failure, but I think we need a better way to check the contents of the profile response. + Unit tests for things like the ProfileVisitors
- Shards can rewrite queries differently (e.g. if the term is not present on one shard), which means chunks of the output could potentially be skipped. Naively handling this by just ignoring components which don't match.
- Potentially gross output, especially with numerics being expressed as byte strings (e.g. `\0001`)
- Fairly abusive use of Visitor pattern. In particular, I'm not overly happy with the ProfileCollapsingVisitor which is used to collect timings from the query tree...but I have no idea how to better structure it. The biggest problem is that all query types need to be hardcoded, so this will be a maintenance tar pit.
- Audit of the supported Query/Filter types...I imagine there are others that I'm missing which need to be added to both visitors
- `/_profile` endpoint could use some love, ideally extending the search endpoint instead of c/p