# Why is there such a big gap between the cumulative time from the search profiler and the latency from esrally? **URL:** \ **Category:** Elasticsearch\ **Tags:** rally\ **Created:** [October 8, 2024, 7:47pm UTC](https://discuss.elastic.co/t/why-is-there-such-a-big-gap-between-the-cumulative-time-from-the-search-profiler-and-the-latency-from-esrally/368479 "2024-10-08T19:47:07Z")\ **Posts on this page:** 6\ **Page:** 1
**Author:** ![corojoon93](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/corojoon93/32/136894_2.png) [@corojoon93](https://discuss.elastic.co/u/corojoon93)\ **Post date:** [October 8, 2024, 7:47pm UTC](https://discuss.elastic.co/t/why-is-there-such-a-big-gap-between-the-cumulative-time-from-the-search-profiler-and-the-latency-from-esrally/368479/1 "2024-10-08T19:47:07Z")
I have been using esrally and search profiler to test the performance of search queries processed by the existing cluster. I turned off request cache and the query cache for the index. ## Test result After running the search query 100 times with the search profiler, I found that it almost always took about 60 ms. The service time from esrally was 10 ms. (client: 1, throughput: 1, iterations: 100) ## Questions Q1. Why is there such a big gap between the two test results? I think this result odd because I think esrally's latency should be higher than the search profiler's cumulative time. As I understand it, the cumulative time from the search profiler is just the query processing time, while esrally's latency includes both the processing time and the network time. Q2. Does esrally show no difference in latency time whether the test query includes a sort clause or not? The search-query used in the tests has a pretty complex sorting clause. The search profiler showed a big difference in cumulative time when the sorting was included versus when it wasn't, but esrally showed almost the same service time in both cases. Here is my esrally track: ```auto { "description": "Benchmarking for product index", "schedule": [ { "operation": { "name": "category-query", "operation-type": "search", "param-source": "category-search-query-source" }, "clients": 1, "warmup-iterations": 10, "iterations": 110, "target-throughput": 1 } ] } ``` Here is my track.py: ```python def category_search(track, params, **kwargs): return { "cache": False, "detailed-results": True, "index": "product", "body": { "track_total_hits": True, "from": 1, "size": 80, "query": { "bool": { "filter": [ { "bool": { "must": [ { "term": { "product_hidden_status": { "value": 0 } } }, { "terms": { "platform_type": parameters.terms_random_platforms() } }, { "terms": { "product_state": parameters.terms_random_product_state() } }, { "bool": { "should": [ { "term": { "category_seq1": { "value": parameters.term_random_category_seq(level=1) } } } ] } } ], "filter": [ { "range": { "sort_date": parameters.range_random_sort_date() } }, { "range": { "product_price": parameters.range_random_price() } } ], "must_not": [ { "exists": { "field": "excluding_search" } }, { "terms": { "product_state": [ 2, 4, 7 ] } } ] } } ] } }, "sort": [ { "image_detect": { "order": "asc", "unmapped_type": "integer" } }, { "_score": { "order": "desc" } }, { "platform_type": { "order": "asc" } }, { "wish_cnt": { "order": "desc", "unmapped_type": "long" } }, { "pay_flag": { "order": "desc", "unmapped_type": "long" } }, { "sort_date": { "order": "desc" } } ] } } def register(registry): registry.register_param_source("category-search-query-source", category_search) ``` Thank you for your time. ---
**Author:** ![json](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/json/32/4125_2.png) [@json](https://discuss.elastic.co/u/json)\ **Post date:** [October 8, 2024, 10:07pm UTC](https://discuss.elastic.co/t/why-is-there-such-a-big-gap-between-the-cumulative-time-from-the-search-profiler-and-the-latency-from-esrally/368479/2 "2024-10-08T22:07:03Z")
Hello, I suspect you could be seeing overhead from the search profiler itself. Can you see if you get a different result by enabling the search profiler in your track.py? The result might answer both of your questions. Thank you, Jason ---
**Author:** ![Christian\_Dahlqvist](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/christian_dahlqvist/32/4617_2.png) [@Christian\_Dahlqvist](https://discuss.elastic.co/u/Christian_Dahlqvist)\ **Post date:** [October 9, 2024, 6:11am UTC](https://discuss.elastic.co/t/why-is-there-such-a-big-gap-between-the-cumulative-time-from-the-search-profiler-and-the-latency-from-esrally/368479/3 "2024-10-09T06:11:53Z")
In addition to what Jason said I would also verify that the queries return a similar number of matches. As you seem to randomise a number of filtering criteria, is it possible that this frequently results in no or few matching documents being found (which would speed up sorting)? ---
**Author:** ![corojoon93](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/corojoon93/32/136894_2.png) [@corojoon93](https://discuss.elastic.co/u/corojoon93)\ **Post date:** [October 14, 2024, 9:07am UTC](https://discuss.elastic.co/t/why-is-there-such-a-big-gap-between-the-cumulative-time-from-the-search-profiler-and-the-latency-from-esrally/368479/4 "2024-10-14T09:07:31Z")
Hello, Christian. I adjusted the search conditions of the query specified in `track.py`. (random -\> values used in the search profiler). As expected, the service time in esrally started to come out longer than the cumulative time in the search profiler. - Search profiler: 60ms - esrally: 70ms Moreover, sorting has started to affect performance. - esrally (no sorting): 70ms - esrally (with sorting): 56ms It seems like random search conditions in the track.py resulted in many cases with fewer search results, which likely caused this issue. Thanks for your help! Hojun ---
**Author:** ![corojoon93](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/corojoon93/32/136894_2.png) [@corojoon93](https://discuss.elastic.co/u/corojoon93)\ **Post date:** [October 14, 2024, 9:17am UTC](https://discuss.elastic.co/t/why-is-there-such-a-big-gap-between-the-cumulative-time-from-the-search-profiler-and-the-latency-from-esrally/368479/5 "2024-10-14T09:17:43Z")
Hello, json Based on Christian Dahlqvist's suggestion, I modified the search conditions and added the `"profile": True` option to the query in `track.py`. - esrally's service time(profile ON): 116ms - esrally's service time(profile OFF): 70ms I realized that the `profile` option affects the benchmarking results in `esrally`. But I have a question. Does the cumulative time in the search profiler also get affected by profile overhead? Thank you, Hojun ---
**Author:** ![json](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/json/32/4125_2.png) [@json](https://discuss.elastic.co/u/json)\ **Post date:** [October 14, 2024, 10:22pm UTC](https://discuss.elastic.co/t/why-is-there-such-a-big-gap-between-the-cumulative-time-from-the-search-profiler-and-the-latency-from-esrally/368479/6 "2024-10-14T22:22:00Z")
Hi Hojun, > [@corojoon93](#): > > But I have a question. Does the cumulative time in the search profiler also get affected by profile overhead? The question is probably best asked in #Elasticsearch where there is more knowledge on the impact of the query profiler. Thanks, Jason