From e709a0bde42137d3bdb70fd96fe95c2967cc61ef Mon Sep 17 00:00:00 2001 From: kimchy Date: Tue, 8 Mar 2011 08:20:48 +0200 Subject: [PATCH] Logging: Add merge level logging, closes #755. --- .../TrackingConcurrentMergeScheduler.java | 25 +++++++++++++---- .../index/TrackingSerialMergeScheduler.java | 27 ++++++++++++++++--- .../ConcurrentMergeSchedulerProvider.java | 7 ++--- .../SerialMergeSchedulerProvider.java | 6 +++-- 4 files changed, 51 insertions(+), 14 deletions(-) diff --git a/modules/elasticsearch/src/main/java/org/apache/lucene/index/TrackingConcurrentMergeScheduler.java b/modules/elasticsearch/src/main/java/org/apache/lucene/index/TrackingConcurrentMergeScheduler.java index aa6b2713aeb..8229d985270 100644 --- a/modules/elasticsearch/src/main/java/org/apache/lucene/index/TrackingConcurrentMergeScheduler.java +++ b/modules/elasticsearch/src/main/java/org/apache/lucene/index/TrackingConcurrentMergeScheduler.java @@ -19,6 +19,9 @@ package org.apache.lucene.index; +import org.elasticsearch.common.logging.ESLogger; +import org.elasticsearch.common.unit.TimeValue; + import java.io.IOException; import java.util.concurrent.atomic.AtomicLong; @@ -28,12 +31,15 @@ import java.util.concurrent.atomic.AtomicLong; */ public class TrackingConcurrentMergeScheduler extends ConcurrentMergeScheduler { - private AtomicLong totalMerges = new AtomicLong(); - private AtomicLong totalMergeTime = new AtomicLong(); - private AtomicLong currentMerges = new AtomicLong(); + private final ESLogger logger; - public TrackingConcurrentMergeScheduler() { + private final AtomicLong totalMerges = new AtomicLong(); + private final AtomicLong totalMergeTime = new AtomicLong(); + private final AtomicLong currentMerges = new AtomicLong(); + + public TrackingConcurrentMergeScheduler(ESLogger logger) { super(); + this.logger = logger; } public long totalMerges() { @@ -51,12 +57,21 @@ public class TrackingConcurrentMergeScheduler extends ConcurrentMergeScheduler { @Override protected void doMerge(MergePolicy.OneMerge merge) throws IOException { long time = System.currentTimeMillis(); currentMerges.incrementAndGet(); + if (logger.isTraceEnabled()) { + logger.trace("merge [{}] starting...", merge.info.name); + } try { super.doMerge(merge); } finally { currentMerges.decrementAndGet(); totalMerges.incrementAndGet(); - totalMergeTime.addAndGet(System.currentTimeMillis() - time); + long took = System.currentTimeMillis() - time; + totalMergeTime.addAndGet(took); + if (took > 20000) { // if more than 20 seconds, DEBUG log it + logger.debug("merge [{}] done, took [{}]", merge.info.name, TimeValue.timeValueMillis(took)); + } else if (logger.isTraceEnabled()) { + logger.trace("merge [{}] done, took [{}]", merge.info.name, TimeValue.timeValueMillis(took)); + } } } } \ No newline at end of file diff --git a/modules/elasticsearch/src/main/java/org/apache/lucene/index/TrackingSerialMergeScheduler.java b/modules/elasticsearch/src/main/java/org/apache/lucene/index/TrackingSerialMergeScheduler.java index 1bee6b6b8d4..8b86110bb6a 100644 --- a/modules/elasticsearch/src/main/java/org/apache/lucene/index/TrackingSerialMergeScheduler.java +++ b/modules/elasticsearch/src/main/java/org/apache/lucene/index/TrackingSerialMergeScheduler.java @@ -19,15 +19,24 @@ package org.apache.lucene.index; +import org.elasticsearch.common.logging.ESLogger; +import org.elasticsearch.common.unit.TimeValue; + import java.io.IOException; import java.util.concurrent.atomic.AtomicLong; // LUCENE MONITOR - Copied from SerialMergeScheduler public class TrackingSerialMergeScheduler extends MergeScheduler { - private AtomicLong totalMerges = new AtomicLong(); - private AtomicLong totalMergeTime = new AtomicLong(); - private AtomicLong currentMerges = new AtomicLong(); + private final ESLogger logger; + + private final AtomicLong totalMerges = new AtomicLong(); + private final AtomicLong totalMergeTime = new AtomicLong(); + private final AtomicLong currentMerges = new AtomicLong(); + + public TrackingSerialMergeScheduler(ESLogger logger) { + this.logger = logger; + } public long totalMerges() { return totalMerges.get(); @@ -53,6 +62,10 @@ public class TrackingSerialMergeScheduler extends MergeScheduler { if (merge == null) break; + if (logger.isTraceEnabled()) { + logger.trace("merge [{}] starting...", merge.info.name); + } + long time = System.currentTimeMillis(); currentMerges.incrementAndGet(); try { @@ -60,7 +73,13 @@ public class TrackingSerialMergeScheduler extends MergeScheduler { } finally { currentMerges.decrementAndGet(); totalMerges.incrementAndGet(); - totalMergeTime.addAndGet(System.currentTimeMillis() - time); + long took = System.currentTimeMillis() - time; + totalMergeTime.addAndGet(took); + if (took > 20000) { // if more than 20 seconds, DEBUG log it + logger.debug("merge [{}] done, took [{}]", merge.info.name, TimeValue.timeValueMillis(took)); + } else if (logger.isTraceEnabled()) { + logger.trace("merge [{}] done, took [{}]", merge.info.name, TimeValue.timeValueMillis(took)); + } } } } diff --git a/modules/elasticsearch/src/main/java/org/elasticsearch/index/merge/scheduler/ConcurrentMergeSchedulerProvider.java b/modules/elasticsearch/src/main/java/org/elasticsearch/index/merge/scheduler/ConcurrentMergeSchedulerProvider.java index 8e7064a01a1..cb5f45fb64a 100644 --- a/modules/elasticsearch/src/main/java/org/elasticsearch/index/merge/scheduler/ConcurrentMergeSchedulerProvider.java +++ b/modules/elasticsearch/src/main/java/org/elasticsearch/index/merge/scheduler/ConcurrentMergeSchedulerProvider.java @@ -22,6 +22,7 @@ package org.elasticsearch.index.merge.scheduler; import org.apache.lucene.index.*; import org.apache.lucene.store.AlreadyClosedException; import org.elasticsearch.common.inject.Inject; +import org.elasticsearch.common.logging.ESLogger; import org.elasticsearch.common.settings.Settings; import org.elasticsearch.index.merge.MergeStats; import org.elasticsearch.index.merge.policy.EnableMergePolicy; @@ -51,7 +52,7 @@ public class ConcurrentMergeSchedulerProvider extends AbstractIndexShardComponen } @Override public MergeScheduler newMergeScheduler() { - CustomConcurrentMergeScheduler concurrentMergeScheduler = new CustomConcurrentMergeScheduler(shardId, this); + CustomConcurrentMergeScheduler concurrentMergeScheduler = new CustomConcurrentMergeScheduler(logger, shardId, this); concurrentMergeScheduler.setMaxThreadCount(maxThreadCount); schedulers.add(concurrentMergeScheduler); return concurrentMergeScheduler; @@ -71,8 +72,8 @@ public class ConcurrentMergeSchedulerProvider extends AbstractIndexShardComponen private final ConcurrentMergeSchedulerProvider provider; - private CustomConcurrentMergeScheduler(ShardId shardId, ConcurrentMergeSchedulerProvider provider) { - super(); + private CustomConcurrentMergeScheduler(ESLogger logger, ShardId shardId, ConcurrentMergeSchedulerProvider provider) { + super(logger); this.shardId = shardId; this.provider = provider; } diff --git a/modules/elasticsearch/src/main/java/org/elasticsearch/index/merge/scheduler/SerialMergeSchedulerProvider.java b/modules/elasticsearch/src/main/java/org/elasticsearch/index/merge/scheduler/SerialMergeSchedulerProvider.java index f690486500f..8ff68c377d7 100644 --- a/modules/elasticsearch/src/main/java/org/elasticsearch/index/merge/scheduler/SerialMergeSchedulerProvider.java +++ b/modules/elasticsearch/src/main/java/org/elasticsearch/index/merge/scheduler/SerialMergeSchedulerProvider.java @@ -25,6 +25,7 @@ import org.apache.lucene.index.MergeScheduler; import org.apache.lucene.index.TrackingSerialMergeScheduler; import org.apache.lucene.store.AlreadyClosedException; import org.elasticsearch.common.inject.Inject; +import org.elasticsearch.common.logging.ESLogger; import org.elasticsearch.common.settings.Settings; import org.elasticsearch.index.merge.MergeStats; import org.elasticsearch.index.merge.policy.EnableMergePolicy; @@ -49,7 +50,7 @@ public class SerialMergeSchedulerProvider extends AbstractIndexShardComponent im } @Override public MergeScheduler newMergeScheduler() { - CustomSerialMergeScheduler scheduler = new CustomSerialMergeScheduler(this); + CustomSerialMergeScheduler scheduler = new CustomSerialMergeScheduler(logger, this); schedulers.add(scheduler); return scheduler; } @@ -66,7 +67,8 @@ public class SerialMergeSchedulerProvider extends AbstractIndexShardComponent im private final SerialMergeSchedulerProvider provider; - public CustomSerialMergeScheduler(SerialMergeSchedulerProvider provider) { + public CustomSerialMergeScheduler(ESLogger logger, SerialMergeSchedulerProvider provider) { + super(logger); this.provider = provider; }