Skip to content

Conversation

quux00
Copy link
Contributor

@quux00 quux00 commented Oct 18, 2024

The revised took time model bug fix #115017
introduced a new bug that allows a race condition between updating the execution info with
"end of planning" timestamp and using that timestamp during execution.

This one line fix reverses the order to ensure the planning phase execution update occurs
before starting the ESQL query execution phase.

@quux00 quux00 added >non-issue Team:Analytics Meta label for analytical engine team (ESQL/Aggs/Geo) auto-backport Automatically create backport pull requests when merged :Analytics/ES|QL AKA ESQL v8.16.0 v9.0.0 labels Oct 18, 2024
@quux00 quux00 requested review from astefan and smalyshev October 18, 2024 17:35
@elasticsearchmachine
Copy link
Collaborator

Pinging @elastic/es-analytical-engine (Team:Analytics)

1 similar comment
@elasticsearchmachine
Copy link
Collaborator

Pinging @elastic/es-analytical-engine (Team:Analytics)

quux00 added a commit to quux00/elasticsearch that referenced this pull request Oct 19, 2024
elasticsearchmachine pushed a commit that referenced this pull request Oct 19, 2024
…es fatal exceptions (#115017) (#115124)

* ES|QL per-cluster took time is incorrectly calculated and causes fatal exceptions (#115017)

The model for calculating per-cluster `took` times from remote clusters in #112595 was flawed. 
It attempted to use Java's System.nanoTime between the local and remote clusters,
which is not safe. This results in per-cluster took times that have arbitrary (invalid) values
including negative values which cause exceptions to be thrown by the `TimeValue` constructor.
(Note: the overall took time calculation was done correctly, so it was the remote per-cluster
took times that were flawed.)

In this PR, I've done a redesign to address this. A key decision of this re-design was whether
to always calculate took times only on the querying cluster (bypassing this whole problem) or
to continue to allow the remote clusters to calculate their own took times for the remote processing
and report that back to the querying cluster via the `ComputeResponse`.

I decided in favor of having remote clusters compute their own took times for the remote processing
and to additionally track "planning" time (encompassing field-caps and policy enrich remote calls), so
that total per-cluster took time is a combination of the two. In _search, remote cluster took times are
calculated entirely on the remote cluster, so network time is not included in the per-cluster took times.
This has been helpful in diagnosing issues on user environments because if you see an overall took time
that is significantly larger than the per cluster took times, that may indicate a network issue, which has
happened in diagnosing cross-cluster issues in _search.

I moved relative time tracking into `EsqlExecutionInfo`. 

The "planning time" marker is currently only used in cross-cluster searches, so it will conflict with
the INLINESTATS 2 phase model (where planning can be done twice). We will improve this design
to handle a 2 phase model in a later ticket, as part of the INLINESTATS work. I tested the 
current overall took time calculation model with local-only INLINESTATS queries and they
work correctly.

I also fixed another secondary bug in this PR. If the remote cluster is an older version that does
not return took time (and shard info) in the ComputeResponse, the per-cluster took time is then
calculated on the querying cluster as a fallback.

Finally, I fixed some minor inconsistencies about whether the `_shards` info is shown in the response.
The rule now is that `_shards` is always shown with 0 shards for SKIPPED clusters, with actual
counts for SUCCESSFUL clusters and for remotes running an older version that doesn't report
shard stats, the `_shards` field is left out of the XContent response.

Fixes #115022

* Added fix for #115127 into this since can't get the build to pass
@quux00 quux00 added v8.17.0 and removed v8.16.0 labels Oct 19, 2024
@quux00 quux00 merged commit b2a2a53 into elastic:main Oct 19, 2024
16 checks passed
@elasticsearchmachine
Copy link
Collaborator

💔 Backport failed

Status Branch Result
8.x Commit could not be cherrypicked due to conflicts

You can use sqren/backport to manually backport by running backport --upstream elastic/elasticsearch --pr 115127

quux00 added a commit to quux00/elasticsearch that referenced this pull request Oct 19, 2024
… phase (elastic#115127)

The revised took time model bug fix elastic#115017
introduced a new bug that allows a race condition between updating the execution info with
"end of planning" timestamp and using that timestamp during execution.

This one line fix reverses the order to ensure the planning phase execution update occurs
before starting the ESQL query execution phase.
quux00 added a commit that referenced this pull request Oct 19, 2024
* ES|QL per-cluster took time is incorrectly calculated and causes fatal exceptions (#115017)

The model for calculating per-cluster `took` times from remote clusters in #112595 was flawed. 
It attempted to use Java's System.nanoTime between the local and remote clusters,
which is not safe. This results in per-cluster took times that have arbitrary (invalid) values
including negative values which cause exceptions to be thrown by the `TimeValue` constructor.
(Note: the overall took time calculation was done correctly, so it was the remote per-cluster
took times that were flawed.)

In this PR, I've done a redesign to address this. A key decision of this re-design was whether
to always calculate took times only on the querying cluster (bypassing this whole problem) or
to continue to allow the remote clusters to calculate their own took times for the remote processing
and report that back to the querying cluster via the `ComputeResponse`.

I decided in favor of having remote clusters compute their own took times for the remote processing
and to additionally track "planning" time (encompassing field-caps and policy enrich remote calls), so
that total per-cluster took time is a combination of the two. In _search, remote cluster took times are
calculated entirely on the remote cluster, so network time is not included in the per-cluster took times.
This has been helpful in diagnosing issues on user environments because if you see an overall took time
that is significantly larger than the per cluster took times, that may indicate a network issue, which has
happened in diagnosing cross-cluster issues in _search.

I moved relative time tracking into `EsqlExecutionInfo`. 

The "planning time" marker is currently only used in cross-cluster searches, so it will conflict with
the INLINESTATS 2 phase model (where planning can be done twice). We will improve this design
to handle a 2 phase model in a later ticket, as part of the INLINESTATS work. I tested the 
current overall took time calculation model with local-only INLINESTATS queries and they
work correctly.

I also fixed another secondary bug in this PR. If the remote cluster is an older version that does
not return took time (and shard info) in the ComputeResponse, the per-cluster took time is then
calculated on the querying cluster as a fallback.

Finally, I fixed some minor inconsistencies about whether the `_shards` info is shown in the response.
The rule now is that `_shards` is always shown with 0 shards for SKIPPED clusters, with actual
counts for SUCCESSFUL clusters and for remotes running an older version that doesn't report
shard stats, the `_shards` field is left out of the XContent response.

Fixes #115022

* Update execution info at end of planning before kicking off execution phase (#115127)

The revised took time model bug fix #115017
introduced a new bug that allows a race condition between updating the execution info with
"end of planning" timestamp and using that timestamp during execution.

This one line fix reverses the order to ensure the planning phase execution update occurs
before starting the ESQL query execution phase.
georgewallace pushed a commit to georgewallace/elasticsearch that referenced this pull request Oct 25, 2024
… phase (elastic#115127)

The revised took time model bug fix elastic#115017
introduced a new bug that allows a race condition between updating the execution info with
"end of planning" timestamp and using that timestamp during execution.

This one line fix reverses the order to ensure the planning phase execution update occurs
before starting the ESQL query execution phase.
jfreden pushed a commit to jfreden/elasticsearch that referenced this pull request Nov 4, 2024
… phase (elastic#115127)

The revised took time model bug fix elastic#115017
introduced a new bug that allows a race condition between updating the execution info with
"end of planning" timestamp and using that timestamp during execution.

This one line fix reverses the order to ensure the planning phase execution update occurs
before starting the ESQL query execution phase.
@quux00
Copy link
Contributor Author

quux00 commented Dec 3, 2024

The auto-backport failed, so it was backported manually here: #115168

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

:Analytics/ES|QL AKA ESQL auto-backport Automatically create backport pull requests when merged backport pending >non-issue Team:Analytics Meta label for analytical engine team (ESQL/Aggs/Geo) v8.17.0 v9.0.0

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants