Skip to content

Commit 662e582

Browse files
penghuopenghuo
committed
Task 1 - Add Phase metrics
Signed-off-by: Peng Huo <penghuo@gmail.com>
1 parent 0349dc3 commit 662e582

10 files changed

Lines changed: 67 additions & 51 deletions

File tree

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

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -28,7 +28,7 @@
2828
package org.opensearch.sql.calcite.utils;
2929

3030
import static java.util.Objects.requireNonNull;
31-
import static org.opensearch.sql.monitor.profile.MetricName.OPTIMIZE_TIME;
31+
import static org.opensearch.sql.monitor.profile.MetricName.OPTIMIZE;
3232

3333
import com.google.common.collect.ImmutableList;
3434
import java.lang.reflect.Type;
@@ -343,7 +343,7 @@ public static class OpenSearchRelRunners {
343343
* org.apache.calcite.tools.RelRunners#run(RelNode)}
344344
*/
345345
public static PreparedStatement run(CalcitePlanContext context, RelNode rel) {
346-
ProfileMetric optimizeTime = QueryProfiling.current().getOrCreateMetric(OPTIMIZE_TIME);
346+
ProfileMetric optimizeTime = QueryProfiling.current().getOrCreateMetric(OPTIMIZE);
347347
long startTime = System.nanoTime();
348348
final RelShuttle shuttle =
349349
new RelHomogeneousShuttle() {

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

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -105,7 +105,7 @@ public void executeWithCalcite(
105105
try {
106106
ProfileContext profileContext =
107107
QueryProfiling.activate(QueryContext.isProfileEnabled());
108-
ProfileMetric metric = profileContext.getOrCreateMetric(MetricName.ANALYZE_TIME);
108+
ProfileMetric analyzeMetric = profileContext.getOrCreateMetric(MetricName.ANALYZE);
109109
long analyzeStart = System.nanoTime();
110110
CalcitePlanContext context =
111111
CalcitePlanContext.create(
@@ -114,7 +114,7 @@ public void executeWithCalcite(
114114
relNode = mergeAdjacentFilters(relNode);
115115
RelNode optimized = optimize(relNode, context);
116116
RelNode calcitePlan = convertToCalcitePlan(optimized);
117-
metric.set(System.nanoTime() - analyzeStart);
117+
analyzeMetric.set(System.nanoTime() - analyzeStart);
118118
executionEngine.execute(calcitePlan, context, listener);
119119
} catch (Throwable t) {
120120
if (isCalciteFallbackAllowed(t) && !(t instanceof NonFallbackCalciteException)) {

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

Lines changed: 4 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -7,9 +7,8 @@
77

88
/** Named metrics used by query profiling. */
99
public enum MetricName {
10-
ANALYZE_TIME,
11-
OPTIMIZE_TIME,
12-
OPENSEARCH_TIME,
13-
POST_EXEC_TIME,
14-
FORMAT_TIME
10+
ANALYZE,
11+
OPTIMIZE,
12+
EXECUTE,
13+
FORMAT
1514
}

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

Lines changed: 35 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@
66
package org.opensearch.sql.monitor.profile;
77

88
import com.google.gson.annotations.SerializedName;
9+
import java.util.LinkedHashMap;
910
import java.util.Locale;
1011
import java.util.Map;
1112
import java.util.Objects;
@@ -15,31 +16,50 @@
1516
@Getter
1617
public final class QueryProfile {
1718

18-
/** Total elapsed milliseconds for the profiled query (rounded to two decimals). */
19-
@SerializedName("total_ms")
20-
private final double totalMillis;
19+
private final Summary summary;
2120

22-
/** Immutable metric values keyed by metric name in milliseconds (rounded to two decimals). */
23-
private final Map<String, Double> metrics;
21+
private final Map<String, Phase> phases;
2422

2523
/**
2624
* Create a new query profile snapshot.
2725
*
28-
* @param totalMillis total elapsed milliseconds for the query (rounded to two decimals)
29-
* @param metrics metric values keyed by {@link MetricName}
26+
* @param totalTimeMillis total elapsed milliseconds for the query (rounded to two decimals)
27+
* @param phases metric values keyed by {@link MetricName}
3028
*/
31-
public QueryProfile(double totalMillis, Map<MetricName, Double> metrics) {
32-
this.totalMillis = totalMillis;
33-
this.metrics = buildMetrics(metrics);
29+
public QueryProfile(double totalTimeMillis, Map<MetricName, Double> phases) {
30+
this.summary = new Summary(totalTimeMillis);
31+
this.phases = buildPhases(phases);
3432
}
3533

36-
private Map<String, Double> buildMetrics(Map<MetricName, Double> metrics) {
37-
Objects.requireNonNull(metrics, "metrics");
38-
Map<String, Double> ordered = new java.util.LinkedHashMap<>(metrics.size());
34+
private Map<String, Phase> buildPhases(Map<MetricName, Double> phases) {
35+
Objects.requireNonNull(phases, "phases");
36+
Map<String, Phase> ordered = new LinkedHashMap<>(MetricName.values().length);
3937
for (MetricName metricName : MetricName.values()) {
40-
Double value = metrics.getOrDefault(metricName, 0d);
41-
ordered.put(metricName.name().toLowerCase(Locale.ROOT) + "_ms", value);
38+
Double value = phases.getOrDefault(metricName, 0d);
39+
ordered.put(metricName.name().toLowerCase(Locale.ROOT), new Phase(value));
4240
}
4341
return ordered;
4442
}
43+
44+
@Getter
45+
public static final class Summary {
46+
47+
@SerializedName("total_time_ms")
48+
private final double totalTimeMillis;
49+
50+
private Summary(double totalTimeMillis) {
51+
this.totalTimeMillis = totalTimeMillis;
52+
}
53+
}
54+
55+
@Getter
56+
public static final class Phase {
57+
58+
@SerializedName("time_ms")
59+
private final double timeMillis;
60+
61+
private Phase(double timeMillis) {
62+
this.timeMillis = timeMillis;
63+
}
64+
}
4565
}

‎docs/user/ppl/interfaces/endpoint.md‎

Lines changed: 8 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -172,13 +172,14 @@ Expected output (trimmed):
172172
```json
173173
{
174174
"profile": {
175-
"total_ms": 25.77,
176-
"metrics": {
177-
"analyze_time_ms": 5.77,
178-
"optimize_time_ms": 13.51,
179-
"opensearch_time_ms": 4.31,
180-
"post_exec_time_ms": 0.77,
181-
"format_time_ms": 0.04
175+
"summary": {
176+
"total_time_ms": 25.77
177+
},
178+
"phases": {
179+
"analyze": { "time_ms": 5.77 },
180+
"optimize": { "time_ms": 13.51 },
181+
"execute": { "time_ms": 0.77 },
182+
"format": { "time_ms": 0.04 }
182183
}
183184
}
184185
}
@@ -188,4 +189,3 @@ Expected output (trimmed):
188189

189190
- Profile output is only returned when the query finishes successfully.
190191
- Profiling runs only when Calcite is enabled.
191-
- For parallel work (for example, joins), `opensearch_time_ms` is cumulative across requests and can exceed `total_ms`.

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

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -49,11 +49,11 @@ teardown:
4949
body:
5050
query: 'source=ppl_profile | fields message'
5151
profile: true
52-
- gt: {profile.total_ms: 0.0}
53-
- gt: {profile.metrics.analyze_time_ms: 0.0}
54-
- gt: {profile.metrics.optimize_time_ms: 0.0}
55-
- gt: {profile.metrics.opensearch_time_ms: 0.0}
56-
- gt: {profile.metrics.format_time_ms: 0.0}
52+
- gt: {profile.summary.total_time_ms: 0.0}
53+
- gt: {profile.phases.analyze.time_ms: 0.0}
54+
- gt: {profile.phases.optimize.time_ms: 0.0}
55+
- gt: {profile.phases.execute.time_ms: 0.0}
56+
- gt: {profile.phases.format.time_ms: 0.0}
5757

5858
---
5959
"Profile ignored for explain api":

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

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -221,8 +221,8 @@ private void buildResultSet(
221221
Integer querySizeLimit,
222222
ResponseListener<QueryResponse> listener)
223223
throws SQLException {
224-
ProfileMetric metric = QueryProfiling.current().getOrCreateMetric(MetricName.POST_EXEC_TIME);
225-
long postExecTime = System.nanoTime();
224+
ProfileMetric metric = QueryProfiling.current().getOrCreateMetric(MetricName.EXECUTE);
225+
long execTime = System.nanoTime();
226226
// Get the ResultSet metadata to know about columns
227227
ResultSetMetaData metaData = resultSet.getMetaData();
228228
int columnCount = metaData.getColumnCount();
@@ -267,7 +267,7 @@ private void buildResultSet(
267267
}
268268
Schema schema = new Schema(columns);
269269
QueryResponse response = new QueryResponse(schema, values, null);
270-
metric.set(System.nanoTime() - postExecTime);
270+
metric.add(System.nanoTime() - execTime);
271271
listener.onResponse(response);
272272
}
273273

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

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -209,8 +209,8 @@ private OpenSearchResponse search(Function<SearchRequest, SearchResponse> search
209209
new OpenSearchResponse(
210210
SearchHits.empty(), exprValueFactory, includes, isCountAggRequest());
211211
} else {
212-
ProfileMetric metric = QueryProfiling.current().getOrCreateMetric(MetricName.OPENSEARCH_TIME);
213-
long engineStartTime = System.nanoTime();
212+
ProfileMetric metric = QueryProfiling.current().getOrCreateMetric(MetricName.EXECUTE);
213+
long executionStartTime = System.nanoTime();
214214
// Set afterKey to request, null for first round (afterKey is null in the beginning).
215215
if (this.sourceBuilder.aggregations() != null) {
216216
this.sourceBuilder.aggregations().getAggregatorFactories().stream()
@@ -243,7 +243,7 @@ private OpenSearchResponse search(Function<SearchRequest, SearchResponse> search
243243
searchDone = true;
244244
}
245245
needClean = searchDone;
246-
metric.add(System.nanoTime() - engineStartTime);
246+
metric.add(System.nanoTime() - executionStartTime);
247247
}
248248
return openSearchResponse;
249249
}
@@ -255,8 +255,8 @@ public OpenSearchResponse searchWithPIT(Function<SearchRequest, SearchResponse>
255255
new OpenSearchResponse(
256256
SearchHits.empty(), exprValueFactory, includes, isCountAggRequest());
257257
} else {
258-
ProfileMetric metric = QueryProfiling.current().getOrCreateMetric(MetricName.OPENSEARCH_TIME);
259-
long engineStartTime = System.nanoTime();
258+
ProfileMetric metric = QueryProfiling.current().getOrCreateMetric(MetricName.EXECUTE);
259+
long executionStartTime = System.nanoTime();
260260
this.sourceBuilder.pointInTimeBuilder(new PointInTimeBuilder(this.pitId));
261261
this.sourceBuilder.timeout(cursorKeepAlive);
262262
// check for search after
@@ -299,7 +299,7 @@ public OpenSearchResponse searchWithPIT(Function<SearchRequest, SearchResponse>
299299
LOG.debug(sourceBuilder);
300300
}
301301
}
302-
metric.add(System.nanoTime() - engineStartTime);
302+
metric.add(System.nanoTime() - executionStartTime);
303303
}
304304
return openSearchResponse;
305305
}

‎opensearch/src/main/java/org/opensearch/sql/opensearch/storage/scan/BackgroundSearchScanner.java‎

Lines changed: 1 addition & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -172,11 +172,8 @@ public SearchBatchResult fetchNextBatch(OpenSearchRequest request) {
172172

173173
// Pre-fetch next batch if needed
174174
if (!stopIteration && isAsync()) {
175-
ProfileContext ctx = QueryProfiling.current();
176175
nextBatchFuture =
177-
CompletableFuture.supplyAsync(
178-
() -> QueryProfiling.withCurrentContext(ctx, () -> client.search(request)),
179-
backgroundExecutor);
176+
CompletableFuture.supplyAsync(() -> client.search(request), backgroundExecutor);
180177
}
181178
} else {
182179
iterator = Collections.emptyIterator();

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

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -44,7 +44,7 @@ public SimpleJsonResponseFormatter(Style style) {
4444

4545
@Override
4646
public Object buildJsonObject(QueryResult response) {
47-
ProfileMetric formatMetric = QueryProfiling.current().getOrCreateMetric(MetricName.FORMAT_TIME);
47+
ProfileMetric formatMetric = QueryProfiling.current().getOrCreateMetric(MetricName.FORMAT);
4848
long formatTime = System.nanoTime();
4949

5050
JsonResponse.JsonResponseBuilder json = JsonResponse.builder();

0 commit comments

Comments
 (0)