Why is there such a big gap between the cumulative time from the search profiler and the latency from esrally?

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:

{
  "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:

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.

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

1 Like

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)?

1 Like

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

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

Hi Hojun,

The question is probably best asked in Elasticsearch where there is more knowledge on the impact of the query profiler.

Thanks,
Jason

1 Like