From 3599585aa7898307303b5434b1594281df12cf65 Mon Sep 17 00:00:00 2001 From: Simon Willnauer Date: Thu, 14 Jan 2016 16:55:07 +0100 Subject: [PATCH] cut over indexing slow log --- .../elasticsearch/cluster/ClusterModule.java | 7 - .../org/elasticsearch/index/IndexService.java | 7 +- .../elasticsearch/index/IndexingSlowLog.java | 151 +++++++++--------- 3 files changed, 79 insertions(+), 86 deletions(-) diff --git a/core/src/main/java/org/elasticsearch/cluster/ClusterModule.java b/core/src/main/java/org/elasticsearch/cluster/ClusterModule.java index fa6ddd35039..a775b0d98ef 100644 --- a/core/src/main/java/org/elasticsearch/cluster/ClusterModule.java +++ b/core/src/main/java/org/elasticsearch/cluster/ClusterModule.java @@ -139,13 +139,6 @@ public class ClusterModule extends AbstractModule { registerIndexDynamicSetting(IndexMetaData.SETTING_SHARED_FS_ALLOW_RECOVERY_ON_ANY_NODE, Validator.EMPTY); registerIndexDynamicSetting(IndexMetaData.SETTING_PRIORITY, Validator.NON_NEGATIVE_INTEGER); registerIndexDynamicSetting(PrimaryShardAllocator.INDEX_RECOVERY_INITIAL_SHARDS, Validator.EMPTY); - registerIndexDynamicSetting(IndexingSlowLog.INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_WARN, Validator.TIME); - registerIndexDynamicSetting(IndexingSlowLog.INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_INFO, Validator.TIME); - registerIndexDynamicSetting(IndexingSlowLog.INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_DEBUG, Validator.TIME); - registerIndexDynamicSetting(IndexingSlowLog.INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_TRACE, Validator.TIME); - registerIndexDynamicSetting(IndexingSlowLog.INDEX_INDEXING_SLOWLOG_REFORMAT, Validator.EMPTY); - registerIndexDynamicSetting(IndexingSlowLog.INDEX_INDEXING_SLOWLOG_LEVEL, Validator.EMPTY); - registerIndexDynamicSetting(IndexingSlowLog.INDEX_INDEXING_SLOWLOG_MAX_SOURCE_CHARS_TO_LOG, Validator.EMPTY); registerIndexDynamicSetting(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_QUERY_WARN, Validator.TIME); registerIndexDynamicSetting(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_QUERY_INFO, Validator.TIME); registerIndexDynamicSetting(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_QUERY_DEBUG, Validator.TIME); diff --git a/core/src/main/java/org/elasticsearch/index/IndexService.java b/core/src/main/java/org/elasticsearch/index/IndexService.java index 806c262711d..11db446f147 100644 --- a/core/src/main/java/org/elasticsearch/index/IndexService.java +++ b/core/src/main/java/org/elasticsearch/index/IndexService.java @@ -141,7 +141,7 @@ public final class IndexService extends AbstractIndexComponent implements IndexC this.engineFactory = engineFactory; // initialize this last -- otherwise if the wrapper requires any other member to be non-null we fail with an NPE this.searcherWrapper = wrapperFactory.newWrapper(this); - this.slowLog = new IndexingSlowLog(indexSettings.getSettings()); + this.slowLog = new IndexingSlowLog(indexSettings); // Add our slowLog to the incoming IndexingOperationListeners: this.listeners = new IndexingOperationListener[1+listenersIn.length]; @@ -575,11 +575,6 @@ public final class IndexService extends AbstractIndexComponent implements IndexC logger.warn("[{}] failed to notify shard about setting change", e, shard.shardId().id()); } } - try { - slowLog.onRefreshSettings(settings); // this will be refactored soon anyway so duplication is ok here - } catch (Exception e) { - logger.warn("failed to refresh slowlog settings", e); - } try { searchSlowLog.onRefreshSettings(settings); // this will be refactored soon anyway so duplication is ok here diff --git a/core/src/main/java/org/elasticsearch/index/IndexingSlowLog.java b/core/src/main/java/org/elasticsearch/index/IndexingSlowLog.java index 5cd3685b2f8..859985c9580 100644 --- a/core/src/main/java/org/elasticsearch/index/IndexingSlowLog.java +++ b/core/src/main/java/org/elasticsearch/index/IndexingSlowLog.java @@ -19,10 +19,12 @@ package org.elasticsearch.index; +import com.sun.org.apache.xpath.internal.operations.Bool; import org.elasticsearch.common.Booleans; import org.elasticsearch.common.Strings; import org.elasticsearch.common.logging.ESLogger; import org.elasticsearch.common.logging.Loggers; +import org.elasticsearch.common.settings.Setting; import org.elasticsearch.common.settings.Settings; import org.elasticsearch.common.unit.TimeValue; import org.elasticsearch.common.xcontent.XContentHelper; @@ -33,17 +35,18 @@ import org.elasticsearch.index.shard.IndexingOperationListener; import java.io.IOException; import java.util.Locale; import java.util.concurrent.TimeUnit; +import java.util.logging.Level; /** */ public final class IndexingSlowLog implements IndexingOperationListener { - private boolean reformat; + private volatile boolean reformat; - private long indexWarnThreshold; - private long indexInfoThreshold; - private long indexDebugThreshold; - private long indexTraceThreshold; + private volatile long indexWarnThreshold; + private volatile long indexInfoThreshold; + private volatile long indexDebugThreshold; + private volatile long indexTraceThreshold; /** * How much of the source to log in the slowlog - 0 means log none and * anything greater than 0 means log at least that many characters @@ -51,21 +54,33 @@ public final class IndexingSlowLog implements IndexingOperationListener { */ private int maxSourceCharsToLog; - private String level; + private volatile Level level; private final ESLogger indexLogger; private final ESLogger deleteLogger; private static final String INDEX_INDEXING_SLOWLOG_PREFIX = "index.indexing.slowlog"; - public static final String INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_WARN = INDEX_INDEXING_SLOWLOG_PREFIX +".threshold.index.warn"; - public static final String INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_INFO = INDEX_INDEXING_SLOWLOG_PREFIX +".threshold.index.info"; - public static final String INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_DEBUG = INDEX_INDEXING_SLOWLOG_PREFIX +".threshold.index.debug"; - public static final String INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_TRACE = INDEX_INDEXING_SLOWLOG_PREFIX +".threshold.index.trace"; - public static final String INDEX_INDEXING_SLOWLOG_REFORMAT = INDEX_INDEXING_SLOWLOG_PREFIX +".reformat"; - public static final String INDEX_INDEXING_SLOWLOG_LEVEL = INDEX_INDEXING_SLOWLOG_PREFIX +".level"; - public static final String INDEX_INDEXING_SLOWLOG_MAX_SOURCE_CHARS_TO_LOG = INDEX_INDEXING_SLOWLOG_PREFIX + ".source"; + public static final Setting INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_WARN_SETTING = Setting.timeSetting(INDEX_INDEXING_SLOWLOG_PREFIX +".threshold.index.warn", TimeValue.timeValueNanos(-1), TimeValue.timeValueNanos(-1), true, Setting.Scope.INDEX); + public static final Setting INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_INFO_SETTING = Setting.timeSetting(INDEX_INDEXING_SLOWLOG_PREFIX +".threshold.index.info", TimeValue.timeValueNanos(-1), TimeValue.timeValueNanos(-1), true, Setting.Scope.INDEX); + public static final Setting INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_DEBUG_SETTING = Setting.timeSetting(INDEX_INDEXING_SLOWLOG_PREFIX +".threshold.index.debug", TimeValue.timeValueNanos(-1), TimeValue.timeValueNanos(-1), true, Setting.Scope.INDEX); + public static final Setting INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_TRACE_SETTING = Setting.timeSetting(INDEX_INDEXING_SLOWLOG_PREFIX +".threshold.index.trace", TimeValue.timeValueNanos(-1), TimeValue.timeValueNanos(-1), true, Setting.Scope.INDEX); + public static final Setting INDEX_INDEXING_SLOWLOG_REFORMAT_SETTING = Setting.boolSetting(INDEX_INDEXING_SLOWLOG_PREFIX +".reformat", true, true, Setting.Scope.INDEX); + public static final Setting INDEX_INDEXING_SLOWLOG_LEVEL_SETTING = new Setting<>(INDEX_INDEXING_SLOWLOG_PREFIX +".level", Level.TRACE.name(), Level::parse, true, Setting.Scope.INDEX); + /** + * Reads how much of the source to log. The user can specify any value they + * like and numbers are interpreted the maximum number of characters to log + * and everything else is interpreted as Elasticsearch interprets booleans + * which is then converted to 0 for false and Integer.MAX_VALUE for true. + */ + public static final Setting INDEX_INDEXING_SLOWLOG_MAX_SOURCE_CHARS_TO_LOG_SETTING = new Setting<>(INDEX_INDEXING_SLOWLOG_PREFIX + ".source", "1000", (value) -> { + try { + return Integer.parseInt(value, 10); + } catch (NumberFormatException e) { + return Booleans.parseBoolean(value, true) ? Integer.MAX_VALUE : 0; + } + }, true, Setting.Scope.INDEX); - IndexingSlowLog(Settings indexSettings) { + IndexingSlowLog(IndexSettings indexSettings) { this(indexSettings, Loggers.getLogger(INDEX_INDEXING_SLOWLOG_PREFIX + ".index"), Loggers.getLogger(INDEX_INDEXING_SLOWLOG_PREFIX + ".delete")); } @@ -73,77 +88,59 @@ public final class IndexingSlowLog implements IndexingOperationListener { /** * Build with the specified loggers. Only used to testing. */ - IndexingSlowLog(Settings indexSettings, ESLogger indexLogger, ESLogger deleteLogger) { + IndexingSlowLog(IndexSettings indexSettings, ESLogger indexLogger, ESLogger deleteLogger) { this.indexLogger = indexLogger; this.deleteLogger = deleteLogger; - this.reformat = indexSettings.getAsBoolean(INDEX_INDEXING_SLOWLOG_REFORMAT, true); - this.indexWarnThreshold = indexSettings.getAsTime(INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_WARN, TimeValue.timeValueNanos(-1)).nanos(); - this.indexInfoThreshold = indexSettings.getAsTime(INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_INFO, TimeValue.timeValueNanos(-1)).nanos(); - this.indexDebugThreshold = indexSettings.getAsTime(INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_DEBUG, TimeValue.timeValueNanos(-1)).nanos(); - this.indexTraceThreshold = indexSettings.getAsTime(INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_TRACE, TimeValue.timeValueNanos(-1)).nanos(); - this.level = indexSettings.get(INDEX_INDEXING_SLOWLOG_LEVEL, "TRACE").toUpperCase(Locale.ROOT); - this.maxSourceCharsToLog = readSourceToLog(indexSettings); - - indexLogger.setLevel(level); - deleteLogger.setLevel(level); + indexSettings.addSettingsUpdateConsumer(INDEX_INDEXING_SLOWLOG_REFORMAT_SETTING, this::setReformat); + this.reformat = indexSettings.getValue(INDEX_INDEXING_SLOWLOG_REFORMAT_SETTING); + indexSettings.addSettingsUpdateConsumer(INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_WARN_SETTING, this::setWarnThreshold); + this.indexWarnThreshold = indexSettings.getValue(INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_WARN_SETTING).nanos(); + indexSettings.addSettingsUpdateConsumer(INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_INFO_SETTING, this::setInfoThreshold); + this.indexInfoThreshold = indexSettings.getValue(INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_INFO_SETTING).nanos(); + indexSettings.addSettingsUpdateConsumer(INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_DEBUG_SETTING, this::setDebugThreshold); + this.indexDebugThreshold = indexSettings.getValue(INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_DEBUG_SETTING).nanos(); + indexSettings.addSettingsUpdateConsumer(INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_TRACE_SETTING, this::setTraceThreshold); + this.indexTraceThreshold = indexSettings.getValue(INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_TRACE_SETTING).nanos(); + indexSettings.addSettingsUpdateConsumer(INDEX_INDEXING_SLOWLOG_LEVEL_SETTING, this::setLevel); + setLevel(indexSettings.getValue(INDEX_INDEXING_SLOWLOG_LEVEL_SETTING)); + indexSettings.addSettingsUpdateConsumer(INDEX_INDEXING_SLOWLOG_MAX_SOURCE_CHARS_TO_LOG_SETTING, this::setMaxSourceCharsToLog); + this.maxSourceCharsToLog = indexSettings.getValue(INDEX_INDEXING_SLOWLOG_MAX_SOURCE_CHARS_TO_LOG_SETTING); } - synchronized void onRefreshSettings(Settings settings) { - long indexWarnThreshold = settings.getAsTime(INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_WARN, TimeValue.timeValueNanos(this.indexWarnThreshold)).nanos(); - if (indexWarnThreshold != this.indexWarnThreshold) { - this.indexWarnThreshold = indexWarnThreshold; - } - long indexInfoThreshold = settings.getAsTime(INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_INFO, TimeValue.timeValueNanos(this.indexInfoThreshold)).nanos(); - if (indexInfoThreshold != this.indexInfoThreshold) { - this.indexInfoThreshold = indexInfoThreshold; - } - long indexDebugThreshold = settings.getAsTime(INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_DEBUG, TimeValue.timeValueNanos(this.indexDebugThreshold)).nanos(); - if (indexDebugThreshold != this.indexDebugThreshold) { - this.indexDebugThreshold = indexDebugThreshold; - } - long indexTraceThreshold = settings.getAsTime(INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_TRACE, TimeValue.timeValueNanos(this.indexTraceThreshold)).nanos(); - if (indexTraceThreshold != this.indexTraceThreshold) { - this.indexTraceThreshold = indexTraceThreshold; - } - - String level = settings.get(INDEX_INDEXING_SLOWLOG_LEVEL, this.level); - if (!level.equals(this.level)) { - this.indexLogger.setLevel(level.toUpperCase(Locale.ROOT)); - this.deleteLogger.setLevel(level.toUpperCase(Locale.ROOT)); - this.level = level; - } - - boolean reformat = settings.getAsBoolean(INDEX_INDEXING_SLOWLOG_REFORMAT, this.reformat); - if (reformat != this.reformat) { - this.reformat = reformat; - } - - int maxSourceCharsToLog = readSourceToLog(settings); - if (maxSourceCharsToLog != this.maxSourceCharsToLog) { - this.maxSourceCharsToLog = maxSourceCharsToLog; - } + private void setMaxSourceCharsToLog(int maxSourceCharsToLog) { + this.maxSourceCharsToLog = maxSourceCharsToLog; } + private void setLevel(Level level) { + this.level = level; + this.indexLogger.setLevel(level.name()); + this.deleteLogger.setLevel(level.name()); + } + + private void setWarnThreshold(TimeValue warnThreshold) { + this.indexWarnThreshold = warnThreshold.nanos(); + } + + private void setInfoThreshold(TimeValue infoThreshold) { + this.indexInfoThreshold = infoThreshold.nanos(); + } + private void setDebugThreshold(TimeValue debugThreshold) { + this.indexDebugThreshold = debugThreshold.nanos(); + } + private void setTraceThreshold(TimeValue traceThreshold) { + this.indexTraceThreshold = traceThreshold.nanos(); + } + private void setReformat(boolean reformat) { + this.reformat = reformat; + } + + public void postIndex(Engine.Index index) { final long took = index.endTime() - index.startTime(); postIndexing(index.parsedDoc(), took); } - /** - * Reads how much of the source to log. The user can specify any value they - * like and numbers are interpreted the maximum number of characters to log - * and everything else is interpreted as Elasticsearch interprets booleans - * which is then converted to 0 for false and Integer.MAX_VALUE for true. - */ - private int readSourceToLog(Settings settings) { - String sourceToLog = settings.get(INDEX_INDEXING_SLOWLOG_MAX_SOURCE_CHARS_TO_LOG, "1000"); - try { - return Integer.parseInt(sourceToLog, 10); - } catch (NumberFormatException e) { - return Booleans.parseBoolean(sourceToLog, true) ? Integer.MAX_VALUE : 0; - } - } private void postIndexing(ParsedDocument doc, long tookInNanos) { if (indexWarnThreshold >= 0 && tookInNanos > indexWarnThreshold) { @@ -194,4 +191,12 @@ public final class IndexingSlowLog implements IndexingOperationListener { return sb.toString(); } } + + public enum Level { + WARN, TRACE, INFO, DEBUG; + + public static Level parse(String level) { + return valueOf(level.toUpperCase(Locale.ROOT)); + } + } }