Speed up SpanReader::findTraceIDs() for Elasticsearch #1475
Conversation
bobrik
requested review from
black-adder,
jpkrohling,
objectiser,
pavolloffay,
tiffon,
vprithvi and
yurishkuro
as code owners
|
Ha, this issue is #1475 just like speedup is 1475x 😦 |
|
Thanks for looking into this! It could be pretty sweet! I'm curious about what would happen if there are only few traces with a large number of spans per service. For e.g., let's assume that there are 10 unique traces with 10k spans all for the same service - if the new query is executed with a size of 10, would it retrieve all 10 traceIDs? |
bobrik
force-pushed
the
ivan/faster-es-search
branch
from
b7f8a44 to
264dc52
Compare
|
It will only return 10 unique traceIDs across the latest 1000 (value of I'm looking into test failures. |
bobrik
force-pushed
the
ivan/faster-es-search
branch
4 times, most recently
from
17d5a7e to
a6feb77
Compare
|
I understand your use case, but I'm not a fan of trading completeness for speed. I'm wondering whether we can trigger the strategy of searching by spans and looking at traceIDs only for certain search patterns. For instance, only applying it if the search interval is less than a minute. Or even better, are there strategies for search that are both complete and quick? |
bobrik
force-pushed
the
ivan/faster-es-search
branch
2 times, most recently
from
4621433 to
0812ed9
Compare
Codecov Report
@@ Coverage Diff @@
## master #1475 +/- ##
==========================================
+ Coverage 98.21% 99.73% +1.51%
==========================================
Files 195 179 -16
Lines 9602 8555 -1047
==========================================
- Hits 9431 8532 -899
+ Misses 134 12 -122
+ Partials 37 11 -26
Continue to review full report at Codecov.
|
The tradeoff is "working ui" vs "not working ui" for me, unfortunately.
The larger the window, the cheaper it is to search by spans. Aggregation looks at all matched docs, while search only looks at the latest ones.
I created a topic in elasticsearch forum to see if there's a proper way to do this: |
|
@bobrik I tried to replicate that slow query in our environment but it ran pretty fast: {
"took": 177,
"timed_out": false,
"_shards": {
"total": 5,
"successful": 5,
"skipped": 0,
"failed": 0
},
"hits": {
"total": 1087815,
"max_score": 0,
"hits": []
},
"aggregations": {
"traceIDs": {
"doc_count_error_upper_bound": -1,
"sum_other_doc_count": 1087569,
"buckets": [.....]
}
}
}I tried to pick something that would match the Obviously, this is not a perfect comparison, but I still wanted to try to replicate it and report back 👍 |
May I know something detail about the config of your environment? |
|
@NijiadeIX I've shared number in a talk. You can get the slides from that page: https://kccnceu19.sched.com/event/MPbm/deploy-scale-and-extend-jaeger-louis-etienne-dorval-ticketmaster Look at slide 14 and 37 |
|
@NijiadeIX this is how much data we have on daily basis (33B spans / 2TB of data per replica): |
We have a service that generates two spans per trace,
around 4K spans per second. It's very slow to query
for the latest traces in this service.
This is the default query that is currently generated:
```json
{
"aggregations": {
"traceIDs": {
"aggregations": {
"startTime": {
"max": {
"field": "startTime"
}
}
},
"terms": {
"field": "traceID",
"order": [
{
"startTime": "desc"
}
],
"size": 20
}
}
},
"query": {
"bool": {
"must": [
{
"range": {
"startTime": {
"from": 1555437540000000,
"include_lower": true,
"include_upper": true,
"to": 1555437600000000
}
}
},
{
"match": {
"process.serviceName": {
"query": "nginx-ssl"
}
}
}
]
}
},
"size": 0
}
```
This takes pretty much forever if there are many spans to aggregate:
```json
{
"took": 38372,
"timed_out": false,
"_shards": {
"total": 5,
"successful": 5,
"skipped": 0,
"failed": 0
},
"hits": {
"total": 331761,
"max_score": 0,
"hits": []
},
"other": "stuff"
}
```
Presumably, because ES takes full window, then sorts as many buckets
as there are traces.
Instead, we can pull the last X spans, and find unique traceIDs there:
```json
{
"query": {
"bool": {
"must": [
{
"range": {
"startTime": {
"from": 1555437540000000,
"include_lower": true,
"include_upper": true,
"to": 1555437600000000
}
}
},
{
"match": {
"process.serviceName": {
"query": "nginx-ssl"
}
}
}
]
}
},
"size": 100,
"sort": [
{
"startTime": "desc"
}
]
}
```
This is a whole lot faster:
```json
{
"took": 26,
"timed_out": false,
"_shards": {
"total": 5,
"successful": 5,
"skipped": 0,
"failed": 0
},
"hits": {
"total": 331761,
"max_score": null,
"hits": [
"100 hits here"
]
},
"other": "stuff"
}
```
So this is 38372 / 26 = 1475x faster, which is pretty nice.
Generally speedup is under 1000x, though.
Signed-off-by: Ivan Babrou <[email protected]>
bobrik
force-pushed
the
ivan/faster-es-search
branch
from
0812ed9 to
60bf9f3
Compare
|
We have also experienced very slow query performance, we altered the index setting, added
|
|
@wqtty how much data do you ingest? What is your data retention? With that setting do you experience increased disk, CPU overhead at ingestion time?
|
we are having about 14k spans per second, and keep them in es for only 2 days, meaning we are having a jaeger-span index about 2.3T every day.
Sorry, I didn't catch you. |
|
If you experience increased CPU load or increased disk space allocation after you applied that setting. |
not very obvious |
|
Our elasticsearch/jaeger setup grinds to a halt as the day goes on! Being able to control the max number of spans in the query result as a config option feels like something many folks (including me) would opt into. |
|
I query the data of today can be very slow: But I query the data of the yesterday can be very fast: |
|
Could somebody submit a new PR or rebase this one? |
|
FYI re my previous comment, we've pretty much solved our performance problems by adding |
|
I suppose we rely on aggregations to get unique traceIds. Is there any way to distinguish the root span alone so that we could filter based on certain field to get all root spans and their traceIDs? I saw |
|
@pavolloffay, I can rebase, but it will still fail a test for reading past 10k spans and I don't really have much time on my hands to work around that. Internally we've moved on from this a bit further, which complicates things. Our index is sorted, so that queries can read data in order and terminate early. This required us to get rid of indexing for nested docs, which means no searching for tags in logs. Overall there's a massive improvement in terms of docs (we used to run out of docs per segment because of nested docs!), and memory footprint: Plus we're looking into Clickhouse as the backend #1438. |
|
@RashmiRam, the aggregation is looking for traceIDs that match the tags. You can't look only at root spans, since they don't have tags of children. |
|
Aah. I somehow missed it. Thanks @bobrik |
|
@Stono Can I know what is your refresh interval and jvm size. I have tried using |
|
@pavolloffay @wqtty @bobrik Improvements we saw were following:
Let me know if you all have any questions. |
@mehta-ankit can we know your cardinality of traceID field, and what is the value of latency you have observed. For us setting the global_ordinals to true didn't help . Our refresh interval is also around 60s. Wanted to know anything I missed |
|
@sivatarunp Looks like i figured out the cardinality. It seems to be 105 million for a single day's index. Used the following query Avg Latencies for Question,
|
|
@mehta-ankit you can have a rough estimation of cardinality by traces/s metric as well. For us for lookback value of 1hr and results_limit to 20, Its taking huge time around 25-30s. Hence the worry |
Thanks for the info @mehta-ankit 👍 🙏 |
|
Closing due to inactivity. |
|
Hey for other people coming to this thread, i've summarised all the things I changed to make jaeger -> elasticsearch super performant for our use case. Hope it might be of use to others. https://karlstoney.com/speeding-up-jaeger-on-elasticsearch |
|
@Stono great post! You didn't always mention the downsides of enabling various settings, so it's a bit hard to judge, but wouldn't some of these changes make sense permanently in the default index template created by Jaeger? Or do you feel that it's hardly ever a good idea to rely on the default template? |
|
That's a really good point to be fair, I'll update it with the negatives tomorrow (which tbh are negligible for us, slightly more CPU during ingest). I think it's hard for jaeger offer a best for all template our the box. The default one is pretty good tbh, but I was pushing the scale. When you start doing that sort of volume really I think you'll end up bespoke tweaking to your use case, and hardware. I personally would however add eager ordinals to traceID and the references (spanID). |
We have a service that generates two spans per trace, around 4K spans per second. It's very slow to query for the latest traces in this service.
This is the default query that is currently generated:
{ "aggregations": { "traceIDs": { "aggregations": { "startTime": { "max": { "field": "startTime" } } }, "terms": { "field": "traceID", "order": [ { "startTime": "desc" } ], "size": 20 } } }, "query": { "bool": { "must": [ { "range": { "startTime": { "from": 1555437540000000, "include_lower": true, "include_upper": true, "to": 1555437600000000 } } }, { "match": { "process.serviceName": { "query": "nginx-ssl" } } } ] } }, "size": 0 }This takes pretty much forever if there are many spans to aggregate:
{ "took": 38372, "timed_out": false, "_shards": { "total": 5, "successful": 5, "skipped": 0, "failed": 0 }, "hits": { "total": 331761, "max_score": 0, "hits": [] }, "other": "stuff" }Presumably, because ES takes full window, then sorts as many buckets
as there are traces.
Instead, we can pull the last X spans, and find unique traceIDs there:
{ "query": { "bool": { "must": [ { "range": { "startTime": { "from": 1555437540000000, "include_lower": true, "include_upper": true, "to": 1555437600000000 } } }, { "match": { "process.serviceName": { "query": "nginx-ssl" } } } ] } }, "size": 100, "sort": [ { "startTime": "desc" } ] }This is a whole lot faster:
{ "took": 26, "timed_out": false, "_shards": { "total": 5, "successful": 5, "skipped": 0, "failed": 0 }, "hits": { "total": 331761, "max_score": null, "hits": [ "100 hits here" ] }, "other": "stuff" }So this is 38372 / 26 = 1475x faster, which is pretty nice. Generally speedup is under 1000x, though.