Logging: Add merge level logging, closes #755.

This commit is contained in:
kimchy 2011-03-08 08:20:48 +02:00
parent 9e2143f343
commit e709a0bde4
4 changed files with 51 additions and 14 deletions

View File

@ -19,6 +19,9 @@
package org.apache.lucene.index; package org.apache.lucene.index;
import org.elasticsearch.common.logging.ESLogger;
import org.elasticsearch.common.unit.TimeValue;
import java.io.IOException; import java.io.IOException;
import java.util.concurrent.atomic.AtomicLong; import java.util.concurrent.atomic.AtomicLong;
@ -28,12 +31,15 @@ import java.util.concurrent.atomic.AtomicLong;
*/ */
public class TrackingConcurrentMergeScheduler extends ConcurrentMergeScheduler { public class TrackingConcurrentMergeScheduler extends ConcurrentMergeScheduler {
private AtomicLong totalMerges = new AtomicLong(); private final ESLogger logger;
private AtomicLong totalMergeTime = new AtomicLong();
private AtomicLong currentMerges = new AtomicLong();
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(); super();
this.logger = logger;
} }
public long totalMerges() { public long totalMerges() {
@ -51,12 +57,21 @@ public class TrackingConcurrentMergeScheduler extends ConcurrentMergeScheduler {
@Override protected void doMerge(MergePolicy.OneMerge merge) throws IOException { @Override protected void doMerge(MergePolicy.OneMerge merge) throws IOException {
long time = System.currentTimeMillis(); long time = System.currentTimeMillis();
currentMerges.incrementAndGet(); currentMerges.incrementAndGet();
if (logger.isTraceEnabled()) {
logger.trace("merge [{}] starting...", merge.info.name);
}
try { try {
super.doMerge(merge); super.doMerge(merge);
} finally { } finally {
currentMerges.decrementAndGet(); currentMerges.decrementAndGet();
totalMerges.incrementAndGet(); 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));
}
} }
} }
} }

View File

@ -19,15 +19,24 @@
package org.apache.lucene.index; package org.apache.lucene.index;
import org.elasticsearch.common.logging.ESLogger;
import org.elasticsearch.common.unit.TimeValue;
import java.io.IOException; import java.io.IOException;
import java.util.concurrent.atomic.AtomicLong; import java.util.concurrent.atomic.AtomicLong;
// LUCENE MONITOR - Copied from SerialMergeScheduler // LUCENE MONITOR - Copied from SerialMergeScheduler
public class TrackingSerialMergeScheduler extends MergeScheduler { public class TrackingSerialMergeScheduler extends MergeScheduler {
private AtomicLong totalMerges = new AtomicLong(); private final ESLogger logger;
private AtomicLong totalMergeTime = new AtomicLong();
private AtomicLong currentMerges = new AtomicLong(); 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() { public long totalMerges() {
return totalMerges.get(); return totalMerges.get();
@ -53,6 +62,10 @@ public class TrackingSerialMergeScheduler extends MergeScheduler {
if (merge == null) if (merge == null)
break; break;
if (logger.isTraceEnabled()) {
logger.trace("merge [{}] starting...", merge.info.name);
}
long time = System.currentTimeMillis(); long time = System.currentTimeMillis();
currentMerges.incrementAndGet(); currentMerges.incrementAndGet();
try { try {
@ -60,7 +73,13 @@ public class TrackingSerialMergeScheduler extends MergeScheduler {
} finally { } finally {
currentMerges.decrementAndGet(); currentMerges.decrementAndGet();
totalMerges.incrementAndGet(); 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));
}
} }
} }
} }

View File

@ -22,6 +22,7 @@ package org.elasticsearch.index.merge.scheduler;
import org.apache.lucene.index.*; import org.apache.lucene.index.*;
import org.apache.lucene.store.AlreadyClosedException; import org.apache.lucene.store.AlreadyClosedException;
import org.elasticsearch.common.inject.Inject; import org.elasticsearch.common.inject.Inject;
import org.elasticsearch.common.logging.ESLogger;
import org.elasticsearch.common.settings.Settings; import org.elasticsearch.common.settings.Settings;
import org.elasticsearch.index.merge.MergeStats; import org.elasticsearch.index.merge.MergeStats;
import org.elasticsearch.index.merge.policy.EnableMergePolicy; import org.elasticsearch.index.merge.policy.EnableMergePolicy;
@ -51,7 +52,7 @@ public class ConcurrentMergeSchedulerProvider extends AbstractIndexShardComponen
} }
@Override public MergeScheduler newMergeScheduler() { @Override public MergeScheduler newMergeScheduler() {
CustomConcurrentMergeScheduler concurrentMergeScheduler = new CustomConcurrentMergeScheduler(shardId, this); CustomConcurrentMergeScheduler concurrentMergeScheduler = new CustomConcurrentMergeScheduler(logger, shardId, this);
concurrentMergeScheduler.setMaxThreadCount(maxThreadCount); concurrentMergeScheduler.setMaxThreadCount(maxThreadCount);
schedulers.add(concurrentMergeScheduler); schedulers.add(concurrentMergeScheduler);
return concurrentMergeScheduler; return concurrentMergeScheduler;
@ -71,8 +72,8 @@ public class ConcurrentMergeSchedulerProvider extends AbstractIndexShardComponen
private final ConcurrentMergeSchedulerProvider provider; private final ConcurrentMergeSchedulerProvider provider;
private CustomConcurrentMergeScheduler(ShardId shardId, ConcurrentMergeSchedulerProvider provider) { private CustomConcurrentMergeScheduler(ESLogger logger, ShardId shardId, ConcurrentMergeSchedulerProvider provider) {
super(); super(logger);
this.shardId = shardId; this.shardId = shardId;
this.provider = provider; this.provider = provider;
} }

View File

@ -25,6 +25,7 @@ import org.apache.lucene.index.MergeScheduler;
import org.apache.lucene.index.TrackingSerialMergeScheduler; import org.apache.lucene.index.TrackingSerialMergeScheduler;
import org.apache.lucene.store.AlreadyClosedException; import org.apache.lucene.store.AlreadyClosedException;
import org.elasticsearch.common.inject.Inject; import org.elasticsearch.common.inject.Inject;
import org.elasticsearch.common.logging.ESLogger;
import org.elasticsearch.common.settings.Settings; import org.elasticsearch.common.settings.Settings;
import org.elasticsearch.index.merge.MergeStats; import org.elasticsearch.index.merge.MergeStats;
import org.elasticsearch.index.merge.policy.EnableMergePolicy; import org.elasticsearch.index.merge.policy.EnableMergePolicy;
@ -49,7 +50,7 @@ public class SerialMergeSchedulerProvider extends AbstractIndexShardComponent im
} }
@Override public MergeScheduler newMergeScheduler() { @Override public MergeScheduler newMergeScheduler() {
CustomSerialMergeScheduler scheduler = new CustomSerialMergeScheduler(this); CustomSerialMergeScheduler scheduler = new CustomSerialMergeScheduler(logger, this);
schedulers.add(scheduler); schedulers.add(scheduler);
return scheduler; return scheduler;
} }
@ -66,7 +67,8 @@ public class SerialMergeSchedulerProvider extends AbstractIndexShardComponent im
private final SerialMergeSchedulerProvider provider; private final SerialMergeSchedulerProvider provider;
public CustomSerialMergeScheduler(SerialMergeSchedulerProvider provider) { public CustomSerialMergeScheduler(ESLogger logger, SerialMergeSchedulerProvider provider) {
super(logger);
this.provider = provider; this.provider = provider;
} }