Skip to content

Commit b0f8c19

Browse files
authored
[8.x] ESQL: Enable visualizing a query profile (elastic#124361) (elastic#124759)
* ESQL: Enable visualizing a query profile (elastic#124361) To understand query performance, we often peruse the output of `_query`-requests run with `"profile": true`. This is difficult when the query runs in a large cluster with many nodes and shards, or in case of CCQ. This adds an option to visualize a query using Chromium's/Chrome's builtin `about:tracing` - or, for even better visuals and querying the different drivers via SQL, perfetto (c.f. https://ui.perfetto.dev/). To use, save the JSON output of a query run with `"profile": true` to a file, like `output.json` and then invoke the following Gradle task: ``` ./gradlew x-pack:plugin:esql:tools:parseProfile --args='~/output.json ~/parsed_profile.json' ``` Either open `about:tracing` in Chromium/Chrome ![image](https://github.com/user-attachments/assets/75e17ddf-f032-4aa1-bf3e-61b985b4e0b6) Or head over to https://ui.perfetto.dev (build locally in case of potentially sensitive data in the profille): ![image](https://github.com/user-attachments/assets/b3372b7d-fbec-45aa-a68c-b24e62a8c704) Every slice is a driver, the colors indicating the ratio of cpu time over total time. - In Perfetto, essentials like duration, cpu duration, timestamp and a few others can be queried via SQL - this allows e.g. querying for all drivers that spent more than 50% of their time waiting and other fun things. ![image](https://github.com/user-attachments/assets/4a0ab2ce-3585-4953-b2eb-71991777b3fa) - Details about a driver, esp. which operators it ran, are available when clicking the driver's slice. ![image](https://github.com/user-attachments/assets/e1c0b30d-0a31-468c-9ff4-27ca452716fc) (cherry picked from commit fc4d8d6) # Conflicts: # x-pack/plugin/esql/qa/server/single-node/src/javaRestTest/java/org/elasticsearch/xpack/esql/qa/single_node/RestEsqlIT.java * Account for missing driver descr., node, cluster
1 parent 07552e8 commit b0f8c19

File tree

6 files changed

+377
-3
lines changed

6 files changed

+377
-3
lines changed

x-pack/plugin/esql/qa/server/single-node/build.gradle

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@ apply plugin: 'elasticsearch.internal-test-artifact'
66
dependencies {
77
javaRestTestImplementation project(xpackModule('esql:qa:testFixtures'))
88
javaRestTestImplementation project(xpackModule('esql:qa:server'))
9+
javaRestTestImplementation project(xpackModule('esql:tools'))
910
yamlRestTestImplementation project(xpackModule('esql:qa:server'))
1011

1112
javaRestTestImplementation('org.apache.arrow:arrow-vector:16.1.0')

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

Lines changed: 130 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@
99
import com.carrotsearch.randomizedtesting.annotations.ParametersFactory;
1010
import com.carrotsearch.randomizedtesting.annotations.ThreadLeakFilters;
1111

12+
import org.apache.http.HttpEntity;
1213
import org.apache.http.util.EntityUtils;
1314
import org.apache.lucene.search.DocIdSetIterator;
1415
import org.elasticsearch.Build;
@@ -17,36 +18,51 @@
1718
import org.elasticsearch.client.ResponseException;
1819
import org.elasticsearch.common.io.Streams;
1920
import org.elasticsearch.common.settings.Settings;
21+
import org.elasticsearch.common.xcontent.XContentHelper;
2022
import org.elasticsearch.test.ListMatcher;
2123
import org.elasticsearch.test.MapMatcher;
2224
import org.elasticsearch.test.TestClustersThreadFilter;
2325
import org.elasticsearch.test.cluster.ElasticsearchCluster;
2426
import org.elasticsearch.test.cluster.LogType;
27+
import org.elasticsearch.xcontent.XContentBuilder;
2528
import org.elasticsearch.xcontent.XContentType;
29+
import org.elasticsearch.xcontent.json.JsonXContent;
2630
import org.elasticsearch.xpack.esql.qa.rest.RestEsqlTestCase;
31+
import org.elasticsearch.xpack.esql.tools.ProfileParser;
2732
import org.hamcrest.Matchers;
2833
import org.junit.Assert;
2934
import org.junit.ClassRule;
3035

36+
import java.io.ByteArrayInputStream;
37+
import java.io.ByteArrayOutputStream;
3138
import java.io.IOException;
3239
import java.io.InputStream;
3340
import java.nio.charset.StandardCharsets;
3441
import java.util.ArrayList;
3542
import java.util.Arrays;
43+
import java.util.HashSet;
3644
import java.util.List;
3745
import java.util.Locale;
3846
import java.util.Map;
47+
import java.util.Set;
3948

4049
import static org.elasticsearch.test.ListMatcher.matchesList;
4150
import static org.elasticsearch.test.MapMatcher.assertMap;
4251
import static org.elasticsearch.test.MapMatcher.matchesMap;
52+
import static org.elasticsearch.xpack.esql.qa.rest.RestEsqlTestCase.Mode.SYNC;
53+
import static org.elasticsearch.xpack.esql.tools.ProfileParser.parseProfile;
54+
import static org.elasticsearch.xpack.esql.tools.ProfileParser.readProfileFromResponse;
4355
import static org.hamcrest.Matchers.containsInAnyOrder;
4456
import static org.hamcrest.Matchers.containsString;
57+
import static org.hamcrest.Matchers.either;
58+
import static org.hamcrest.Matchers.empty;
4559
import static org.hamcrest.Matchers.equalTo;
4660
import static org.hamcrest.Matchers.greaterThan;
61+
import static org.hamcrest.Matchers.greaterThanOrEqualTo;
4762
import static org.hamcrest.Matchers.hasItem;
4863
import static org.hamcrest.Matchers.instanceOf;
4964
import static org.hamcrest.Matchers.not;
65+
import static org.hamcrest.Matchers.oneOf;
5066
import static org.hamcrest.Matchers.startsWith;
5167
import static org.hamcrest.core.Is.is;
5268

@@ -320,6 +336,120 @@ public void testProfile() throws IOException {
320336
);
321337
}
322338

339+
private final String PROCESS_NAME = "process_name";
340+
private final String THREAD_NAME = "thread_name";
341+
342+
@SuppressWarnings("unchecked")
343+
public void testProfileParsing() throws IOException {
344+
indexTimestampData(1);
345+
346+
RequestObjectBuilder builder = new RequestObjectBuilder(XContentType.JSON).query(fromIndex() + " | stats avg(value)").profile(true);
347+
Request request = prepareRequestWithOptions(builder, SYNC);
348+
HttpEntity response = performRequest(request).getEntity();
349+
350+
ProfileParser.Profile profile;
351+
try (InputStream responseContent = response.getContent()) {
352+
profile = readProfileFromResponse(responseContent);
353+
}
354+
355+
ByteArrayOutputStream os = new ByteArrayOutputStream();
356+
try (XContentBuilder jsonOutputBuilder = new XContentBuilder(JsonXContent.jsonXContent, os)) {
357+
parseProfile(profile, jsonOutputBuilder);
358+
}
359+
360+
// Read the written JSON again into a map, so we can make assertions on it
361+
ByteArrayInputStream profileJson = new ByteArrayInputStream(os.toByteArray());
362+
Map<String, Object> parsedProfile = XContentHelper.convertToMap(JsonXContent.jsonXContent, profileJson, true);
363+
364+
assertEquals("ns", parsedProfile.get("displayTimeUnit"));
365+
List<Map<String, Object>> events = (List<Map<String, Object>>) parsedProfile.get("traceEvents");
366+
// At least 1 metadata event to declare the node, and 2 events each for the data, node_reduce and final drivers, resp.
367+
assertThat(events.size(), greaterThanOrEqualTo(7));
368+
369+
String clusterName = "test-cluster";
370+
Set<String> expectedProcessNames = new HashSet<>();
371+
for (int i = 0; i < cluster.getNumNodes(); i++) {
372+
expectedProcessNames.add(clusterName + ":" + cluster.getName(i));
373+
}
374+
// Workaround for the missing driver fields (missing backport to 8.x).
375+
expectedProcessNames.add("missing node/cluster name");
376+
377+
int seenNodes = 0;
378+
int seenDrivers = 0;
379+
// Declaration of each node as a "process" via a metadata event (phase `ph` is `M`)
380+
// First event has to declare the first seen node.
381+
Map<String, Object> nodeMetadata = events.get(0);
382+
assertProcessMetadataForNextNode(nodeMetadata, expectedProcessNames, seenNodes++);
383+
384+
// The rest should be pairs of 2 events: first, a metadata event, declaring 1 "thread" per driver in the profile, then
385+
// a "complete" event (phase `ph` is `X`) with a timestamp, duration `dur`, thread duration `tdur` (cpu time) and additional
386+
// arguments obtained from the driver.
387+
// Except when run as part of the Serverless tests, which can involve more than 1 node - in which case, there will be more node
388+
// metadata events.
389+
for (int i = 1; i < events.size() - 1;) {
390+
String eventName = (String) events.get(i).get("name");
391+
assertTrue(Set.of(THREAD_NAME, PROCESS_NAME).contains(eventName));
392+
if (eventName.equals(THREAD_NAME)) {
393+
Map<String, Object> metadataEventForDriver = events.get(i);
394+
Map<String, Object> eventForDriver = events.get(i + 1);
395+
assertDriverData(metadataEventForDriver, eventForDriver, seenNodes, seenDrivers);
396+
i = i + 2;
397+
seenDrivers++;
398+
} else if (eventName.equals(PROCESS_NAME)) {
399+
Map<String, Object> metadataEventForNode = events.get(i);
400+
assertProcessMetadataForNextNode(metadataEventForNode, expectedProcessNames, seenNodes);
401+
i++;
402+
seenNodes++;
403+
}
404+
}
405+
}
406+
407+
@SuppressWarnings("unchecked")
408+
public void assertProcessMetadataForNextNode(Map<String, Object> nodeMetadata, Set<String> expectedNamesForNodes, int seenNodes) {
409+
assertEquals("M", nodeMetadata.get("ph"));
410+
assertEquals(PROCESS_NAME, nodeMetadata.get("name"));
411+
assertEquals(seenNodes, nodeMetadata.get("pid"));
412+
413+
Map<String, Object> nodeMetadataArgs = (Map<String, Object>) nodeMetadata.get("args");
414+
assertTrue(expectedNamesForNodes.contains((String) nodeMetadataArgs.get("name")));
415+
}
416+
417+
@SuppressWarnings("unchecked")
418+
public void assertDriverData(Map<String, Object> driverMetadata, Map<String, Object> driverEvent, int seenNodes, int seenDrivers) {
419+
assertEquals("M", driverMetadata.get("ph"));
420+
assertEquals(THREAD_NAME, driverMetadata.get("name"));
421+
assertTrue((int) driverMetadata.get("pid") < seenNodes);
422+
assertEquals(seenDrivers, driverMetadata.get("tid"));
423+
Map<String, Object> driverMetadataArgs = (Map<String, Object>) driverMetadata.get("args");
424+
String driverType = (String) driverMetadataArgs.get("name");
425+
// Workaround for the missing driver fields (missing backport to 8.x).
426+
assertThat(driverType, oneOf("data", "node_reduce", "final", "missing driver description"));
427+
428+
assertEquals("X", driverEvent.get("ph"));
429+
// Workaround for the missing driver fields (missing backport to 8.x).
430+
assertThat((String) driverEvent.get("name"), either(startsWith(driverType)).or(equalTo("missing driver description")));
431+
// Category used to implicitly colour-code and group drivers
432+
assertEquals(driverType, driverEvent.get("cat"));
433+
assertTrue((int) driverEvent.get("pid") < seenNodes);
434+
assertEquals(seenDrivers, driverEvent.get("tid"));
435+
long timestampMillis = (long) driverEvent.get("ts");
436+
double durationMicros = (double) driverEvent.get("dur");
437+
double cpuDurationMicros = (double) driverEvent.get("tdur");
438+
assertTrue(timestampMillis >= 0);
439+
assertTrue(durationMicros >= 0);
440+
assertTrue(cpuDurationMicros >= 0);
441+
assertTrue(durationMicros >= cpuDurationMicros);
442+
443+
// This should contain the essential information from a driver, like its operators, and will be just attached to the slice/
444+
// visible when clicking on it.
445+
Map<String, Object> driverSliceArgs = (Map<String, Object>) driverEvent.get("args");
446+
assertNotNull(driverSliceArgs.get("cpu_nanos"));
447+
assertNotNull(driverSliceArgs.get("took_nanos"));
448+
assertNotNull(driverSliceArgs.get("iterations"));
449+
assertNotNull(driverSliceArgs.get("sleeps"));
450+
assertThat(((List<String>) driverSliceArgs.get("operators")), not(empty()));
451+
}
452+
323453
public void testProfileOrdinalsGroupingOperator() throws IOException {
324454
assumeTrue("requires pragmas", Build.current().isSnapshot());
325455
indexTimestampData(1);

x-pack/plugin/esql/qa/server/src/main/java/org/elasticsearch/xpack/esql/qa/rest/RestEsqlTestCase.java

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1153,7 +1153,7 @@ public void testAsyncGetWithoutContentType() throws IOException {
11531153

11541154
}
11551155

1156-
static Request prepareRequestWithOptions(RequestObjectBuilder requestObject, Mode mode) throws IOException {
1156+
protected static Request prepareRequestWithOptions(RequestObjectBuilder requestObject, Mode mode) throws IOException {
11571157
requestObject.build();
11581158
Request request = prepareRequest(mode);
11591159
String mediaType = attachBody(requestObject, request);
@@ -1355,7 +1355,7 @@ private static HttpEntity performRequest(Request request, AssertWarnings assertW
13551355
return assertWarnings(performRequest(request), assertWarnings);
13561356
}
13571357

1358-
private static Response performRequest(Request request) throws IOException {
1358+
protected static Response performRequest(Request request) throws IOException {
13591359
Response response = client().performRequest(request);
13601360
if (shouldLog()) {
13611361
LOGGER.info("RESPONSE={}", response);

x-pack/plugin/esql/qa/testFixtures/build.gradle

Lines changed: 0 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -39,4 +39,3 @@ tasks.register("loadCsvSpecData", JavaExec) {
3939
classpath = sourceSets.main.runtimeClasspath
4040
mainClass = "org.elasticsearch.xpack.esql.CsvTestsDataLoader"
4141
}
42-
Lines changed: 27 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,27 @@
1+
apply plugin: 'elasticsearch.java'
2+
3+
dependencies {
4+
implementation project(":libs:x-content")
5+
implementation project(':libs:logging')
6+
// Required for log4j, there's probably a more direct way to depend on it.
7+
implementation project(':test:framework')
8+
api "com.fasterxml.jackson.core:jackson-core:${versions.jackson}"
9+
api "com.fasterxml.jackson.core:jackson-annotations:${versions.jackson}"
10+
api "com.fasterxml.jackson.core:jackson-databind:${versions.jackson}"
11+
}
12+
13+
/**
14+
* To visualize the profile of an ES|QL query, run the query with {@code "profile": true} then parse it with this task to import the profile into
15+
* Chromium's profile visualizer (type {@code about:tracing} in the URL bar) or into Perfetto (<a href=" https://ui.perfetto.dev/"/>;run Perfetto
16+
* locally if the profile might contain sensitive information, see instructions at
17+
* <a href="https://perfetto.dev/docs/contributing/build-instructions#ui-development"/>).
18+
*
19+
* eg.
20+
* ./gradlew x-pack:plugin:esql:tools:parseProfile --args='~/elasticsearch/query_output.json ~/elasticsearch/parsed_profile.json'
21+
*/
22+
tasks.register("parseProfile", JavaExec) {
23+
group = "Execution"
24+
description = "Parses the output of a query run with profile:true to be imported into the Chromium trace viewer (about:tracing) or Perfetto."
25+
classpath = sourceSets.main.runtimeClasspath
26+
mainClass = "org.elasticsearch.xpack.esql.tools.ProfileParser"
27+
}

0 commit comments

Comments
 (0)