From d6a3fc09f03fec24d86a33e82784b482613dbd27 Mon Sep 17 00:00:00 2001 From: Shay Banon Date: Fri, 13 Sep 2013 22:46:04 +0200 Subject: [PATCH] better logging trace log the low level details on recovery --- bin/plugin | 1 - .../gateway/IndexShardGatewayService.java | 4 ++- .../gateway/none/NoneIndexShardGateway.java | 2 +- .../indices/recovery/RecoveryTarget.java | 29 +++++++++++-------- 4 files changed, 21 insertions(+), 15 deletions(-) diff --git a/bin/plugin b/bin/plugin index 42727f9fc15..1cabad2347b 100644 --- a/bin/plugin +++ b/bin/plugin @@ -28,7 +28,6 @@ else JAVA=`which java` fi -# this is a poor mans getopt replacement # real getopt cannot be used because we need to hand options over to the PluginManager while [ $# -gt 0 ]; do case $1 in diff --git a/src/main/java/org/elasticsearch/index/gateway/IndexShardGatewayService.java b/src/main/java/org/elasticsearch/index/gateway/IndexShardGatewayService.java index 11d93f84a41..e8eaaa00396 100644 --- a/src/main/java/org/elasticsearch/index/gateway/IndexShardGatewayService.java +++ b/src/main/java/org/elasticsearch/index/gateway/IndexShardGatewayService.java @@ -189,6 +189,8 @@ public class IndexShardGatewayService extends AbstractIndexShardComponent implem recoveryStatus.updateStage(RecoveryStatus.Stage.DONE); if (logger.isDebugEnabled()) { + logger.debug("recovery completed from [{}], took [{}]", shardGateway, timeValueMillis(recoveryStatus.time())); + } else if (logger.isTraceEnabled()) { StringBuilder sb = new StringBuilder(); sb.append("recovery completed from ").append(shardGateway).append(", took [").append(timeValueMillis(recoveryStatus.time())).append("]\n"); sb.append(" index : files [").append(recoveryStatus.index().numberOfFiles()).append("] with total_size [").append(new ByteSizeValue(recoveryStatus.index().totalSize())).append("], took[").append(TimeValue.timeValueMillis(recoveryStatus.index().time())).append("]\n"); @@ -196,7 +198,7 @@ public class IndexShardGatewayService extends AbstractIndexShardComponent implem sb.append(" : reusing_files [").append(recoveryStatus.index().numberOfReusedFiles()).append("] with total_size [").append(new ByteSizeValue(recoveryStatus.index().reusedTotalSize())).append("]\n"); sb.append(" start : took [").append(TimeValue.timeValueMillis(recoveryStatus.start().time())).append("], check_index [").append(timeValueMillis(recoveryStatus.start().checkIndexTime())).append("]\n"); sb.append(" translog : number_of_operations [").append(recoveryStatus.translog().currentTranslogOperations()).append("], took [").append(TimeValue.timeValueMillis(recoveryStatus.translog().time())).append("]"); - logger.debug(sb.toString()); + logger.trace(sb.toString()); } listener.onRecoveryDone(); scheduleSnapshotIfNeeded(); diff --git a/src/main/java/org/elasticsearch/index/gateway/none/NoneIndexShardGateway.java b/src/main/java/org/elasticsearch/index/gateway/none/NoneIndexShardGateway.java index f06b4fe341f..1a3e8e01c31 100644 --- a/src/main/java/org/elasticsearch/index/gateway/none/NoneIndexShardGateway.java +++ b/src/main/java/org/elasticsearch/index/gateway/none/NoneIndexShardGateway.java @@ -61,7 +61,7 @@ public class NoneIndexShardGateway extends AbstractIndexShardComponent implement @Override public void recover(boolean indexShouldExists, RecoveryStatus recoveryStatus) throws IndexShardGatewayRecoveryException { - recoveryStatus().index().startTime(System.currentTimeMillis()); + recoveryStatus.index().startTime(System.currentTimeMillis()); // in the none case, we simply start the shard // clean the store, there should be nothing there... try { diff --git a/src/main/java/org/elasticsearch/indices/recovery/RecoveryTarget.java b/src/main/java/org/elasticsearch/indices/recovery/RecoveryTarget.java index 537692c2a7c..3117668ab8c 100644 --- a/src/main/java/org/elasticsearch/indices/recovery/RecoveryTarget.java +++ b/src/main/java/org/elasticsearch/indices/recovery/RecoveryTarget.java @@ -47,8 +47,11 @@ import org.elasticsearch.indices.IndicesService; import org.elasticsearch.threadpool.ThreadPool; import org.elasticsearch.transport.*; -import java.util.*; +import java.util.Collections; +import java.util.Iterator; +import java.util.Map; import java.util.Map.Entry; +import java.util.Set; import static org.elasticsearch.common.unit.TimeValue.timeValueMillis; @@ -145,9 +148,9 @@ public class RecoveryTarget extends AbstractComponent { } } } finally { - removeAndCleanOnGoingRecovery(recoveryStatus); + removeAndCleanOnGoingRecovery(recoveryStatus); } - + } public void startRecovery(final StartRecoveryRequest request, final InternalIndexShard indexShard, final RecoveryListener listener) { @@ -217,6 +220,8 @@ public class RecoveryTarget extends AbstractComponent { } stopWatch.stop(); if (logger.isDebugEnabled()) { + logger.debug("recovery completed from [{}], took [{}]", request.shardId(), request.sourceNode(), stopWatch.totalTime()); + } else if (logger.isTraceEnabled()) { StringBuilder sb = new StringBuilder(); sb.append('[').append(request.shardId().index().name()).append(']').append('[').append(request.shardId().id()).append("] "); sb.append("recovery completed from ").append(request.sourceNode()).append(", took[").append(stopWatch.totalTime()).append("]\n"); @@ -230,7 +235,7 @@ public class RecoveryTarget extends AbstractComponent { .append("\n"); sb.append(" phase3: recovered [").append(recoveryResponse.phase3Operations).append("]").append(" transaction log operations") .append(", took [").append(timeValueMillis(recoveryResponse.phase3Time)).append("]"); - logger.debug(sb.toString()); + logger.trace(sb.toString()); } removeAndCleanOnGoingRecovery(recoveryStatus); listener.onRecoveryDone(); @@ -344,13 +349,13 @@ public class RecoveryTarget extends AbstractComponent { Set> entrySet = status.cancleAndClearOpenIndexInputs(); Iterator> iterator = entrySet.iterator(); while (iterator.hasNext()) { - Map.Entry entry = iterator.next(); + Map.Entry entry = iterator.next(); synchronized (entry.getValue()) { IOUtils.closeWhileHandlingException(entry.getValue()); } iterator.remove(); - - } + + } status.checksums = null; } @@ -640,11 +645,11 @@ public class RecoveryTarget extends AbstractComponent { } success = true; } finally { - if (!success || onGoingRecovery.isCanceled()) { - IndexOutput remove = onGoingRecovery.removeOpenIndexOutputs(request.name()); - assert remove == indexOutput; - IOUtils.closeWhileHandlingException(indexOutput); - } + if (!success || onGoingRecovery.isCanceled()) { + IndexOutput remove = onGoingRecovery.removeOpenIndexOutputs(request.name()); + assert remove == indexOutput; + IOUtils.closeWhileHandlingException(indexOutput); + } } } if (onGoingRecovery.isCanceled()) {