Skip to content

Commit ef46998

Browse files
idegtiarenkoidegtiarenko
authored
[8.19] Expose more detailed profiling information (elastic#126525) (elastic#129029)
1 parent 4c6bb2c commit ef46998

File tree

10 files changed

+146
-44
lines changed

10 files changed

+146
-44
lines changed

‎server/src/main/java/org/elasticsearch/TransportVersions.java‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -235,6 +235,7 @@ static TransportVersion def(int id) {
235235
public static final TransportVersion JOIN_ON_ALIASES_8_19 = def(8_841_0_42);
236236
public static final TransportVersion ILM_ADD_SKIP_SETTING_8_19 = def(8_841_0_43);
237237
public static final TransportVersion ESQL_REGEX_MATCH_WITH_CASE_INSENSITIVITY_8_19 = def(8_841_0_44);
238+
public static final TransportVersion ESQL_QUERY_PLANNING_DURATION_8_19 = def(8_841_0_45);
238239
/*
239240
* STOP! READ THIS FIRST! No, really,
240241
* ____ _____ ___ ____ _ ____ _____ _ ____ _____ _ _ ___ ____ _____ ___ ____ ____ _____ _

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

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -144,6 +144,7 @@
144144
import static org.hamcrest.Matchers.everyItem;
145145
import static org.hamcrest.Matchers.greaterThanOrEqualTo;
146146
import static org.hamcrest.Matchers.in;
147+
import static org.hamcrest.Matchers.instanceOf;
147148
import static org.hamcrest.Matchers.notNullValue;
148149

149150
/**
@@ -2690,6 +2691,12 @@ public static Request newXContentRequest(HttpMethod method, String endpoint, ToX
26902691
return request;
26912692
}
26922693

2694+
protected static MapMatcher getProfileMatcher() {
2695+
return matchesMap().entry("query", instanceOf(Map.class))
2696+
.entry("planning", instanceOf(Map.class))
2697+
.entry("drivers", instanceOf(List.class));
2698+
}
2699+
26932700
protected static MapMatcher getResultMatcher(boolean includeMetadata, boolean includePartial) {
26942701
MapMatcher mapMatcher = matchesMap();
26952702
if (includeMetadata) {

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

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -219,7 +219,12 @@ private void testPushQuery(String value, String esqlQuery, List<String> luceneQu
219219
Map<String, Object> result = runEsql(builder, new AssertWarnings.NoWarnings(), RestEsqlTestCase.Mode.SYNC);
220220
assertResultMap(
221221
result,
222-
getResultMatcher(result).entry("profile", matchesMap().entry("drivers", instanceOf(List.class))),
222+
getResultMatcher(result).entry(
223+
"profile",
224+
matchesMap().entry("drivers", instanceOf(List.class))
225+
.entry("planning", matchesMap().extraOk())
226+
.entry("query", matchesMap().extraOk())
227+
),
223228
matchesList().item(matchesMap().entry("name", "test").entry("type", "text")),
224229
equalTo(found ? List.of(List.of(value)) : List.of())
225230
);

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

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -299,7 +299,7 @@ public void testProfile() throws IOException {
299299
Map<String, Object> result = runEsql(builder);
300300
assertResultMap(
301301
result,
302-
getResultMatcher(result).entry("profile", matchesMap().entry("drivers", instanceOf(List.class))),
302+
getResultMatcher(result).entry("profile", getProfileMatcher()),
303303
matchesList().item(matchesMap().entry("name", "AVG(value)").entry("type", "double")),
304304
equalTo(List.of(List.of(499.5d)))
305305
);
@@ -506,7 +506,7 @@ public void testInlineStatsProfile() throws IOException {
506506
}
507507
assertResultMap(
508508
result,
509-
getResultMatcher(result).entry("profile", matchesMap().entry("drivers", instanceOf(List.class))),
509+
getResultMatcher(result).entry("profile", getProfileMatcher()),
510510
matchesList().item(matchesMap().entry("name", "@timestamp").entry("type", "date"))
511511
.item(matchesMap().entry("name", "test").entry("type", "text"))
512512
.item(matchesMap().entry("name", "test.keyword").entry("type", "keyword"))
@@ -609,7 +609,7 @@ public void testForceSleepsProfile() throws IOException {
609609
}
610610
assertResultMap(
611611
result,
612-
getResultMatcher(result).entry("profile", matchesMap().entry("drivers", instanceOf(List.class))),
612+
getResultMatcher(result).entry("profile", getProfileMatcher()),
613613
matchesList().item(matchesMap().entry("name", "AVG(value)").entry("type", "double"))
614614
.item(matchesMap().entry("name", "MAX(value)").entry("type", "long"))
615615
.item(matchesMap().entry("name", "MIN(value)").entry("type", "long"))

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

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -110,7 +110,12 @@ private void testQuery(Double percent, String query, int documentsFound, boolean
110110
result,
111111
matchesMap()
112112
// .entry("documents_found", documentsFound) Backport incoming maybe
113-
.entry("profile", matchesMap().entry("drivers", instanceOf(List.class)))
113+
.entry(
114+
"profile",
115+
matchesMap().entry("drivers", instanceOf(List.class))
116+
.entry("planning", matchesMap().extraOk())
117+
.entry("query", matchesMap().extraOk())
118+
)
114119
.extraOk()
115120
);
116121

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

Lines changed: 33 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -35,7 +35,6 @@
3535
import java.util.Objects;
3636
import java.util.Set;
3737
import java.util.concurrent.ConcurrentMap;
38-
import java.util.concurrent.TimeUnit;
3938
import java.util.function.BiFunction;
4039
import java.util.function.Predicate;
4140

@@ -64,17 +63,20 @@ public class EsqlExecutionInfo implements ChunkedToXContentObject, Writeable {
6463
// Updates to the Cluster occur with the updateCluster method that given the key to map transforms an
6564
// old Cluster Object to a new Cluster Object with the remapping function.
6665
public final Map<String, Cluster> clusterInfo;
67-
private TimeValue overallTook;
6866
// whether the user has asked for CCS metadata to be in the JSON response (the overall took will always be present)
6967
private final boolean includeCCSMetadata;
7068

7169
// fields that are not Writeable since they are only needed on the primary CCS coordinator
7270
private final transient Predicate<String> skipUnavailablePredicate;
73-
private final transient Long relativeStartNanos; // start time for an ESQL query for calculating took times
74-
private transient TimeValue planningTookTime; // time elapsed since start of query to calling ComputeService.execute
7571
private volatile boolean isPartial; // Does this request have partial results?
7672
private transient volatile boolean isStopped; // Have we received stop command?
7773

74+
// start time for the ESQL query for calculating time spans relative to the beginning of the query
75+
private final transient TimeSpan.Builder relativeStart;
76+
private transient TimeSpan overallTimeSpan;
77+
private transient TimeSpan planningTimeSpan; // time elapsed since start of query to calling ComputeService.execute
78+
private TimeValue overallTook;
79+
7880
public EsqlExecutionInfo(boolean includeCCSMetadata) {
7981
this(Predicates.always(), includeCCSMetadata); // default all clusters to skip_unavailable=true
8082
}
@@ -87,18 +89,17 @@ public EsqlExecutionInfo(Predicate<String> skipUnavailablePredicate, boolean inc
8789
this.clusterInfo = ConcurrentCollections.newConcurrentMap();
8890
this.skipUnavailablePredicate = skipUnavailablePredicate;
8991
this.includeCCSMetadata = includeCCSMetadata;
90-
this.relativeStartNanos = System.nanoTime();
92+
this.relativeStart = TimeSpan.start();
9193
}
9294

9395
/**
9496
* For testing use with fromXContent parsing only
95-
* @param clusterInfo
9697
*/
9798
EsqlExecutionInfo(ConcurrentMap<String, Cluster> clusterInfo, boolean includeCCSMetadata) {
9899
this.clusterInfo = clusterInfo;
99100
this.includeCCSMetadata = includeCCSMetadata;
100101
this.skipUnavailablePredicate = Predicates.always();
101-
this.relativeStartNanos = null;
102+
this.relativeStart = null;
102103
}
103104

104105
public EsqlExecutionInfo(StreamInput in) throws IOException {
@@ -124,7 +125,11 @@ public EsqlExecutionInfo(StreamInput in) throws IOException {
124125
}
125126

126127
this.skipUnavailablePredicate = Predicates.always();
127-
this.relativeStartNanos = null;
128+
this.relativeStart = null;
129+
if (in.getTransportVersion().onOrAfter(TransportVersions.ESQL_QUERY_PLANNING_DURATION_8_19)) {
130+
this.overallTimeSpan = in.readOptional(TimeSpan::readFrom);
131+
this.planningTimeSpan = in.readOptional(TimeSpan::readFrom);
132+
}
128133
}
129134

130135
@Override
@@ -141,37 +146,38 @@ public void writeTo(StreamOutput out) throws IOException {
141146
if (out.getTransportVersion().onOrAfter(TransportVersions.ESQL_RESPONSE_PARTIAL)) {
142147
out.writeBoolean(isPartial);
143148
}
149+
if (out.getTransportVersion().onOrAfter(TransportVersions.ESQL_QUERY_PLANNING_DURATION_8_19)) {
150+
out.writeOptionalWriteable(overallTimeSpan);
151+
out.writeOptionalWriteable(planningTimeSpan);
152+
}
144153
}
145154

146155
public boolean includeCCSMetadata() {
147156
return includeCCSMetadata;
148157
}
149158

150-
public Long getRelativeStartNanos() {
151-
return relativeStartNanos;
152-
}
153-
154159
/**
155160
* Call when ES|QL "planning" phase is complete and query execution (in ComputeService) is about to start.
156161
* Note this is currently only built for a single phase planning/execution model. When INLINESTATS
157162
* moves towards GA we may need to revisit this model. Currently, it should never be called more than once.
158163
*/
159164
public void markEndPlanning() {
160-
assert planningTookTime == null : "markEndPlanning should only be called once";
161-
assert relativeStartNanos != null : "Relative start time must be set when markEndPlanning is called";
162-
planningTookTime = new TimeValue(System.nanoTime() - relativeStartNanos, TimeUnit.NANOSECONDS);
165+
assert planningTimeSpan == null : "markEndPlanning should only be called once";
166+
assert relativeStart != null : "Relative start time must be set when markEndPlanning is called";
167+
planningTimeSpan = relativeStart.stop();
163168
}
164169

165170
public TimeValue planningTookTime() {
166-
return planningTookTime;
171+
return planningTimeSpan != null ? planningTimeSpan.toTimeValue() : null;
167172
}
168173

169174
/**
170175
* Call when ES|QL execution is complete in order to set the overall took time for an ES|QL query.
171176
*/
172177
public void markEndQuery() {
173-
assert relativeStartNanos != null : "Relative start time must be set when markEndQuery is called";
174-
overallTook = new TimeValue(System.nanoTime() - relativeStartNanos, TimeUnit.NANOSECONDS);
178+
assert relativeStart != null : "Relative start time must be set when markEndQuery is called";
179+
overallTimeSpan = relativeStart.stop();
180+
overallTook = overallTimeSpan.toTimeValue();
175181
}
176182

177183
// for testing only - use markEndQuery in production code
@@ -187,11 +193,15 @@ public TimeValue overallTook() {
187193
* How much time the query took since starting.
188194
*/
189195
public TimeValue tookSoFar() {
190-
if (relativeStartNanos == null) {
191-
return new TimeValue(0);
192-
} else {
193-
return new TimeValue(System.nanoTime() - relativeStartNanos, TimeUnit.NANOSECONDS);
194-
}
196+
return relativeStart != null ? relativeStart.stop().toTimeValue() : TimeValue.ZERO;
197+
}
198+
199+
public TimeSpan overallTimeSpan() {
200+
return overallTimeSpan;
201+
}
202+
203+
public TimeSpan planningTimeSpan() {
204+
return planningTimeSpan;
195205
}
196206

197207
public Set<String> clusterAliases() {

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

Lines changed: 10 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -208,8 +208,8 @@ public Iterator<? extends ToXContent> toXContentChunked(ToXContent.Params params
208208
b.field(EsqlExecutionInfo.IS_PARTIAL_FIELD.getPreferredName(), executionInfo.isPartial());
209209
}
210210
if (dropNullColumns) {
211-
b.append(ResponseXContentUtils.allColumns(columns, "all_columns"))
212-
.append(ResponseXContentUtils.nonNullColumns(columns, nullColumns, "columns"));
211+
b.append(ResponseXContentUtils.allColumns(columns, "all_columns"));
212+
b.append(ResponseXContentUtils.nonNullColumns(columns, nullColumns, "columns"));
213213
} else {
214214
b.append(ResponseXContentUtils.allColumns(columns, "columns"));
215215
}
@@ -218,7 +218,13 @@ public Iterator<? extends ToXContent> toXContentChunked(ToXContent.Params params
218218
b.field("_clusters", executionInfo);
219219
}
220220
if (profile != null) {
221-
b.field("profile", profile);
221+
b.field("profile", p -> ChunkedToXContent.builder(p).object(ob -> {
222+
if (executionInfo != null) {
223+
ob.field("query", executionInfo.overallTimeSpan());
224+
ob.field("planning", executionInfo.planningTimeSpan());
225+
}
226+
ob.array("drivers", profile.drivers.iterator(), ChunkedToXContentBuilder::append);
227+
}));
222228
}
223229
});
224230
}
@@ -324,7 +330,7 @@ public EsqlResponse responseInternal() {
324330
return esqlResponse;
325331
}
326332

327-
public static class Profile implements Writeable, ChunkedToXContentObject {
333+
public static class Profile implements Writeable {
328334
private final List<DriverProfile> drivers;
329335

330336
public Profile(List<DriverProfile> drivers) {
@@ -357,12 +363,6 @@ public int hashCode() {
357363
return Objects.hash(drivers);
358364
}
359365

360-
@Override
361-
public Iterator<? extends ToXContent> toXContentChunked(ToXContent.Params params) {
362-
return ChunkedToXContent.builder(params)
363-
.object(ob -> ob.array("drivers", drivers.iterator(), ChunkedToXContentBuilder::append));
364-
}
365-
366366
List<DriverProfile> drivers() {
367367
return drivers;
368368
}

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

Lines changed: 77 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,77 @@
1+
/*
2+
* Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
3+
* or more contributor license agreements. Licensed under the Elastic License
4+
* 2.0; you may not use this file except in compliance with the Elastic License
5+
* 2.0.
6+
*/
7+
8+
package org.elasticsearch.xpack.esql.action;
9+
10+
import org.elasticsearch.common.io.stream.StreamInput;
11+
import org.elasticsearch.common.io.stream.StreamOutput;
12+
import org.elasticsearch.common.io.stream.Writeable;
13+
import org.elasticsearch.core.TimeValue;
14+
import org.elasticsearch.xcontent.ToXContentObject;
15+
import org.elasticsearch.xcontent.XContentBuilder;
16+
17+
import java.io.IOException;
18+
19+
import static org.elasticsearch.core.TimeValue.timeValueNanos;
20+
21+
/**
22+
* THis class is used to capture a duration of some process, including start and stop point int time.
23+
*/
24+
public record TimeSpan(long startMillis, long startNanos, long stopMillis, long stopNanos) implements Writeable, ToXContentObject {
25+
26+
public static TimeSpan readFrom(StreamInput in) throws IOException {
27+
return new TimeSpan(in.readVLong(), in.readVLong(), in.readVLong(), in.readVLong());
28+
}
29+
30+
@Override
31+
public void writeTo(StreamOutput out) throws IOException {
32+
out.writeVLong(startMillis);
33+
out.writeVLong(startNanos);
34+
out.writeVLong(stopMillis);
35+
out.writeVLong(stopNanos);
36+
}
37+
38+
@Override
39+
public XContentBuilder toXContent(XContentBuilder builder, Params params) throws IOException {
40+
builder.startObject();
41+
builder.timestampFieldsFromUnixEpochMillis("start_millis", "start", startMillis);
42+
builder.timestampFieldsFromUnixEpochMillis("stop_millis", "stop", stopMillis);
43+
if (builder.humanReadable()) {
44+
builder.field("took_time", toTimeValue());
45+
}
46+
builder.field("took_millis", durationInMillis());
47+
builder.field("took_nanos", durationInNanos());
48+
builder.endObject();
49+
return builder;
50+
}
51+
52+
public TimeValue toTimeValue() {
53+
return timeValueNanos(stopNanos - startNanos);
54+
}
55+
56+
public long durationInMillis() {
57+
return stopMillis - startMillis;
58+
}
59+
60+
public long durationInNanos() {
61+
return stopNanos - startNanos;
62+
}
63+
64+
public static Builder start() {
65+
return new Builder();
66+
}
67+
68+
public static class Builder {
69+
70+
private final long startMillis = System.currentTimeMillis();
71+
private final long startNanos = System.nanoTime();
72+
73+
public TimeSpan stop() {
74+
return new TimeSpan(startMillis, startNanos, System.currentTimeMillis(), System.nanoTime());
75+
}
76+
}
77+
}

‎x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/ComputeService.java‎

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -26,7 +26,6 @@
2626
import org.elasticsearch.compute.operator.exchange.ExchangeSourceHandler;
2727
import org.elasticsearch.core.Releasable;
2828
import org.elasticsearch.core.Releasables;
29-
import org.elasticsearch.core.TimeValue;
3029
import org.elasticsearch.core.Tuple;
3130
import org.elasticsearch.index.query.SearchExecutionContext;
3231
import org.elasticsearch.logging.LogManager;
@@ -231,7 +230,7 @@ public void execute(
231230
computeListener.acquireCompute().delegateFailure((l, profiles) -> {
232231
if (execInfo.clusterInfo.containsKey(LOCAL_CLUSTER)) {
233232
execInfo.swapCluster(LOCAL_CLUSTER, (k, v) -> {
234-
var tookTime = TimeValue.timeValueNanos(System.nanoTime() - execInfo.getRelativeStartNanos());
233+
var tookTime = execInfo.tookSoFar();
235234
var builder = new EsqlExecutionInfo.Cluster.Builder(v).setTook(tookTime);
236235
if (v.getStatus() == EsqlExecutionInfo.Cluster.Status.RUNNING) {
237236
final Integer failedShards = execInfo.getCluster(LOCAL_CLUSTER).getFailedShards();

‎x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/session/EsqlCCSUtilsTests.java‎

Lines changed: 2 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -518,12 +518,10 @@ public void testUpdateExecutionInfoAtEndOfPlanning() {
518518
(k, v) -> new EsqlExecutionInfo.Cluster(REMOTE1_ALIAS, "*", true, EsqlExecutionInfo.Cluster.Status.SKIPPED)
519519
);
520520
executionInfo.swapCluster(REMOTE2_ALIAS, (k, v) -> new EsqlExecutionInfo.Cluster(REMOTE2_ALIAS, "mylogs1,mylogs2,logs*", false));
521-
522521
assertNull(executionInfo.planningTookTime());
523522
assertNull(executionInfo.overallTook());
524-
try {
525-
Thread.sleep(1);
526-
} catch (InterruptedException e) {}
523+
524+
safeSleep(1);
527525

528526
EsqlCCSUtils.updateExecutionInfoAtEndOfPlanning(executionInfo);
529527

0 commit comments

Comments
 (0)