Add Task 1 - Add Phases level metrics

Signed-off-by: Peng Huo <penghuo@gmail.com>

Author: penghuo

core/src/main/java/org/opensearch/sql/calcite/utils/CalciteToolsHelper.java

@@ -28,7 +28,7 @@
 package org.opensearch.sql.calcite.utils;
 
 import static java.util.Objects.requireNonNull;
-import static org.opensearch.sql.monitor.profile.MetricName.OPTIMIZE_TIME;
+import static org.opensearch.sql.monitor.profile.MetricName.OPTIMIZE;
 
 import com.google.common.collect.ImmutableList;
 import java.lang.reflect.Type;
@@ -343,7 +343,7 @@ public static class OpenSearchRelRunners {
      * org.apache.calcite.tools.RelRunners#run(RelNode)}
      */
     public static PreparedStatement run(CalcitePlanContext context, RelNode rel) {
-      ProfileMetric optimizeTime = QueryProfiling.current().getOrCreateMetric(OPTIMIZE_TIME);
+      ProfileMetric optimizeTime = QueryProfiling.current().getOrCreateMetric(OPTIMIZE);
       long startTime = System.nanoTime();
       final RelShuttle shuttle =
           new RelHomogeneousShuttle() {

core/src/main/java/org/opensearch/sql/executor/QueryService.java

@@ -105,7 +105,7 @@ public void executeWithCalcite(
           try {
             ProfileContext profileContext =
                 QueryProfiling.activate(QueryContext.isProfileEnabled());
-            ProfileMetric metric = profileContext.getOrCreateMetric(MetricName.ANALYZE_TIME);
+            ProfileMetric analyzeMetric = profileContext.getOrCreateMetric(MetricName.ANALYZE);
             long analyzeStart = System.nanoTime();
             CalcitePlanContext context =
                 CalcitePlanContext.create(
@@ -114,7 +114,7 @@ public void executeWithCalcite(
             relNode = mergeAdjacentFilters(relNode);
             RelNode optimized = optimize(relNode, context);
             RelNode calcitePlan = convertToCalcitePlan(optimized);
-            metric.set(System.nanoTime() - analyzeStart);
+            analyzeMetric.set(System.nanoTime() - analyzeStart);
             executionEngine.execute(calcitePlan, context, listener);
           } catch (Throwable t) {
             if (isCalciteFallbackAllowed(t) && !(t instanceof NonFallbackCalciteException)) {

core/src/main/java/org/opensearch/sql/monitor/profile/DefaultMetricImpl.java

@@ -11,7 +11,7 @@
 final class DefaultMetricImpl implements ProfileMetric {
 
   private final String name;
-  private long value = 0;
+  private final LongAdder value = new LongAdder();
 
   /**
    * Construct a metric with the provided name.
@@ -29,17 +29,17 @@ public String name() {
 
   @Override
   public long value() {
-    return value;
+    return value.sum();
   }
 
   @Override
   public void add(long delta) {
-    value += delta;
+    value.add(delta);
   }
 
   @Override
   public void set(long value) {
-    this.value = 0;
-    add(value);
+    this.value.reset();
+    this.value.add(value);
   }
 }

core/src/main/java/org/opensearch/sql/monitor/profile/MetricName.java

@@ -7,9 +7,8 @@
 
 /** Named metrics used by query profiling. */
 public enum MetricName {
-  ANALYZE_TIME,
-  OPTIMIZE_TIME,
-  OPENSEARCH_TIME,
-  POST_EXEC_TIME,
-  FORMAT_TIME
+  ANALYZE,
+  OPTIMIZE,
+  EXECUTE,
+  FORMAT
 }

core/src/main/java/org/opensearch/sql/monitor/profile/QueryProfile.java

@@ -6,6 +6,8 @@
 package org.opensearch.sql.monitor.profile;
 
 import com.google.gson.annotations.SerializedName;
+import java.util.LinkedHashMap;
+import java.util.Locale;
 import java.util.Map;
 import java.util.Objects;
 import lombok.Getter;
@@ -14,31 +16,50 @@
 @Getter
 public final class QueryProfile {
 
-  /** Total elapsed milliseconds for the profiled query (rounded to two decimals). */
-  @SerializedName("total_ms")
-  private final double totalMillis;
+  private final Summary summary;
 
-  /** Immutable metric values keyed by metric name in milliseconds (rounded to two decimals). */
-  private final Map<String, Double> metrics;
+  private final Map<String, Phase> phases;
 
   /**
    * Create a new query profile snapshot.
    *
-   * @param totalMillis total elapsed milliseconds for the query (rounded to two decimals)
-   * @param metrics metric values keyed by {@link MetricName}
+   * @param totalTimeMillis total elapsed milliseconds for the query (rounded to two decimals)
+   * @param phases metric values keyed by {@link MetricName}
    */
-  public QueryProfile(double totalMillis, Map<MetricName, Double> metrics) {
-    this.totalMillis = totalMillis;
-    this.metrics = buildMetrics(metrics);
+  public QueryProfile(double totalTimeMillis, Map<MetricName, Double> phases) {
+    this.summary = new Summary(totalTimeMillis);
+    this.phases = buildPhases(phases);
   }
 
-  private Map<String, Double> buildMetrics(Map<MetricName, Double> metrics) {
-    Objects.requireNonNull(metrics, "metrics");
-    Map<String, Double> ordered = new java.util.LinkedHashMap<>(metrics.size());
+  private Map<String, Phase> buildPhases(Map<MetricName, Double> phases) {
+    Objects.requireNonNull(phases, "phases");
+    Map<String, Phase> ordered = new LinkedHashMap<>(MetricName.values().length);
     for (MetricName metricName : MetricName.values()) {
-      Double value = metrics.getOrDefault(metricName, 0d);
-      ordered.put(metricName.name() + "_MS", value);
+      Double value = phases.getOrDefault(metricName, 0d);
+      ordered.put(metricName.name().toLowerCase(Locale.ROOT), new Phase(value));
     }
     return ordered;
   }
+
+  @Getter
+  public static final class Summary {
+
+    @SerializedName("total_time_ms")
+    private final double totalTimeMillis;
+
+    private Summary(double totalTimeMillis) {
+      this.totalTimeMillis = totalTimeMillis;
+    }
+  }
+
+  @Getter
+  public static final class Phase {
+
+    @SerializedName("time_ms")
+    private final double timeMillis;
+
+    private Phase(double timeMillis) {
+      this.timeMillis = timeMillis;
+    }
+  }
 }

docs/user/ppl/interfaces/endpoint.md

@@ -172,13 +172,14 @@ Expected output (trimmed):
 ```json
 {
    "profile": {
-      "total_ms": 25.77,
-      "metrics": {
-         "ANALYZE_TIME_MS": 5.77,
-         "OPTIMIZE_TIME_MS": 13.51,
-         "OPENSEARCH_TIME_MS": 4.31,
-         "POST_EXEC_TIME_MS": 0.77,
-         "FORMAT_TIME_MS": 0.04
+      "summary": {
+         "total_time_ms": 25.77
+      },
+      "phases": {
+         "analyze": { "time_ms": 5.77 },
+         "optimize": { "time_ms": 13.51 },
+         "execute": { "time_ms": 0.77 },
+         "format": { "time_ms": 0.04 }
       }
    }
 }

integ-test/src/yamlRestTest/resources/rest-api-spec/test/api/ppl.profile.yml

@@ -49,9 +49,11 @@ teardown:
         body:
           query: 'source=ppl_profile | fields message'
           profile: true
-  - gt: {profile.total_ms: 0.0}
-  - gt: {profile.metrics.ANALYZE_TIME_MS: 0.0}
-  - gt: {profile.metrics.OPENSEARCH_TIME_MS: 0.0}
+  - gt: {profile.summary.total_time_ms: 0.0}
+  - gt: {profile.phases.analyze.time_ms: 0.0}
+  - gt: {profile.phases.optimize.time_ms: 0.0}
+  - gt: {profile.phases.execute.time_ms: 0.0}
+  - gt: {profile.phases.format.time_ms: 0.0}
 
 ---
 "Profile ignored for explain api":

opensearch/src/main/java/org/opensearch/sql/opensearch/executor/OpenSearchExecutionEngine.java

@@ -221,8 +221,8 @@ private void buildResultSet(
       Integer querySizeLimit,
       ResponseListener<QueryResponse> listener)
       throws SQLException {
-    ProfileMetric metric = QueryProfiling.current().getOrCreateMetric(MetricName.POST_EXEC_TIME);
-    long postExecTime = System.nanoTime();
+    ProfileMetric metric = QueryProfiling.current().getOrCreateMetric(MetricName.EXECUTE);
+    long execTime = System.nanoTime();
     // Get the ResultSet metadata to know about columns
     ResultSetMetaData metaData = resultSet.getMetaData();
     int columnCount = metaData.getColumnCount();
@@ -267,7 +267,7 @@ private void buildResultSet(
     }
     Schema schema = new Schema(columns);
     QueryResponse response = new QueryResponse(schema, values, null);
-    metric.set(System.nanoTime() - postExecTime);
+    metric.add(System.nanoTime() - execTime);
     listener.onResponse(response);
   }
 

opensearch/src/main/java/org/opensearch/sql/opensearch/request/OpenSearchQueryRequest.java

@@ -209,8 +209,8 @@ private OpenSearchResponse search(Function<SearchRequest, SearchResponse> search
           new OpenSearchResponse(
               SearchHits.empty(), exprValueFactory, includes, isCountAggRequest());
     } else {
-      ProfileMetric metric = QueryProfiling.current().getOrCreateMetric(MetricName.OPENSEARCH_TIME);
-      long engineStartTime = System.nanoTime();
+      ProfileMetric metric = QueryProfiling.current().getOrCreateMetric(MetricName.EXECUTE);
+      long executionStartTime = System.nanoTime();
       // Set afterKey to request, null for first round (afterKey is null in the beginning).
       if (this.sourceBuilder.aggregations() != null) {
         this.sourceBuilder.aggregations().getAggregatorFactories().stream()
@@ -243,7 +243,7 @@ private OpenSearchResponse search(Function<SearchRequest, SearchResponse> search
         searchDone = true;
       }
       needClean = searchDone;
-      metric.set(System.nanoTime() - engineStartTime);
+      metric.add(System.nanoTime() - executionStartTime);
     }
     return openSearchResponse;
   }
@@ -255,8 +255,8 @@ public OpenSearchResponse searchWithPIT(Function<SearchRequest, SearchResponse>
           new OpenSearchResponse(
               SearchHits.empty(), exprValueFactory, includes, isCountAggRequest());
     } else {
-      ProfileMetric metric = QueryProfiling.current().getOrCreateMetric(MetricName.OPENSEARCH_TIME);
-      long engineStartTime = System.nanoTime();
+      ProfileMetric metric = QueryProfiling.current().getOrCreateMetric(MetricName.EXECUTE);
+      long executionStartTime = System.nanoTime();
       this.sourceBuilder.pointInTimeBuilder(new PointInTimeBuilder(this.pitId));
       this.sourceBuilder.timeout(cursorKeepAlive);
       // check for search after
@@ -299,7 +299,7 @@ public OpenSearchResponse searchWithPIT(Function<SearchRequest, SearchResponse>
           LOG.debug(sourceBuilder);
         }
       }
-      metric.add(System.nanoTime() - engineStartTime);
+      metric.add(System.nanoTime() - executionStartTime);
     }
     return openSearchResponse;
   }

protocol/src/main/java/org/opensearch/sql/protocol/response/format/SimpleJsonResponseFormatter.java

@@ -44,7 +44,7 @@ public SimpleJsonResponseFormatter(Style style) {
 
   @Override
   public Object buildJsonObject(QueryResult response) {
-    ProfileMetric formatMetric = QueryProfiling.current().getOrCreateMetric(MetricName.FORMAT_TIME);
+    ProfileMetric formatMetric = QueryProfiling.current().getOrCreateMetric(MetricName.FORMAT);
     long formatTime = System.nanoTime();
 
     JsonResponse.JsonResponseBuilder json = JsonResponse.builder();