Author: mduerig
Date: Thu Nov 24 17:03:37 2016
New Revision: 1771191
URL: http://svn.apache.org/viewvc?rev=1771191&view=rev
Log:
OAK-5161: Improve logging of compaction cycles
Add more information to compaction cycles and reduce logging for removed files.
Credits to Valentin Oltenau for an initial patch
Modified:
jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/file/FileReaper.java
jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/file/FileStore.java
jackrabbit/oak/trunk/oak-segment-tar/src/test/java/org/apache/jackrabbit/oak/segment/SegmentCompactionIT.java
Modified:
jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/file/FileReaper.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/file/FileReaper.java?rev=1771191&r1=1771190&r2=1771191&view=diff
==============================================================================
---
jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/file/FileReaper.java
(original)
+++
jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/file/FileReaper.java
Thu Nov 24 17:03:37 2016
@@ -17,12 +17,16 @@
package org.apache.jackrabbit.oak.segment.file;
+import static com.google.common.collect.Lists.newArrayList;
+
import java.io.File;
import java.io.IOException;
import java.nio.file.Files;
import java.util.HashSet;
+import java.util.List;
import java.util.Set;
+import com.google.common.base.Joiner;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
@@ -63,16 +67,19 @@ class FileReaper {
}
Set<File> redo = new HashSet<>();
-
+ List<File> removed = newArrayList();
for (File file : reap) {
try {
Files.deleteIfExists(file.toPath());
- logger.info("Removed file {}", file);
+ removed.add(file);
} catch (IOException e) {
logger.warn(String.format("Unable to remove file %s", file),
e);
redo.add(file);
}
}
+ if (!removed.isEmpty()) {
+ logger.info("Removed files {}", Joiner.on(",").join(removed));
+ }
if (redo.isEmpty()) {
return;
Modified:
jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/file/FileStore.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/file/FileStore.java?rev=1771191&r1=1771190&r2=1771191&view=diff
==============================================================================
---
jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/file/FileStore.java
(original)
+++
jackrabbit/oak/trunk/oak-segment-tar/src/main/java/org/apache/jackrabbit/oak/segment/file/FileStore.java
Thu Nov 24 17:03:37 2016
@@ -67,6 +67,7 @@ import javax.annotation.Nonnull;
import javax.annotation.Nullable;
import com.google.common.base.Function;
+import com.google.common.base.Joiner;
import com.google.common.base.Predicate;
import com.google.common.base.Stopwatch;
import com.google.common.base.Supplier;
@@ -819,8 +820,8 @@ public class FileStore extends AbstractF
return -newGeneration;
}
- gcListener.info("TarMK GC #{}: compacted {} to {}",
- GC_COUNT, before.getRecordId(), after.getRecordId());
+ gcListener.info("TarMK GC #{}: compaction cycle 0 completed in
{} ({} ms). Compacted {} to {}",
+ GC_COUNT, watch, watch.elapsed(MILLISECONDS),
before.getRecordId(), after.getRecordId());
int cycles = 0;
boolean success = false;
@@ -834,6 +835,7 @@ public class FileStore extends AbstractF
"Compacting these commits. Cycle {} of {}",
GC_COUNT, cycles, gcOptions.getRetryCount());
gcListener.updateStatus(COMPACTION_RETRY.message() +
cycles);
+ Stopwatch cycleWatch = Stopwatch.createStarted();
SegmentNodeState head = getHead();
after = compact(head, writer, cancel);
@@ -842,8 +844,9 @@ public class FileStore extends AbstractF
return -newGeneration;
}
- gcListener.info("TarMK GC #{}: compacted {} against {} to
{}",
- GC_COUNT, head.getRecordId(),
before.getRecordId(), after.getRecordId());
+ gcListener.info("TarMK GC #{}: compaction cycle {}
completed in {} ({} ms). Compacted {} against {} to {}",
+ GC_COUNT, cycles, cycleWatch,
cycleWatch.elapsed(MILLISECONDS),
+ head.getRecordId(), before.getRecordId(),
after.getRecordId());
before = head;
}
@@ -852,19 +855,27 @@ public class FileStore extends AbstractF
GC_COUNT, cycles);
int forceTimeout = gcOptions.getForceTimeout();
if (forceTimeout > 0) {
- gcListener.info("TarMK GC #{}: trying to force compact
remaining commits for {} seconds",
+ gcListener.info("TarMK GC #{}: trying to force compact
remaining commits for {} seconds. " +
+ "Concurrent commits to the store will be
blocked.",
GC_COUNT, forceTimeout);
gcListener.updateStatus(COMPACTION_FORCE_COMPACT.message());
+ Stopwatch forceWatch = Stopwatch.createStarted();
cycles++;
success = forceCompact(writer, or(cancel,
timeOut(forceTimeout, SECONDS)));
- if (!success) {
+ if (success) {
+ gcListener.info("TarMK GC #{}: compaction
succeeded to force compact remaining commits " +
+ "after {} ({} ms).",
+ GC_COUNT, forceWatch,
forceWatch.elapsed(MILLISECONDS));
+ } else {
if (cancel.get()) {
- gcListener.warn("TarMK GC #{}: compaction
failed to force compact remaining commits. " +
- "Compaction was cancelled: {}.",
GC_COUNT, cancel);
+ gcListener.warn("TarMK GC #{}: compaction
failed to force compact remaining commits " +
+ "after {} ({} ms). Compaction was
cancelled: {}.",
+ GC_COUNT, forceWatch,
forceWatch.elapsed(MILLISECONDS), cancel);
} else {
gcListener.warn("TarMK GC #{}: compaction
failed to force compact remaining commits. " +
- "Most likely compaction didn't get
exclusive access to the store.", GC_COUNT);
+ "after {} ({} ms). Most likely
compaction didn't get exclusive access to the store.",
+ GC_COUNT, forceWatch,
forceWatch.elapsed(MILLISECONDS));
}
}
}
@@ -1085,9 +1096,9 @@ public class FileStore extends AbstractF
for (TarReader oldReader : oldReaders) {
closeAndLogOnFail(oldReader);
File file = oldReader.getFile();
- gcListener.info("TarMK GC #{}: cleanup marking file for
deletion: {}", GC_COUNT, file.getName());
toRemove.addLast(file);
}
+ gcListener.info("TarMK GC #{}: cleanup marking files for deletion:
{}", GC_COUNT, toFileNames(toRemove));
long finalSize = size();
long reclaimedSize = initialSize - afterCleanupSize;
@@ -1102,6 +1113,14 @@ public class FileStore extends AbstractF
return toRemove;
}
+ private String toFileNames(@Nonnull List<File> files) {
+ if (files.isEmpty()) {
+ return "none";
+ } else {
+ return Joiner.on(",").join(files);
+ }
+ }
+
private void collectBulkReferences(Set<UUID> bulkRefs) {
Set<UUID> refs = newHashSet();
for (SegmentId id : tracker.getReferencedSegmentIds()) {
Modified:
jackrabbit/oak/trunk/oak-segment-tar/src/test/java/org/apache/jackrabbit/oak/segment/SegmentCompactionIT.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-segment-tar/src/test/java/org/apache/jackrabbit/oak/segment/SegmentCompactionIT.java?rev=1771191&r1=1771190&r2=1771191&view=diff
==============================================================================
---
jackrabbit/oak/trunk/oak-segment-tar/src/test/java/org/apache/jackrabbit/oak/segment/SegmentCompactionIT.java
(original)
+++
jackrabbit/oak/trunk/oak-segment-tar/src/test/java/org/apache/jackrabbit/oak/segment/SegmentCompactionIT.java
Thu Nov 24 17:03:37 2016
@@ -155,7 +155,7 @@ public class SegmentCompactionIT {
private volatile int nodeAddRatio = 40;
private volatile int addStringRatio = 20;
private volatile int addBinaryRatio = 0;
- private volatile int compactionInterval = 60;
+ private volatile int compactionInterval = 2;
private volatile boolean stopping;
private volatile Reference rootReference;
private volatile long fileStoreSize;
