-
Notifications
You must be signed in to change notification settings - Fork 1.8k
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
[Tiered Caching] Adding took time for QuerySearchResult #10510
[Tiered Caching] Adding took time for QuerySearchResult #10510
Conversation
Is this already covered by #10351 ? That one adds timing for each query phase to the search result. |
Gradle Check (Jenkins) Run Completed with:
|
Compatibility status:Checks if related components are compatible with change 81dc9ef Incompatible componentsIncompatible components: [https://github.com/opensearch-project/security-analytics.git, https://github.com/opensearch-project/ml-commons.git, https://github.com/opensearch-project/cross-cluster-replication.git, https://github.com/opensearch-project/security.git, https://github.com/opensearch-project/neural-search.git, https://github.com/opensearch-project/k-nn.git, https://github.com/opensearch-project/performance-analyzer.git] Skipped componentsCompatible componentsCompatible components: [https://github.com/opensearch-project/observability.git, https://github.com/opensearch-project/job-scheduler.git, https://github.com/opensearch-project/opensearch-oci-object-storage.git, https://github.com/opensearch-project/custom-codecs.git, https://github.com/opensearch-project/sql.git, https://github.com/opensearch-project/asynchronous-search.git, https://github.com/opensearch-project/reporting.git, https://github.com/opensearch-project/notifications.git, https://github.com/opensearch-project/common-utils.git, https://github.com/opensearch-project/geospatial.git, https://github.com/opensearch-project/index-management.git, https://github.com/opensearch-project/anomaly-detection.git, https://github.com/opensearch-project/alerting.git, https://github.com/opensearch-project/performance-analyzer-rca.git] |
This is not related to #10351. This adds a took time part of shard level response which is eventually cached as well in RequestCache. We wanted this info in cached value to take a decision whether we want to spill this entry to disk cache or not during evictions(from in-memory cache). |
Gradle Check (Jenkins) Run Completed with:
|
Signed-off-by: Peter Alfonsi <petealft@amazon.com>
Signed-off-by: Peter Alfonsi <petealft@amazon.com>
Signed-off-by: Peter Alfonsi <petealft@amazon.com>
f5db1aa
to
a9ab327
Compare
Gradle Check (Jenkins) Run Completed with:
|
@@ -364,6 +366,11 @@ public void readFromWithId(ShardSearchContextId id, StreamInput in) throws IOExc | |||
nodeQueueSize = in.readInt(); | |||
setShardSearchRequest(in.readOptionalWriteable(ShardSearchRequest::new)); | |||
setRescoreDocIds(new RescoreDocIds(in)); | |||
if (in.getVersion().onOrAfter(Version.V_3_0_0)) { | |||
tookTimeNanos = in.readVLong(); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Better to make this OptionalLong? in.readOptionalLong()
and set below as null instead of -1.
Setting it -1 might be error prone if used and requires special checking. Though same for null but makes it more clear.
Gradle Check (Jenkins) Run Completed with:
|
Signed-off-by: Peter Alfonsi <petealft@amazon.com>
a68f44e
to
4e57f4c
Compare
Gradle Check (Jenkins) Run Completed with:
|
assertEquals(querySearchResult.getTookTimeNanos(), deserialized.getTookTimeNanos()); | ||
if (i == 1) { | ||
assertNull(deserialized.getTookTimeNanos()); | ||
} |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
It would probably read better to iterate over a map of expectedInput: expected value
.
Signed-off-by: Peter Alfonsi <petealft@amazon.com>
Gradle Check (Jenkins) Run Completed with:
|
@msfroh Would you be able us in getting this reviewed and merge in? |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
LGTM!
@@ -87,6 +88,7 @@ public final class QuerySearchResult extends SearchPhaseResult { | |||
private int nodeQueueSize = -1; | |||
|
|||
private final boolean isNull; | |||
private Long tookTimeNanos = null; |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Ideally the tookTimeNanos should also be final, since we never modify it once set. Although, not sure how we can communicate that intent while invoking setTookTimeNanos
from QueryPhase
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
You can define this field with SetOnce
@@ -131,13 +131,15 @@ public void preProcess(SearchContext context) { | |||
} | |||
|
|||
public void execute(SearchContext searchContext) throws QueryPhaseExecutionException { | |||
final long startTime = System.nanoTime(); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Sorry missed this earlier. Given we don't report this as stats anywhere, wondering if millis suffice for our use case. Nano is generally much more expensive:
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
We need an accurate elapsed time for queryPhase so that we can take decisions based on that. So we need nanos for that instead of millis.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
As per my understanding, since we need this time for evaluating whether to store result on disk or not, and disk access can be few ms, I don't completely understand the reason for using nanos instead of millis. Although it should be fine to use nanos as well, just want to ensure my understanding is not lacking.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
It is not just about whether disk access would be in few ms, System.currentTimeMilis() is tied to System clock, so using this might be a bit error prone. While System.nanoTime measures time relative to an arbitrary point in time and not affected by System clock skewness. Elapsed time is calculated using nanoTime across OpenSearch while millis used to display human readable dates to users.
try { | ||
Thread.sleep(sleepMillis); | ||
} catch (Exception ignored) {} | ||
return super.searchWith(searchContext, searcher, query, collectors, hasFilterCollector, hasTimeout); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Ah! In general, it is bad coding practice as it can eat exceptions, although here we intentionally doing that.
@@ -131,13 +131,15 @@ public void preProcess(SearchContext context) { | |||
} | |||
|
|||
public void execute(SearchContext searchContext) throws QueryPhaseExecutionException { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Hi @peteralfonsi, could you please evaluate the use of Timer class for this change? I'd like to hear your thoughts on whether utilizing the existing Timer class is a feasible choice. Thank you.
This PR is stalled because it has been open for 30 days with no activity. |
Hi @peteralfonsi, Is this being worked upon? Pls free to reach out to maintainers for further reviews. |
expectedValues.put(false, null); | ||
expectedValues.put(true, 1000L); | ||
for (Boolean doSetTookTime : expectedValues.keySet()) { | ||
QuerySearchResult querySearchResult = createTestInstance(); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
You can instead update the createTestInstance
to randomly add the tookTime and then assert on created instance tookTime with the took time in deserialized one.
@@ -87,6 +88,7 @@ public final class QuerySearchResult extends SearchPhaseResult { | |||
private int nodeQueueSize = -1; | |||
|
|||
private final boolean isNull; | |||
private Long tookTimeNanos = null; |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
You can define this field with SetOnce
@@ -165,6 +167,7 @@ public void execute(SearchContext searchContext) throws QueryPhaseExecutionExcep | |||
); | |||
searchContext.queryResult().profileResults(shardResults); | |||
} | |||
searchContext.queryResult().setTookTimeNanos(System.nanoTime() - startTime); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
couple of questions:
- The query phase time is also computed in
SearchOperationListenerExecutor
but I see that you need it in QueryResult which is stored in cache before above records the time. - If we store this time in
QueryResult
then while eviction it will need to deserialize each evicted value to get the tookTime and make decision of keeping it in disk tier or not. Wondering if the cache should have it as a separate wrapped object of QueryResult instead, to make it easily available ? Is there a need to output this value in the QueryResult ? If yes, then will probably use the value computed bySearchOperationListenerExecutor
to keep it consistent with search stats.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
For 1), I wasn't aware of that - let me see if it's doable to get that stored time into the QueryResult.
For 2), in my tiered caching policies PR that should hopefully get raised soon, there is a separate wrapper with just the important info to decide whether to add a result to a disk tier. This gets written first, before the actual result, so when it decides it can just read that wrapper and doesn't have to spend time deserializing the whole result. I will see if i can get the other value into there instead.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
For 2, not sure if I understood correctly. If you already have a wrapper concept, then that wrapper can hold to the computed tookTime
and the computation can be done here instead. That way QueryResult
can be kept agnostic of tookTime
Signed-off-by: Peter Alfonsi <petealft@amazon.com>
❌ Gradle check result for 81dc9ef: FAILURE Please examine the workflow log, locate, and copy-paste the failure(s) below, then iterate to green. Is the failure a flaky test unrelated to your change? |
@@ -165,6 +167,7 @@ public void execute(SearchContext searchContext) throws QueryPhaseExecutionExcep | |||
); | |||
searchContext.queryResult().profileResults(shardResults); | |||
} | |||
searchContext.queryResult().setTookTimeNanos(System.nanoTime() - startTime); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
For 2, not sure if I understood correctly. If you already have a wrapper concept, then that wrapper can hold to the computed tookTime
and the computation can be done here instead. That way QueryResult
can be kept agnostic of tookTime
if (in.getVersion().onOrAfter(Version.V_3_0_0)) { | ||
tookTimeNanos = new SetOnce<>(in.readOptionalLong()); | ||
} else { | ||
tookTimeNanos = new SetOnce<>(); | ||
} |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
if (in.getVersion().onOrAfter(Version.V_3_0_0)) { | |
tookTimeNanos = new SetOnce<>(in.readOptionalLong()); | |
} else { | |
tookTimeNanos = new SetOnce<>(); | |
} | |
if (in.getVersion().onOrAfter(Version.V_3_0_0)) { | |
tookTimeNanos.set(in.readOptionalLong()); | |
} |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
That is a very good point. I definitely should have thought of that... the wrapper concept came in much later as we were worried about reading the whole QSR into memory on each eviction, and by then I didn't consider going back and changing this. In that case, we can probably close this PR and just stick that computation into the upcoming policies PR.
Description
Adds time taken in nanoseconds to QuerySearchResult in the query phase, part of the shard-level query response. This will be used as part of tiered caching, to decide whether or not to move cached entries to the disk tier based on how long it would take to recompute them.
Unit tested in QuerySearchResultTests.java. The tests add a random delay to QueryPhase::execute() and assert the took time in the result is greater than or equal to this delay.
Related Issues
Resolves #10411
Milestone of larger tiered caching feature.
Check List
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.