Fix false positive query timeouts due to using cached time

[aabukhalil]

Signed-off-by: Ahmad AbuKhalil [email protected]

Description

• Use System.nanoTime() for startTime when creating query timeout cancellation runnable to prevent premature false positive query timeouts. More info on how this fix will resolve the issue.

Issues Resolved

fixes #2000

Testing

The new units tests has dependency on actual system time which is not the recommended method but these tests has passed ./gradlew test -Dtests.class=org.opensearch.search.query.QueryPhaseTests -Dtests.iters=200 -Dtests.method=testQueryTimeoutChecker* so I would assume they are reliable enough.

For performance, now we will have additional nanoTime called when timeout is set per query which might have slight performance impact so I will follow up on performance test after merging this.

Check List

• New functionality includes testing.
  • All tests pass
• New functionality has been documented.
  • New functionality has javadoc added
• Commits are signed per the DCO using --signoff

By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.
For more information on following Developer Certificate of Origin and signing off your commits, please check here.

[opensearch-ci-bot]

✅   Gradle Check success f604902
Log 5618

Reports 5618

[reta]

@aabukhalil I think we are focusing only on one aspect of the problem rather than whole:

• if thread_pool.estimated_time_interval is set to 0, no changes needed - the original implementation will work right away
• if thread_pool.estimated_time_interval is not set to 0, we may have an issues here but only if the timeout value is significantly smaller than thread_pool.estimated_time_interval

Instead of changing QueryPhase, I would like to suggest introducing new method getRelativeTimeInMillisForTimeout(final long timeout) (or even modifying the existing method getRelativeTimeInMillis to accept timeout argument, seems like it is used only in QueryPhase). Inside, depending on the thread_pool.estimated_time_interval and timeout value the decision could be made to either use cached time provider or fallback to System.nanoTime(). WDYT?

[aabukhalil]

@reta thank you for reviewing this and providing feedback :)
Can you please elaborate on your concern on the reason of introducing more branching logic to compute initial time (which depend on cache lifespan and timeout value) as you suggested instead of using one logic which will always work with no branching ?

And yeah I have concern of calling System.nanoTime directly from QueryPhase but I think adding additional method getRelativeTimeInMillisForTimeout or override to getRelativeTimeInMillis(long timeout) will be more confusing to which one to use. (It will be harder to decide which method/override to use in here for example or any caller and eventually need to look at implementation details to decide which one). My suggestion is to introduce method like getNonCachedRelativeTimeInMillis or override like getRelativeTimeInMillis(boolean useCache) where it is clear for caller what is the difference between them and let caller decide on branching logic. What do you think ?

[reta]

thanks @aabukhalil

Can you please elaborate on your concern on the reason of introducing more branching logic to compute initial time (which depend on cache lifespan and timeout value) as you suggested instead of using one logic which will always work with no branching ?

Sure, the decision what is getRelativeTime() is made in one place and in one place only. Taking into account possible set of values, we should not do the work someone else (the time provider in this case) should be doing.

And yeah I have concern of calling System.nanoTime directly from QueryPhase but I think adding additional method getRelativeTimeInMillisForTimeout or override to getRelativeTimeInMillis(long timeout) will be more confusing to which one to use.

If I am not mistaken, this is the only place when this method is being used, so fixing it in a way that prevents wrong usage makes sense to me. Keeping this method unchanged leaves opportunities for future misuse. The getRelativeTimeInMillisForTimeout is not a good name, but may be getRelativeTimeInMillisWithPrecision(long precision) would be better.

[aabukhalil]

@reta yeah I agree that time provider should be the only responsible module for time but I'm asking about your concern of adding new branch (if timeout < cache lifespan then return non cached time else fallback to default implementation) instead of always returning non cached time and without promising that we have actual control of time precision because I think we have cached time and non cached time actually. WDYT ?

[reta]

