From b2d8a1fd1b4aff1a8e918d87abfe07bf0be2397a Mon Sep 17 00:00:00 2001 From: Jason Tedor Date: Tue, 7 Jul 2015 10:19:29 -0400 Subject: [PATCH] Count scans in search stats and add metrics for scrolls Each scroll on a scan causes a query to be executed. This commit adds support for these indirect queries to count against the search stats. Additionally, this commit adds three new search stats: scroll_count, scroll_time_in_millis, and scroll_current. scroll_count tracks the number of completed scrolls. scroll_time_in_millis tracks the total time that scrolls were held open. scroll_current tracks the number of scrolls currently open. Closes #9109 --- .../index/search/stats/SearchStats.java | 56 ++++++++++++++++++- .../index/search/stats/ShardSearchStats.java | 21 ++++++- .../elasticsearch/search/SearchService.java | 45 +++++++++++---- .../search/stats/SearchStatsTests.java | 29 +++++++++- .../search/stats/SearchStatsUnitTests.java | 9 ++- 5 files changed, 140 insertions(+), 20 deletions(-) diff --git a/core/src/main/java/org/elasticsearch/index/search/stats/SearchStats.java b/core/src/main/java/org/elasticsearch/index/search/stats/SearchStats.java index 44d93230401..2d3ee81d0ce 100644 --- a/core/src/main/java/org/elasticsearch/index/search/stats/SearchStats.java +++ b/core/src/main/java/org/elasticsearch/index/search/stats/SearchStats.java @@ -47,21 +47,38 @@ public class SearchStats implements Streamable, ToXContent { private long fetchTimeInMillis; private long fetchCurrent; + private long scrollCount; + private long scrollTimeInMillis; + private long scrollCurrent; + Stats() { } - public Stats(long queryCount, long queryTimeInMillis, long queryCurrent, long fetchCount, long fetchTimeInMillis, long fetchCurrent) { + public Stats( + long queryCount, long queryTimeInMillis, long queryCurrent, + long fetchCount, long fetchTimeInMillis, long fetchCurrent, + long scrollCount, long scrollTimeInMillis, long scrollCurrent + ) { this.queryCount = queryCount; this.queryTimeInMillis = queryTimeInMillis; this.queryCurrent = queryCurrent; + this.fetchCount = fetchCount; this.fetchTimeInMillis = fetchTimeInMillis; this.fetchCurrent = fetchCurrent; + + this.scrollCount = scrollCount; + this.scrollTimeInMillis = scrollTimeInMillis; + this.scrollCurrent = scrollCurrent; } public Stats(Stats stats) { - this(stats.queryCount, stats.queryTimeInMillis, stats.queryCurrent, stats.fetchCount, stats.fetchTimeInMillis, stats.fetchCurrent); + this( + stats.queryCount, stats.queryTimeInMillis, stats.queryCurrent, + stats.fetchCount, stats.fetchTimeInMillis, stats.fetchCurrent, + stats.scrollCount, stats.scrollTimeInMillis, stats.scrollCurrent + ); } public void add(Stats stats) { @@ -72,6 +89,10 @@ public class SearchStats implements Streamable, ToXContent { fetchCount += stats.fetchCount; fetchTimeInMillis += stats.fetchTimeInMillis; fetchCurrent += stats.fetchCurrent; + + scrollCount += stats.scrollCount; + scrollTimeInMillis += stats.scrollTimeInMillis; + scrollCurrent += stats.scrollCurrent; } public long getQueryCount() { @@ -106,6 +127,21 @@ public class SearchStats implements Streamable, ToXContent { return fetchCurrent; } + public long getScrollCount() { + return scrollCount; + } + + public TimeValue getScrollTime() { + return new TimeValue(scrollTimeInMillis); + } + + public long getScrollTimeInMillis() { + return scrollTimeInMillis; + } + + public long getScrollCurrent() { + return scrollCurrent; + } public static Stats readStats(StreamInput in) throws IOException { Stats stats = new Stats(); @@ -122,6 +158,10 @@ public class SearchStats implements Streamable, ToXContent { fetchCount = in.readVLong(); fetchTimeInMillis = in.readVLong(); fetchCurrent = in.readVLong(); + + scrollCount = in.readVLong(); + scrollTimeInMillis = in.readVLong(); + scrollCurrent = in.readVLong(); } @Override @@ -133,6 +173,10 @@ public class SearchStats implements Streamable, ToXContent { out.writeVLong(fetchCount); out.writeVLong(fetchTimeInMillis); out.writeVLong(fetchCurrent); + + out.writeVLong(scrollCount); + out.writeVLong(scrollTimeInMillis); + out.writeVLong(scrollCurrent); } @Override @@ -145,6 +189,10 @@ public class SearchStats implements Streamable, ToXContent { builder.timeValueField(Fields.FETCH_TIME_IN_MILLIS, Fields.FETCH_TIME, fetchTimeInMillis); builder.field(Fields.FETCH_CURRENT, fetchCurrent); + builder.field(Fields.SCROLL_TOTAL, scrollCount); + builder.timeValueField(Fields.SCROLL_TIME_IN_MILLIS, Fields.SCROLL_TIME, scrollTimeInMillis); + builder.field(Fields.SCROLL_CURRENT, scrollCurrent); + return builder; } } @@ -233,6 +281,10 @@ public class SearchStats implements Streamable, ToXContent { static final XContentBuilderString FETCH_TIME = new XContentBuilderString("fetch_time"); static final XContentBuilderString FETCH_TIME_IN_MILLIS = new XContentBuilderString("fetch_time_in_millis"); static final XContentBuilderString FETCH_CURRENT = new XContentBuilderString("fetch_current"); + static final XContentBuilderString SCROLL_TOTAL = new XContentBuilderString("scroll_total"); + static final XContentBuilderString SCROLL_TIME = new XContentBuilderString("scroll_time"); + static final XContentBuilderString SCROLL_TIME_IN_MILLIS = new XContentBuilderString("scroll_time_in_millis"); + static final XContentBuilderString SCROLL_CURRENT = new XContentBuilderString("scroll_current"); } public static SearchStats readSearchStats(StreamInput in) throws IOException { diff --git a/core/src/main/java/org/elasticsearch/index/search/stats/ShardSearchStats.java b/core/src/main/java/org/elasticsearch/index/search/stats/ShardSearchStats.java index ade73676709..53b986b96b3 100644 --- a/core/src/main/java/org/elasticsearch/index/search/stats/ShardSearchStats.java +++ b/core/src/main/java/org/elasticsearch/index/search/stats/ShardSearchStats.java @@ -169,6 +169,15 @@ public final class ShardSearchStats { openContexts.dec(); } + public void onNewScrollContext(SearchContext context) { + totalStats.scrollCurrent.inc(); + } + + public void onFreeScrollContext(SearchContext context) { + totalStats.scrollCurrent.dec(); + totalStats.scrollMetric.inc(TimeUnit.MILLISECONDS.toNanos(System.currentTimeMillis() - context.nowInMillis())); + } + public void onRefreshSettings(Settings settings) { slowLogSearchService.onRefreshSettings(settings); } @@ -176,21 +185,27 @@ public final class ShardSearchStats { final static class StatsHolder { public final MeanMetric queryMetric = new MeanMetric(); public final MeanMetric fetchMetric = new MeanMetric(); + public final MeanMetric scrollMetric = new MeanMetric(); public final CounterMetric queryCurrent = new CounterMetric(); public final CounterMetric fetchCurrent = new CounterMetric(); + public final CounterMetric scrollCurrent = new CounterMetric(); public SearchStats.Stats stats() { - return new SearchStats.Stats(queryMetric.count(), TimeUnit.NANOSECONDS.toMillis(queryMetric.sum()), queryCurrent.count(), - fetchMetric.count(), TimeUnit.NANOSECONDS.toMillis(fetchMetric.sum()), fetchCurrent.count()); + return new SearchStats.Stats( + queryMetric.count(), TimeUnit.NANOSECONDS.toMillis(queryMetric.sum()), queryCurrent.count(), + fetchMetric.count(), TimeUnit.NANOSECONDS.toMillis(fetchMetric.sum()), fetchCurrent.count(), + scrollMetric.count(), TimeUnit.NANOSECONDS.toMillis(scrollMetric.sum()), scrollCurrent.count() + ); } public long totalCurrent() { - return queryCurrent.count() + fetchCurrent.count(); + return queryCurrent.count() + fetchCurrent.count() + scrollCurrent.count(); } public void clear() { queryMetric.clear(); fetchMetric.clear(); + scrollMetric.clear(); } } } diff --git a/core/src/main/java/org/elasticsearch/search/SearchService.java b/core/src/main/java/org/elasticsearch/search/SearchService.java index 41b8e154751..f15a802a394 100644 --- a/core/src/main/java/org/elasticsearch/search/SearchService.java +++ b/core/src/main/java/org/elasticsearch/search/SearchService.java @@ -267,22 +267,39 @@ public class SearchService extends AbstractLifecycleComponent { public ScrollQueryFetchSearchResult executeScan(InternalScrollSearchRequest request) { final SearchContext context = findContext(request.id()); + ShardSearchStats shardSearchStats = context.indexShard().searchService(); contextProcessing(context); try { processScroll(request, context); - if (context.searchType() == SearchType.QUERY_THEN_FETCH) { - // first scanning, reset the from to 0 - context.searchType(SearchType.SCAN); - context.from(0); + shardSearchStats.onPreQueryPhase(context); + long time = System.nanoTime(); + try { + if (context.searchType() == SearchType.QUERY_THEN_FETCH) { + // first scanning, reset the from to 0 + context.searchType(SearchType.SCAN); + context.from(0); + } + queryPhase.execute(context); + } catch (Throwable e) { + shardSearchStats.onFailedQueryPhase(context); + throw ExceptionsHelper.convertToRuntime(e); } - queryPhase.execute(context); - shortcutDocIdsToLoadForScanning(context); - fetchPhase.execute(context); - if (context.scroll() == null || context.fetchResult().hits().hits().length < context.size()) { - freeContext(request.id()); - } else { - contextProcessedSuccessfully(context); + long queryFinishTime = System.nanoTime(); + shardSearchStats.onQueryPhase(context, queryFinishTime - time); + shardSearchStats.onPreFetchPhase(context); + try { + shortcutDocIdsToLoadForScanning(context); + fetchPhase.execute(context); + if (context.scroll() == null || context.fetchResult().hits().hits().length < context.size()) { + freeContext(request.id()); + } else { + contextProcessedSuccessfully(context); + } + } catch (Throwable e) { + shardSearchStats.onFailedQueryPhase(context); + throw ExceptionsHelper.convertToRuntime(e); } + shardSearchStats.onFetchPhase(context, System.nanoTime() - queryFinishTime); return new ScrollQueryFetchSearchResult(new QueryFetchSearchResult(context.queryResult(), context.fetchResult()), context.shardTarget()); } catch (Throwable e) { logger.trace("Scan phase failed", e); @@ -569,6 +586,9 @@ public class SearchService extends AbstractLifecycleComponent { boolean success = false; try { putContext(context); + if (request.scroll() != null) { + context.indexShard().searchService().onNewScrollContext(context); + } context.indexShard().searchService().onNewContext(context); success = true; return context; @@ -643,6 +663,9 @@ public class SearchService extends AbstractLifecycleComponent { if (context != null) { try { context.indexShard().searchService().onFreeContext(context); + if (context.scroll() != null) { + context.indexShard().searchService().onFreeScrollContext(context); + } } finally { context.close(); } diff --git a/core/src/test/java/org/elasticsearch/search/stats/SearchStatsTests.java b/core/src/test/java/org/elasticsearch/search/stats/SearchStatsTests.java index a4d17090ed7..fd100a64b9b 100644 --- a/core/src/test/java/org/elasticsearch/search/stats/SearchStatsTests.java +++ b/core/src/test/java/org/elasticsearch/search/stats/SearchStatsTests.java @@ -33,11 +33,13 @@ import org.elasticsearch.common.unit.TimeValue; import org.elasticsearch.index.query.QueryBuilders; import org.elasticsearch.index.search.stats.SearchStats.Stats; import org.elasticsearch.script.Script; +import org.elasticsearch.search.SearchHit; import org.elasticsearch.test.ElasticsearchIntegrationTest; import org.junit.Test; import java.util.HashSet; import java.util.Set; +import java.util.concurrent.TimeUnit; import static org.elasticsearch.cluster.metadata.IndexMetaData.SETTING_NUMBER_OF_REPLICAS; import static org.elasticsearch.cluster.metadata.IndexMetaData.SETTING_NUMBER_OF_SHARDS; @@ -178,7 +180,32 @@ public class SearchStatsTests extends ElasticsearchIntegrationTest { assertSearchResponse(searchResponse); indicesStats = client().admin().indices().prepareStats().execute().actionGet(); - assertThat(indicesStats.getTotal().getSearch().getOpenContexts(), equalTo((long)numAssignedShards("test1"))); + assertThat(indicesStats.getTotal().getSearch().getOpenContexts(), equalTo((long) numAssignedShards("test1"))); + assertThat(indicesStats.getTotal().getSearch().getTotal().getScrollCurrent(), equalTo((long) numAssignedShards("test1"))); + + // force the scan to complete measuring the time taken + // the total time the scroll is open should be greater than this + // the number of queries should equal the number of pages in the scan times the number of shards + long time = System.nanoTime(); + int count = 0; + while (true) { + count++; + searchResponse = client().prepareSearchScroll(searchResponse.getScrollId()) + .setScroll(TimeValue.timeValueMinutes(2)) + .execute().actionGet(); + if (searchResponse.getHits().getHits().length == 0) { + break; + } + } + long total = System.nanoTime() - time; + + indicesStats = client().admin().indices().prepareStats().execute().actionGet(); + assertThat(indicesStats.getTotal().getSearch().getTotal().getQueryCount(), equalTo(count * (long)numAssignedShards("test1"))); + assertThat(indicesStats.getTotal().getSearch().getTotal().getScrollCount(), equalTo((long)numAssignedShards("test1"))); + assertThat( + indicesStats.getTotal().getSearch().getTotal().getScrollTimeInMillis(), + greaterThan(TimeUnit.NANOSECONDS.toMillis(total * numAssignedShards("test1"))) + ); // scroll, but with no timeout (so no context) searchResponse = client().prepareSearchScroll(searchResponse.getScrollId()).execute().actionGet(); diff --git a/core/src/test/java/org/elasticsearch/search/stats/SearchStatsUnitTests.java b/core/src/test/java/org/elasticsearch/search/stats/SearchStatsUnitTests.java index a9f134b1be6..7128991b24f 100644 --- a/core/src/test/java/org/elasticsearch/search/stats/SearchStatsUnitTests.java +++ b/core/src/test/java/org/elasticsearch/search/stats/SearchStatsUnitTests.java @@ -35,9 +35,9 @@ public class SearchStatsUnitTests extends ElasticsearchTestCase { // let's create two dummy search stats with groups Map groupStats1 = new HashMap<>(); Map groupStats2 = new HashMap<>(); - groupStats2.put("group1", new Stats(1, 1, 1, 1, 1, 1)); - SearchStats searchStats1 = new SearchStats(new Stats(1, 1, 1, 1, 1, 1), 0, groupStats1); - SearchStats searchStats2 = new SearchStats(new Stats(1, 1, 1, 1, 1, 1), 0, groupStats2); + groupStats2.put("group1", new Stats(1, 1, 1, 1, 1, 1, 1, 1, 1)); + SearchStats searchStats1 = new SearchStats(new Stats(1, 1, 1, 1, 1, 1, 1, 1, 1), 0, groupStats1); + SearchStats searchStats2 = new SearchStats(new Stats(1, 1, 1, 1, 1, 1, 1, 1, 1), 0, groupStats2); // adding these two search stats and checking group stats are correct searchStats1.add(searchStats2); @@ -62,5 +62,8 @@ public class SearchStatsUnitTests extends ElasticsearchTestCase { assertEquals(equalTo, stats.getFetchCount()); assertEquals(equalTo, stats.getFetchTimeInMillis()); assertEquals(equalTo, stats.getFetchCurrent()); + assertEquals(equalTo, stats.getScrollCount()); + assertEquals(equalTo, stats.getScrollTimeInMillis()); + assertEquals(equalTo, stats.getScrollCurrent()); } } \ No newline at end of file