ES|QL - Add parsing, preanalysis and analysis timing information to profile

docs/changelog/139540.yaml

@@ -0,0 +1,5 @@
+pr: 139540
+summary: ES|QL - Add parsing, preanalysis and analysis timing information to profile
+area: ES|QL
+type: enhancement
+issues: []

server/src/main/resources/transport/definitions/referable/esql_query_planning_profile.csv

@@ -0,0 +1 @@
+9251000

server/src/main/resources/transport/upper_bounds/9.4.csv

@@ -1 +1 @@
-initial_9.3.0,9250000
+esql_query_planning_profile,9251000

test/framework/src/main/java/org/elasticsearch/test/rest/ESRestTestCase.java

@@ -2763,6 +2763,10 @@ protected static MapMatcher getProfileMatcher() {
         return matchesMap() //
             .entry("query", instanceOf(Map.class))
             .entry("planning", instanceOf(Map.class))
+            .entry("parsing", instanceOf(Map.class))
+            .entry("preanalysis", instanceOf(Map.class))
+            .entry("dependency_resolution", instanceOf(Map.class))
+            .entry("analysis", instanceOf(Map.class))
             .entry("drivers", instanceOf(List.class))
             .entry("plans", instanceOf(List.class))
             .entry("minimumTransportVersion", instanceOf(Integer.class));

x-pack/plugin/esql/qa/server/single-node/src/javaRestTest/java/org/elasticsearch/xpack/esql/qa/single_node/PushExpressionToLoadIT.java

@@ -763,6 +763,10 @@ private void test(
                     .entry("drivers", instanceOf(List.class))
                     .entry("plans", instanceOf(List.class))
                     .entry("planning", matchesMap().extraOk())
+                    .entry("parsing", matchesMap().extraOk())
+                    .entry("preanalysis", matchesMap().extraOk())
+                    .entry("dependency_resolution", matchesMap().extraOk())
+                    .entry("analysis", matchesMap().extraOk())
                     .entry("query", matchesMap().extraOk())
                     .entry("minimumTransportVersion", instanceOf(Integer.class))
             ),

x-pack/plugin/esql/qa/server/single-node/src/javaRestTest/java/org/elasticsearch/xpack/esql/qa/single_node/PushQueriesIT.java

@@ -365,6 +365,10 @@ private void testPushQuery(
                     .entry("drivers", instanceOf(List.class))
                     .entry("plans", instanceOf(List.class))
                     .entry("planning", matchesMap().extraOk())
+                    .entry("parsing", matchesMap().extraOk())
+                    .entry("preanalysis", matchesMap().extraOk())
+                    .entry("dependency_resolution", matchesMap().extraOk())
+                    .entry("analysis", matchesMap().extraOk())
                     .entry("query", matchesMap().extraOk())
                     .entry("minimumTransportVersion", instanceOf(Integer.class))
             ),

x-pack/plugin/esql/qa/server/single-node/src/javaRestTest/java/org/elasticsearch/xpack/esql/qa/single_node/StoredFieldsSequentialIT.java

@@ -121,6 +121,10 @@ private void testQuery(Double percent, String query, int documentsFound, boolean
                         .entry("drivers", instanceOf(List.class))
                         .entry("plans", instanceOf(List.class))
                         .entry("planning", matchesMap().extraOk())
+                        .entry("parsing", matchesMap().extraOk())
+                        .entry("preanalysis", matchesMap().extraOk())
+                        .entry("dependency_resolution", matchesMap().extraOk())
+                        .entry("analysis", matchesMap().extraOk())
                         .entry("query", matchesMap().extraOk())
                         .entry("minimumTransportVersion", instanceOf(Integer.class))
                 )

x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlQueryLogIT.java

@@ -26,20 +26,27 @@
 import org.junit.AfterClass;
 import org.junit.BeforeClass;
 
+import java.util.List;
 import java.util.Map;
 import java.util.concurrent.CountDownLatch;
 import java.util.concurrent.ExecutionException;
 
 import static org.elasticsearch.test.hamcrest.ElasticsearchAssertions.assertAcked;
 import static org.elasticsearch.xpack.esql.action.EsqlQueryRequest.syncEsqlQueryRequest;
+import static org.elasticsearch.xpack.esql.action.PlanningProfile.ANALYSIS;
+import static org.elasticsearch.xpack.esql.action.PlanningProfile.DEPENDENCY_RESOLUTION;
+import static org.elasticsearch.xpack.esql.action.PlanningProfile.PARSING;
+import static org.elasticsearch.xpack.esql.action.PlanningProfile.PLANNING;
+import static org.elasticsearch.xpack.esql.action.PlanningProfile.PRE_ANALYSIS;
 import static org.elasticsearch.xpack.esql.querylog.EsqlQueryLog.ELASTICSEARCH_QUERYLOG_ERROR_MESSAGE;
 import static org.elasticsearch.xpack.esql.querylog.EsqlQueryLog.ELASTICSEARCH_QUERYLOG_ERROR_TYPE;
-import static org.elasticsearch.xpack.esql.querylog.EsqlQueryLog.ELASTICSEARCH_QUERYLOG_PLANNING_TOOK;
-import static org.elasticsearch.xpack.esql.querylog.EsqlQueryLog.ELASTICSEARCH_QUERYLOG_PLANNING_TOOK_MILLIS;
+import static org.elasticsearch.xpack.esql.querylog.EsqlQueryLog.ELASTICSEARCH_QUERYLOG_PREFIX;
 import static org.elasticsearch.xpack.esql.querylog.EsqlQueryLog.ELASTICSEARCH_QUERYLOG_QUERY;
 import static org.elasticsearch.xpack.esql.querylog.EsqlQueryLog.ELASTICSEARCH_QUERYLOG_SUCCESS;
 import static org.elasticsearch.xpack.esql.querylog.EsqlQueryLog.ELASTICSEARCH_QUERYLOG_TOOK;
 import static org.elasticsearch.xpack.esql.querylog.EsqlQueryLog.ELASTICSEARCH_QUERYLOG_TOOK_MILLIS;
+import static org.elasticsearch.xpack.esql.querylog.EsqlQueryLog.ELASTICSEARCH_QUERYLOG_TOOK_MILLIS_SUFFIX;
+import static org.elasticsearch.xpack.esql.querylog.EsqlQueryLog.ELASTICSEARCH_QUERYLOG_TOOK_SUFFIX;
 import static org.hamcrest.Matchers.containsString;
 import static org.hamcrest.Matchers.equalTo;
 import static org.hamcrest.Matchers.greaterThan;
@@ -184,12 +191,18 @@ private static void testAllLevels(
                     assertThat(tookMillis, is(tookMillisExpected));
 
                     if (expectedException == null) {
-                        long planningTook = Long.valueOf(msg.get(ELASTICSEARCH_QUERYLOG_PLANNING_TOOK));
-                        long planningTookMillisExpected = planningTook / 1_000_000;
-                        long planningTookMillis = Long.valueOf(msg.get(ELASTICSEARCH_QUERYLOG_PLANNING_TOOK_MILLIS));
-                        assertThat(planningTook, greaterThanOrEqualTo(0L));
-                        assertThat(planningTookMillis, is(planningTookMillisExpected));
-                        assertThat(took, greaterThan(planningTook));
+                        for (String timing : List.of(PLANNING, PARSING, PRE_ANALYSIS, DEPENDENCY_RESOLUTION, ANALYSIS)) {
+                            long timingTook = Long.valueOf(
+                                msg.get(ELASTICSEARCH_QUERYLOG_PREFIX + timing + ELASTICSEARCH_QUERYLOG_TOOK_SUFFIX)
+                            );
+                            long timingTookMillisExpected = timingTook / 1_000_000;
+                            long timingTookMillis = Long.valueOf(
+                                msg.get(ELASTICSEARCH_QUERYLOG_PREFIX + timing + ELASTICSEARCH_QUERYLOG_TOOK_MILLIS_SUFFIX)
+                            );
+                            assertThat(timingTook, greaterThanOrEqualTo(0L));
+                            assertThat(timingTookMillis, is(timingTookMillisExpected));
+                            assertThat(took, greaterThan(timingTook));
+                        }
                     }
 
                     assertThat(msg.get(ELASTICSEARCH_QUERYLOG_QUERY), is(query));

x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/action/EsqlExecutionInfo.java

@@ -90,11 +90,10 @@ public enum IncludeExecutionMetadata {
     private volatile boolean isPartial; // Does this request have partial results?
     private transient volatile boolean isStopped; // Have we received stop command?
 
-    // 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
+    private final PlanningProfile planningProfile;
     private TimeValue overallTook;
+    private transient TimeSpan overallTimeSpan;
 
     // Are we doing subplans? No need to serialize this because it is only relevant for the coordinator node.
     private transient boolean inSubplan = false;
@@ -118,6 +117,7 @@ public EsqlExecutionInfo(Predicate<String> skipOnPlanTimeFailurePredicate, Inclu
         this.skipOnFailurePredicate = skipOnPlanTimeFailurePredicate;
         this.includeExecutionMetadata = includeExecutionMetadata;
         this.relativeStart = relativeStart;
+        this.planningProfile = new PlanningProfile();
     }
 
     public EsqlExecutionInfo(StreamInput in) throws IOException {
@@ -133,7 +133,9 @@ public EsqlExecutionInfo(StreamInput in) throws IOException {
         this.relativeStart = null;
         if (in.getTransportVersion().supports(ESQL_QUERY_PLANNING_DURATION)) {
             this.overallTimeSpan = in.readOptional(TimeSpan::readFrom);
-            this.planningTimeSpan = in.readOptional(TimeSpan::readFrom);
+            this.planningProfile = PlanningProfile.readFrom(in);
+        } else {
+            this.planningProfile = new PlanningProfile();
         }
     }
 
@@ -153,8 +155,9 @@ public void writeTo(StreamOutput out) throws IOException {
         out.writeBoolean(isPartial);
         if (out.getTransportVersion().supports(ESQL_QUERY_PLANNING_DURATION)) {
             out.writeOptionalWriteable(overallTimeSpan);
-            out.writeOptionalWriteable(planningTimeSpan);
+            planningProfile.writeTo(out);
         }
+
         assert inSubplan == false : "Should not be serializing execution info while in subplans";
     }
 
@@ -167,26 +170,10 @@ public IncludeExecutionMetadata includeExecutionMetadata() {
         return includeExecutionMetadata;
     }
 
-    /**
-     * Call when ES|QL "planning" phase is complete and query execution (in ComputeService) is about to start.
-     * Note this is currently only built for a single phase planning/execution model. When INLINE STATS
-     * moves towards GA we may need to revisit this model. Currently, it should never be called more than once.
-     */
-    public void markEndPlanning() {
-        assert planningTimeSpan == null : "markEndPlanning should only be called once";
-        assert relativeStart != null : "Relative start time must be set when markEndPlanning is called";
-        planningTimeSpan = relativeStart.stop();
-    }
-
-    public TimeValue planningTookTime() {
-        return planningTimeSpan != null ? planningTimeSpan.toTimeValue() : null;
-    }
-
     /**
      * Call when ES|QL execution is complete in order to set the overall took time for an ES|QL query.
      */
     public void markEndQuery() {
-        assert relativeStart != null : "Relative start time must be set when markEndQuery is called";
         if (isMainPlan()) {
             overallTimeSpan = relativeStart.stop();
             overallTook = overallTimeSpan.toTimeValue();
@@ -212,14 +199,14 @@ public TimeSpan overallTimeSpan() {
         return overallTimeSpan;
     }
 
-    public TimeSpan planningTimeSpan() {
-        return planningTimeSpan;
-    }
-
     public Set<String> clusterAliases() {
         return clusterInfo.keySet();
     }
 
+    public PlanningProfile planningProfile() {
+        return planningProfile;
+    }
+
     /**
      * @param clusterAlias to check if we should skip this cluster on failure
      * @return whether it's OK to skip the cluster on failure.

x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/action/EsqlQueryResponse.java

@@ -325,7 +325,7 @@ public Iterator<? extends ToXContent> toXContentChunked(ToXContent.Params params
             content.add(ChunkedToXContentHelper.chunk((b, p) -> {
                 if (executionInfo != null) {
                     b.field("query", executionInfo.overallTimeSpan());
-                    b.field("planning", executionInfo.planningTimeSpan());
+                    executionInfo.planningProfile().toXContent(b, p);
                 }
                 return b;
             }));