Skip to content

Expose more detailed profiling information #126525

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.

Sign up for GitHub

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

Jump to bottom
Merged
merged 14 commits into from
Apr 15, 2025
Merged

Expose more detailed profiling information #126525

merged 14 commits into from
Apr 15, 2025

Conversation

idegtiarenko
Copy link
Contributor

This change adds the following to the profiling output:

...
    ]
  ],
  "profile": {
    "query": { <----
      "start_millis": 1744199242905,
      "stop_millis": 20626146536141,
      "took_nanos": 294
    },
    "planning": { <----
      "start_millis": 1744199242905,
      "stop_millis": 20626015900065,
      "took_nanos": 163
    },
    "drivers": [
      {
        "description": "data",
        "cluster_name": "runTask",
        "node_name": "runTask-0",
...

This is not an exhausting planning profiling information, however it:

  • Estimates planning duration on coordinating node relying on planningTookTime. This ignores data nodes planning entirely and does not expose additional details until we finalize Esql - Add planner information to the profile #124919
  • Exposes query start/stop time. This allows us to position each driver span correctly, relative to the query start time (driver has start/top/duration time, but query had only duration field before this change). Prior to this there were no way to estimate time between completing last driver and starting rendering results in case (hopefully not) it contains some non trivial slow code..

Related to: ES-11102

@idegtiarenko idegtiarenko added >non-issue Team:Analytics Meta label for analytical engine team (ESQL/Aggs/Geo) :Analytics/ES|QL AKA ESQL v9.1.0 labels Apr 9, 2025
@idegtiarenko idegtiarenko requested a review from nik9000 April 9, 2025 12:16
@elasticsearchmachine
Copy link
Collaborator

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

idegtiarenko
idegtiarenko commented Apr 9, 2025
View reviewed changes
x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/action/EsqlExecutionInfo.java
// whether the user has asked for CCS metadata to be in the JSON response (the overall took will always be present)
private final boolean includeCCSMetadata;

// fields that are not Writeable since they are only needed on the primary CCS coordinator
private final transient Predicate<String> skipUnavailablePredicate;
private final transient Long relativeStartNanos; // start time for an ESQL query for calculating took times
private transient TimeValue planningTookTime; // time elapsed since start of query to calling ComputeService.execute
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Moved down and converted to TimeSpans

idegtiarenko
idegtiarenko commented Apr 9, 2025
View reviewed changes
x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/action/EsqlExecutionInfo.java
@@ -90,18 +92,17 @@ public EsqlExecutionInfo(Predicate<String> skipUnavailablePredicate, boolean inc
this.clusterInfo = ConcurrentCollections.newConcurrentMap();
this.skipUnavailablePredicate = skipUnavailablePredicate;
this.includeCCSMetadata = includeCCSMetadata;
this.relativeStartNanos = System.nanoTime();
this.relativeStart = TimeSpan.start();
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should be always present on coordinating node

idegtiarenko
idegtiarenko commented Apr 15, 2025
View reviewed changes
x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/action/EsqlExecutionInfo.java
// start time for the ESQL query for calculating time spans relative to the beginning of the query
private final transient TimeSpan.Builder relativeStart;
private transient TimeSpan overallTimeSpan;
private transient TimeSpan planningTimeSpan; // time elapsed since start of query to calling ComputeService.execute
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Okay, this actually need to be serialized in order to pass this information when executing query async

@idegtiarenko idegtiarenko merged commit 07cb14e into elastic:main Apr 15, 2025
17 checks passed
@idegtiarenko idegtiarenko deleted the profiling branch April 15, 2025 10:27
afoucret pushed a commit to afoucret/elasticsearch that referenced this pull request Apr 16, 2025
@idegtiarenko @afoucret
Expose more detailed profiling information (elastic#126525)
7f8032f
@idegtiarenko idegtiarenko mentioned this pull request Jun 6, 2025
Merged
idegtiarenko added a commit to idegtiarenko/elasticsearch that referenced this pull request Jun 6, 2025
@idegtiarenko
Expose more detailed profiling information (elastic#126525)
f32713a 
(cherry picked from commit 07cb14e)
idegtiarenko added a commit that referenced this pull request Jun 6, 2025
@idegtiarenko
[8.19] Expose more detailed profiling information (#126525) (#129029)
ef46998
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@nik9000 nik9000 nik9000 approved these changes

Assignees
No one assigned
Labels
:Analytics/ES|QL AKA ESQL >non-issue Team:Analytics Meta label for analytical engine team (ESQL/Aggs/Geo) v8.19.0 v9.1.0
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
3 participants
@idegtiarenko @elasticsearchmachine @nik9000