From 3dc21e780b397304a2ce7bf587cbfddf1c736c08 Mon Sep 17 00:00:00 2001 From: Jim Ferenczi Date: Mon, 18 Apr 2016 12:13:10 +0200 Subject: [PATCH] Add missing index name to search slow log. This commits adds the index name as part of the logging message. Closes #17025 --- .../elasticsearch/index/SearchSlowLog.java | 27 ++-- .../index/SearchSlowLogTests.java | 117 +++++++++++++++++- 2 files changed, 131 insertions(+), 13 deletions(-) diff --git a/core/src/main/java/org/elasticsearch/index/SearchSlowLog.java b/core/src/main/java/org/elasticsearch/index/SearchSlowLog.java index 57d879ab584..b4a6430b69e 100644 --- a/core/src/main/java/org/elasticsearch/index/SearchSlowLog.java +++ b/core/src/main/java/org/elasticsearch/index/SearchSlowLog.java @@ -33,7 +33,7 @@ import java.util.concurrent.TimeUnit; /** */ public final class SearchSlowLog implements SearchOperationListener { - + private final Index index; private boolean reformat; private long queryWarnThreshold; @@ -87,6 +87,8 @@ public final class SearchSlowLog implements SearchOperationListener { this.queryLogger = Loggers.getLogger(INDEX_SEARCH_SLOWLOG_PREFIX + ".query"); this.fetchLogger = Loggers.getLogger(INDEX_SEARCH_SLOWLOG_PREFIX + ".fetch"); + this.index = indexSettings.getIndex(); + indexSettings.getScopedSettings().addSettingsUpdateConsumer(INDEX_SEARCH_SLOWLOG_REFORMAT, this::setReformat); this.reformat = indexSettings.getValue(INDEX_SEARCH_SLOWLOG_REFORMAT); @@ -120,36 +122,38 @@ public final class SearchSlowLog implements SearchOperationListener { @Override public void onQueryPhase(SearchContext context, long tookInNanos) { if (queryWarnThreshold >= 0 && tookInNanos > queryWarnThreshold) { - queryLogger.warn("{}", new SlowLogSearchContextPrinter(context, tookInNanos, reformat)); + queryLogger.warn("{}", new SlowLogSearchContextPrinter(index, context, tookInNanos, reformat)); } else if (queryInfoThreshold >= 0 && tookInNanos > queryInfoThreshold) { - queryLogger.info("{}", new SlowLogSearchContextPrinter(context, tookInNanos, reformat)); + queryLogger.info("{}", new SlowLogSearchContextPrinter(index, context, tookInNanos, reformat)); } else if (queryDebugThreshold >= 0 && tookInNanos > queryDebugThreshold) { - queryLogger.debug("{}", new SlowLogSearchContextPrinter(context, tookInNanos, reformat)); + queryLogger.debug("{}", new SlowLogSearchContextPrinter(index, context, tookInNanos, reformat)); } else if (queryTraceThreshold >= 0 && tookInNanos > queryTraceThreshold) { - queryLogger.trace("{}", new SlowLogSearchContextPrinter(context, tookInNanos, reformat)); + queryLogger.trace("{}", new SlowLogSearchContextPrinter(index, context, tookInNanos, reformat)); } } @Override public void onFetchPhase(SearchContext context, long tookInNanos) { if (fetchWarnThreshold >= 0 && tookInNanos > fetchWarnThreshold) { - fetchLogger.warn("{}", new SlowLogSearchContextPrinter(context, tookInNanos, reformat)); + fetchLogger.warn("{}", new SlowLogSearchContextPrinter(index, context, tookInNanos, reformat)); } else if (fetchInfoThreshold >= 0 && tookInNanos > fetchInfoThreshold) { - fetchLogger.info("{}", new SlowLogSearchContextPrinter(context, tookInNanos, reformat)); + fetchLogger.info("{}", new SlowLogSearchContextPrinter(index, context, tookInNanos, reformat)); } else if (fetchDebugThreshold >= 0 && tookInNanos > fetchDebugThreshold) { - fetchLogger.debug("{}", new SlowLogSearchContextPrinter(context, tookInNanos, reformat)); + fetchLogger.debug("{}", new SlowLogSearchContextPrinter(index, context, tookInNanos, reformat)); } else if (fetchTraceThreshold >= 0 && tookInNanos > fetchTraceThreshold) { - fetchLogger.trace("{}", new SlowLogSearchContextPrinter(context, tookInNanos, reformat)); + fetchLogger.trace("{}", new SlowLogSearchContextPrinter(index, context, tookInNanos, reformat)); } } - private static class SlowLogSearchContextPrinter { + static final class SlowLogSearchContextPrinter { private final SearchContext context; + private final Index index; private final long tookInNanos; private final boolean reformat; - public SlowLogSearchContextPrinter(SearchContext context, long tookInNanos, boolean reformat) { + public SlowLogSearchContextPrinter(Index index, SearchContext context, long tookInNanos, boolean reformat) { this.context = context; + this.index = index; this.tookInNanos = tookInNanos; this.reformat = reformat; } @@ -157,6 +161,7 @@ public final class SearchSlowLog implements SearchOperationListener { @Override public String toString() { StringBuilder sb = new StringBuilder(); + sb.append(index).append(" "); sb.append("took[").append(TimeValue.timeValueNanos(tookInNanos)).append("], took_millis[").append(TimeUnit.NANOSECONDS.toMillis(tookInNanos)).append("], "); if (context.getQueryShardContext().getTypes() == null) { sb.append("types[], "); diff --git a/core/src/test/java/org/elasticsearch/index/SearchSlowLogTests.java b/core/src/test/java/org/elasticsearch/index/SearchSlowLogTests.java index 855291ace6c..49283d7b73a 100644 --- a/core/src/test/java/org/elasticsearch/index/SearchSlowLogTests.java +++ b/core/src/test/java/org/elasticsearch/index/SearchSlowLogTests.java @@ -20,13 +20,126 @@ package org.elasticsearch.index; import org.elasticsearch.Version; +import org.elasticsearch.action.search.SearchType; +import org.elasticsearch.cache.recycler.PageCacheRecycler; import org.elasticsearch.cluster.metadata.IndexMetaData; +import org.elasticsearch.common.bytes.BytesReference; import org.elasticsearch.common.settings.Settings; import org.elasticsearch.common.unit.TimeValue; -import org.elasticsearch.test.ESTestCase; +import org.elasticsearch.common.util.BigArrays; +import org.elasticsearch.index.query.QueryShardContext; +import org.elasticsearch.index.shard.ShardId; +import org.elasticsearch.script.ScriptService; +import org.elasticsearch.script.Template; +import org.elasticsearch.search.Scroll; +import org.elasticsearch.search.builder.SearchSourceBuilder; +import org.elasticsearch.search.internal.SearchContext; +import org.elasticsearch.search.internal.ShardSearchRequest; +import org.elasticsearch.test.ESSingleNodeTestCase; +import org.elasticsearch.test.TestSearchContext; +import org.elasticsearch.threadpool.ThreadPool; + +import java.io.IOException; + +import static org.hamcrest.Matchers.startsWith; -public class SearchSlowLogTests extends ESTestCase { +public class SearchSlowLogTests extends ESSingleNodeTestCase { + @Override + protected SearchContext createSearchContext(IndexService indexService) { + BigArrays bigArrays = indexService.getBigArrays(); + ThreadPool threadPool = indexService.getThreadPool(); + PageCacheRecycler pageCacheRecycler = node().injector().getInstance(PageCacheRecycler.class); + ScriptService scriptService = node().injector().getInstance(ScriptService.class); + return new TestSearchContext(threadPool, pageCacheRecycler, bigArrays, scriptService, indexService) { + @Override + public ShardSearchRequest request() { + return new ShardSearchRequest() { + @Override + public ShardId shardId() { + return null; + } + + @Override + public String[] types() { + return new String[0]; + } + + @Override + public SearchSourceBuilder source() { + return null; + } + + @Override + public void source(SearchSourceBuilder source) { + + } + + @Override + public int numberOfShards() { + return 0; + } + + @Override + public SearchType searchType() { + return null; + } + + @Override + public String[] filteringAliases() { + return new String[0]; + } + + @Override + public long nowInMillis() { + return 0; + } + + @Override + public Template template() { + return null; + } + + @Override + public Boolean requestCache() { + return null; + } + + @Override + public Scroll scroll() { + return null; + } + + @Override + public void setProfile(boolean profile) { + + } + + @Override + public boolean isProfile() { + return false; + } + + @Override + public BytesReference cacheKey() throws IOException { + return null; + } + + @Override + public void rewrite(QueryShardContext context) throws IOException { + } + }; + } + }; + } + + public void testSlowLogSearchContextPrinterToLog() throws IOException { + IndexService index = createIndex("foo"); + // Turning off document logging doesn't log source[] + SearchContext searchContext = createSearchContext(index); + SearchSlowLog.SlowLogSearchContextPrinter p = new SearchSlowLog.SlowLogSearchContextPrinter(index.index(), searchContext, 10, true); + assertThat(p.toString(), startsWith(index.index().toString())); + } public void testReformatSetting() { IndexMetaData metaData = newIndexMeta("index", Settings.builder()