@aabukhalil sorry missed that, I don't know the full story behind caching, but may be we could measure the overhead of calling System.nanoTime vs query execution time? (like [1] fe) Calling System.nanoTime directly and dropping all the caching impl would make things simpler for sure.

[1] https://bugs.openjdk.java.net/browse/JDK-6440430

[aabukhalil]

@reta System.nanoTime is known to be a slow operation and that's why it is cached. But the caching advantage is still applicable here because getting time here is still using the cached time and which will be called almost per matched document. So the overhead I'm adding is one System.nanoSecond per query when timeout is set and after merging this I need to look on the performance impact of this single call. For now I will refactor this to delegate calling System.nanoSecond to SearchContext.

[reta]

@reta, what sort of testing would give you confidence that we could just remove the caching all together?

@aabukhalil @andrross there is this excellent analysis [1] from OpenJDK developer(s) regarding the System.nanoTime() usage, the takeaway (one of) is: "nanoTime is not dirt cheap; at best, you can hope for 15-30 ns per call" (is highly depends on operating system as well).

[1] https://shipilev.net/blog/2014/nanotrusting-nanotime/

[Bukhtawar]

Can we not refresh the cache at a faster interval, I would like to understand the overall overhead of caching System#nanoTime. We should look into optimizing/correcting the clock used for the query and its timeout rather than adding more code for the timeout

[aabukhalil]

@reta @andrross Yes nanoTime is not cheap and seems nothing has changed since these analysis were made. According to a micro benchmark I've just made (will include it's code in next revision), calling System.nanoTime has latency of ~30 nanoseconds while accessing volatile long variable and incrementing it has latency of ~3 nanoseconds (which is upper bound of what is happening in ThreadPool time cache ).

The benchmark was run on Linux on EC2 c6a.12xlarge (AMD processor), Linux on EC2 m5.12xlarge (Intel processor), Macbook locally (Intel(R) Core(TM) i7-9750H) and Windows locally (Intel(R) Core(TM) 7-10750H) and all shows the consistent behavior of 30ns latency when calling nanoTime.

My call here is that the advantage of cached time optimization is still applicable as getting time here is still using the cached time which will be called almost per matched document in query result which even the 30ns latency MIGHT be amplified depending on match set size because of how checkCancelled is called as currently there are 21 caller of that method and some of them with no sampling (e.g. 100K matching documents might add up to 30 millisecond to query's took when timeout is set with no time caching).

My change is called once only per query where timeout is set which will add ~30ns to overall search latency per query which I don't think will impact overall system latency or throughput and still I need to follow up on performance test after merging this to confirm that there is no impact made. What do you think ?

[aabukhalil]

@Bukhtawar since current supported timeout granularity is millisecond so solve this issue completely we need to speed up time cache eviction to be each 1ms, no ?

I've run this program locally

public class MainTestTimeSleep {
    volatile static long time = 0L;
    public static void main(String[] args) throws Exception{
        while (true) {
            time = System.nanoTime();
            Thread.sleep(1);
        }
    }
}

which mimics updating time each 1ms and this program resulted in utilizing ~6% of one CPU by itself due switching process state from running to sleeping so frequently I guess.
Sleeping each 10ms reduced CPU consumption to ~1%.

My concern is if want to support timeout granularity in milliseconds, we might run into same situation consuming CPU resources almost busy waiting. What do you think ?

[nknize]

Pinging @Bukhtawar @andrross and @reta for any followup to avoid this becoming stale.

[reta]

Pinging @Bukhtawar @andrross and @reta for any followup to avoid this becoming stale.

I think there are 3 approaches we could take:

1. Fix the API: the getRelativeTimeInMillis under the hood uses caching controlled by thread_pool.estimated_time_interval. When this setting is largely misaligned with measurements (like small timeouts), we see this issue. Solution: the getRelativeTimeInMillis should be hinted with desirable resolution and fall back to System.nanoTime() if it could not satisfy the measurement with cached value.
2. Drop caching and make API always call System.nanoTime() (possibly, paying higher price for such calls).
3. Do validate timeouts to be aligned with thread_pool.estimated_time_interval so to make sure they could be more or less satisfied.

@andrross @Bukhtawar please feel free to add or correct me, thank you.

[andrross]

2. Drop caching and make API always call System.nanoTime() (possibly, paying higher price for such calls).

I think calling System.nanoTime() with no caching is probably a non-starter because the check happens too frequently, if my understanding is correct. However, what if reduced the cached time interval from 200ms down to 10ms or 20ms? A 30ns cost every 10000000ns (please check my math :) ) seems trivial. Would the inaccuracy be small enough as to not matter? I think this is what @Bukhtawar was hinting at above, and it would be a super simple fix with no extra logic added.

