From a2a8553faf2cc02d8ab2ccd5099c296770d4d7e3 Mon Sep 17 00:00:00 2001 From: Shay Banon Date: Mon, 3 Dec 2012 10:21:59 +0100 Subject: [PATCH] Indexing Slow Log closes #2457 --- config/elasticsearch.yml | 6 +- config/logging.yml | 10 + .../index/indexing/ShardIndexingModule.java | 2 + .../index/indexing/ShardIndexingService.java | 15 +- .../slowlog/ShardSlowLogIndexingService.java | 176 ++++++++++++++++++ .../engine/robin/SimpleRobinEngineTests.java | 5 +- 6 files changed, 209 insertions(+), 5 deletions(-) create mode 100644 src/main/java/org/elasticsearch/index/indexing/slowlog/ShardSlowLogIndexingService.java diff --git a/config/elasticsearch.yml b/config/elasticsearch.yml index 14ab8ea13cc..5eeab7616e5 100644 --- a/config/elasticsearch.yml +++ b/config/elasticsearch.yml @@ -338,7 +338,6 @@ # Shard level query and fetch threshold logging. -#index.search.slowlog.level: TRACE #index.search.slowlog.threshold.query.warn: 10s #index.search.slowlog.threshold.query.info: 5s #index.search.slowlog.threshold.query.debug: 2s @@ -349,6 +348,11 @@ #index.search.slowlog.threshold.fetch.debug: 500ms #index.search.slowlog.threshold.fetch.trace: 200ms +#index.indexing.slowlog.threshold.index.warn: 10s +#index.indexing.slowlog.threshold.index.info: 5s +#index.indexing.slowlog.threshold.index.debug: 2s +#index.indexing.slowlog.threshold.index.trace: 500ms + ################################## GC Logging ################################ #monitor.jvm.gc.ParNew.warn: 1000ms diff --git a/config/logging.yml b/config/logging.yml index 5f8c973d282..fe837f75228 100644 --- a/config/logging.yml +++ b/config/logging.yml @@ -16,9 +16,11 @@ logger: #discovery: TRACE index.search.slowlog: TRACE, index_search_slow_log_file + index.indexing.slowlog: TRACE, index_indexing_slow_log_file additivity: index.search.slowlog: false + index.indexing.slowlog: false appender: console: @@ -42,3 +44,11 @@ appender: layout: type: pattern conversionPattern: "[%d{ISO8601}][%-5p][%-25c] %m%n" + + index_indexing_slow_log_file: + type: dailyRollingFile + file: ${path.logs}/${cluster.name}_index_indexing_slowlog.log + datePattern: "'.'yyyy-MM-dd" + layout: + type: pattern + conversionPattern: "[%d{ISO8601}][%-5p][%-25c] %m%n" diff --git a/src/main/java/org/elasticsearch/index/indexing/ShardIndexingModule.java b/src/main/java/org/elasticsearch/index/indexing/ShardIndexingModule.java index a85a4ade4b2..93a9f3b7f2d 100644 --- a/src/main/java/org/elasticsearch/index/indexing/ShardIndexingModule.java +++ b/src/main/java/org/elasticsearch/index/indexing/ShardIndexingModule.java @@ -20,6 +20,7 @@ package org.elasticsearch.index.indexing; import org.elasticsearch.common.inject.AbstractModule; +import org.elasticsearch.index.indexing.slowlog.ShardSlowLogIndexingService; /** */ @@ -28,5 +29,6 @@ public class ShardIndexingModule extends AbstractModule { @Override protected void configure() { bind(ShardIndexingService.class).asEagerSingleton(); + bind(ShardSlowLogIndexingService.class).asEagerSingleton(); } } diff --git a/src/main/java/org/elasticsearch/index/indexing/ShardIndexingService.java b/src/main/java/org/elasticsearch/index/indexing/ShardIndexingService.java index 79020d43ad7..45cb2685378 100644 --- a/src/main/java/org/elasticsearch/index/indexing/ShardIndexingService.java +++ b/src/main/java/org/elasticsearch/index/indexing/ShardIndexingService.java @@ -26,6 +26,7 @@ import org.elasticsearch.common.metrics.CounterMetric; import org.elasticsearch.common.metrics.MeanMetric; import org.elasticsearch.common.settings.Settings; import org.elasticsearch.index.engine.Engine; +import org.elasticsearch.index.indexing.slowlog.ShardSlowLogIndexingService; import org.elasticsearch.index.settings.IndexSettings; import org.elasticsearch.index.shard.AbstractIndexShardComponent; import org.elasticsearch.index.shard.ShardId; @@ -39,6 +40,8 @@ import java.util.concurrent.TimeUnit; */ public class ShardIndexingService extends AbstractIndexShardComponent { + private final ShardSlowLogIndexingService slowLog; + private final StatsHolder totalStats = new StatsHolder(); private volatile Map typesStats = ImmutableMap.of(); @@ -46,8 +49,9 @@ public class ShardIndexingService extends AbstractIndexShardComponent { private CopyOnWriteArrayList listeners = null; @Inject - public ShardIndexingService(ShardId shardId, @IndexSettings Settings indexSettings) { + public ShardIndexingService(ShardId shardId, @IndexSettings Settings indexSettings, ShardSlowLogIndexingService slowLog) { super(shardId, indexSettings); + this.slowLog = slowLog; } /** @@ -95,6 +99,8 @@ public class ShardIndexingService extends AbstractIndexShardComponent { } public Engine.Create preCreate(Engine.Create create) { + totalStats.indexCurrent.inc(); + typeStats(create.type()).indexCurrent.inc(); if (listeners != null) { for (IndexingOperationListener listener : listeners) { create = listener.preCreate(create); @@ -118,7 +124,11 @@ public class ShardIndexingService extends AbstractIndexShardComponent { public void postCreate(Engine.Create create) { long took = create.endTime() - create.startTime(); totalStats.indexMetric.inc(took); - typeStats(create.type()).indexMetric.inc(took); + totalStats.indexCurrent.dec(); + StatsHolder typeStats = typeStats(create.type()); + typeStats.indexMetric.inc(took); + typeStats.indexCurrent.dec(); + slowLog.postCreate(create, took); if (listeners != null) { for (IndexingOperationListener listener : listeners) { try { @@ -160,6 +170,7 @@ public class ShardIndexingService extends AbstractIndexShardComponent { StatsHolder typeStats = typeStats(index.type()); typeStats.indexMetric.inc(took); typeStats.indexCurrent.dec(); + slowLog.postIndex(index, took); if (listeners != null) { for (IndexingOperationListener listener : listeners) { try { diff --git a/src/main/java/org/elasticsearch/index/indexing/slowlog/ShardSlowLogIndexingService.java b/src/main/java/org/elasticsearch/index/indexing/slowlog/ShardSlowLogIndexingService.java new file mode 100644 index 00000000000..1933d1375f2 --- /dev/null +++ b/src/main/java/org/elasticsearch/index/indexing/slowlog/ShardSlowLogIndexingService.java @@ -0,0 +1,176 @@ +/* + * Licensed to ElasticSearch and Shay Banon under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. ElasticSearch licenses this + * file to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +package org.elasticsearch.index.indexing.slowlog; + +import org.elasticsearch.cluster.metadata.IndexMetaData; +import org.elasticsearch.common.inject.Inject; +import org.elasticsearch.common.logging.ESLogger; +import org.elasticsearch.common.logging.Loggers; +import org.elasticsearch.common.settings.Settings; +import org.elasticsearch.common.unit.TimeValue; +import org.elasticsearch.common.xcontent.XContentHelper; +import org.elasticsearch.index.engine.Engine; +import org.elasticsearch.index.mapper.ParsedDocument; +import org.elasticsearch.index.settings.IndexSettings; +import org.elasticsearch.index.settings.IndexSettingsService; +import org.elasticsearch.index.shard.AbstractIndexShardComponent; +import org.elasticsearch.index.shard.ShardId; + +import java.io.IOException; +import java.util.concurrent.TimeUnit; + +/** + */ +public class ShardSlowLogIndexingService extends AbstractIndexShardComponent { + + private boolean reformat; + + private long indexWarnThreshold; + private long indexInfoThreshold; + private long indexDebugThreshold; + private long indexTraceThreshold; + + private String level; + + private final ESLogger indexLogger; + private final ESLogger deleteLogger; + + static { + IndexMetaData.addDynamicSettings( + "index.indexing.slowlog.threshold.index.warn", + "index.indexing.slowlog.threshold.index.info", + "index.indexing.slowlog.threshold.index.debug", + "index.indexing.slowlog.threshold.index.trace", + "index.indexing.slowlog.reformat", + "index.indexing.slowlog.level" + ); + } + + class ApplySettings implements IndexSettingsService.Listener { + @Override + public synchronized void onRefreshSettings(Settings settings) { + long indexWarnThreshold = settings.getAsTime("index.indexing.slowlog.threshold.index.warn", TimeValue.timeValueNanos(ShardSlowLogIndexingService.this.indexWarnThreshold)).nanos(); + if (indexWarnThreshold != ShardSlowLogIndexingService.this.indexWarnThreshold) { + ShardSlowLogIndexingService.this.indexWarnThreshold = indexWarnThreshold; + } + long indexInfoThreshold = settings.getAsTime("index.indexing.slowlog.threshold.index.info", TimeValue.timeValueNanos(ShardSlowLogIndexingService.this.indexInfoThreshold)).nanos(); + if (indexInfoThreshold != ShardSlowLogIndexingService.this.indexInfoThreshold) { + ShardSlowLogIndexingService.this.indexInfoThreshold = indexInfoThreshold; + } + long indexDebugThreshold = settings.getAsTime("index.indexing.slowlog.threshold.index.debug", TimeValue.timeValueNanos(ShardSlowLogIndexingService.this.indexDebugThreshold)).nanos(); + if (indexDebugThreshold != ShardSlowLogIndexingService.this.indexDebugThreshold) { + ShardSlowLogIndexingService.this.indexDebugThreshold = indexDebugThreshold; + } + long indexTraceThreshold = settings.getAsTime("index.indexing.slowlog.threshold.index.trace", TimeValue.timeValueNanos(ShardSlowLogIndexingService.this.indexTraceThreshold)).nanos(); + if (indexTraceThreshold != ShardSlowLogIndexingService.this.indexTraceThreshold) { + ShardSlowLogIndexingService.this.indexTraceThreshold = indexTraceThreshold; + } + + String level = settings.get("index.indexing.slowlog.level", ShardSlowLogIndexingService.this.level); + if (!level.equals(ShardSlowLogIndexingService.this.level)) { + ShardSlowLogIndexingService.this.indexLogger.setLevel(level.toUpperCase()); + ShardSlowLogIndexingService.this.deleteLogger.setLevel(level.toUpperCase()); + ShardSlowLogIndexingService.this.level = level; + } + + boolean reformat = settings.getAsBoolean("index.indexing.slowlog.reformat", ShardSlowLogIndexingService.this.reformat); + if (reformat != ShardSlowLogIndexingService.this.reformat) { + ShardSlowLogIndexingService.this.reformat = reformat; + } + } + } + + @Inject + public ShardSlowLogIndexingService(ShardId shardId, @IndexSettings Settings indexSettings, IndexSettingsService indexSettingsService) { + super(shardId, indexSettings); + + this.reformat = componentSettings.getAsBoolean("reformat", true); + + this.indexWarnThreshold = componentSettings.getAsTime("threshold.index.warn", TimeValue.timeValueNanos(-1)).nanos(); + this.indexInfoThreshold = componentSettings.getAsTime("threshold.index.info", TimeValue.timeValueNanos(-1)).nanos(); + this.indexDebugThreshold = componentSettings.getAsTime("threshold.index.debug", TimeValue.timeValueNanos(-1)).nanos(); + this.indexTraceThreshold = componentSettings.getAsTime("threshold.index.trace", TimeValue.timeValueNanos(-1)).nanos(); + + this.level = componentSettings.get("level", "TRACE").toUpperCase(); + + this.indexLogger = Loggers.getLogger(logger, ".index"); + this.deleteLogger = Loggers.getLogger(logger, ".delete"); + + indexLogger.setLevel(level); + deleteLogger.setLevel(level); + + indexSettingsService.addListener(new ApplySettings()); + } + + public void postIndex(Engine.Index index, long tookInNanos) { + postIndexing(index.parsedDoc(), tookInNanos); + } + + public void postCreate(Engine.Create create, long tookInNanos) { + postIndexing(create.parsedDoc(), tookInNanos); + } + + private void postIndexing(ParsedDocument doc, long tookInNanos) { + if (indexWarnThreshold >= 0 && tookInNanos > indexWarnThreshold) { + indexLogger.warn("{}", new SlowLogParsedDocumentPrinter(doc, tookInNanos, reformat)); + } else if (indexInfoThreshold >= 0 && tookInNanos > indexInfoThreshold) { + indexLogger.info("{}", new SlowLogParsedDocumentPrinter(doc, tookInNanos, reformat)); + } else if (indexDebugThreshold >= 0 && tookInNanos > indexDebugThreshold) { + indexLogger.debug("{}", new SlowLogParsedDocumentPrinter(doc, tookInNanos, reformat)); + } else if (indexTraceThreshold >= 0 && tookInNanos > indexTraceThreshold) { + indexLogger.trace("{}", new SlowLogParsedDocumentPrinter(doc, tookInNanos, reformat)); + } + } + + public static class SlowLogParsedDocumentPrinter { + private final ParsedDocument doc; + private final long tookInNanos; + private final boolean reformat; + + public SlowLogParsedDocumentPrinter(ParsedDocument doc, long tookInNanos, boolean reformat) { + this.doc = doc; + this.tookInNanos = tookInNanos; + this.reformat = reformat; + } + + @Override + public String toString() { + StringBuilder sb = new StringBuilder(); + sb.append("took[").append(TimeValue.timeValueNanos(tookInNanos)).append("], took_millis[").append(TimeUnit.NANOSECONDS.toMillis(tookInNanos)).append("], "); + sb.append("type[").append(doc.type()).append("], "); + sb.append("id[").append(doc.id()).append("], "); + if (doc.routing() == null) { + sb.append("routing[], "); + } else { + sb.append("routing[").append(doc.routing()).append("], "); + } + if (doc.source() != null && doc.source().length() > 0) { + try { + sb.append("source[").append(XContentHelper.convertToJson(doc.source(), reformat)).append("]"); + } catch (IOException e) { + sb.append("source[_failed_to_convert_]"); + } + } else { + sb.append("source[]"); + } + return sb.toString(); + } + } +} \ No newline at end of file diff --git a/src/test/java/org/elasticsearch/test/unit/index/engine/robin/SimpleRobinEngineTests.java b/src/test/java/org/elasticsearch/test/unit/index/engine/robin/SimpleRobinEngineTests.java index 929b69e388e..3526f660984 100644 --- a/src/test/java/org/elasticsearch/test/unit/index/engine/robin/SimpleRobinEngineTests.java +++ b/src/test/java/org/elasticsearch/test/unit/index/engine/robin/SimpleRobinEngineTests.java @@ -19,12 +19,12 @@ package org.elasticsearch.test.unit.index.engine.robin; -import org.apache.lucene.search.similarities.DefaultSimilarity; import org.elasticsearch.index.analysis.AnalysisService; import org.elasticsearch.index.codec.CodecService; import org.elasticsearch.index.engine.Engine; import org.elasticsearch.index.engine.robin.RobinEngine; import org.elasticsearch.index.indexing.ShardIndexingService; +import org.elasticsearch.index.indexing.slowlog.ShardSlowLogIndexingService; import org.elasticsearch.index.settings.IndexSettingsService; import org.elasticsearch.index.similarity.SimilarityService; import org.elasticsearch.index.store.Store; @@ -39,7 +39,8 @@ import static org.elasticsearch.common.settings.ImmutableSettings.Builder.EMPTY_ public class SimpleRobinEngineTests extends AbstractSimpleEngineTests { protected Engine createEngine(Store store, Translog translog) { - return new RobinEngine(shardId, EMPTY_SETTINGS, threadPool, new IndexSettingsService(shardId.index(), EMPTY_SETTINGS), new ShardIndexingService(shardId, EMPTY_SETTINGS), null, store, createSnapshotDeletionPolicy(), translog, createMergePolicy(), createMergeScheduler(), + IndexSettingsService indexSettingsService = new IndexSettingsService(shardId.index(), EMPTY_SETTINGS); + return new RobinEngine(shardId, EMPTY_SETTINGS, threadPool, indexSettingsService, new ShardIndexingService(shardId, EMPTY_SETTINGS, new ShardSlowLogIndexingService(shardId, EMPTY_SETTINGS, indexSettingsService)), null, store, createSnapshotDeletionPolicy(), translog, createMergePolicy(), createMergeScheduler(), new AnalysisService(shardId.index()), new SimilarityService(shardId.index()), new CodecService(shardId.index())); } }