Rescoring phase adds unexplained latency to queries #108568
Comments
Mikep86
added
:Search/Ranking
|
Pinging @elastic/es-search (Team:Search) |
|
@nemphys does the Elasticsearch profiling output show a similar distribution of runtime? The absolute numbers with Elasticsearch How are you profiling the rescore step? Do you utilize various fields stored for each doc for your rescoring? I wonder a couple of things:
|
|
@benwtrent I already checked the profile output, but I could not find anything useful: For the rescorer profiling, I am using a simple System.currentTimeInMillis() diff (start/end of the method), should be the actual execution time since the method is only called once for each request. I indeed gather doc_values from various document fields during the rescoring, but shouldn't the time spent there be included in the profiled time? |
|
@nemphys is your |
|
@benwtrent actually the window size is ignored (set to the maximum allowed), since I must process all query results in the rescorer (if you are wondering why I don't do it using normal scoring, eg. with a ScriptEngine, it is because I am considering implementing some kind of LTR in the rescorer that must process the top k results before all results are rescored using some additional logic). |
By So the number of documents in your query testing performance difference & the number of documents handled by your rescorer are exactly the same? |
Yes, both queries are exactly the same, with the only difference being the rescorer (which processes all results). |
|
I think I should elaborate a little more in order to clarify what I am trying to achieve here: Until now, I have already implemented a ScriptEngine that performs custom rescoring on top of BM25. Since I would like to introduce a LTR layer to the scoring process (not using the native ES LTR functionality, nor the ES LTR plugin), I am experimenting with a custom rescorer. The problem is that the initial custom rescoring logic must be applied after LTR rescoring, and must be applied on all query results (whereas LTR could affect only the top n). Therefore, I created the rescorer (which does exactly what the ScriptEngine has been doing until now) and I am trying to make sure that I will not get some kind of latency overhead before I start experimenting with the LTR part. Sadly, this is not the case and I am trying to figure out what is going on :-) |
|
@benwtrent New finding: if I remove the score processing code (including doc_values loading, etc) from the custom rescorer rescore() method (effectively turning it to a no-op), I still get ~50ms added latency to search responses (!) This definitely means that there is something else going on, outside the rescorer. Update: just tried using a small window size (instead of the max I have been using), and the overhead is gone. Does this mean that it is impossible to process all search results inside a rescorer without the added latency, even if the rescorer itself is fast? Update2: did some further tests regarding window size and I cannot understand why it affects latency so much; the specific query I am using has a total of 5252 results. Gradually increasing the window size from 10 to 5300 increases the latency proportionally (this should be considered normal I guess?). What is really weird, is that if I keep increasing it up to the max (500000), query response times continue to go up; shouldn't the window size have no negative effect when raised above the actual total result count of the query? |
When rescoring, we have to actually search for, score, and gather But, the fact that increasing the window_size, but knowing for sure only 5252 will actually return, and window_size increasing continues to make things slower, this is weird. I wonder if your rescorer is ignoring the matched docs and is instead iterating past the matched docs and assuming they have a score of This warrants some investigation on our side. Something weird and I cannot put my finger on it. |
The rescorer is only processing the matched docs, I am 100% certain about that. This is further confirmed by the fact that response times go up in proportion to the window_size, even with a no-op rescorer (return topDocs)! After digging deeper, I stumbled upon a comment in the Lucene TopScoreDocCollectorManager/TopFieldCollectorManager classes noting that "The instances returned by this method pre-allocate a full array of length numHits" (which I confirmed to be equal to the window_size setting, initially set by org.elasticsearch.search.query.QueryPhaseCollectorManager's createQueryPhaseCollectorManager method). Could this have something to do with the overhead (10/100 vs 500,000 entries could potentially make a difference I suppose)?
That would be great, looking forward to hearing about any interesting findings for potential optimization! |
🫤 |
Does 🫤 mean "Bummer, we can do nothing about that" or "Gee, we will look into it!"? 😅 |
|
It means that it is likely done this way for a reason and I am not sure we can fix it. We don't know how many docs are going to match until we start searching. There are optimized ways to gather the matching docs, allowing a two pass (one to count, the other to score), but this will likely make things slower. Especially for queries where an optimized count option just doesn't exist. Maybe we can under allocate the array and grow it, but that might lead to concurrency issues. We could switch from an array to some concurrent collection that grows dynamically, but this might slow down the common case. |
|
So, does this mean that this is definitely the culprit here? Is there any chance that something else might be also affecting latency? |
|
It may be part of the cause, but it's likely not all of it. We do sort the docs multiple times, etc. It would be interesting to see allocations and CPU usage via jfr or async-profiler. |
Elasticsearch Version
8.13.3
Installed Plugins
analysis-icu
Java Version
bundled
OS Version
macOS Sonoma
Problem Description
I have created a custom rescorer, following the examples of QueryRescorer / ExampleRescorer.
It works fine, but the latency added to the responses is much bigger than it seemingly should be.
I am using a test query, which consistently takes around 40ms to execute (without rescoring).
When I add my custom rescorer, the response times shoot up to ~130ms.
I have profiled the rescore() method of my custom class and it is consistently executed within 30-35ms. I would expect the total query time to be close to the sum of the plain query and the rescoring, ie. 70-75ms.
What could possibly induce the extra overhead? I looked through the rescoring-related code, but could not find anything suspicious.
Steps to Reproduce
It is not possible to provide a reproducible example, since it depends on a custom plugin.
Logs (if relevant)
No response
The text was updated successfully, but these errors were encountered: