From 8269e4285fe51c035c7e0db2ed790d676f2d5910 Mon Sep 17 00:00:00 2001 From: Ticheng Lin Date: Fri, 2 Jun 2023 01:08:51 +0000 Subject: [PATCH] Bringing new query profile collector fields with concurrent search execution Signed-off-by: Ticheng Lin --- CHANGELOG.md | 1 + .../search/profile/query/CollectorResult.java | 126 +++++++++++++++++- .../query/InternalProfileCollector.java | 76 +++++++++++ .../InternalProfileCollectorManager.java | 66 ++++++++- .../query/InternalProfileComponent.java | 25 ++++ .../profile/query/ProfileCollector.java | 6 + .../profile/query/CollectorResultTests.java | 43 +++++- .../query/QueryProfileShardResultTests.java | 2 +- 8 files changed, 326 insertions(+), 19 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 93f21e2d8462f..b3d06f014b210 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -88,6 +88,7 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/), ### Changed - Replace jboss-annotations-api_1.2_spec with jakarta.annotation-api ([#7836](https://github.com/opensearch-project/OpenSearch/pull/7836)) - Add min, max, average and thread info to resource stats in tasks API ([#7673](https://github.com/opensearch-project/OpenSearch/pull/7673)) +- Add new query profile collector fields with concurrent search execution ([#7355](https://github.com/opensearch-project/OpenSearch/pull/7355)) ### Deprecated diff --git a/server/src/main/java/org/opensearch/search/profile/query/CollectorResult.java b/server/src/main/java/org/opensearch/search/profile/query/CollectorResult.java index f345fe8b9a427..20d1dabe08601 100644 --- a/server/src/main/java/org/opensearch/search/profile/query/CollectorResult.java +++ b/server/src/main/java/org/opensearch/search/profile/query/CollectorResult.java @@ -71,6 +71,11 @@ public class CollectorResult implements ToXContentObject, Writeable { private static final ParseField REASON = new ParseField("reason"); private static final ParseField TIME = new ParseField("time"); private static final ParseField TIME_NANOS = new ParseField("time_in_nanos"); + private static final ParseField REDUCE_TIME_NANOS = new ParseField("reduce_time_in_nanos"); + private static final ParseField MAX_SLICE_TIME_NANOS = new ParseField("max_slice_time_in_nanos"); + private static final ParseField MIN_SLICE_TIME_IN_NANOS = new ParseField("min_slice_time_in_nanos"); + private static final ParseField AVG_SLICE_TIME_IN_NANOS = new ParseField("avg_slice_time_in_nanos"); + private static final ParseField SLICE_COUNT = new ParseField("slice_count"); private static final ParseField CHILDREN = new ParseField("children"); /** @@ -88,6 +93,31 @@ public class CollectorResult implements ToXContentObject, Writeable { */ private final Long time; + /** + * The total elapsed time in reduce phase for this CollectorManager + */ + private final Long reduceTime; + + /** + * The maximum slice time for this CollectorManager + */ + private final Long maxSliceTime; + + /** + * The minimum slice time for this CollectorManager + */ + private final Long minSliceTime; + + /** + * The average slice time for this CollectorManager + */ + private final Long avgSliceTime; + + /** + * The segment slice count for this CollectorManager + */ + private final int sliceCount; + /** * A list of children collectors "embedded" inside this collector */ @@ -97,6 +127,24 @@ public CollectorResult(String collectorName, String reason, Long time, List children) { + this.collectorName = collectorName; + this.reason = reason; + this.time = time; + this.reduceTime = reduceTime; + this.maxSliceTime = maxSliceTime; + this.minSliceTime = minSliceTime; + this.avgSliceTime = avgSliceTime; + this.sliceCount = sliceCount; this.children = children; } @@ -107,6 +155,11 @@ public CollectorResult(StreamInput in) throws IOException { this.collectorName = in.readString(); this.reason = in.readString(); this.time = in.readLong(); + this.reduceTime = in.readLong(); + this.maxSliceTime = in.readLong(); + this.minSliceTime = in.readLong(); + this.avgSliceTime = in.readLong(); + this.sliceCount = in.readVInt(); int size = in.readVInt(); this.children = new ArrayList<>(size); for (int i = 0; i < size; i++) { @@ -120,6 +173,11 @@ public void writeTo(StreamOutput out) throws IOException { out.writeString(collectorName); out.writeString(reason); out.writeLong(time); + out.writeLong(reduceTime); + out.writeLong(maxSliceTime); + out.writeLong(minSliceTime); + out.writeLong(avgSliceTime); + out.writeVInt(sliceCount); out.writeVInt(children.size()); for (CollectorResult child : children) { child.writeTo(out); @@ -127,28 +185,63 @@ public void writeTo(StreamOutput out) throws IOException { } /** - * @return the profiled time for this collector (inclusive of children) + * @return the profiled time for this collector/collector manager (inclusive of children) */ public long getTime() { return this.time; } /** - * @return a human readable "hint" about what this collector was used for + * @return the profiled reduce time for this collector manager (inclusive of children) + */ + public long getReduceTime() { + return this.reduceTime; + } + + /** + * @return the profiled maximum slice time for this collector manager (inclusive of children) + */ + public long getMaxSliceTime() { + return this.maxSliceTime; + } + + /** + * @return the profiled minimum slice time for this collector manager (inclusive of children) + */ + public long getMinSliceTime() { + return this.minSliceTime; + } + + /** + * @return the profiled average slice time for this collector manager (inclusive of children) + */ + public long getAvgSliceTime() { + return this.avgSliceTime; + } + + /** + * @return the profiled segment slice count for this collector manager (inclusive of children) + */ + public long getSliceCount() { + return this.sliceCount; + } + + /** + * @return a human readable "hint" about what this collector/collector manager was used for */ public String getReason() { return this.reason; } /** - * @return the lucene class name of the collector + * @return the lucene class name of the collector/collector manager */ public String getName() { return this.collectorName; } /** - * @return a list of children collectors + * @return a list of children collectors/collector managers */ public List getProfiledChildren() { return children; @@ -163,6 +256,13 @@ public XContentBuilder toXContent(XContentBuilder builder, ToXContent.Params par builder.field(TIME.getPreferredName(), new TimeValue(getTime(), TimeUnit.NANOSECONDS).toString()); } builder.field(TIME_NANOS.getPreferredName(), getTime()); + if (getName().contains("CollectorManager")) { + builder.field(REDUCE_TIME_NANOS.getPreferredName(), getReduceTime()); + builder.field(MAX_SLICE_TIME_NANOS.getPreferredName(), getMaxSliceTime()); + builder.field(MIN_SLICE_TIME_IN_NANOS.getPreferredName(), getMinSliceTime()); + builder.field(AVG_SLICE_TIME_IN_NANOS.getPreferredName(), getAvgSliceTime()); + builder.field(SLICE_COUNT.getPreferredName(), getSliceCount()); + } if (!children.isEmpty()) { builder = builder.startArray(CHILDREN.getPreferredName()); @@ -181,6 +281,11 @@ public static CollectorResult fromXContent(XContentParser parser) throws IOExcep String currentFieldName = null; String name = null, reason = null; long time = -1; + long reduceTime = -1; + long maxSliceTime = -1; + long minSliceTime = -1; + long avgSliceTime = -1; + int sliceCount = 0; List children = new ArrayList<>(); while ((token = parser.nextToken()) != XContentParser.Token.END_OBJECT) { if (token == XContentParser.Token.FIELD_NAME) { @@ -195,6 +300,16 @@ public static CollectorResult fromXContent(XContentParser parser) throws IOExcep parser.text(); } else if (TIME_NANOS.match(currentFieldName, parser.getDeprecationHandler())) { time = parser.longValue(); + } else if (REDUCE_TIME_NANOS.match(currentFieldName, parser.getDeprecationHandler())) { + reduceTime = parser.longValue(); + } else if (MAX_SLICE_TIME_NANOS.match(currentFieldName, parser.getDeprecationHandler())) { + maxSliceTime = parser.longValue(); + } else if (MIN_SLICE_TIME_IN_NANOS.match(currentFieldName, parser.getDeprecationHandler())) { + minSliceTime = parser.longValue(); + } else if (AVG_SLICE_TIME_IN_NANOS.match(currentFieldName, parser.getDeprecationHandler())) { + avgSliceTime = parser.longValue(); + } else if (SLICE_COUNT.match(currentFieldName, parser.getDeprecationHandler())) { + sliceCount = parser.intValue(); } else { parser.skipChildren(); } @@ -210,6 +325,7 @@ public static CollectorResult fromXContent(XContentParser parser) throws IOExcep parser.skipChildren(); } } - return new CollectorResult(name, reason, time, children); + return new CollectorResult(name, reason, time, reduceTime, maxSliceTime, minSliceTime, avgSliceTime, sliceCount, + children); } } diff --git a/server/src/main/java/org/opensearch/search/profile/query/InternalProfileCollector.java b/server/src/main/java/org/opensearch/search/profile/query/InternalProfileCollector.java index 1300782ae1194..7b5fc3b0e832b 100644 --- a/server/src/main/java/org/opensearch/search/profile/query/InternalProfileCollector.java +++ b/server/src/main/java/org/opensearch/search/profile/query/InternalProfileCollector.java @@ -68,6 +68,21 @@ public class InternalProfileCollector implements Collector, InternalProfileCompo /** The wrapped collector */ private final ProfileCollector collector; + /** The elapsed time in the concurrent search reduce phase */ + private final Long reduceTime; + + /** The maximum slice time for this collector manager */ + private final Long maxSliceTime; + + /** The minimum slice time for this collector manager */ + private final Long minSliceTime; + + /** The average slice time for this collector manager */ + private final Long avgSliceTime; + + /** The segment slice count for this collector manager */ + private final int sliceCount; + /** * A list of "embedded" children collectors */ @@ -75,6 +90,25 @@ public class InternalProfileCollector implements Collector, InternalProfileCompo public InternalProfileCollector(Collector collector, String reason, List children) { this.collector = new ProfileCollector(collector); + this.reduceTime = null; + this.maxSliceTime = null; + this.minSliceTime = null; + this.avgSliceTime = null; + this.sliceCount = 1; + this.reason = reason; + this.collectorName = deriveCollectorName(collector); + this.children = children; + } + + public InternalProfileCollector(Collector collector, Long reduceTime, Long maxCollectorTime, Long minSliceTime, + Long avgSliceTime, int sliceCount, String reason, + List children) { + this.collector = new ProfileCollector(collector); + this.reduceTime = reduceTime; + this.maxSliceTime = maxCollectorTime; + this.minSliceTime = minSliceTime; + this.avgSliceTime = avgSliceTime; + this.sliceCount = sliceCount; this.reason = reason; this.collectorName = deriveCollectorName(collector); this.children = children; @@ -87,6 +121,48 @@ public long getTime() { return collector.getTime(); } + /** + * @return the profiled start time for this collector (inclusive of children) + */ + public long getSliceStartTime() { + return collector.getSliceStartTime(); + } + + /** + * @return the profiled reduce time for this collector (inclusive of children) + */ + public long getReduceTime() { + return this.reduceTime; + } + + /** + * @return the profiled maximum time for this collector (inclusive of children) + */ + public long getMaxSliceTime() { + return this.maxSliceTime; + } + + /** + * @return the profiled minimum time for this collector (inclusive of children) + */ + public long getMinSliceTime() { + return this.minSliceTime; + } + + /** + * @return the profiled average time for this collector (inclusive of children) + */ + public long getAvgSliceTime() { + return this.avgSliceTime; + } + + /** + * @return the profiled segment slice count for this collector (inclusive of children) + */ + public int getSliceCount() { + return this.sliceCount; + } + /** * @return a human readable "hint" about what this collector was used for */ diff --git a/server/src/main/java/org/opensearch/search/profile/query/InternalProfileCollectorManager.java b/server/src/main/java/org/opensearch/search/profile/query/InternalProfileCollectorManager.java index 2732b2ccffc79..44cec67d74ef6 100644 --- a/server/src/main/java/org/opensearch/search/profile/query/InternalProfileCollectorManager.java +++ b/server/src/main/java/org/opensearch/search/profile/query/InternalProfileCollectorManager.java @@ -31,6 +31,13 @@ public class InternalProfileCollectorManager private final String reason; private final List children; private long time = 0; + private long reduceTime = 0; + private long maxSliceEndTime = 0; + private long minSliceStartTime = Long.MAX_VALUE; + private long maxSliceTime = 0; + private long minSliceTime = Long.MAX_VALUE; + private long avgSliceTime = 0; + private int sliceCount = 0; public InternalProfileCollectorManager( CollectorManager manager, @@ -44,20 +51,34 @@ public InternalProfileCollectorManager( @Override public InternalProfileCollector newCollector() throws IOException { - return new InternalProfileCollector(manager.newCollector(), reason, children); + return new InternalProfileCollector(manager.newCollector(), reduceTime, maxSliceTime, minSliceTime, + avgSliceTime, sliceCount, reason, children); } @SuppressWarnings("unchecked") @Override public ReduceableSearchResult reduce(Collection collectors) throws IOException { - final Collection subs = new ArrayList<>(); + final long reduceStart = System.nanoTime(); + try { + final Collection subs = new ArrayList<>(); - for (final InternalProfileCollector collector : collectors) { - subs.add(collector.getCollector()); - time += collector.getTime(); + for (final InternalProfileCollector collector : collectors) { + subs.add(collector.getCollector()); + maxSliceEndTime = Math.max(maxSliceEndTime, collector.getSliceStartTime() + collector.getTime()); + minSliceStartTime = Math.min(minSliceStartTime, collector.getSliceStartTime()); + maxSliceTime = Math.max(maxSliceTime, collector.getTime()); + minSliceTime = Math.min(minSliceTime, collector.getTime()); + avgSliceTime += collector.getTime(); + } + time = maxSliceEndTime - minSliceStartTime; + sliceCount = collectors.size(); + avgSliceTime = sliceCount == 0 ? 0 : avgSliceTime / sliceCount; + + return ((CollectorManager) manager).reduce(subs); + } finally { + reduceTime = Math.max(1, System.nanoTime() - reduceStart); } - return ((CollectorManager) manager).reduce(subs); } @Override @@ -70,6 +91,26 @@ public long getTime() { return time; } + public long getReduceTime() { + return reduceTime; + } + + public long getMaxSliceTime() { + return maxSliceTime; + } + + public long getMinSliceTime() { + return minSliceTime; + } + + public long getAvgSliceTime() { + return avgSliceTime; + } + + public int getSliceCount() { + return sliceCount; + } + @Override public Collection children() { return children; @@ -82,7 +123,18 @@ public String getName() { @Override public CollectorResult getCollectorTree() { - return InternalProfileCollector.doGetCollectorTree(this); + return doGetCollectorManagerTree(this); + } + + static CollectorResult doGetCollectorManagerTree(InternalProfileComponent collector) { + List childResults = new ArrayList<>(collector.children().size()); + for (InternalProfileComponent child : collector.children()) { + CollectorResult result = doGetCollectorManagerTree(child); + childResults.add(result); + } + return new CollectorResult(collector.getName(), collector.getReason(), collector.getTime(), + collector.getReduceTime(), collector.getMaxSliceTime(), collector.getMinSliceTime(), + collector.getAvgSliceTime(), collector.getSliceCount(), childResults); } @Override diff --git a/server/src/main/java/org/opensearch/search/profile/query/InternalProfileComponent.java b/server/src/main/java/org/opensearch/search/profile/query/InternalProfileComponent.java index 1752d76e27f06..52c2df4bc0fa3 100644 --- a/server/src/main/java/org/opensearch/search/profile/query/InternalProfileComponent.java +++ b/server/src/main/java/org/opensearch/search/profile/query/InternalProfileComponent.java @@ -31,6 +31,31 @@ public interface InternalProfileComponent { */ long getTime(); + /** + * @return the elapsed time in the reduce phase taken by this profile component + */ + long getReduceTime(); + + /** + * @return the maximum slice time taken by this profile component + */ + long getMaxSliceTime(); + + /** + * @return the minimum slice time taken by this profile component + */ + long getMinSliceTime(); + + /** + * @return the average slice time taken by this profile component + */ + long getAvgSliceTime(); + + /** + * @return the segment slice count taken by this profile component + */ + int getSliceCount(); + /** * @return the profiling results for this profile component */ diff --git a/server/src/main/java/org/opensearch/search/profile/query/ProfileCollector.java b/server/src/main/java/org/opensearch/search/profile/query/ProfileCollector.java index 837145c287faf..a5dee90cbb9c8 100644 --- a/server/src/main/java/org/opensearch/search/profile/query/ProfileCollector.java +++ b/server/src/main/java/org/opensearch/search/profile/query/ProfileCollector.java @@ -50,6 +50,7 @@ final class ProfileCollector extends FilterCollector { private long time; + private long sliceStartTime; /** Sole constructor. */ ProfileCollector(Collector in) { @@ -67,6 +68,7 @@ public ScoreMode scoreMode() { try { return super.scoreMode(); } finally { + sliceStartTime = sliceStartTime == 0 ? start : sliceStartTime; time += Math.max(1, System.nanoTime() - start); } } @@ -109,4 +111,8 @@ public long getTime() { return time; } + /** Return the start time on this collector. */ + public long getSliceStartTime() { + return sliceStartTime; + } } diff --git a/server/src/test/java/org/opensearch/search/profile/query/CollectorResultTests.java b/server/src/test/java/org/opensearch/search/profile/query/CollectorResultTests.java index 29e9d0a4ef013..a07e48589ae04 100644 --- a/server/src/test/java/org/opensearch/search/profile/query/CollectorResultTests.java +++ b/server/src/test/java/org/opensearch/search/profile/query/CollectorResultTests.java @@ -53,7 +53,7 @@ public class CollectorResultTests extends OpenSearchTestCase { - public static CollectorResult createTestItem(int depth) { + public static CollectorResult createTestItem(int depth, boolean concurrentSearchEnabled) { String name = randomAlphaOfLengthBetween(5, 10); String reason = randomAlphaOfLengthBetween(5, 10); long time = randomNonNegativeLong(); @@ -61,26 +61,38 @@ public static CollectorResult createTestItem(int depth) { // also often use relatively "small" values, otherwise we will mostly test huge longs time = time % 100000; } + long reduceTime = time; + long maxSliceTime = time; + long minSliceTime = time; + long avgSliceTime = time; + int sliceCount = randomIntBetween(1, 10); int size = randomIntBetween(0, 5); List children = new ArrayList<>(size); if (depth > 0) { for (int i = 0; i < size; i++) { - children.add(createTestItem(depth - 1)); + children.add(createTestItem(depth - 1, concurrentSearchEnabled)); } } + + if (concurrentSearchEnabled) { + return new CollectorResult("defaultCollectorManager", "some reason", time, reduceTime, + maxSliceTime, minSliceTime, avgSliceTime, sliceCount, children); + } return new CollectorResult(name, reason, time, children); } public void testFromXContent() throws IOException { - doFromXContentTestWithRandomFields(false); + doFromXContentTestWithRandomFields(false, false); + doFromXContentTestWithRandomFields(false, true); } public void testFromXContentWithRandomFields() throws IOException { - doFromXContentTestWithRandomFields(true); + doFromXContentTestWithRandomFields(true, false); + doFromXContentTestWithRandomFields(true, true); } - private void doFromXContentTestWithRandomFields(boolean addRandomFields) throws IOException { - CollectorResult collectorResult = createTestItem(1); + private void doFromXContentTestWithRandomFields(boolean addRandomFields, boolean concurrentSearchEnabled) throws IOException { + CollectorResult collectorResult = createTestItem(1, concurrentSearchEnabled); XContentType xContentType = randomFrom(XContentType.values()); boolean humanReadable = randomBoolean(); BytesReference originalBytes = toShuffledXContent(collectorResult, xContentType, ToXContent.EMPTY_PARAMS, humanReadable); @@ -177,5 +189,24 @@ public void testToXContent() throws IOException { + "}", Strings.toString(builder) ); + + result = new CollectorResult("defaultCollectorManager", "some reason", 123456789L, + 123456789L, 123456789L, 123456789L, 123456789L, 5, Collections.emptyList()); + builder = XContentFactory.jsonBuilder().prettyPrint().humanReadable(true); + result.toXContent(builder, ToXContent.EMPTY_PARAMS); + assertEquals( + "{\n" + + " \"name\" : \"defaultCollectorManager\",\n" + + " \"reason\" : \"some reason\",\n" + + " \"time\" : \"123.4ms\",\n" + + " \"time_in_nanos\" : 123456789,\n" + + " \"reduce_time_in_nanos\" : 123456789,\n" + + " \"max_slice_time_in_nanos\" : 123456789,\n" + + " \"min_slice_time_in_nanos\" : 123456789,\n" + + " \"avg_slice_time_in_nanos\" : 123456789,\n" + + " \"slice_count\" : 5\n" + + "}", + Strings.toString(builder) + ); } } diff --git a/server/src/test/java/org/opensearch/search/profile/query/QueryProfileShardResultTests.java b/server/src/test/java/org/opensearch/search/profile/query/QueryProfileShardResultTests.java index 39fd8a4480415..a878acc8868c3 100644 --- a/server/src/test/java/org/opensearch/search/profile/query/QueryProfileShardResultTests.java +++ b/server/src/test/java/org/opensearch/search/profile/query/QueryProfileShardResultTests.java @@ -56,7 +56,7 @@ public static QueryProfileShardResult createTestItem() { for (int i = 0; i < size; i++) { queryProfileResults.add(ProfileResultTests.createTestItem(1)); } - CollectorResult profileCollector = CollectorResultTests.createTestItem(2); + CollectorResult profileCollector = CollectorResultTests.createTestItem(2, false); long rewriteTime = randomNonNegativeLong(); if (randomBoolean()) { rewriteTime = rewriteTime % 1000; // make sure to often test this with small values too