Also, this wasn't super clear to me on the linked issue (#2000), but I think the only thing at issue here is the accuracy of the search timeout and not the took value, because search time is measured separate and makes a call to System.nanoTime() at the beginning and end of the operation.

[reta]

However, what if reduced the cached time interval from 200ms down to 10ms or 20ms?

We have this setting thread_pool.estimated_time_interval to manage that, we could change the default as suggested but users still have the option to change it (and apparently, not drawing the parallels between the impact of this setting on query timeouts). I think changing the default should be more or less safe.

[andrross]

I agree that it's non-obvious and confusing that the thread_pool.estimated_time_interval setting impacts the accuracy of query timeouts. @reta's "Fix the API" approach above fixes that problem, but I'm concerned that it would introduce other confusing modal behavior that impacts performance if the estimated_time_interval value and the query timeout were mis-aligned and the system reverted back to making the nanoTime() call every time. @reta Do you think that's a valid concern?

For completeness, I'll add a couple more options:

4. Modify QueryPhase to record the real time once at the beginning of each search request to prevent premature false positive timeouts (that's the approach taken in this PR)
5. Reduce the default thread_pool.estimated_time_interval and document it's relationship with the search timeout

[reta]

Thanks @andrross

@reta Do you think that's a valid concern?

I think this is the best we can do in this case.

4. Modify QueryPhase to record the real time once at the beginning of each search request to prevent premature false positive timeouts (that's the approach taken in this PR)

The part which I am not comfortable with - we do use 2 different approaches for the same thing: nanoTime() at the start, getRelativeTimeInMillis() at the end. It is very confusing and basically asks the question: why is that? Fixing the API or/and always using nanoTime() would address the problem at core.

5. Reduce the default `thread_pool.estimated_time_interval` and [document it's relationship with the search timeout](https://opensearch.org/docs/latest/opensearch/rest-api/search/#url-parameters)

👍

[opensearch-ci-bot]

✅   Gradle Check success 8955d64d74546e2d4c70fc31f582cc0764e04efb
Log 5993

Reports 5993

[opensearch-ci-bot]

❌   Gradle Check failure f604902
Log 6003

Reports 6003

[opensearch-ci-bot]

❌   Gradle Check failure d1bd21d2054a95294dd64dc220e932a88dcb6127
Log 6004

Reports 6004

[opensearch-ci-bot]

❌   Gradle Check failure ddbfa15
Log 6005

Reports 6005

[opensearch-ci-bot]

❌   Gradle Check failure f27cb96
Log 6006

Reports 6006

[aabukhalil]

@reta @andrross can you review this again as I pushed a change to keep current approach as is (use non cached time for startTime for once and then use the cached time per document ) but I've changed the time API to be more accurate and less confusing. This approach does not have performance compromise and still fixes the problem and is not discarding any optimizations made.

[reta]

@reta @andrross can you review this again as I pushed a change to keep current approach as is (use non cached time for startTime for once and then use the cached time per document ) but I've changed the time API to be more accurate and less confusing. This approach does not have performance compromise and still fixes the problem and is not discarding any optimizations made.

@aabukhalil My apologies but I did not get it: before we just called final long startTime = TimeValue.nsecToMSec(System.nanoTime()); directly, now we just wrap the same call into a method getPreciseRelativeTimeInMillis(). Instead of 1 problem with getRelativeTimeInMillis() we have 2: getPreciseRelativeTimeInMillis() and getRelativeTimeInMillis()

May be we should just flip thread_pool.estimated_time_interval to 0 which means - always call nanoTime() but let still keep the door for users to opt-out if they see the significant performance degradation?

[aabukhalil]

@reta @andrross can you review this again as I pushed a change to keep current approach as is (use non cached time for startTime for once and then use the cached time per document ) but I've changed the time API to be more accurate and less confusing. This approach does not have performance compromise and still fixes the problem and is not discarding any optimizations made.

@aabukhalil My apologies but I did not get it: before we just called final long startTime = TimeValue.nsecToMSec(System.nanoTime()); directly, now we just wrap the same call into a method getPreciseRelativeTimeInMillis(). Instead of 1 problem with getRelativeTimeInMillis() we have 2: getPreciseRelativeTimeInMillis() and getRelativeTimeInMillis()

May be we should just flip thread_pool.estimated_time_interval to 0 which means - always call nanoTime() but let still keep the door for users to opt-out if they see the significant performance degradation?

Yes the new change is just a wrapper of the old procedure but I think this time it is better abstracted as one method might be cached and the other is not cached and let caller decide which to use depending on usage. I think abstracting this behavior as getRelativeTimeInMillisWithPrecision(long precision) is misleading and hard to explain and the abstraction will eventually get leaked. IMHO, I think that getPreciseRelativeTimeInMillis is less abstracted while lending your idea to use the term 'Precise'.

For flipping thread_pool.estimated_time_interval to 0 by default, that sound like an option here but I didn't get why we might ship an optimization turned off by default while this optimization's side effect can be solved by default with no penalty for users and less static configurations to decide on. what do you think ?

By shipping this, false positive timeouts should be eliminated by default without affecting anything else and it is a one step toward a better product.

[reta]

For flipping thread_pool.estimated_time_interval to 0 by default, that sound like an option here but I didn't get why we might ship an optimization turned off by default while this optimization's side effect can be solved by default with no penalty for users and less static configurations to decide on. what do you think ?

This is the most straightforward and concise way to address the problem (or reducing it to smaller value fe 10ms). The few nanonseconds per call sounds like not a dramatic performance hit (if we account for caching implementation - even less so) for calling nanoTime().

By shipping this, false positive timeouts should be eliminated by default without affecting anything else and it is a one step toward a better product.

This is a patch for the particular flow - it does not address the problem that getRelativeTimeInMillis API is flawed and produces misleading results (as this issue demonstrates). This is what we have to fix (in my opinion).

[aabukhalil]

This is the most straightforward and concise way to address the problem (or reducing it to smaller value fe 10ms). The few nanonseconds per call sounds like not a dramatic performance hit (if we account for caching implementation - even less so) for calling nanoTime().

Yeah definitely couple of nanoseconds per call is not my concern. The concern and which is why this optimization was made (most probably) is due the fact that total latency per whole search call will be impacted by extra couple milliseconds because getRelativeTimeInMillis get called per each document in the result set so it will get amplified. The question now is why would we do that intentionally ?

This is a patch for the particular flow - it does not address the problem that getRelativeTimeInMillis API is flawed and produces misleading results (as this issue demonstrates). This is what we have to fix (in my opinion).

Yes but now it's well documented that getRelativeTimeInMillis API is flawed and might be cached time and there is more precise alternative which is getPreciseRelativeTimeInMillis

[opensearch-ci-bot]

❌   Gradle Check failure f0aa95c
Log 6039

Reports 6039

[reta]

As on option, we could update getRelativeTimeInMillis to be explicit if cached relative time is allowed or not - the ambiguity which API to use will be gone.

[aabukhalil]

As on option, we could update getRelativeTimeInMillis to be explicit if cached relative time is allowed or not - the ambiguity which API to use will be gone.

you mean what was proposed in here as getRelativeTimeInMillis(boolean useCache) ? I can do that and I'm okay with that

[reta]

you mean what was proposed in here as getRelativeTimeInMillis(boolean useCache) ? I can do that and I'm okay with that

Exactly, yes, sorry I missed that, I think out of all options it is the best one.

[dblock]

you mean what was proposed in here as getRelativeTimeInMillis(boolean useCache) ? I can do that and I'm okay with that

Exactly, yes, sorry I missed that, I think out of all options it is the best one.

Does this mean passing cached = true/false all the way to CachedTimeThread? Adjusting all of absoluteTimeInMillis and relativeTimeInNanos to match? It might get messy.

[reta]

Should we deprecate this one and point to getRelativeTimeInMillis(boolean useCache) ? We definitely don't need 2 methods for same thing.

[aabukhalil]

@reta if want to deprecate getRelativeTimeInMillis which is an abstract method then getRelativeTimeInMillis(boolean useCache) should be abstract too to give child classes ability to implement it and I think that not all child classes really should care about useCache because they might not have such concept so this will cause even more abstraction leak. while by keeping both overrides then child class has to implement one method/logic. so I'm not sure what is best here as both options is causing abstraction leak anyway. do you mean by deprecation just annotating the old method with @Deprecated and leave it ?

[dblock]

I think I agree with @aabukhalil. The fact that getRelativeTimeInMillis() is being overloaded and eventually comes from some other time thread class made it really hard to follow and understand. I'm happy we're solving the SearchContext problem here and would defer trying to solve the more general problem to a radical simplification of this code.

[reta]

do you mean by deprecation just annotating the old method with @deprecated and leave it ?

@aabukhalil yeah, exactly, mark as @deprecated, we cannot remove it right now

@dblock no breaking changes, everything would be working as-is, just hinting that new method is preferred for use.

[aabukhalil]

@reta marking getRelativeTimeInMillis() as deprecated while still abstract and forcing child classes to implement it because there is no path forward to implement, does not make sense to me. Deprecation is not inherited in java so if you deprecate getRelativeTimeInMillis() in SearchContext and you have subclass MySearchContext which extends SearchContext and you call getRelativeTimeInMillis() on MySearchContext it won't be marked as deprecated which somehow breaks Liskov substitution principle because the behavior of compiler will change if you have your variable defined as SearchContext vs MySearchContext, what do you think ? I don't see strong reason to deprecate this.

[reta]

Oh this is true, @Deprecated indeed has an issue with inheritance, you are right @aabukhalil

[aabukhalil]

thank you @reta, appreciate your help and dedication :)

[opensearch-ci-bot]

❌   Gradle Check failure 75bcb5ed569a34daf046bc43327a3fb7c2915d0c
Log 6042

Reports 6042

[dblock]

Needs a fix for this:

> Task :server:compileJava
/var/CITOOL/workflow/OpenSearch_CI/PR_Checks/Gradle_Check/search/server/src/main/java/org/opensearch/search/internal/SearchContext.java:399: warning: no description for @param
     * @param useCache
       ^
/var/CITOOL/workflow/OpenSearch_CI/PR_Checks/Gradle_Check/search/server/src/main/java/org/opensearch/search/internal/SearchContext.java:400: warning: no description for @return
     * @return
       ^

[aabukhalil]

Needs a fix for this:

> Task :server:compileJava
/var/CITOOL/workflow/OpenSearch_CI/PR_Checks/Gradle_Check/search/server/src/main/java/org/opensearch/search/internal/SearchContext.java:399: warning: no description for @param
     * @param useCache
       ^
/var/CITOOL/workflow/OpenSearch_CI/PR_Checks/Gradle_Check/search/server/src/main/java/org/opensearch/search/internal/SearchContext.java:400: warning: no description for @return
     * @return
       ^

@dblock thank you for catching this. it is updated now.

[opensearch-ci-bot]

✅   Gradle Check success 7f73aa7
Log 6079

Reports 6079