This is an automated email from the ASF dual-hosted git repository. daim pushed a commit to branch DetailedGC/OAK-10199 in repository https://gitbox.apache.org/repos/asf/jackrabbit-oak.git
commit c3b6a735e94ad799d7772d71c0d4e5ebbb4cae05 Author: Rishabh Kumar <[email protected]> AuthorDate: Fri Sep 1 13:37:25 2023 +0530 Merge pull request #1079 from apache/OAK-10378 OAK-10378 : added metrics to collect detailedGC cycle & deleted properties data --- .../document/DetailedRevisionGCStatsCollector.java | 40 ++++++ .../DetailedRevisionGCStatsCollectorImpl.java | 146 +++++++++++++++++++ .../oak/plugins/document/DocumentStore.java | 2 +- .../plugins/document/VersionGarbageCollector.java | 62 ++++++-- .../document/util/LoggingDocumentStoreWrapper.java | 1 + .../DetailedRevisionGCStatsCollectorImplTest.java | 160 +++++++++++++++++++++ .../oak/plugins/document/VersionGCStatsTest.java | 22 ++- .../document/VersionGarbageCollectorIT.java | 63 +++++++- 8 files changed, 465 insertions(+), 31 deletions(-) diff --git a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DetailedRevisionGCStatsCollector.java b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DetailedRevisionGCStatsCollector.java new file mode 100644 index 0000000000..151195f3bd --- /dev/null +++ b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DetailedRevisionGCStatsCollector.java @@ -0,0 +1,40 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF 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.apache.jackrabbit.oak.plugins.document; + +import org.apache.jackrabbit.oak.plugins.document.VersionGarbageCollector.VersionGCStats; + +/** + * Collector interface for {@link DocumentNodeStore} Detailed revision garbage collection + * statistics. + */ +public interface DetailedRevisionGCStatsCollector { + + void documentRead(); + + void propertiesDeleted(long numProps); + + void documentsUpdated(long numDocs); + + void documentsSkippedUpdation(long numDocs); + + void started(); + + void finished(VersionGCStats stats); +} diff --git a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DetailedRevisionGCStatsCollectorImpl.java b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DetailedRevisionGCStatsCollectorImpl.java new file mode 100644 index 0000000000..b400f7401b --- /dev/null +++ b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DetailedRevisionGCStatsCollectorImpl.java @@ -0,0 +1,146 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF 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.apache.jackrabbit.oak.plugins.document; + +import org.apache.jackrabbit.oak.plugins.document.VersionGarbageCollector.VersionGCStats; +import org.apache.jackrabbit.oak.stats.CounterStats; +import org.apache.jackrabbit.oak.stats.MeterStats; +import org.apache.jackrabbit.oak.stats.StatisticsProvider; +import org.apache.jackrabbit.oak.stats.TimerStats; + +import static java.util.concurrent.TimeUnit.MICROSECONDS; +import static org.apache.jackrabbit.oak.stats.StatsOptions.DEFAULT; +import static org.apache.jackrabbit.oak.stats.StatsOptions.METRICS_ONLY; + +/** + * {@link DocumentNodeStore} Detailed revision garbage collection statistics. + */ +class DetailedRevisionGCStatsCollectorImpl implements DetailedRevisionGCStatsCollector { + + static final String DETAILED_GC = "DetailedGC"; + static final String READ_DOC = "READ_DOC"; + static final String DELETED_PROPERTY = "DELETED_PROPERTY"; + static final String UPDATED_DOC = "UPDATED_DOC"; + static final String SKIPPED_DOC = "SKIPPED_DOC"; + static final String DETAILED_GC_ACTIVE_TIMER = "DETAILED_GC_ACTIVE_TIMER"; + static final String DETAILED_GC_TIMER = "DETAILED_GC_TIMER"; + static final String COLLECT_DETAILED_GARBAGE_TIMER = "COLLECT_DETAILED_GARBAGE_TIMER"; + static final String COLLECT_DELETED_PROPS_TIMER = "COLLECT_DELETED_PROPS_TIMER"; + static final String COLLECT_DELETED_OLD_REVS_TIMER = "COLLECT_DELETED_OLD_REVS_TIMER"; + static final String COLLECT_UNMERGED_BC_TIMER = "COLLECT_UNMERGED_BC_TIMER"; + static final String DELETE_DETAILED_GC_DOCS_TIMER = "DELETE_DETAILED_GC_DOCS_TIMER"; + + static final String COUNTER = "COUNTER"; + static final String FAILURE_COUNTER = "FAILURE"; + + private final MeterStats readDoc; + private final MeterStats deletedProperty; + private final MeterStats updatedDoc; + private final MeterStats skippedDoc; + private final TimerStats detailedGCActiveTimer; + private final TimerStats detailedGCTimer; + private final TimerStats collectDetailedGarbageTimer; + private final TimerStats collectDeletedPropsTimer; + private final TimerStats collectDeletedOldRevsTimer; + private final TimerStats collectUnmergedBCTimer; + private final TimerStats deleteDetailedGCDocsTimer; + + private final CounterStats counter; + private final CounterStats failureCounter; + + DetailedRevisionGCStatsCollectorImpl(StatisticsProvider provider) { + + readDoc = meter(provider, READ_DOC); + deletedProperty = meter(provider, DELETED_PROPERTY); + updatedDoc = meter(provider, UPDATED_DOC); + skippedDoc = meter(provider, SKIPPED_DOC); + + detailedGCActiveTimer = timer(provider, DETAILED_GC_ACTIVE_TIMER); + detailedGCTimer = timer(provider, DETAILED_GC_TIMER); + collectDetailedGarbageTimer = timer(provider, COLLECT_DETAILED_GARBAGE_TIMER); + collectDeletedPropsTimer = timer(provider, COLLECT_DELETED_PROPS_TIMER); + collectDeletedOldRevsTimer = timer(provider, COLLECT_DELETED_OLD_REVS_TIMER); + collectUnmergedBCTimer = timer(provider, COLLECT_UNMERGED_BC_TIMER); + deleteDetailedGCDocsTimer = timer(provider, DELETE_DETAILED_GC_DOCS_TIMER); + + counter = counter(provider, COUNTER); + failureCounter = counter(provider, FAILURE_COUNTER); + } + + //---------------------< DetailedRevisionGCStatsCollector >------------------------- + + @Override + public void documentRead() { + readDoc.mark(); + } + + @Override + public void propertiesDeleted(long numProps) { + deletedProperty.mark(numProps); + } + + @Override + public void documentsUpdated(long numDocs) { + updatedDoc.mark(numDocs); + } + + @Override + public void documentsSkippedUpdation(long numDocs) { + skippedDoc.mark(numDocs); + } + + @Override + public void started() { + counter.inc(); + } + + @Override + public void finished(VersionGCStats stats) { + detailedGCActiveTimer.update(stats.detailedGCActiveElapsed, MICROSECONDS); + detailedGCTimer.update(stats.detailedGCDocsElapsed, MICROSECONDS); + collectDetailedGarbageTimer.update(stats.collectDetailedGarbageElapsed, MICROSECONDS); + collectDeletedPropsTimer.update(stats.collectDeletedPropsElapsed, MICROSECONDS); + collectDeletedOldRevsTimer.update(stats.collectDeletedOldRevsElapsed, MICROSECONDS); + collectUnmergedBCTimer.update(stats.collectUnmergedBCElapsed, MICROSECONDS); + deleteDetailedGCDocsTimer.update(stats.deleteDetailedGCDocsElapsed, MICROSECONDS); + if (!stats.success) { + failureCounter.inc(); + } + } + + + //----------------------------< internal >---------------------------------- + + private static MeterStats meter(StatisticsProvider provider, String name) { + return provider.getMeter(qualifiedName(name), DEFAULT); + } + + private static TimerStats timer(StatisticsProvider provider, String name) { + return provider.getTimer(qualifiedName(name), METRICS_ONLY); + } + + private static CounterStats counter(StatisticsProvider provider, String name) { + return provider.getCounterStats(qualifiedName(name), METRICS_ONLY); + } + + private static String qualifiedName(String metricName) { + return DETAILED_GC + "." + metricName; + } + +} diff --git a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentStore.java b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentStore.java index 28e6b22b1a..8b73a57714 100644 --- a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentStore.java +++ b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentStore.java @@ -546,7 +546,7 @@ public interface DocumentStore { /** * Performs a conditional update (e.g. using * {@link UpdateOp.Condition.Type#EXISTS} and only update the - * document if the condition is <code>true</code>. The returned documents are + * document(s) if the respective condition is <code>true</code>. The returned documents are * immutable. * <p> * In case of a {@code DocumentStoreException} (e.g. when a communication diff --git a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/VersionGarbageCollector.java b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/VersionGarbageCollector.java index a32ded6c5b..d20f5683bc 100644 --- a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/VersionGarbageCollector.java +++ b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/VersionGarbageCollector.java @@ -78,6 +78,7 @@ import static org.apache.jackrabbit.oak.plugins.document.NodeDocument.MODIFIED_I import static org.apache.jackrabbit.oak.plugins.document.NodeDocument.SplitDocType.COMMIT_ROOT_ONLY; import static org.apache.jackrabbit.oak.plugins.document.NodeDocument.SplitDocType.DEFAULT_LEAF; import static org.apache.jackrabbit.oak.plugins.document.NodeDocument.SplitDocType.DEFAULT_NO_BRANCH; +import static org.apache.jackrabbit.oak.stats.StatisticsProvider.NOOP; import static org.slf4j.helpers.MessageFormatter.arrayFormat; public class VersionGarbageCollector { @@ -129,7 +130,8 @@ public class VersionGarbageCollector { private final AtomicReference<GCJob> collector = newReference(); private VersionGCOptions options; private GCMonitor gcMonitor = GCMonitor.EMPTY; - private RevisionGCStats gcStats = new RevisionGCStats(StatisticsProvider.NOOP); + private RevisionGCStats gcStats = new RevisionGCStats(NOOP); + private DetailedRevisionGCStatsCollector detailedGCStats = new DetailedRevisionGCStatsCollectorImpl(NOOP); VersionGarbageCollector(DocumentNodeStore nodeStore, VersionGCSupport gcSupport, @@ -143,6 +145,7 @@ public class VersionGarbageCollector { void setStatisticsProvider(StatisticsProvider provider) { this.gcStats = new RevisionGCStats(provider); + this.detailedGCStats = new DetailedRevisionGCStatsCollectorImpl(provider); } @NotNull @@ -161,6 +164,9 @@ public class VersionGarbageCollector { VersionGCStats overall = new VersionGCStats(); overall.active.start(); gcStats.started(); + if (detailedGCEnabled) { + detailedGCStats.started(); + } boolean success = false; try { long averageDurationMs = 0; @@ -186,6 +192,9 @@ public class VersionGarbageCollector { collector.set(null); overall.success = success; gcStats.finished(overall); + if (detailedGCEnabled) { + detailedGCStats.finished(overall); + } if (overall.iterationCount > 1) { gcMonitor.info("Revision garbage collection finished after {} iterations - aggregate statistics: {}", overall.iterationCount, overall); @@ -289,6 +298,7 @@ public class VersionGarbageCollector { int deletedPropsGCCount; final TimeDurationFormatter df = TimeDurationFormatter.forLogging(); final Stopwatch active = Stopwatch.createUnstarted(); + final Stopwatch detailedGCActive = Stopwatch.createUnstarted(); final Stopwatch collectDeletedDocs = Stopwatch.createUnstarted(); final Stopwatch checkDeletedDocs = Stopwatch.createUnstarted(); final Stopwatch detailedGCDocs = Stopwatch.createUnstarted(); @@ -298,12 +308,14 @@ public class VersionGarbageCollector { final Stopwatch updateResurrectedDocuments = Stopwatch.createUnstarted(); final Stopwatch deleteDeletedDocs = Stopwatch.createUnstarted(); final Stopwatch collectAndDeleteSplitDocs = Stopwatch.createUnstarted(); + final Stopwatch collectDetailedGarbage = Stopwatch.createUnstarted(); final Stopwatch collectDeletedProps = Stopwatch.createUnstarted(); final Stopwatch collectDeletedOldRevs = Stopwatch.createUnstarted(); final Stopwatch collectUnmergedBC = Stopwatch.createUnstarted(); - long activeElapsed, collectDeletedDocsElapsed, checkDeletedDocsElapsed, deleteDeletedDocsElapsed, collectAndDeleteSplitDocsElapsed, - deleteSplitDocsElapsed, sortDocIdsElapsed, updateResurrectedDocumentsElapsed, detailedGCDocsElapsed, collectDeletedPropsElapsed, - deleteDetailedGCDocsElapsed, collectDeletedOldRevsElapsed, collectUnmergedBCElapsed; + long activeElapsed, detailedGCActiveElapsed, collectDeletedDocsElapsed, checkDeletedDocsElapsed, deleteDeletedDocsElapsed, + collectAndDeleteSplitDocsElapsed, deleteSplitDocsElapsed, sortDocIdsElapsed, updateResurrectedDocumentsElapsed, + detailedGCDocsElapsed, collectDetailedGarbageElapsed, collectDeletedPropsElapsed, deleteDetailedGCDocsElapsed, + collectDeletedOldRevsElapsed, collectUnmergedBCElapsed; @Override public String toString() { @@ -342,6 +354,7 @@ public class VersionGarbageCollector { df.format(collectAndDeleteSplitDocs.elapsed(MICROSECONDS), MICROSECONDS), df.format(detailedGCDocs.elapsed(MICROSECONDS), MICROSECONDS), df.format(deleteDetailedGCDocs.elapsed(MICROSECONDS), MICROSECONDS), + df.format(collectDetailedGarbage.elapsed(MICROSECONDS), MICROSECONDS), df.format(collectDeletedProps.elapsed(MICROSECONDS), MICROSECONDS), df.format(collectDeletedOldRevs.elapsed(MICROSECONDS), MICROSECONDS), df.format(collectUnmergedBC.elapsed(MICROSECONDS), MICROSECONDS), @@ -361,6 +374,7 @@ public class VersionGarbageCollector { ", updatedDetailedGCDocsCount=" + updatedDetailedGCDocsCount + ", deletedPropsGCCount=" + deletedPropsGCCount + ", iterationCount=" + iterationCount + + ", timeDetailedGCActive=" + df.format(detailedGCActiveElapsed, MICROSECONDS) + ", timeActive=" + df.format(activeElapsed, MICROSECONDS) + ", " + timings + "}"; } @@ -385,6 +399,7 @@ public class VersionGarbageCollector { if (run.iterationCount > 0) { // run is cumulative with times in elapsed fields this.activeElapsed += run.activeElapsed; + this.detailedGCActiveElapsed += run.detailedGCActiveElapsed; this.collectDeletedDocsElapsed += run.collectDeletedDocsElapsed; this.checkDeletedDocsElapsed += run.checkDeletedDocsElapsed; this.deleteDeletedDocsElapsed += run.deleteDeletedDocsElapsed; @@ -394,12 +409,14 @@ public class VersionGarbageCollector { this.updateResurrectedDocumentsElapsed += run.updateResurrectedDocumentsElapsed; this.detailedGCDocsElapsed += run.detailedGCDocsElapsed; this.deleteDetailedGCDocsElapsed += run.deleteDetailedGCDocsElapsed; + this.collectDetailedGarbageElapsed += run.collectDetailedGarbageElapsed; this.collectDeletedPropsElapsed += run.collectDeletedPropsElapsed; this.collectDeletedOldRevsElapsed += run.collectDeletedOldRevsElapsed; this.collectUnmergedBCElapsed += run.collectUnmergedBCElapsed; } else { // single run -> read from stop watches this.activeElapsed += run.active.elapsed(MICROSECONDS); + this.detailedGCActiveElapsed += run.detailedGCActive.elapsed(MICROSECONDS); this.collectDeletedDocsElapsed += run.collectDeletedDocs.elapsed(MICROSECONDS); this.checkDeletedDocsElapsed += run.checkDeletedDocs.elapsed(MICROSECONDS); this.deleteDeletedDocsElapsed += run.deleteDeletedDocs.elapsed(MICROSECONDS); @@ -409,6 +426,7 @@ public class VersionGarbageCollector { this.updateResurrectedDocumentsElapsed += run.updateResurrectedDocuments.elapsed(MICROSECONDS); this.detailedGCDocsElapsed += run.detailedGCDocs.elapsed(MICROSECONDS); this.deleteDetailedGCDocsElapsed += run.deleteDetailedGCDocs.elapsed(MICROSECONDS); + this.collectDetailedGarbageElapsed += run.collectDetailedGarbage.elapsed(MICROSECONDS); this.collectDeletedPropsElapsed += run.collectDeletedProps.elapsed(MICROSECONDS); this.collectDeletedOldRevsElapsed += run.collectDeletedOldRevs.elapsed(MICROSECONDS); this.collectUnmergedBCElapsed += run.collectUnmergedBC.elapsed(MICROSECONDS); @@ -424,6 +442,7 @@ public class VersionGarbageCollector { SORTING, SPLITS_CLEANUP, DETAILED_GC, + DETAILED_GC_COLLECT_GARBAGE, DETAILED_GC_COLLECT_PROPS, DETAILED_GC_COLLECT_OLD_REVS, DETAILED_GC_COLLECT_UNMERGED_BC, @@ -457,6 +476,7 @@ public class VersionGarbageCollector { this.watches.put(GCPhase.SPLITS_CLEANUP, stats.collectAndDeleteSplitDocs); this.watches.put(GCPhase.UPDATING, stats.updateResurrectedDocuments); this.watches.put(GCPhase.DETAILED_GC, stats.detailedGCDocs); + this.watches.put(GCPhase.DETAILED_GC_COLLECT_GARBAGE, stats.collectDetailedGarbage); this.watches.put(GCPhase.DETAILED_GC_COLLECT_PROPS, stats.collectDeletedProps); this.watches.put(GCPhase.DETAILED_GC_COLLECT_OLD_REVS, stats.collectDeletedOldRevs); this.watches.put(GCPhase.DETAILED_GC_COLLECT_UNMERGED_BC, stats.collectUnmergedBC); @@ -586,6 +606,7 @@ public class VersionGarbageCollector { // now run detailed GC if enabled if (detailedGCEnabled) { + stats.detailedGCActive.start(); if (rec.ignoreDetailedGCDueToCheckPoint) { phases.stats.ignoredDetailedGCDueToCheckPoint = true; monitor.skipped("Checkpoint prevented detailed revision garbage collection"); @@ -610,6 +631,9 @@ public class VersionGarbageCollector { rec.evaluate(stats); monitor.info("Revision garbage collection finished in {}. {}", TimeDurationFormatter.forLogging().format(phases.elapsed.elapsed(MICROSECONDS), MICROSECONDS), stats); + if (detailedGCEnabled) { + stats.detailedGCActive.stop(); + } stats.active.stop(); return stats; } @@ -670,9 +694,9 @@ public class VersionGarbageCollector { lastDoc = doc; // collect the data to delete in next step - if (phases.start(GCPhase.COLLECTING)) { + if (phases.start(GCPhase.DETAILED_GC_COLLECT_GARBAGE)) { gc.collectGarbage(doc, phases); - phases.stop(GCPhase.COLLECTING); + phases.stop(GCPhase.DETAILED_GC_COLLECT_GARBAGE); } final Long modified = lastDoc.getModified(); @@ -697,15 +721,7 @@ public class VersionGarbageCollector { } finally { Utils.closeIfCloseable(itr); phases.stats.oldestModifiedDocTimeStamp = fromModifiedMs; - if (fromModifiedMs > oldModifiedMs) { - // we have moved ahead, now we can reset oldestModifiedId to min value - fromId = MIN_ID_VALUE; - phases.stats.oldestModifiedDocId = MIN_ID_VALUE; - } else { - // there are still documents pending at oldest Modified timestamp, - // save the last _id traversed to avoid re-fetching of ids - phases.stats.oldestModifiedDocId = fromId; - } + phases.stats.oldestModifiedDocId = fromId; oldModifiedMs = fromModifiedMs; } // if we didn't find any document i.e. either we are already at last document @@ -826,6 +842,16 @@ public class VersionGarbageCollector { private final Stopwatch timer; private final List<UpdateOp> updateOpList; + /** + * Map of documentId => total no. of deleted properties. + * <p> + * + * The document can be updated or property might get recreated between collecting and deletion phases. + * This would lead to document not getting deleted (since now modified date & mod count would have changed) + * SO the Bulk API wouldn't update this doc. + * <p> + * In order to calculate the correct no. of updated documents & deleted properties, we save them in a map + */ private final Map<String, Integer> deletedPropsCountMap; private int garbageDocsCount; private int totalGarbageDocsCount; @@ -841,6 +867,7 @@ public class VersionGarbageCollector { public void collectGarbage(final NodeDocument doc, final GCPhases phases) { + detailedGCStats.documentRead(); monitor.info("Collecting Detailed Garbage for doc [{}]", doc.getId()); final UpdateOp op = new UpdateOp(requireNonNull(doc.getId()), false); @@ -955,6 +982,11 @@ public class VersionGarbageCollector { updateOpList.clear(); deletedPropsCountMap.clear(); garbageDocsCount = 0; + + // save stats + detailedGCStats.propertiesDeleted(deletedProps); + detailedGCStats.documentsUpdated(updatedDocs); + detailedGCStats.documentsSkippedUpdation(oldDocs.size() - updatedDocs); } finally { delayOnModifications(timer.stop().elapsed(MILLISECONDS), cancel); } diff --git a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/util/LoggingDocumentStoreWrapper.java b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/util/LoggingDocumentStoreWrapper.java index 099eca91de..7cde39cffc 100644 --- a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/util/LoggingDocumentStoreWrapper.java +++ b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/util/LoggingDocumentStoreWrapper.java @@ -283,6 +283,7 @@ public class LoggingDocumentStoreWrapper implements DocumentStore { } @Override + @NotNull public <T extends Document> List<T> findAndUpdate(@NotNull Collection<T> collection, @NotNull List<UpdateOp> updateOps) { try { logMethod("findAndUpdate", collection, updateOps); diff --git a/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/DetailedRevisionGCStatsCollectorImplTest.java b/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/DetailedRevisionGCStatsCollectorImplTest.java new file mode 100644 index 0000000000..b84084d439 --- /dev/null +++ b/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/DetailedRevisionGCStatsCollectorImplTest.java @@ -0,0 +1,160 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF 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.apache.jackrabbit.oak.plugins.document; + +import com.codahale.metrics.Counter; +import com.codahale.metrics.Meter; +import com.codahale.metrics.Timer; +import org.apache.jackrabbit.oak.commons.concurrent.ExecutorCloser; +import org.apache.jackrabbit.oak.plugins.metric.MetricStatisticsProvider; +import org.apache.jackrabbit.oak.stats.MeterStats; +import org.junit.After; +import org.junit.Test; + +import java.util.concurrent.ScheduledExecutorService; + +import static java.lang.management.ManagementFactory.getPlatformMBeanServer; +import static java.util.concurrent.Executors.newSingleThreadScheduledExecutor; +import static java.util.concurrent.TimeUnit.MILLISECONDS; +import static java.util.concurrent.TimeUnit.NANOSECONDS; +import static org.apache.commons.lang3.reflect.FieldUtils.readField; +import static org.apache.jackrabbit.oak.plugins.document.DetailedRevisionGCStatsCollectorImpl.COLLECT_DELETED_OLD_REVS_TIMER; +import static org.apache.jackrabbit.oak.plugins.document.DetailedRevisionGCStatsCollectorImpl.COLLECT_DELETED_PROPS_TIMER; +import static org.apache.jackrabbit.oak.plugins.document.DetailedRevisionGCStatsCollectorImpl.COLLECT_DETAILED_GARBAGE_TIMER; +import static org.apache.jackrabbit.oak.plugins.document.DetailedRevisionGCStatsCollectorImpl.COLLECT_UNMERGED_BC_TIMER; +import static org.apache.jackrabbit.oak.plugins.document.DetailedRevisionGCStatsCollectorImpl.COUNTER; +import static org.apache.jackrabbit.oak.plugins.document.DetailedRevisionGCStatsCollectorImpl.DELETED_PROPERTY; +import static org.apache.jackrabbit.oak.plugins.document.DetailedRevisionGCStatsCollectorImpl.DELETE_DETAILED_GC_DOCS_TIMER; +import static org.apache.jackrabbit.oak.plugins.document.DetailedRevisionGCStatsCollectorImpl.DETAILED_GC; +import static org.apache.jackrabbit.oak.plugins.document.DetailedRevisionGCStatsCollectorImpl.DETAILED_GC_ACTIVE_TIMER; +import static org.apache.jackrabbit.oak.plugins.document.DetailedRevisionGCStatsCollectorImpl.DETAILED_GC_TIMER; +import static org.apache.jackrabbit.oak.plugins.document.DetailedRevisionGCStatsCollectorImpl.FAILURE_COUNTER; +import static org.apache.jackrabbit.oak.plugins.document.DetailedRevisionGCStatsCollectorImpl.READ_DOC; +import static org.apache.jackrabbit.oak.plugins.document.DetailedRevisionGCStatsCollectorImpl.SKIPPED_DOC; +import static org.apache.jackrabbit.oak.plugins.document.DetailedRevisionGCStatsCollectorImpl.UPDATED_DOC; +import static org.junit.Assert.assertEquals; + +/** + * Unit Cases for {@link DetailedRevisionGCStatsCollectorImpl} + */ +public class DetailedRevisionGCStatsCollectorImplTest { + + private final ScheduledExecutorService executor = newSingleThreadScheduledExecutor(); + private final MetricStatisticsProvider statsProvider = new MetricStatisticsProvider(getPlatformMBeanServer(), executor); + private final DetailedRevisionGCStatsCollectorImpl stats = new DetailedRevisionGCStatsCollectorImpl(statsProvider); + + @After + public void shutDown(){ + statsProvider.close(); + new ExecutorCloser(executor).close(); + } + + @Test + public void getReadDocCount() throws IllegalAccessException { + final Meter m = getMeter(READ_DOC); + long count = m.getCount(); + stats.documentRead(); + assertEquals(count + 1, m.getCount()); + assertEquals(count + 1, ((MeterStats) readField(stats, "readDoc", true)).getCount()); + } + + @Test + public void getDocumentsSkippedUpdationCount() throws IllegalAccessException { + Meter m = getMeter(SKIPPED_DOC); + long count = m.getCount(); + stats.documentsSkippedUpdation(17); + assertEquals(count + 17, m.getCount()); + assertEquals(count + 17, ((MeterStats) readField(stats, "skippedDoc", true)).getCount()); + } + + @Test + public void getPropertiesDeletedCount() throws IllegalAccessException { + Meter m = getMeter(DELETED_PROPERTY); + long count = m.getCount(); + stats.propertiesDeleted(10); + assertEquals(count + 10, m.getCount()); + assertEquals(count + 10, ((MeterStats) readField(stats, "deletedProperty", true)).getCount()); + } + + @Test + public void getDocumentsUpdatedCount() throws IllegalAccessException { + Meter m = getMeter(UPDATED_DOC); + long count = m.getCount(); + stats.documentsUpdated(10); + assertEquals(count + 10, m.getCount()); + assertEquals(count + 10, ((MeterStats) readField(stats, "updatedDoc", true)).getCount()); + } + + @Test + public void timers() { + final VersionGarbageCollector.VersionGCStats vgcs = new VersionGarbageCollector.VersionGCStats(); + vgcs.detailedGCActiveElapsed = MILLISECONDS.toMicros(2); + vgcs.detailedGCDocsElapsed = MILLISECONDS.toMicros(3); + vgcs.collectDetailedGarbageElapsed = MILLISECONDS.toMicros(5); + vgcs.collectDeletedPropsElapsed = MILLISECONDS.toMicros(7); + vgcs.collectDeletedOldRevsElapsed = MILLISECONDS.toMicros(11); + vgcs.collectUnmergedBCElapsed = MILLISECONDS.toMicros(13); + vgcs.deleteDetailedGCDocsElapsed = MILLISECONDS.toMicros(15); + vgcs.detailedGCActive.start(); + + stats.finished(vgcs); + assertTimer(2, DETAILED_GC_ACTIVE_TIMER); + assertTimer(3, DETAILED_GC_TIMER); + assertTimer(5, COLLECT_DETAILED_GARBAGE_TIMER); + assertTimer(7, COLLECT_DELETED_PROPS_TIMER); + assertTimer(11, COLLECT_DELETED_OLD_REVS_TIMER); + assertTimer(13, COLLECT_UNMERGED_BC_TIMER); + assertTimer(15, DELETE_DETAILED_GC_DOCS_TIMER); + } + + @Test + public void counters() { + Counter counter = getCounter(COUNTER); + Counter failureCounter = getCounter(FAILURE_COUNTER); + + VersionGarbageCollector.VersionGCStats vgcs = new VersionGarbageCollector.VersionGCStats(); + stats.started(); + stats.finished(vgcs); + assertEquals(1, counter.getCount()); + assertEquals(0, failureCounter.getCount()); + + vgcs.success = false; + stats.started(); + stats.finished(vgcs); + assertEquals(2, counter.getCount()); + assertEquals(1, failureCounter.getCount()); + } + + private void assertTimer(long expected, String name) { + assertEquals(expected, NANOSECONDS.toMillis(getTimer(name).getSnapshot().getMax())); + } + + private Timer getTimer(String name) { + return statsProvider.getRegistry().getTimers().get(DETAILED_GC + "." + name); + } + + private Meter getMeter(String name) { + return statsProvider.getRegistry().getMeters().get(DETAILED_GC + "." + name); + } + + private Counter getCounter(String name) { + return statsProvider.getRegistry().getCounters().get(DETAILED_GC + "." + name); + } + +} diff --git a/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/VersionGCStatsTest.java b/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/VersionGCStatsTest.java index 1515ea9312..a1e889fe18 100644 --- a/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/VersionGCStatsTest.java +++ b/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/VersionGCStatsTest.java @@ -31,21 +31,11 @@ import static org.junit.Assert.assertEquals; public class VersionGCStatsTest { - private static final Callable START = new Callable() { - @Override - public void call(Stopwatch watch) { - watch.start(); - } - }; + private static final Callable START = Stopwatch::start; - private static final Callable STOP = new Callable() { - @Override - public void call(Stopwatch watch) { - watch.stop(); - } - }; + private static final Callable STOP = Stopwatch::stop; - private VersionGCStats stats = new VersionGCStats(); + private final VersionGCStats stats = new VersionGCStats(); @Before public void before() throws Exception { @@ -61,6 +51,7 @@ public class VersionGCStatsTest { VersionGCStats cumulative = new VersionGCStats(); cumulative.addRun(stats); assertEquals(stats.active.elapsed(MICROSECONDS), cumulative.activeElapsed); + assertEquals(stats.detailedGCActive.elapsed(MICROSECONDS), cumulative.detailedGCActiveElapsed); assertEquals(stats.collectDeletedDocs.elapsed(MICROSECONDS), cumulative.collectDeletedDocsElapsed); assertEquals(stats.checkDeletedDocs.elapsed(MICROSECONDS), cumulative.checkDeletedDocsElapsed); assertEquals(stats.deleteDeletedDocs.elapsed(MICROSECONDS), cumulative.deleteDeletedDocsElapsed); @@ -69,6 +60,7 @@ public class VersionGCStatsTest { assertEquals(stats.updateResurrectedDocuments.elapsed(MICROSECONDS), cumulative.updateResurrectedDocumentsElapsed); assertEquals(stats.detailedGCDocs.elapsed(MICROSECONDS), cumulative.detailedGCDocsElapsed); assertEquals(stats.deleteDetailedGCDocs.elapsed(MICROSECONDS), cumulative.deleteDetailedGCDocsElapsed); + assertEquals(stats.collectDetailedGarbage.elapsed(MICROSECONDS), cumulative.collectDetailedGarbageElapsed); assertEquals(stats.collectDeletedProps.elapsed(MICROSECONDS), cumulative.collectDeletedPropsElapsed); assertEquals(stats.collectDeletedOldRevs.elapsed(MICROSECONDS), cumulative.collectDeletedOldRevsElapsed); assertEquals(stats.collectUnmergedBC.elapsed(MICROSECONDS), cumulative.collectUnmergedBCElapsed); @@ -82,6 +74,7 @@ public class VersionGCStatsTest { cumulative.addRun(cumulative); // now the stats must have doubled assertEquals(stats.active.elapsed(MICROSECONDS) * 2, cumulative.activeElapsed); + assertEquals(stats.detailedGCActive.elapsed(MICROSECONDS) * 2, cumulative.detailedGCActiveElapsed); assertEquals(stats.collectDeletedDocs.elapsed(MICROSECONDS) * 2, cumulative.collectDeletedDocsElapsed); assertEquals(stats.checkDeletedDocs.elapsed(MICROSECONDS) * 2, cumulative.checkDeletedDocsElapsed); assertEquals(stats.deleteDeletedDocs.elapsed(MICROSECONDS) * 2, cumulative.deleteDeletedDocsElapsed); @@ -90,6 +83,7 @@ public class VersionGCStatsTest { assertEquals(stats.updateResurrectedDocuments.elapsed(MICROSECONDS) * 2, cumulative.updateResurrectedDocumentsElapsed); assertEquals(stats.detailedGCDocs.elapsed(MICROSECONDS) * 2, cumulative.detailedGCDocsElapsed); assertEquals(stats.deleteDetailedGCDocs.elapsed(MICROSECONDS) * 2, cumulative.deleteDetailedGCDocsElapsed); + assertEquals(stats.collectDetailedGarbage.elapsed(MICROSECONDS) * 2, cumulative.collectDetailedGarbageElapsed); assertEquals(stats.collectDeletedProps.elapsed(MICROSECONDS) * 2, cumulative.collectDeletedPropsElapsed); assertEquals(stats.collectDeletedOldRevs.elapsed(MICROSECONDS) * 2, cumulative.collectDeletedOldRevsElapsed); assertEquals(stats.collectUnmergedBC.elapsed(MICROSECONDS) * 2, cumulative.collectUnmergedBCElapsed); @@ -97,6 +91,7 @@ public class VersionGCStatsTest { private void forEachStopwatch(VersionGCStats stats, Callable c) { c.call(stats.active); + c.call(stats.detailedGCActive); c.call(stats.collectDeletedDocs); c.call(stats.checkDeletedDocs); c.call(stats.deleteDeletedDocs); @@ -105,6 +100,7 @@ public class VersionGCStatsTest { c.call(stats.updateResurrectedDocuments); c.call(stats.detailedGCDocs); c.call(stats.deleteDetailedGCDocs); + c.call(stats.collectDetailedGarbage); c.call(stats.collectDeletedProps); c.call(stats.collectDeletedOldRevs); c.call(stats.collectUnmergedBC); diff --git a/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/VersionGarbageCollectorIT.java b/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/VersionGarbageCollectorIT.java index 195a37d433..5f7335d73a 100644 --- a/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/VersionGarbageCollectorIT.java +++ b/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/VersionGarbageCollectorIT.java @@ -40,6 +40,7 @@ import static java.util.concurrent.TimeUnit.MILLISECONDS; import static java.util.stream.Collectors.toList; import static java.util.stream.StreamSupport.stream; import static org.apache.commons.lang3.reflect.FieldUtils.writeField; +import static org.apache.jackrabbit.guava.common.base.Strings.repeat; import static org.apache.jackrabbit.guava.common.collect.Iterables.filter; import static org.apache.jackrabbit.guava.common.collect.Iterables.size; import static java.util.concurrent.TimeUnit.HOURS; @@ -61,6 +62,7 @@ import static org.apache.jackrabbit.oak.plugins.document.VersionGarbageCollector import static org.apache.jackrabbit.oak.plugins.document.VersionGarbageCollector.SETTINGS_COLLECTION_DETAILED_GC_TIMESTAMP_PROP; import static org.apache.jackrabbit.oak.plugins.document.VersionGarbageCollector.SETTINGS_COLLECTION_ID; import static org.apache.jackrabbit.oak.plugins.document.bundlor.DocumentBundlor.META_PROP_PATTERN; +import static org.apache.jackrabbit.oak.plugins.document.util.Utils.PATH_LONG; import static org.junit.Assert.assertEquals; import static org.junit.Assert.assertFalse; import static org.junit.Assert.assertNotEquals; @@ -72,7 +74,6 @@ import static org.junit.Assume.assumeTrue; import org.apache.jackrabbit.guava.common.base.Function; import org.apache.jackrabbit.guava.common.base.Predicate; -import org.apache.jackrabbit.guava.common.base.Strings; import org.apache.jackrabbit.guava.common.collect.AbstractIterator; import org.apache.jackrabbit.guava.common.collect.ImmutableList; import org.apache.jackrabbit.guava.common.collect.Iterators; @@ -250,7 +251,7 @@ public class VersionGarbageCollectorIT { @Test public void gcLongPathSplitDocs() throws Exception { - gcSplitDocsInternal(Strings.repeat("sub", 120)); + gcSplitDocsInternal(repeat("sub", 120)); } // OAK-10199 @@ -701,6 +702,64 @@ public class VersionGarbageCollectorIT { assertEquals(0, stats.updatedDetailedGCDocsCount); } + @Test + public void testGCDeletedLongPathProps() throws Exception { + //1. Create nodes with properties + NodeBuilder b1 = store.getRoot().builder(); + String longPath = repeat("p", PATH_LONG + 1); + b1.child(longPath); + + // Add property to node & save + for (int i = 0; i < 10; i++) { + b1.child(longPath).child("foo").setProperty("test"+i, "t", STRING); + } + store.merge(b1, EmptyHook.INSTANCE, CommitInfo.EMPTY); + + // enable the detailed gc flag + writeField(gc, "detailedGCEnabled", true, true); + long maxAge = 1; //hours + long delta = MINUTES.toMillis(10); + //1. Go past GC age and check no GC done as nothing deleted + clock.waitUntil(getCurrentTimestamp() + maxAge); + VersionGCStats stats = gc.gc(maxAge, HOURS); + assertEquals(0, stats.deletedPropsGCCount); + assertEquals(0, stats.updatedDetailedGCDocsCount); + + //Remove property + NodeBuilder b2 = store.getRoot().builder(); + for (int i = 0; i < 10; i++) { + b2.child(longPath).child("foo").removeProperty("test"+i); + } + store.merge(b2, EmptyHook.INSTANCE, CommitInfo.EMPTY); + + store.runBackgroundOperations(); + + //2. Check that a deleted property is not collected before maxAge + //Clock cannot move back (it moved forward in #1) so double the maxAge + clock.waitUntil(clock.getTime() + delta); + stats = gc.gc(maxAge*2, HOURS); + assertEquals(0, stats.deletedPropsGCCount); + assertEquals(0, stats.updatedDetailedGCDocsCount); + + //3. Check that deleted property does get collected post maxAge + clock.waitUntil(clock.getTime() + HOURS.toMillis(maxAge*2) + delta); + + stats = gc.gc(maxAge*2, HOURS); + assertEquals(10, stats.deletedPropsGCCount); + + //4. Check that a revived property (deleted and created again) does not get gc + NodeBuilder b4 = store.getRoot().builder(); + for (int i = 0; i < 10; i++) { + b4.child(longPath).child("foo").setProperty("test"+i, "t", STRING); + } + store.merge(b4, EmptyHook.INSTANCE, CommitInfo.EMPTY); + + clock.waitUntil(clock.getTime() + HOURS.toMillis(maxAge*2) + delta); + stats = gc.gc(maxAge*2, HOURS); + assertEquals(0, stats.deletedPropsGCCount); + assertEquals(0, stats.updatedDetailedGCDocsCount); + } + @Test public void testGCDeletedNonBundledProps() throws Exception {
